airflow-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Ash Berlin-Taylor (Jira)" <j...@apache.org>
Subject [jira] [Commented] (AIRFLOW-6082) Tasks taking poising pill few seconds after started
Date Wed, 27 Nov 2019 12:22:00 GMT

    [ https://issues.apache.org/jira/browse/AIRFLOW-6082?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16983468#comment-16983468
] 

Ash Berlin-Taylor commented on AIRFLOW-6082:
--------------------------------------------

Are you manually triggering two runs in quick succession (with-in the same second) here?

{noformat}
[2019-11-27 03:48:16,430] [logging_mixin.py:95] WARNING - /usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py:536:
Warning: Data truncated for column 'start_date' at row 1
cursor.execute(statement, parameters)
{noformat}

Looks suspect. What version of mysql are you on? I would suggest trying postgres, or at least
a more recent version of mysql.

> Tasks taking poising pill few seconds after started
> ---------------------------------------------------
>
>                 Key: AIRFLOW-6082
>                 URL: https://issues.apache.org/jira/browse/AIRFLOW-6082
>             Project: Apache Airflow
>          Issue Type: Bug
>          Components: DAG, scheduler, worker
>    Affects Versions: 1.10.0
>         Environment: Debian 8.10
>            Reporter: Sébastien GENESTA
>            Priority: Major
>
> Hi,
>  
> We are encountering strange behaviour using Airflow.
>  
> Randomly, tasks "take poison pill" few second after starting.
>  
> *** Reading local file: ************************************************************************************************
> [2019-11-27 03:48:16,430] [logging_mixin.py:95] WARNING - /usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py:536:
Warning: Data truncated for column 'start_date' at row 1
>  cursor.execute(statement, parameters)
> [2019-11-27 03:48:16,431] [logging_mixin.py:95] WARNING - /usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py:536:
Warning: Data truncated for column 'latest_heartbeat' at row 1
>  cursor.execute(statement, parameters)
> [2019-11-27 03:48:16,450] [models.py:1359] INFO - Dependencies all met for <TaskInstance:
*********************** [queued]>
> [2019-11-27 03:48:16,460] [models.py:1353] INFO - Dependencies not met for <TaskInstance:
********************************** [queued]>, dependency 'Task Instance Slots Available'
FAILED: The maximum number of running tasks (16) for this task's DAG 'cron_flux_ftp' has been
reached.
> [2019-11-27 03:48:16,460] [models.py:1554] WARNING - 
> --------------------------------------------------------------------------------
> FIXME: Rescheduling due to concurrency limits reached at task runtime. Attempt 1 of 2.
State set to NONE.
> --------------------------------------------------------------------------------
> [2019-11-27 03:48:16,460] [models.py:1557] INFO - Queuing into pool None
> [2019-11-27 03:48:16,472] [logging_mixin.py:95] WARNING - /usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py:536:
Warning: Data truncated for column 'queued_dttm' at row 1
>  cursor.execute(statement, parameters)
> [2019-11-27 03:48:16,475] [logging_mixin.py:95] INFO - [2019-11-27 03:48:16,475] [jobs.py:2514]
INFO - Task is not able to be run
> [2019-11-27 03:48:16,486] [logging_mixin.py:95] WARNING - /usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py:536:
Warning: Data truncated for column 'end_date' at row 1
>  cursor.execute(statement, parameters)
> [2019-11-27 03:48:38,384] [logging_mixin.py:95] WARNING - /usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py:536:
Warning: Data truncated for column 'start_date' at row 1
>  cursor.execute(statement, parameters)
> [2019-11-27 03:48:38,384] [logging_mixin.py:95] WARNING - /usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py:536:
Warning: Data truncated for column 'latest_heartbeat' at row 1
>  cursor.execute(statement, parameters)
> [2019-11-27 03:48:38,401] [models.py:1359] INFO - Dependencies all met for <TaskInstance:
**************************** [queued]>
> [2019-11-27 03:48:38,411] [models.py:1359] INFO - Dependencies all met for <TaskInstance:
************************************************************** [queued]>
> [2019-11-27 03:48:38,411] [models.py:1571] INFO - 
> --------------------------------------------------------------------------------
> Starting attempt 1 of 2
> --------------------------------------------------------------------------------
> [2019-11-27 03:48:38,426] [models.py:1593] INFO - Executing <Task(BashOperator): *********************>
on 2019-11-26T02:30:00+00:00
> [2019-11-27 03:48:38,426] [base_task_runner.py:118] INFO - Running: ['bash', '-c', u'airflow
run cron_flux_ftp ********************* 2019-11-26T02:30:00+00:00 --job_id 40947091 --raw
-sd DAGS_************* --cfg_path /tmp/tmpg9r3RQ']
> [2019-11-27 03:48:38,815] [base_task_runner.py:101] INFO - Job 40947091: Subtask *********************
[2019-11-27 03:48:38,815] [settings.py:174] INFO - settings.configure_orm(): Using pool settings.
pool_size=5, pool_recycle=1800, pid=12120
> [2019-11-27 03:48:39,036] [base_task_runner.py:101] INFO - Job 40947091: Subtask *********************
[2019-11-27 03:48:39,036] [__init__.py:51] INFO - Using executor CeleryExecutor
> [2019-11-27 03:48:39,175] [base_task_runner.py:101] INFO - Job 40947091: Subtask *********************
/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py:536: Warning: Data truncated
for column 'dttm' at row 1
> [2019-11-27 03:48:39,175] [base_task_runner.py:101] INFO - Job 40947091: Subtask *********************
cursor.execute(statement, parameters)
> [2019-11-27 03:48:39,175] [base_task_runner.py:101] INFO - Job 40947091: Subtask *********************
/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py:536: Warning: Data truncated
for column 'execution_date' at row 1
> [2019-11-27 03:48:39,175] [base_task_runner.py:101] INFO - Job 40947091: Subtask *********************
cursor.execute(statement, parameters)
> [2019-11-27 03:48:39,182] [base_task_runner.py:101] INFO - Job 40947091: Subtask *********************
[2019-11-27 03:48:39,181] [models.py:273] INFO - Filling up the DagBag from /home/production/airflow/dags/flux_ftp.py
> [2019-11-27 03:48:39,231] [base_task_runner.py:101] INFO - Job 40947091: Subtask *********************
/usr/local/lib/python2.7/dist-packages/airflow/utils/helpers.py:356: DeprecationWarning: Importing
'PythonOperator' directly from 'airflow.operators' has been deprecated. Please import from
'airflow.operators.[operator_module]' instead. Support for direct imports will be dropped
entirely in Airflow 2.0.
> [2019-11-27 03:48:39,231] [base_task_runner.py:101] INFO - Job 40947091: Subtask *********************
DeprecationWarning)
> [2019-11-27 03:48:39,231] [base_task_runner.py:101] INFO - Job 40947091: Subtask *********************
/usr/local/lib/python2.7/dist-packages/airflow/utils/helpers.py:356: DeprecationWarning: Importing
'DummyOperator' directly from 'airflow.operators' has been deprecated. Please import from
'airflow.operators.[operator_module]' instead. Support for direct imports will be dropped
entirely in Airflow 2.0.
> [2019-11-27 03:48:39,231] [base_task_runner.py:101] INFO - Job 40947091: Subtask *********************
DeprecationWarning)
> [2019-11-27 03:48:39,515] [base_task_runner.py:101] INFO - Job 40947091: Subtask *********************
/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py:536: Warning: Incorrect
datetime value: '2019-11-26 02:30:00+00:00' for column 'execution_date' at row 1
> [2019-11-27 03:48:39,516] [base_task_runner.py:101] INFO - Job 40947091: Subtask *********************
cursor.execute(statement, parameters)
> [2019-11-27 03:48:39,516] [base_task_runner.py:101] INFO - Job 40947091: Subtask *********************
/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py:536: Warning: Truncated
incorrect datetime value: '2019-11-26 02:30:00+00:00'
> [2019-11-27 03:48:39,516] [base_task_runner.py:101] INFO - Job 40947091: Subtask *********************
cursor.execute(statement, parameters)
> [2019-11-27 03:48:39,551] [base_task_runner.py:101] INFO - Job 40947091: Subtask *********************
[2019-11-27 03:48:39,551] [cli.py:520] INFO - Running <TaskInstance: cron_flux_ftp.*********************
2019-11-26T02:30:00+00:00 [up_for_retry]> on host ip-172-31-48-142.eu-west-1.compute.internal
> [2019-11-27 03:48:39,584] [bash_operator.py:77] INFO - Tmp dir root location: 
>  /tmp
> [2019-11-27 03:48:39,607] [bash_operator.py:86] INFO - Exporting the following env vars:
> AIRFLOW_CTX_TASK_ID=*********************
> AIRFLOW_CTX_DAG_ID=cron_flux_ftp
> AIRFLOW_CTX_EXECUTION_DATE=2019-11-26T02:30:00+00:00
> AIRFLOW_CTX_DAG_RUN_ID=scheduled__2019-11-26T02:30:00+00:00
> [2019-11-27 03:48:39,608] [bash_operator.py:100] INFO - Temporary script location: /tmp/airflowtmpQ4h8TB/*********************k2YRcb
> [2019-11-27 03:48:39,608] [bash_operator.py:110] INFO - Running command: temp_file=$(mktemp)
&& echo $temp_file && cd ***************** && php cron_script_flux_ftp.php
*************************** > $temp_file && **************************** $temp_file
&& rm $temp_file || (php ****************************************** $temp_file &&
rm $temp_file && exit 1) 
> [2019-11-27 03:48:39,612] [bash_operator.py:119] INFO - Output:
> [2019-11-27 03:48:39,642] [bash_operator.py:123] INFO - /tmp/tmp.H4Ipn1K3uU
> [2019-11-27 03:48:43,432] [logging_mixin.py:95] INFO - [2019-11-27 03:48:43,431] [jobs.py:2595]
WARNING - State of this instance has been externally set to up_for_retry. Taking the poison
pill.
> [2019-11-27 03:48:43,446] [helpers.py:250] INFO - Sending 15 to GPID 12120
> [2019-11-27 03:48:43,446] [models.py:1634] ERROR - Received SIGTERM. Terminating subprocesses.
> [2019-11-27 03:48:43,446] [bash_operator.py:137] INFO - Sending SIGTERM signal to bash
process group
> [2019-11-27 03:48:43,460] [helpers.py:232] INFO - Process psutil.Process(pid=12680, status='terminated')
(12680) terminated with exit code None
> [2019-11-27 03:48:43,458] [models.py:1788] ERROR - Task received SIGTERM signal
> Traceback (most recent call last):



--
This message was sent by Atlassian Jira
(v8.3.4#803005)

Mime
View raw message