Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Task processes killed with WARNING - Recorded pid does not match the current pid #17507

Closed
iasoon opened this issue Aug 9, 2021 · 66 comments
Closed
Labels
affected_version:2.1 Issues Reported for 2.1 affected_version:2.2 Issues Reported for 2.2 affected_version:2.3 Issues Reported for 2.3 affected_version:2.4 Issues Reported for 2.4 kind:bug This is a clearly a bug

Comments

@iasoon
Copy link

iasoon commented Aug 9, 2021

Apache Airflow version: 2.1.3

Apache Airflow Provider versions (please include all providers that are relevant to your bug):

apache-airflow-providers-amazon==2.0.0
apache-airflow-providers-celery==2.0.0
apache-airflow-providers-cncf-kubernetes==2.0.0
apache-airflow-providers-docker==2.0.0
apache-airflow-providers-elasticsearch==2.0.2
apache-airflow-providers-ftp==2.0.0
apache-airflow-providers-google==4.0.0
apache-airflow-providers-grpc==2.0.0
apache-airflow-providers-hashicorp==2.0.0
apache-airflow-providers-http==2.0.0
apache-airflow-providers-imap==2.0.0
apache-airflow-providers-microsoft-azure==3.0.0
apache-airflow-providers-mysql==2.0.0
apache-airflow-providers-postgres==2.0.0
apache-airflow-providers-redis==2.0.0
apache-airflow-providers-sendgrid==2.0.0
apache-airflow-providers-sftp==2.0.0
apache-airflow-providers-slack==4.0.0
apache-airflow-providers-sqlite==2.0.0
apache-airflow-providers-ssh==2.0.0

Environment:

I'm using the airflow-2.1.2 container from dockerhub.

  • Cloud provider or hardware configuration: AWS
  • OS (e.g. from /etc/os-release): Debian GNU/Linux 10 (buster)
  • Kernel (e.g. uname -a): Linux fe52079d9ade 5.12.13-200.fc33.x86_64 #1 SMP Wed Jun 23 16:20:26 UTC 2021 x86_64 GNU/Linux

What happened:

When using the EMRStepSensor (set to reschedule mode) to monitor EMR steps, the task will sometimes fail while the EMR step sucessfully ran. Most of the time the sensor will work fine, but every so often this issue occurs (on the same DAG, without modifications).

EMRStepSensor task instance debug log
*** Reading local file: /opt/airflow/logs/derived.adobe_target_catalog_sporza/watch_adobe_target_catalog_sporza_job_emr_step/2021-08-07T05:28:00+00:00/1.log
[2021-08-08 05:29:20,367] {__init__.py:51} DEBUG - Loading core task runner: StandardTaskRunner
[2021-08-08 05:29:21,594] {base_task_runner.py:62} DEBUG - Planning to run as the  user
[2021-08-08 05:29:21,597] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> from DB
[2021-08-08 05:29:22,086] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]>
[2021-08-08 05:29:22,086] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:29:22,086] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Task Instance State' PASSED: True, Task state queued was valid.
[2021-08-08 05:29:22,128] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:29:22,128] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:29:22,129] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Task Instance Not Running' PASSED: True, Task is not in running state.
[2021-08-08 05:29:22,130] {taskinstance.py:896} INFO - Dependencies all met for <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]>
[2021-08-08 05:29:22,130] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:29:22,165] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:29:22,206] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:29:22,327] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Pool Slots Available' PASSED: True, ('There are enough open slots in %s to execute the task', 'default_pool')
[2021-08-08 05:29:22,327] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Task Concurrency' PASSED: True, Task concurrency is not set.
[2021-08-08 05:29:22,327] {taskinstance.py:896} INFO - Dependencies all met for <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]>
[2021-08-08 05:29:22,327] {taskinstance.py:1087} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:29:22,327] {taskinstance.py:1088} INFO - Starting attempt 1 of 1
[2021-08-08 05:29:22,327] {taskinstance.py:1089} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:29:24,417] {taskinstance.py:1107} INFO - Executing <Task(EmrStepSensor): watch_adobe_target_catalog_sporza_job_emr_step> on 2021-08-07T05:28:00+00:00
[2021-08-08 05:29:24,421] {standard_task_runner.py:52} INFO - Started process 7426 to run task
[2021-08-08 05:29:24,427] {standard_task_runner.py:76} INFO - Running: ['airflow', 'tasks', 'run', 'derived.adobe_target_catalog_sporza', 'watch_adobe_target_catalog_sporza_job_emr_step', '2021-08-07T05:28:00+00:00', '--job-id', '98940', '--pool', 'default_pool', '--raw', '--subdir', 'DAGS_FOLDER/adobe_target_catalog_sporza_wf.py', '--cfg-path', '/tmp/tmpucsqr5ep', '--error-file', '/tmp/tmpi1wh32jz']
[2021-08-08 05:29:24,427] {standard_task_runner.py:77} INFO - Job 98940: Subtask watch_adobe_target_catalog_sporza_job_emr_step
[2021-08-08 05:29:24,428] {cli_action_loggers.py:66} DEBUG - Calling callbacks: [<function default_action_log at 0x7fc8dfbe5d90>]
[2021-08-08 05:29:26,223] {settings.py:208} DEBUG - Setting up DB connection pool (PID 7426)
[2021-08-08 05:29:26,223] {settings.py:244} DEBUG - settings.prepare_engine_args(): Using NullPool
[2021-08-08 05:29:26,226] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [None]> from DB
[2021-08-08 05:29:27,030] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]>
[2021-08-08 05:29:27,523] {logging_mixin.py:104} INFO - Running <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]> on host ip-172-31-58-121.eu-west-1.compute.internal
[2021-08-08 05:29:27,523] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]> from DB
[2021-08-08 05:29:28,218] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]>
[2021-08-08 05:29:28,871] {taskinstance.py:677} DEBUG - Clearing XCom data
[2021-08-08 05:29:29,515] {taskinstance.py:684} DEBUG - XCom data cleared
[2021-08-08 05:29:32,916] {taskinstance.py:1302} INFO - Exporting the following env vars:
AIRFLOW_CTX_DAG_OWNER=vrt
AIRFLOW_CTX_DAG_ID=derived.adobe_target_catalog_sporza
AIRFLOW_CTX_TASK_ID=watch_adobe_target_catalog_sporza_job_emr_step
AIRFLOW_CTX_EXECUTION_DATE=2021-08-07T05:28:00+00:00
AIRFLOW_CTX_DAG_RUN_ID=scheduled__2021-08-07T05:28:00+00:00
[2021-08-08 05:29:32,916] {__init__.py:146} DEBUG - Preparing lineage inlets and outlets
[2021-08-08 05:29:32,916] {__init__.py:190} DEBUG - inlets: [], outlets: []
[2021-08-08 05:29:33,486] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]> from DB
[2021-08-08 05:29:36,437] {base_aws.py:368} INFO - Airflow Connection: aws_conn_id=aws_default
[2021-08-08 05:29:36,521] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]>
[2021-08-08 05:29:36,562] {base_job.py:227} DEBUG - [heartbeat]
[2021-08-08 05:29:38,654] {base_aws.py:179} INFO - No credentials retrieved from Connection
[2021-08-08 05:29:38,654] {base_aws.py:87} INFO - Creating session with aws_access_key_id=None region_name=None
[2021-08-08 05:29:38,655] {hooks.py:417} DEBUG - Changing event name from creating-client-class.iot-data to creating-client-class.iot-data-plane
[2021-08-08 05:29:38,656] {hooks.py:417} DEBUG - Changing event name from before-call.apigateway to before-call.api-gateway
[2021-08-08 05:29:38,657] {hooks.py:417} DEBUG - Changing event name from request-created.machinelearning.Predict to request-created.machine-learning.Predict
[2021-08-08 05:29:38,659] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.autoscaling.CreateLaunchConfiguration to before-parameter-build.auto-scaling.CreateLaunchConfiguration
[2021-08-08 05:29:38,659] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.route53 to before-parameter-build.route-53
[2021-08-08 05:29:38,659] {hooks.py:417} DEBUG - Changing event name from request-created.cloudsearchdomain.Search to request-created.cloudsearch-domain.Search
[2021-08-08 05:29:38,660] {hooks.py:417} DEBUG - Changing event name from docs.*.autoscaling.CreateLaunchConfiguration.complete-section to docs.*.auto-scaling.CreateLaunchConfiguration.complete-section
[2021-08-08 05:29:38,663] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.logs.CreateExportTask to before-parameter-build.cloudwatch-logs.CreateExportTask
[2021-08-08 05:29:38,663] {hooks.py:417} DEBUG - Changing event name from docs.*.logs.CreateExportTask.complete-section to docs.*.cloudwatch-logs.CreateExportTask.complete-section
[2021-08-08 05:29:38,663] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.cloudsearchdomain.Search to before-parameter-build.cloudsearch-domain.Search
[2021-08-08 05:29:38,663] {hooks.py:417} DEBUG - Changing event name from docs.*.cloudsearchdomain.Search.complete-section to docs.*.cloudsearch-domain.Search.complete-section
[2021-08-08 05:29:38,664] {base_aws.py:157} INFO - role_arn is None
[2021-08-08 05:29:38,667] {utils.py:364} DEBUG - IMDS ENDPOINT: http://169.254.169.254/
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: env
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: assume-role
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: assume-role-with-web-identity
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: sso
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: shared-credentials-file
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: custom-process
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: config-file
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: ec2-credentials-file
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: boto-config
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: container-role
[2021-08-08 05:29:38,671] {connectionpool.py:230} DEBUG - Starting new HTTP connection (1): 169.254.170.2:80
[2021-08-08 05:29:38,673] {connectionpool.py:442} DEBUG - http://169.254.170.2:80 "GET /v2/credentials/c5f7099a-d46e-4472-a48f-6c137db9e75d HTTP/1.1" 200 1307
[2021-08-08 05:29:38,674] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/endpoints.json
[2021-08-08 05:29:38,683] {hooks.py:210} DEBUG - Event choose-service-name: calling handler <function handle_service_name_alias at 0x7fc8dbee8bf8>
[2021-08-08 05:29:38,691] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/emr/2009-03-31/service-2.json
[2021-08-08 05:29:38,695] {hooks.py:210} DEBUG - Event creating-client-class.emr: calling handler <function add_generate_presigned_url at 0x7fc8dbf947b8>
[2021-08-08 05:29:38,697] {endpoint.py:292} DEBUG - Setting elasticmapreduce timeout as (60, 60)
[2021-08-08 05:29:38,698] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/_retry.json
[2021-08-08 05:29:38,698] {client.py:166} DEBUG - Registering retry handlers for service: emr
[2021-08-08 05:29:38,699] {emr_step.py:73} INFO - Poking step s-581MKMYKRED7 on cluster j-XDTNJDHR23RQ
[2021-08-08 05:29:38,699] {hooks.py:210} DEBUG - Event before-parameter-build.emr.DescribeStep: calling handler <function generate_idempotent_uuid at 0x7fc8dbf06048>
[2021-08-08 05:29:38,699] {hooks.py:210} DEBUG - Event before-call.emr.DescribeStep: calling handler <function inject_api_version_header_if_needed at 0x7fc8dbf077b8>
[2021-08-08 05:29:38,699] {endpoint.py:101} DEBUG - Making request for OperationModel(name=DescribeStep) with params: {'url_path': '/', 'query_string': '', 'method': 'POST', 'headers': {'X-Amz-Target': 'ElasticMapReduce.DescribeStep', 'Content-Type': 'application/x-amz-json-1.1', 'User-Agent': 'Boto3/1.17.107 Python/3.6.13 Linux/4.14.238-182.422.amzn2.x86_64 exec-env/AWS_ECS_FARGATE Botocore/1.20.107'}, 'body': b'{"ClusterId": "j-XDTNJDHR23RQ", "StepId": "s-581MKMYKRED7"}', 'url': 'https://eu-west-1.elasticmapreduce.amazonaws.com/', 'context': {'client_region': 'eu-west-1', 'client_config': <botocore.config.Config object at 0x7fc8dba19470>, 'has_streaming_input': False, 'auth_type': None}}
[2021-08-08 05:29:38,700] {hooks.py:210} DEBUG - Event request-created.emr.DescribeStep: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7fc8dba19438>>
[2021-08-08 05:29:38,700] {hooks.py:210} DEBUG - Event choose-signer.emr.DescribeStep: calling handler <function set_operation_specific_signer at 0x7fc8dbf01ea0>
[2021-08-08 05:29:38,700] {auth.py:380} DEBUG - Calculating signature using v4 auth.
[2021-08-08 05:29:38,700] {auth.py:381} DEBUG - CanonicalRequest:
POST
/

content-type:application/x-amz-json-1.1
host:eu-west-1.elasticmapreduce.amazonaws.com
x-amz-date:20210808T052938Z
x-amz-security-token:IQoJb3JpZ2luX2VjEGwaCWV1LXdlc3QtMSJHMEUCIQCZ4NXI3+3YJKZwyu+L4vTyY4swRSd7+zHkDO3Nwc0JiwIgdDuzR2+qJ5vFE03B1RRhzZYGV4Iy/pt7jVXRr0YjXTUqogQIhP//////////ARABGgwyODM3NzQxNDgzNTciDDl+9YdFHetmruZnfSr2A4vFCZwFNe0LEigdz0ayjIhvTZMsjY6CClml27JRBbUllyWz6t3b5SjafRWERgfEe1xIjnFFvp/UFSDIrZVuOefX94uUcgWQKV5zhz/dHdpCzpPltF+syapd2IeY5lgaUZWr+ax+Pfs75JILyfTpa7u43hg1M6P9L07zP/IUWdrXvyvu0wVh07r6/bHUDKJGy52Ok2q6Hr4ltT4MVAY/EZIEDZA8dlNdd7/UDddecp+/7/QIMftzZsgQJVyO+IIB+cfHCIV+1g/ACnsSbBkJuH2fn/B0YeP6e1135yTFknzNKVUxf6OeBIuPrkcu78HnaOXcjv+JSKb9AcFP+2zOo9JYmr040XGVqesZiAc+uDWbL74LDQ7ze5b4sLSNXfCCEvqsYVy9Nt7UlopCXoIS2lBrWgXNhsppDQ976Gr+WgyV1Wbjx2NZlJFCtSNarwF0qDPBmm6yhQxyKMYarOrUpy9aNl/18ujIhJZ2/JMUYlzH0TOBc1YCKIuZLNPwYfxZW6JmosfKXjAFUK7eDn4tU6LSXyo2GNLYzjY71OyCOpllJYtxg/NDAQBlmMCbFPpFCCTjPECU0sGnhfPAdlsyYngT3L0bSyjAZpPRfYrfPd4i3j2niPq9BwF/iOIR95T2CK7zqxXB4TIpporSE0pItmFgynGTh+IwtZm9iAY6pgENShKQaHxJvNj1O5ddYeCwW3H2SqjrHroeOt82xGkH5stZ7g28Uy7iPIPEehlkrB7ry/KjLq9DAo4zVneHhfKJBUBTBxz944AZhd0d9VvSRGgEXnmxzTsHma9hnkwQfGdbXwH4ja582o7hPEI98AAgoo5OCuV/vyMHHgrJBa7z+7eRtGnCeg+EJZy9WlsilHHGze4QGDEDc4NJypNZM4JON503hXON
x-amz-target:ElasticMapReduce.DescribeStep

content-type;host;x-amz-date;x-amz-security-token;x-amz-target
2a131454435119560c6fa09b6b1eeeb557aba91e61af62fe4883ccc24890c4f3
[2021-08-08 05:29:38,700] {auth.py:383} DEBUG - StringToSign:
AWS4-HMAC-SHA256
20210808T052938Z
20210808/eu-west-1/elasticmapreduce/aws4_request
29f0d229d76daf02f334b8c7d193cb06de4619f4adb7b3057683f53b2ea79c80
[2021-08-08 05:29:38,700] {auth.py:385} DEBUG - Signature:
66e13f874221cb3c1b275a052ac56a7e827d431e940bfe9b14414104e0a3b162
[2021-08-08 05:29:38,701] {endpoint.py:187} DEBUG - Sending http request: <AWSPreparedRequest stream_output=False, method=POST, url=https://eu-west-1.elasticmapreduce.amazonaws.com/, headers={'X-Amz-Target': b'ElasticMapReduce.DescribeStep', 'Content-Type': b'application/x-amz-json-1.1', 'User-Agent': b'Boto3/1.17.107 Python/3.6.13 Linux/4.14.238-182.422.amzn2.x86_64 exec-env/AWS_ECS_FARGATE Botocore/1.20.107', 'X-Amz-Date': b'20210808T052938Z', 'X-Amz-Security-Token': b'IQoJb3JpZ2luX2VjEGwaCWV1LXdlc3QtMSJHMEUCIQCZ4NXI3+3YJKZwyu+L4vTyY4swRSd7+zHkDO3Nwc0JiwIgdDuzR2+qJ5vFE03B1RRhzZYGV4Iy/pt7jVXRr0YjXTUqogQIhP//////////ARABGgwyODM3NzQxNDgzNTciDDl+9YdFHetmruZnfSr2A4vFCZwFNe0LEigdz0ayjIhvTZMsjY6CClml27JRBbUllyWz6t3b5SjafRWERgfEe1xIjnFFvp/UFSDIrZVuOefX94uUcgWQKV5zhz/dHdpCzpPltF+syapd2IeY5lgaUZWr+ax+Pfs75JILyfTpa7u43hg1M6P9L07zP/IUWdrXvyvu0wVh07r6/bHUDKJGy52Ok2q6Hr4ltT4MVAY/EZIEDZA8dlNdd7/UDddecp+/7/QIMftzZsgQJVyO+IIB+cfHCIV+1g/ACnsSbBkJuH2fn/B0YeP6e1135yTFknzNKVUxf6OeBIuPrkcu78HnaOXcjv+JSKb9AcFP+2zOo9JYmr040XGVqesZiAc+uDWbL74LDQ7ze5b4sLSNXfCCEvqsYVy9Nt7UlopCXoIS2lBrWgXNhsppDQ976Gr+WgyV1Wbjx2NZlJFCtSNarwF0qDPBmm6yhQxyKMYarOrUpy9aNl/18ujIhJZ2/JMUYlzH0TOBc1YCKIuZLNPwYfxZW6JmosfKXjAFUK7eDn4tU6LSXyo2GNLYzjY71OyCOpllJYtxg/NDAQBlmMCbFPpFCCTjPECU0sGnhfPAdlsyYngT3L0bSyjAZpPRfYrfPd4i3j2niPq9BwF/iOIR95T2CK7zqxXB4TIpporSE0pItmFgynGTh+IwtZm9iAY6pgENShKQaHxJvNj1O5ddYeCwW3H2SqjrHroeOt82xGkH5stZ7g28Uy7iPIPEehlkrB7ry/KjLq9DAo4zVneHhfKJBUBTBxz944AZhd0d9VvSRGgEXnmxzTsHma9hnkwQfGdbXwH4ja582o7hPEI98AAgoo5OCuV/vyMHHgrJBa7z+7eRtGnCeg+EJZy9WlsilHHGze4QGDEDc4NJypNZM4JON503hXON', 'Authorization': b'AWS4-HMAC-SHA256 Credential=ASIAUEESB34CT3URIQHE/20210808/eu-west-1/elasticmapreduce/aws4_request, SignedHeaders=content-type;host;x-amz-date;x-amz-security-token;x-amz-target, Signature=66e13f874221cb3c1b275a052ac56a7e827d431e940bfe9b14414104e0a3b162', 'Content-Length': '59'}>
[2021-08-08 05:29:38,702] {httpsession.py:50} DEBUG - Certificate path: /home/airflow/.local/lib/python3.6/site-packages/certifi/cacert.pem
[2021-08-08 05:29:38,702] {connectionpool.py:943} DEBUG - Starting new HTTPS connection (1): eu-west-1.elasticmapreduce.amazonaws.com:443
[2021-08-08 05:29:38,752] {connectionpool.py:442} DEBUG - https://eu-west-1.elasticmapreduce.amazonaws.com:443 "POST / HTTP/1.1" 200 799
[2021-08-08 05:29:38,752] {parsers.py:233} DEBUG - Response headers: {'x-amzn-RequestId': 'ecacd9e3-44b2-4a00-a4f0-48efe0d65847', 'Content-Type': 'application/x-amz-json-1.1', 'Content-Length': '799', 'Date': 'Sun, 08 Aug 2021 05:29:38 GMT'}
[2021-08-08 05:29:38,752] {parsers.py:234} DEBUG - Response body:
b'{"Step":{"ActionOnFailure":"CONTINUE","Config":{"Args":["spark-submit","--deploy-mode","cluster","--master","yarn","--driver-memory","2G","--executor-memory","8G","--num-executors","5","--executor-cores","3","--packages","io.delta:delta-core_2.11:0.6.1","--py-files","s3://vrt-datalake-artifacts-prod/adobe-target-catalog-sporza/python/adobe_target_catalog_sporza-1.0.0-py3.7_6.egg,s3://vrt-datalake-artifacts-prod/python-datalake-helpers/vrt_datalake_helpers-21-py3-none-any.whl","s3://vrt-datalake-artifacts-prod/adobe-target-catalog-sporza/python/run_6.py","prod","2021-08-08 05:28:00"],"Jar":"command-runner.jar","Properties":{}},"Id":"s-581MKMYKRED7","Name":"adobe-target-catalog-sporza-job","Status":{"State":"PENDING","StateChangeReason":{},"Timeline":{"CreationDateTime":1.628400523922E9}}}}'
[2021-08-08 05:29:38,753] {hooks.py:210} DEBUG - Event needs-retry.emr.DescribeStep: calling handler <botocore.retryhandler.RetryHandler object at 0x7fc8dba19860>
[2021-08-08 05:29:38,753] {retryhandler.py:187} DEBUG - No retry needed.
[2021-08-08 05:29:38,753] {emr_base.py:66} INFO - Job flow currently PENDING
[2021-08-08 05:29:38,753] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]> from DB
[2021-08-08 05:29:39,718] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]>
[2021-08-08 05:29:39,748] {taskinstance.py:1906} DEBUG - Task Duration set to 17.617928
[2021-08-08 05:29:42,695] {taskinstance.py:1484} INFO - Rescheduling task, marking task as UP_FOR_RESCHEDULE
[2021-08-08 05:29:42,696] {cli_action_loggers.py:84} DEBUG - Calling callbacks: []
[2021-08-08 05:29:44,944] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]> from DB
[2021-08-08 05:29:48,268] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]>
[2021-08-08 05:29:48,674] {base_job.py:227} DEBUG - [heartbeat]
[2021-08-08 05:29:48,674] {local_task_job.py:149} INFO - Task exited with return code 0
[2021-08-08 05:29:48,675] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]> from DB
[2021-08-08 05:29:49,740] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]>
[2021-08-08 05:30:49,437] {__init__.py:51} DEBUG - Loading core task runner: StandardTaskRunner
[2021-08-08 05:30:51,569] {base_task_runner.py:62} DEBUG - Planning to run as the  user
[2021-08-08 05:30:51,572] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> from DB
[2021-08-08 05:30:52,465] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]>
[2021-08-08 05:30:52,465] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:30:52,465] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Task Instance State' PASSED: True, Task state queued was valid.
[2021-08-08 05:30:52,544] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:30:52,544] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:30:52,545] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Task Instance Not Running' PASSED: True, Task is not in running state.
[2021-08-08 05:30:52,546] {taskinstance.py:896} INFO - Dependencies all met for <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]>
[2021-08-08 05:30:52,546] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:30:52,593] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:30:52,593] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:30:52,756] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Pool Slots Available' PASSED: True, ('There are enough open slots in %s to execute the task', 'default_pool')
[2021-08-08 05:30:52,756] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Task Concurrency' PASSED: True, Task concurrency is not set.
[2021-08-08 05:30:52,756] {taskinstance.py:896} INFO - Dependencies all met for <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]>
[2021-08-08 05:30:52,756] {taskinstance.py:1087} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:30:52,756] {taskinstance.py:1088} INFO - Starting attempt 1 of 1
[2021-08-08 05:30:52,756] {taskinstance.py:1089} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:30:53,648] {taskinstance.py:1107} INFO - Executing <Task(EmrStepSensor): watch_adobe_target_catalog_sporza_job_emr_step> on 2021-08-07T05:28:00+00:00
[2021-08-08 05:30:53,651] {standard_task_runner.py:52} INFO - Started process 7972 to run task
[2021-08-08 05:30:53,655] {standard_task_runner.py:76} INFO - Running: ['airflow', 'tasks', 'run', 'derived.adobe_target_catalog_sporza', 'watch_adobe_target_catalog_sporza_job_emr_step', '2021-08-07T05:28:00+00:00', '--job-id', '98953', '--pool', 'default_pool', '--raw', '--subdir', 'DAGS_FOLDER/adobe_target_catalog_sporza_wf.py', '--cfg-path', '/tmp/tmppdcqbh0o', '--error-file', '/tmp/tmpdky_uy36']
[2021-08-08 05:30:53,655] {standard_task_runner.py:77} INFO - Job 98953: Subtask watch_adobe_target_catalog_sporza_job_emr_step
[2021-08-08 05:30:53,656] {cli_action_loggers.py:66} DEBUG - Calling callbacks: [<function default_action_log at 0x7fc8dfbe5d90>]
[2021-08-08 05:30:54,515] {settings.py:208} DEBUG - Setting up DB connection pool (PID 7972)
[2021-08-08 05:30:54,515] {settings.py:244} DEBUG - settings.prepare_engine_args(): Using NullPool
[2021-08-08 05:30:54,517] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [None]> from DB
[2021-08-08 05:30:57,090] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]>
[2021-08-08 05:30:58,979] {logging_mixin.py:104} INFO - Running <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]> on host ip-172-31-58-121.eu-west-1.compute.internal
[2021-08-08 05:30:58,979] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]> from DB
[2021-08-08 05:30:59,588] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]>
[2021-08-08 05:31:03,931] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]> from DB
[2021-08-08 05:31:04,181] {taskinstance.py:677} DEBUG - Clearing XCom data
[2021-08-08 05:31:04,914] {taskinstance.py:684} DEBUG - XCom data cleared
[2021-08-08 05:31:05,896] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]>
[2021-08-08 05:31:05,934] {base_job.py:227} DEBUG - [heartbeat]
[2021-08-08 05:31:12,815] {taskinstance.py:1302} INFO - Exporting the following env vars:
AIRFLOW_CTX_DAG_OWNER=vrt
AIRFLOW_CTX_DAG_ID=derived.adobe_target_catalog_sporza
AIRFLOW_CTX_TASK_ID=watch_adobe_target_catalog_sporza_job_emr_step
AIRFLOW_CTX_EXECUTION_DATE=2021-08-07T05:28:00+00:00
AIRFLOW_CTX_DAG_RUN_ID=scheduled__2021-08-07T05:28:00+00:00
[2021-08-08 05:31:12,815] {__init__.py:146} DEBUG - Preparing lineage inlets and outlets
[2021-08-08 05:31:12,816] {__init__.py:190} DEBUG - inlets: [], outlets: []
[2021-08-08 05:31:13,431] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]> from DB
[2021-08-08 05:31:13,718] {base_aws.py:368} INFO - Airflow Connection: aws_conn_id=aws_default
[2021-08-08 05:31:14,251] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]>
[2021-08-08 05:31:14,293] {base_job.py:227} DEBUG - [heartbeat]
[2021-08-08 05:31:14,780] {base_aws.py:179} INFO - No credentials retrieved from Connection
[2021-08-08 05:31:14,780] {base_aws.py:87} INFO - Creating session with aws_access_key_id=None region_name=None
[2021-08-08 05:31:14,781] {hooks.py:417} DEBUG - Changing event name from creating-client-class.iot-data to creating-client-class.iot-data-plane
[2021-08-08 05:31:14,783] {hooks.py:417} DEBUG - Changing event name from before-call.apigateway to before-call.api-gateway
[2021-08-08 05:31:14,784] {hooks.py:417} DEBUG - Changing event name from request-created.machinelearning.Predict to request-created.machine-learning.Predict
[2021-08-08 05:31:14,786] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.autoscaling.CreateLaunchConfiguration to before-parameter-build.auto-scaling.CreateLaunchConfiguration
[2021-08-08 05:31:14,786] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.route53 to before-parameter-build.route-53
[2021-08-08 05:31:14,786] {hooks.py:417} DEBUG - Changing event name from request-created.cloudsearchdomain.Search to request-created.cloudsearch-domain.Search
[2021-08-08 05:31:14,787] {hooks.py:417} DEBUG - Changing event name from docs.*.autoscaling.CreateLaunchConfiguration.complete-section to docs.*.auto-scaling.CreateLaunchConfiguration.complete-section
[2021-08-08 05:31:14,790] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.logs.CreateExportTask to before-parameter-build.cloudwatch-logs.CreateExportTask
[2021-08-08 05:31:14,790] {hooks.py:417} DEBUG - Changing event name from docs.*.logs.CreateExportTask.complete-section to docs.*.cloudwatch-logs.CreateExportTask.complete-section
[2021-08-08 05:31:14,790] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.cloudsearchdomain.Search to before-parameter-build.cloudsearch-domain.Search
[2021-08-08 05:31:14,790] {hooks.py:417} DEBUG - Changing event name from docs.*.cloudsearchdomain.Search.complete-section to docs.*.cloudsearch-domain.Search.complete-section
[2021-08-08 05:31:14,791] {base_aws.py:157} INFO - role_arn is None
[2021-08-08 05:31:14,794] {utils.py:364} DEBUG - IMDS ENDPOINT: http://169.254.169.254/
[2021-08-08 05:31:14,796] {credentials.py:1974} DEBUG - Looking for credentials via: env
[2021-08-08 05:31:14,796] {credentials.py:1974} DEBUG - Looking for credentials via: assume-role
[2021-08-08 05:31:14,796] {credentials.py:1974} DEBUG - Looking for credentials via: assume-role-with-web-identity
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: sso
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: shared-credentials-file
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: custom-process
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: config-file
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: ec2-credentials-file
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: boto-config
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: container-role
[2021-08-08 05:31:14,798] {connectionpool.py:230} DEBUG - Starting new HTTP connection (1): 169.254.170.2:80
[2021-08-08 05:31:14,799] {connectionpool.py:442} DEBUG - http://169.254.170.2:80 "GET /v2/credentials/c5f7099a-d46e-4472-a48f-6c137db9e75d HTTP/1.1" 200 1307
[2021-08-08 05:31:14,800] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/endpoints.json
[2021-08-08 05:31:14,810] {hooks.py:210} DEBUG - Event choose-service-name: calling handler <function handle_service_name_alias at 0x7fc8dbee9bf8>
[2021-08-08 05:31:14,817] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/emr/2009-03-31/service-2.json
[2021-08-08 05:31:14,822] {hooks.py:210} DEBUG - Event creating-client-class.emr: calling handler <function add_generate_presigned_url at 0x7fc8dbf957b8>
[2021-08-08 05:31:14,824] {endpoint.py:292} DEBUG - Setting elasticmapreduce timeout as (60, 60)
[2021-08-08 05:31:14,825] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/_retry.json
[2021-08-08 05:31:14,825] {client.py:166} DEBUG - Registering retry handlers for service: emr
[2021-08-08 05:31:14,826] {emr_step.py:73} INFO - Poking step s-581MKMYKRED7 on cluster j-XDTNJDHR23RQ
[2021-08-08 05:31:14,826] {hooks.py:210} DEBUG - Event before-parameter-build.emr.DescribeStep: calling handler <function generate_idempotent_uuid at 0x7fc8dbf07048>
[2021-08-08 05:31:14,826] {hooks.py:210} DEBUG - Event before-call.emr.DescribeStep: calling handler <function inject_api_version_header_if_needed at 0x7fc8dbf087b8>
[2021-08-08 05:31:14,826] {endpoint.py:101} DEBUG - Making request for OperationModel(name=DescribeStep) with params: {'url_path': '/', 'query_string': '', 'method': 'POST', 'headers': {'X-Amz-Target': 'ElasticMapReduce.DescribeStep', 'Content-Type': 'application/x-amz-json-1.1', 'User-Agent': 'Boto3/1.17.107 Python/3.6.13 Linux/4.14.238-182.422.amzn2.x86_64 exec-env/AWS_ECS_FARGATE Botocore/1.20.107'}, 'body': b'{"ClusterId": "j-XDTNJDHR23RQ", "StepId": "s-581MKMYKRED7"}', 'url': 'https://eu-west-1.elasticmapreduce.amazonaws.com/', 'context': {'client_region': 'eu-west-1', 'client_config': <botocore.config.Config object at 0x7fc8dba0feb8>, 'has_streaming_input': False, 'auth_type': None}}
[2021-08-08 05:31:14,826] {hooks.py:210} DEBUG - Event request-created.emr.DescribeStep: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7fc8dba0fe80>>
[2021-08-08 05:31:14,827] {hooks.py:210} DEBUG - Event choose-signer.emr.DescribeStep: calling handler <function set_operation_specific_signer at 0x7fc8dbf01ea0>
[2021-08-08 05:31:14,827] {auth.py:380} DEBUG - Calculating signature using v4 auth.
[2021-08-08 05:31:14,827] {auth.py:381} DEBUG - CanonicalRequest:
POST
/

content-type:application/x-amz-json-1.1
host:eu-west-1.elasticmapreduce.amazonaws.com
x-amz-date:20210808T053114Z
x-amz-security-token:IQoJb3JpZ2luX2VjEGwaCWV1LXdlc3QtMSJHMEUCIQCZ4NXI3+3YJKZwyu+L4vTyY4swRSd7+zHkDO3Nwc0JiwIgdDuzR2+qJ5vFE03B1RRhzZYGV4Iy/pt7jVXRr0YjXTUqogQIhP//////////ARABGgwyODM3NzQxNDgzNTciDDl+9YdFHetmruZnfSr2A4vFCZwFNe0LEigdz0ayjIhvTZMsjY6CClml27JRBbUllyWz6t3b5SjafRWERgfEe1xIjnFFvp/UFSDIrZVuOefX94uUcgWQKV5zhz/dHdpCzpPltF+syapd2IeY5lgaUZWr+ax+Pfs75JILyfTpa7u43hg1M6P9L07zP/IUWdrXvyvu0wVh07r6/bHUDKJGy52Ok2q6Hr4ltT4MVAY/EZIEDZA8dlNdd7/UDddecp+/7/QIMftzZsgQJVyO+IIB+cfHCIV+1g/ACnsSbBkJuH2fn/B0YeP6e1135yTFknzNKVUxf6OeBIuPrkcu78HnaOXcjv+JSKb9AcFP+2zOo9JYmr040XGVqesZiAc+uDWbL74LDQ7ze5b4sLSNXfCCEvqsYVy9Nt7UlopCXoIS2lBrWgXNhsppDQ976Gr+WgyV1Wbjx2NZlJFCtSNarwF0qDPBmm6yhQxyKMYarOrUpy9aNl/18ujIhJZ2/JMUYlzH0TOBc1YCKIuZLNPwYfxZW6JmosfKXjAFUK7eDn4tU6LSXyo2GNLYzjY71OyCOpllJYtxg/NDAQBlmMCbFPpFCCTjPECU0sGnhfPAdlsyYngT3L0bSyjAZpPRfYrfPd4i3j2niPq9BwF/iOIR95T2CK7zqxXB4TIpporSE0pItmFgynGTh+IwtZm9iAY6pgENShKQaHxJvNj1O5ddYeCwW3H2SqjrHroeOt82xGkH5stZ7g28Uy7iPIPEehlkrB7ry/KjLq9DAo4zVneHhfKJBUBTBxz944AZhd0d9VvSRGgEXnmxzTsHma9hnkwQfGdbXwH4ja582o7hPEI98AAgoo5OCuV/vyMHHgrJBa7z+7eRtGnCeg+EJZy9WlsilHHGze4QGDEDc4NJypNZM4JON503hXON
x-amz-target:ElasticMapReduce.DescribeStep

content-type;host;x-amz-date;x-amz-security-token;x-amz-target
2a131454435119560c6fa09b6b1eeeb557aba91e61af62fe4883ccc24890c4f3
[2021-08-08 05:31:14,827] {auth.py:383} DEBUG - StringToSign:
AWS4-HMAC-SHA256
20210808T053114Z
20210808/eu-west-1/elasticmapreduce/aws4_request
a2f4ed4536a8bb05d35fc345f45eec9b42f7e071c230286854f034ea4878ced2
[2021-08-08 05:31:14,827] {auth.py:385} DEBUG - Signature:
90da79c86917ea04d8aed50abba5b1b3d5152e5327941eda3bf485e6af620e6b
[2021-08-08 05:31:14,827] {endpoint.py:187} DEBUG - Sending http request: <AWSPreparedRequest stream_output=False, method=POST, url=https://eu-west-1.elasticmapreduce.amazonaws.com/, headers={'X-Amz-Target': b'ElasticMapReduce.DescribeStep', 'Content-Type': b'application/x-amz-json-1.1', 'User-Agent': b'Boto3/1.17.107 Python/3.6.13 Linux/4.14.238-182.422.amzn2.x86_64 exec-env/AWS_ECS_FARGATE Botocore/1.20.107', 'X-Amz-Date': b'20210808T053114Z', 'X-Amz-Security-Token': b'IQoJb3JpZ2luX2VjEGwaCWV1LXdlc3QtMSJHMEUCIQCZ4NXI3+3YJKZwyu+L4vTyY4swRSd7+zHkDO3Nwc0JiwIgdDuzR2+qJ5vFE03B1RRhzZYGV4Iy/pt7jVXRr0YjXTUqogQIhP//////////ARABGgwyODM3NzQxNDgzNTciDDl+9YdFHetmruZnfSr2A4vFCZwFNe0LEigdz0ayjIhvTZMsjY6CClml27JRBbUllyWz6t3b5SjafRWERgfEe1xIjnFFvp/UFSDIrZVuOefX94uUcgWQKV5zhz/dHdpCzpPltF+syapd2IeY5lgaUZWr+ax+Pfs75JILyfTpa7u43hg1M6P9L07zP/IUWdrXvyvu0wVh07r6/bHUDKJGy52Ok2q6Hr4ltT4MVAY/EZIEDZA8dlNdd7/UDddecp+/7/QIMftzZsgQJVyO+IIB+cfHCIV+1g/ACnsSbBkJuH2fn/B0YeP6e1135yTFknzNKVUxf6OeBIuPrkcu78HnaOXcjv+JSKb9AcFP+2zOo9JYmr040XGVqesZiAc+uDWbL74LDQ7ze5b4sLSNXfCCEvqsYVy9Nt7UlopCXoIS2lBrWgXNhsppDQ976Gr+WgyV1Wbjx2NZlJFCtSNarwF0qDPBmm6yhQxyKMYarOrUpy9aNl/18ujIhJZ2/JMUYlzH0TOBc1YCKIuZLNPwYfxZW6JmosfKXjAFUK7eDn4tU6LSXyo2GNLYzjY71OyCOpllJYtxg/NDAQBlmMCbFPpFCCTjPECU0sGnhfPAdlsyYngT3L0bSyjAZpPRfYrfPd4i3j2niPq9BwF/iOIR95T2CK7zqxXB4TIpporSE0pItmFgynGTh+IwtZm9iAY6pgENShKQaHxJvNj1O5ddYeCwW3H2SqjrHroeOt82xGkH5stZ7g28Uy7iPIPEehlkrB7ry/KjLq9DAo4zVneHhfKJBUBTBxz944AZhd0d9VvSRGgEXnmxzTsHma9hnkwQfGdbXwH4ja582o7hPEI98AAgoo5OCuV/vyMHHgrJBa7z+7eRtGnCeg+EJZy9WlsilHHGze4QGDEDc4NJypNZM4JON503hXON', 'Authorization': b'AWS4-HMAC-SHA256 Credential=ASIAUEESB34CT3URIQHE/20210808/eu-west-1/elasticmapreduce/aws4_request, SignedHeaders=content-type;host;x-amz-date;x-amz-security-token;x-amz-target, Signature=90da79c86917ea04d8aed50abba5b1b3d5152e5327941eda3bf485e6af620e6b', 'Content-Length': '59'}>
[2021-08-08 05:31:14,828] {httpsession.py:50} DEBUG - Certificate path: /home/airflow/.local/lib/python3.6/site-packages/certifi/cacert.pem
[2021-08-08 05:31:14,828] {connectionpool.py:943} DEBUG - Starting new HTTPS connection (1): eu-west-1.elasticmapreduce.amazonaws.com:443
[2021-08-08 05:31:15,021] {connectionpool.py:442} DEBUG - https://eu-west-1.elasticmapreduce.amazonaws.com:443 "POST / HTTP/1.1" 200 799
[2021-08-08 05:31:15,021] {parsers.py:233} DEBUG - Response headers: {'x-amzn-RequestId': '12e9220a-4dc3-4ca0-9ec9-93a529032f9b', 'Content-Type': 'application/x-amz-json-1.1', 'Content-Length': '799', 'Date': 'Sun, 08 Aug 2021 05:31:14 GMT'}
[2021-08-08 05:31:15,021] {parsers.py:234} DEBUG - Response body:
b'{"Step":{"ActionOnFailure":"CONTINUE","Config":{"Args":["spark-submit","--deploy-mode","cluster","--master","yarn","--driver-memory","2G","--executor-memory","8G","--num-executors","5","--executor-cores","3","--packages","io.delta:delta-core_2.11:0.6.1","--py-files","s3://vrt-datalake-artifacts-prod/adobe-target-catalog-sporza/python/adobe_target_catalog_sporza-1.0.0-py3.7_6.egg,s3://vrt-datalake-artifacts-prod/python-datalake-helpers/vrt_datalake_helpers-21-py3-none-any.whl","s3://vrt-datalake-artifacts-prod/adobe-target-catalog-sporza/python/run_6.py","prod","2021-08-08 05:28:00"],"Jar":"command-runner.jar","Properties":{}},"Id":"s-581MKMYKRED7","Name":"adobe-target-catalog-sporza-job","Status":{"State":"PENDING","StateChangeReason":{},"Timeline":{"CreationDateTime":1.628400523922E9}}}}'
[2021-08-08 05:31:15,022] {hooks.py:210} DEBUG - Event needs-retry.emr.DescribeStep: calling handler <botocore.retryhandler.RetryHandler object at 0x7fc8db9b82e8>
[2021-08-08 05:31:15,022] {retryhandler.py:187} DEBUG - No retry needed.
[2021-08-08 05:31:15,023] {emr_base.py:66} INFO - Job flow currently PENDING
[2021-08-08 05:31:15,023] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]> from DB
[2021-08-08 05:31:17,730] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]>
[2021-08-08 05:31:17,771] {taskinstance.py:1906} DEBUG - Task Duration set to 25.225634
[2021-08-08 05:31:21,580] {taskinstance.py:1484} INFO - Rescheduling task, marking task as UP_FOR_RESCHEDULE
[2021-08-08 05:31:21,581] {cli_action_loggers.py:84} DEBUG - Calling callbacks: []
[2021-08-08 05:31:24,405] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]> from DB
[2021-08-08 05:31:26,452] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]>
[2021-08-08 05:31:26,531] {base_job.py:227} DEBUG - [heartbeat]
[2021-08-08 05:31:26,531] {local_task_job.py:149} INFO - Task exited with return code 0
[2021-08-08 05:31:26,531] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]> from DB
[2021-08-08 05:31:27,269] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]>
[2021-08-08 05:32:35,215] {__init__.py:51} DEBUG - Loading core task runner: StandardTaskRunner
[2021-08-08 05:32:36,815] {base_task_runner.py:62} DEBUG - Planning to run as the  user
[2021-08-08 05:32:36,817] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> from DB
[2021-08-08 05:32:38,537] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]>
[2021-08-08 05:32:38,537] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:32:38,538] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Task Instance State' PASSED: True, Task state queued was valid.
[2021-08-08 05:32:38,578] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:32:38,578] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:32:38,579] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Task Instance Not Running' PASSED: True, Task is not in running state.
[2021-08-08 05:32:38,579] {taskinstance.py:896} INFO - Dependencies all met for <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]>
[2021-08-08 05:32:38,579] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:32:39,309] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:32:39,310] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:32:39,477] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Pool Slots Available' PASSED: True, ('There are enough open slots in %s to execute the task', 'default_pool')
[2021-08-08 05:32:39,477] {taskinstance.py:911} DEBUG - <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]> dependency 'Task Concurrency' PASSED: True, Task concurrency is not set.
[2021-08-08 05:32:39,477] {taskinstance.py:896} INFO - Dependencies all met for <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]>
[2021-08-08 05:32:39,477] {taskinstance.py:1087} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:32:39,477] {taskinstance.py:1088} INFO - Starting attempt 1 of 1
[2021-08-08 05:32:39,477] {taskinstance.py:1089} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:32:43,976] {taskinstance.py:1107} INFO - Executing <Task(EmrStepSensor): watch_adobe_target_catalog_sporza_job_emr_step> on 2021-08-07T05:28:00+00:00
[2021-08-08 05:32:43,979] {standard_task_runner.py:52} INFO - Started process 8339 to run task
[2021-08-08 05:32:43,984] {standard_task_runner.py:76} INFO - Running: ['airflow', 'tasks', 'run', 'derived.adobe_target_catalog_sporza', 'watch_adobe_target_catalog_sporza_job_emr_step', '2021-08-07T05:28:00+00:00', '--job-id', '98962', '--pool', 'default_pool', '--raw', '--subdir', 'DAGS_FOLDER/adobe_target_catalog_sporza_wf.py', '--cfg-path', '/tmp/tmpbqux_rdl', '--error-file', '/tmp/tmpyb9gdojg']
[2021-08-08 05:32:43,984] {standard_task_runner.py:77} INFO - Job 98962: Subtask watch_adobe_target_catalog_sporza_job_emr_step
[2021-08-08 05:32:43,985] {cli_action_loggers.py:66} DEBUG - Calling callbacks: [<function default_action_log at 0x7fc8dfbe5d90>]
[2021-08-08 05:32:51,719] {settings.py:208} DEBUG - Setting up DB connection pool (PID 8339)
[2021-08-08 05:32:51,720] {settings.py:244} DEBUG - settings.prepare_engine_args(): Using NullPool
[2021-08-08 05:32:51,722] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [None]> from DB
[2021-08-08 05:32:53,315] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]>
[2021-08-08 05:32:54,868] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]> from DB
[2021-08-08 05:32:55,812] {logging_mixin.py:104} INFO - Running <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]> on host ip-172-31-58-121.eu-west-1.compute.internal
[2021-08-08 05:32:55,813] {taskinstance.py:614} DEBUG - Refreshing TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]> from DB
[2021-08-08 05:32:57,199] {taskinstance.py:649} DEBUG - Refreshed TaskInstance <TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]>
[2021-08-08 05:32:57,203] {local_task_job.py:194} WARNING - Recorded pid 7972 does not match the current pid 8339
[2021-08-08 05:32:57,206] {process_utils.py:100} INFO - Sending Signals.SIGTERM to GPID 8339
[2021-08-08 05:32:57,210] {process_utils.py:66} INFO - Process psutil.Process(pid=8339, status='terminated', exitcode=<Negsignal.SIGTERM: -15>, started='05:32:43') (8339) terminated with exit code Negsignal.SIGTERM

What you expected to happen:

I'd expect the EMRStepSensor to run until the EMR step succeeded, and report a succesful run.

If my understanding is correct, these final lines in the log show the runner terminating the task process. If I'm reading the log correctly, 8339 is the correct PID for the task, and the recorded pid 7972 is the pid for a previous run. Could it be possible that this pid is not correctly being updated?

[2021-08-08 05:32:57,203] {local_task_job.py:194} WARNING - Recorded pid 7972 does not match the current pid 8339
[2021-08-08 05:32:57,206] {process_utils.py:100} INFO - Sending Signals.SIGTERM to GPID 8339
[2021-08-08 05:32:57,210] {process_utils.py:66} INFO - Process psutil.Process(pid=8339, status='terminated', exitcode=<Negsignal.SIGTERM: -15>, started='05:32:43') (8339) terminated with exit code Negsignal.SIGTERM

Anything else we need to know:

The symptoms look very similar to #17394, but I'm not using run_as_user, and the reported pids are not the same, so I'm not sure whether this is the same issue.

@iasoon iasoon added the kind:bug This is a clearly a bug label Aug 9, 2021
@boring-cyborg
Copy link

boring-cyborg bot commented Aug 9, 2021

Thanks for opening your first issue here! Be sure to follow the issue template!

@iasoon iasoon changed the title Tasks get terminated with WARNING - Recorded pid does not match the current pid Task processes killed with WARNING - Recorded pid does not match the current pid Aug 9, 2021
@ephraimbuddy
Copy link
Contributor

We added a fix contained in: #16301 that would be released in 2.1.3. Can you try if you can reproduce with the current main branch

@crazyproger
Copy link

We're using 2.1.3, see exactly same message sometimes in task runs. Using celery executor.

@ephraimbuddy
Copy link
Contributor

@crazyproger do you have a dag to reproduce this behaviour? please share

@crazyproger
Copy link

We met this on different dags. Clearing dagrun helps in all cases.
Task log:

*** Reading local file: /opt/airflow/logs/<Dag id>/wait_cache_ready/2021-08-31T17:00:00+00:00/1.log
[2021-08-31 18:14:43,582] {taskinstance.py:903} INFO - Dependencies all met for <TaskInstance:<Dag id>.wait_cache_ready 2021-08-31T17:00:00+00:00 [queued]>
[2021-08-31 18:14:43,608] {taskinstance.py:903} INFO - Dependencies all met for <TaskInstance: <Dag id>.wait_cache_ready 2021-08-31T17:00:00+00:00 [queued]>
[2021-08-31 18:14:43,609] {taskinstance.py:1094} INFO - 
--------------------------------------------------------------------------------
[2021-08-31 18:14:43,609] {taskinstance.py:1095} INFO - Starting attempt 1 of 1
[2021-08-31 18:14:43,609] {taskinstance.py:1096} INFO - 
--------------------------------------------------------------------------------
[2021-08-31 18:14:43,631] {taskinstance.py:1114} INFO - Executing <Task(PythonSensor): wait_cache_ready> on 2021-08-31T17:00:00+00:00
[2021-08-31 18:14:43,638] {standard_task_runner.py:52} INFO - Started process 25320 to run task
[2021-08-31 18:14:43,643] {standard_task_runner.py:76} INFO - Running: ['airflow', 'tasks', 'run', '<Dag id>', 'wait_cache_ready', '2021-08-31T17:00:00+00:00', '--job-id', '45735641', '--pool', 'default_pool', '--raw', '--subdir', 'DAGS_FOLDER/<integration>/upload_dags/installs_hourly_2.py', '--cfg-path', '/tmp/tmp90yuh86s', '--error-file', '/tmp/tmp3s15tqza']
[2021-08-31 18:14:43,644] {standard_task_runner.py:77} INFO - Job 45735641: Subtask wait_cache_ready
[2021-08-31 18:14:48,697] {local_task_job.py:204} WARNING - Recorded pid 23138 does not match the current pid 25320
[2021-08-31 18:14:48,699] {process_utils.py:100} INFO - Sending Signals.SIGTERM to GPID 25320
[2021-08-31 18:14:48,707] {process_utils.py:66} INFO - Process psutil.Process(pid=25320, status='terminated', exitcode=<Negsignal.SIGTERM: -15>, started='18:14:42') (25320) terminated with exit code Negsignal.SIGTERM

function that creates dag is here: https://gist.github.com/crazyproger/a2a516f8e6b757b88d29f6fccca16990
It has failed on first task - sensor, implementation is at the bottom - def check_file_exists.
I omit other tasks implementations.

@noelmcloughlin
Copy link
Contributor

noelmcloughlin commented Sep 2, 2021

We're using 2.1.3, see exactly same message sometimes in task runs. Using celery executor.

Yes. I downgraded to 2.1.2 and the issue is gone away for now: See related #10026

@ashb
Copy link
Member

ashb commented Sep 2, 2021

@noelmcloughlin In the issue you mention 2.1.2 -- did you mean 2.1.3?

@ashb ashb added this to the Airflow 2.1.4 milestone Sep 2, 2021
@noelmcloughlin
Copy link
Contributor

noelmcloughlin commented Sep 2, 2021

Sorry I was on 2.1.2 (okay), took 2.1.3 (issue seen), downgraded to 2.1.2 (okay again).

@ashb
Copy link
Member

ashb commented Sep 2, 2021

That's what I thought, just wanted to confirm.

@nmehraein
Copy link
Contributor

Hi, that should be link with that PR ? #17333 .
The problem seem very similar.

@laserpedro
Copy link

laserpedro commented Sep 7, 2021

So for info, I incorporated the fix proposed by @nmehraein here unfortunately I am still getting the same error ...

@laserpedro
Copy link

laserpedro commented Sep 7, 2021

Also as mentionned here it seems that the run_as_user is part of the issue: https://www.gitmemory.com/issue/apache/airflow/17394/892065842

As @potiuk mentioned it is related but having passed airflow in the config for the default impersonation did not help

@noelmcloughlin
Copy link
Contributor

it seems that the run_as_user is part of the issue

I was not using run_as_user #10026 (comment) so I think we need to collect more data. There is probably a common attribute but I'm not sure run_as_user is important.

@laserpedro
Copy link

Is there any workaround since my dags are no longer working properly ? tks

@kiwy42
Copy link
Contributor

kiwy42 commented Sep 8, 2021

I tried disable run_as_user and trying to disable some stuff.
I'm using spark and other java program and py4j .
I'm using TriggerMultiDagRun Operator.
I'm currently adapting old dags to airflow 2 and as soon as I clear task to update my code and try new stuff, I have those strange error as well.
I'm working on docker airflow 2.1.2 Python 3.9.
So far this release seems very unstable.

@laserpedro
Copy link

laserpedro commented Sep 8, 2021

cf #18041 (comment)

For me for the moment the pb is on backfill mode. tonight my processes will run on this new airflow session I will see If I get the same errors.

UPDATE: I have modified the param scheduler_heartbeat_sec to 60 sec instead of 5 sec and it is better: so maybe a problem of performance in the backend (postgresql) creates this issue ....
@kiwy42 what backend are u using to store the task instances ?

@george-zubrienko
Copy link

cf #18041 (comment)

For me for the moment the pb is on backfill mode. tonight my processes will run on this new airflow session I will see If I get the same errors.

UPDATE: I have modified the param scheduler_heartbeat_sec to 60 sec instead of 5 sec and it is better: so maybe a problem of performance in the backend (postgresql) creates this issue ....
@kiwy42 what backend are u using to store the task instances ?

In our case with Kubernetes Executor it definitely seems scheduler related. In a DAG with 55 tasks, around a third receives sigterm shortly after starting and then goes into a retry loop with Pid X does not match Pid Y. It was fixed after I reduced pool size from 128 (all tasks queued at the same time) to 32, so 23 tasks were left in scheduled state. After I reverted the pool change, issue came back

@kaxil kaxil modified the milestones: Airflow 2.1.4, Airflow 2.2 Sep 11, 2021
@laserpedro
Copy link

laserpedro commented Sep 13, 2021

I will revert also to lastest 2.0 version available: however I do not know what impact it will have on the metadata db (need a downgrade or sth like that) ...

Does someone know if there is an official guide to downgrade ?

So what I did is:

  • setup a dedicated postgresql server on Linux for the meta database
  • downgrade to airflow 2.0.2
  • increase the heartbeat signal (so that the tasks gets not killed by the heart beat concurrency (mainly for sensors): and will incorporate https://github.com/apache/airflow/pull/16289/files in order to fix the race condition tomorrow.

With this set up my dags are working "properly" (remaining the below bug) ! I no longer have mismatch of pid and no longer have random sigterm on task execution relatively large queries.

@ridwantahir
Copy link

this proble is still there in airflow 2.13!!

@MarvinSchenkel
Copy link

I will revert also to lastest 2.0 version available: however I do not know what impact it will have on the metadata db (need a downgrade or sth like that) ...

Does someone know if there is an official guide to downgrade ?

So what I did is:

  • setup a dedicated postgresql server on Linux for the meta database
  • downgrade to airflow 2.0.2
  • increase the heartbeat signal (so that the tasks gets not killed by the heart beat concurrency (mainly for sensors): and will incorporate https://github.com/apache/airflow/pull/16289/files in order to fix the race condition tomorrow.

With this set up my dags are working "properly" (remaining the below bug) ! I no longer have mismatch of pid and no longer have random sigterm on task execution relatively large queries.

How did you increase the heartbeat signal? I am running Airflow on a Kubernetes cluster and run into this issue on 2.1.3, 2.1.2 and 2.0.2.

@laserpedro
Copy link

laserpedro commented Sep 14, 2021

Hello @MarvinSchenkel , to increase the scheduler heartbeat signal you can either export it in your env variable when installing airflow or after having already installed it modifiy the param your airflow.cfg file.

  • bash profile: export AIRFLOW__SCHEDULER__SCHEDULER_HEARTBEAT_SEC=120
  • airflow.cfg: scheduler_heartbeat_sec=120.

to make sure that the values are correctly set you can use
airflow config get-value scheduler scheduler_heartbeat_sec btw

And then restart the scheduler and the webserver.

@ephraimbuddy
Copy link
Contributor

I am also seeing this same issue on 2.2.2, I have to use run_as_user in order to access user environment configurations for some DAGs. These DAGs can never complete successfully, instead they always result in the message Recorded pid <> does not match the current pid <>.

Most "solutions" I'm finding recommend not using run_as_user and also clearing default_impersonation. unfortunately this isn't a solution, as we actually do need the functionality from those.

In other to use run_as_user, you must follow this guide http://airflow.apache.org/docs/apache-airflow/stable/security/workload.html#impersonation

@kcphila
Copy link

kcphila commented Jun 21, 2022

Hi all,

I am experiencing this on 2.3.2 with LocalExecutor (4 schedulers), Postgres, and Ubuntu 22.04.

This is, however, running a clone of our staging environment of dags that run fine on 2.1.4 and Ubuntu 16.04. I'm also running on a much smaller and less powerful instance, and so it may be exacerbating race conditions.

I did some investigation into the process state, and when this error leads to a failure, this is what I see in process executions:

  • The Scheduler task is the root of everything, as you'd expect (airflow scheduler)
  • recorded_pid , which is assigned to be the taskinstance pid (ti.pid) normally and the parent of the taskinstance pid (psutil.Process(ti.pid).ppid()) when RUN_AS_USER is set. When failing, this consistently shows up as the worker (worker -- LocalExecutor). This is a persistent and long term process.
  • The child of the recorded_pid is the pid of the current process (as reported by os.getpid()), which is the airflow task supervisor. This (and everything below) is one of the short term task-specific processes.
  • The current_pid can be different things, but always appears to be the child of the task supervisor / current pid. Often times this must be a fleeting process as I can barely catch a record of it when I'm trying to fetch a snapshot. Here are a couple that I have seen:
    • In some cases, I have seen this as the task runner's pid - airflow tasks run [taskname]
    • I have also seen this as the airflow task su, and the tasks are RUN_AS_USER, so likely related.

I came to wonder, since this error happens because (a) the final recorded_pid is not None and (B) recorded_pid != current_pid - it doesn't make much sense to ever be comparing against the Task Instance pid since that's hanging around for a very long time and the heatbeat function appears to be identifying when the current task runner is zombified or missing.

As I've investigated further, I've found on task failures for RUN_AS_USER tasks in which this fails, the ti.pid is almost invariably None, which means the recorded_pid comes in as psutil.Process(None).ppid(), which will be the parent of the current process. I am currently under the impression that this was not intended - and that the error condition should only be tested when ti.pid is not None, instead of recorded_pid is not None.

I'm testing this right now and it seems to work - and if that seems to hold up I'll put in a PR.

@kcphila
Copy link

kcphila commented Jun 22, 2022

This does seem to be working consistently for LocalExecutor - I haven't checked Celery or Kubernetes.

It will take me a little while to set up the dev environment and do the testing before submitting a PR, but feel free to give it a whirl, I have a tentative branch set up here: https://github.com/krcrouse/airflow/tree/fix-pid-check

@shubhampatel94
Copy link

shubhampatel94 commented May 4, 2023

I see the same issue happening on 2.4.3
Multiple dags started getting terminated within range of 5 minutes after running fine for weeks due to this error.
here is my config detail.

Python 3.10 (setup through miniconda)
Airflow 2.4.3
MetadataDB: MySql 8
Executor -> LocalExecutor
run_as_user is not set. The config is empty.

OS details.
NAME="Ubuntu"
VERSION="18.04.6 LTS (Bionic Beaver)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 18.04.6 LTS"
VERSION_ID="18.04"
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
VERSION_CODENAME=bionic
UBUNTU_CODENAME=bionic

Seen this in the Tasks logs.

[2023-05-04, 02:28:21 EDT] {local_task_job.py:205} WARNING - Recorded pid 3738156 does not match the current pid 3634136
[2023-05-04, 02:28:21 EDT] {process_utils.py:129} INFO - Sending Signals.SIGTERM to group 3634136. PIDs of all processes in the group: [3634136]
[2023-05-04, 02:28:21 EDT] {process_utils.py:84} INFO - Sending the signal Signals.SIGTERM to group 3634136
[2023-05-04, 02:28:21 EDT] {taskinstance.py:1562} ERROR - Received SIGTERM. Terminating subprocesses.

Airflow Logs

[2023-05-04 02:28:08,454] {manager.py:288} WARNING - DagFileProcessorManager (PID=3732979) exited with exit code 1 - re-launching
[2023-05-04 02:28:08,469] {manager.py:163} INFO - Launched DagFileProcessorManager with pid: 3737637
[2023-05-04 02:28:08,480] {settings.py:58} INFO - Configured default timezone Timezone('UTC')
[2023-05-04 02:28:08,541] {scheduler_job.py:1380} INFO - Resetting orphaned tasks for active dag runs
[2023-05-04 02:28:08,547] {scheduler_job.py:1403} INFO - Marked 1 SchedulerJob instances as failed
[2023-05-04 02:28:08,767] {scheduler_job.py:1444} INFO - Reset the following 38 orphaned TaskInstances:
	<TaskInstance: *** scheduled__2023-05-04T01:05:00+00:00 [queued]>
	<TaskInstance: *** scheduled__2023-04-30T20:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-02T20:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T02:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-04-16T00:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-04-29T08:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-04-30T08:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-04T05:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-04T00:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-04-23T00:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-04T04:05:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-04T04:30:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T20:05:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T01:03:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-04T00:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T19:36:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-04T05:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-04T06:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-04-30T19:30:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-04T05:05:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-04T06:20:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-04T00:05:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-04T06:20:00+00:00 [running]>
	<TaskInstance: *** scheduled__2023-05-03T05:00:00+00:00 [running]>
[2023-05-04 02:28:13,780] {scheduler_job.py:346} INFO - 23 tasks up for execution:
	<TaskInstance: *** scheduled__2023-05-04T00:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-04-30T08:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-04-30T20:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T01:03:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T02:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T20:05:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T04:05:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T05:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T06:20:00+00:00 [scheduled]>
[2023-05-04 02:28:13,780] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:13,780] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:13,781] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:13,781] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:13,781] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:13,781] {scheduler_job.py:411} INFO - DAG *** has 1/50 running and queued tasks
[2023-05-04 02:28:13,781] {scheduler_job.py:411} INFO - DAG *** has 2/50 running and queued tasks
[2023-05-04 02:28:13,781] {scheduler_job.py:411} INFO - DAG *** has 3/50 running and queued tasks
[2023-05-04 02:28:13,781] {scheduler_job.py:411} INFO - DAG *** has 4/50 running and queued tasks
[2023-05-04 02:28:13,781] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:13,781] {scheduler_job.py:411} INFO - DAG *** has 1/50 running and queued tasks
[2023-05-04 02:28:13,782] {scheduler_job.py:411} INFO - DAG *** has 2/50 running and queued tasks
[2023-05-04 02:28:13,782] {scheduler_job.py:411} INFO - DAG *** has 3/50 running and queued tasks
[2023-05-04 02:28:13,782] {scheduler_job.py:411} INFO - DAG *** has 4/50 running and queued tasks
[2023-05-04 02:28:13,782] {scheduler_job.py:411} INFO - DAG *** has 5/50 running and queued tasks
[2023-05-04 02:28:13,782] {scheduler_job.py:411} INFO - DAG *** has 6/50 running and queued tasks
[2023-05-04 02:28:13,782] {scheduler_job.py:411} INFO - DAG *** has 5/50 running and queued tasks
[2023-05-04 02:28:13,782] {scheduler_job.py:411} INFO - DAG *** has 6/50 running and queued tasks
[2023-05-04 02:28:13,783] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:13,783] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:13,783] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:13,783] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:13,783] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:13,783] {scheduler_job.py:497} INFO - Setting the following tasks to queued state:
	<TaskInstance: *** scheduled__2023-05-04T00:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-04-30T08:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-04-30T20:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T01:03:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T02:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T20:05:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T04:05:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T05:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T06:20:00+00:00 [scheduled]>
[2023-05-04 02:28:13,960] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, try_number=2, map_index=-1) to executor with priority 7 and queue default
[2023-05-04 02:28:13,961] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T00:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,961] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-04-30T08:00:00+00:00', try_number=2, map_index=-1) to executor with priority 4 and queue default
[2023-05-04 02:28:13,961] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-04-30T08:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,962] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-04-30T20:00:00+00:00', try_number=5, map_index=-1) to executor with priority 3 and queue default
[2023-05-04 02:28:13,962] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-04-30T20:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,962] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T01:03:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:13,962] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T01:03:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,963] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T06:00:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:13,963] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,963] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T06:00:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:13,963] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,964] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T06:00:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:13,964] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,964] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T06:00:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:13,964] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,964] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T06:00:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:13,965] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,965] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T06:00:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:13,965] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,965] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T06:00:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:13,966] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,966] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T06:00:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:13,966] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,966] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T06:00:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:13,967] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,967] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T06:00:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:13,967] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,967] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T06:00:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:13,967] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,968] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T06:00:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:13,968] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,968] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T06:00:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:13,968] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,969] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T06:00:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:13,969] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,969] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T02:00:00+00:00', try_number=2, map_index=-1) to executor with priority 1 and queue default
[2023-05-04 02:28:13,969] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T02:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,970] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T20:05:00+00:00', try_number=2, map_index=-1) to executor with priority 1 and queue default
[2023-05-04 02:28:13,970] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T20:05:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,970] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-04T04:05:00+00:00', try_number=2, map_index=-1) to executor with priority 1 and queue default
[2023-05-04 02:28:13,970] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T04:05:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,970] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-04T05:00:00+00:00', try_number=2, map_index=-1) to executor with priority 1 and queue default
[2023-05-04 02:28:13,971] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T05:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,971] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-04T06:20:00+00:00', try_number=2, map_index=-1) to executor with priority 1 and queue default
[2023-05-04 02:28:13,971] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T06:20:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,999] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T00:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,999] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-04-30T08:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:13,999] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-04-30T20:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,000] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T01:03:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,000] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,000] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,000] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,001] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,001] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,002] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,002] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,002] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,002] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,003] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,003] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,004] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,004] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,004] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,004] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T02:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,005] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T20:05:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,005] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T04:05:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,005] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T05:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,010] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T06:20:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:14,099] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,108] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,110] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,127] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,134] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,137] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,152] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,194] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,237] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,247] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,248] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,250] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,251] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,253] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,255] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,257] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,257] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,275] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,293] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,304] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,318] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,324] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,332] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:14,517] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,591] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,595] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,597] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,682] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,733] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,757] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,771] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,782] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,790] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,822] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,840] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,844] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,845] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,847] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,882] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,893] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,902] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,918] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,935] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,937] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,939] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,952] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,973] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:14,979] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:15,015] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:15,024] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:15,040] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:15,044] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:15,054] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:15,075] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:15,079] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:15,090] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:15,095] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:15,102] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:15,136] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,139] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:15,183] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,190] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:15,225] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:15,228] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T02:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,240] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:15,248] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,259] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:15,282] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,315] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,353] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,384] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,412] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,444] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-04T04:05:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,445] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,528] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-04T05:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,568] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,583] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,669] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-04-30T20:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,669] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-04T06:20:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,707] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,710] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,779] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T01:03:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,779] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T06:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,796] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T20:05:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,861] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-04T00:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:15,952] {credentials.py:1255} INFO - Found credentials in shared credentials file: ~/.aws/credentials
[2023-05-04 02:28:15,990] {scheduler_job.py:346} INFO - 9 tasks up for execution:
	<TaskInstance: *** scheduled__2023-04-29T08:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-02T20:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T05:05:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T05:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T00:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-04-30T19:30:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T19:36:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T00:05:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T05:00:00+00:00 [scheduled]>
[2023-05-04 02:28:15,995] {scheduler_job.py:411} INFO - DAG *** has 1/50 running and queued tasks
[2023-05-04 02:28:15,996] {scheduler_job.py:411} INFO - DAG *** has 1/50 running and queued tasks
[2023-05-04 02:28:15,996] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:15,996] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:15,996] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:15,996] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:15,996] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:15,996] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:15,996] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:15,997] {scheduler_job.py:497} INFO - Setting the following tasks to queued state:
	<TaskInstance: *** scheduled__2023-04-29T08:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-02T20:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T05:05:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T05:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T00:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-04-30T19:30:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-03T19:36:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T00:05:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T05:00:00+00:00 [scheduled]>
[2023-05-04 02:28:16,014] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-04-29T08:00:00+00:00', try_number=2, map_index=-1) to executor with priority 4 and queue default
[2023-05-04 02:28:16,015] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-04-29T08:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,015] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-02T20:00:00+00:00', try_number=2, map_index=-1) to executor with priority 3 and queue default
[2023-05-04 02:28:16,016] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-02T20:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,016] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-04T05:05:00+00:00', try_number=2, map_index=-1) to executor with priority 3 and queue default
[2023-05-04 02:28:16,016] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T05:05:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,016] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T05:00:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:16,016] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T05:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,016] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-04T00:00:00+00:00', try_number=2, map_index=-1) to executor with priority 2 and queue default
[2023-05-04 02:28:16,016] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T00:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,017] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-04-30T19:30:00+00:00', try_number=2, map_index=-1) to executor with priority 1 and queue default
[2023-05-04 02:28:16,017] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-04-30T19:30:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,017] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-03T19:36:00+00:00', try_number=2, map_index=-1) to executor with priority 1 and queue default
[2023-05-04 02:28:16,017] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T19:36:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,017] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-04T00:05:00+00:00', try_number=2, map_index=-1) to executor with priority 1 and queue default
[2023-05-04 02:28:16,017] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T00:05:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,018] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-04T05:00:00+00:00', try_number=2, map_index=-1) to executor with priority 1 and queue default
[2023-05-04 02:28:16,018] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T05:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,051] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-04-29T08:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,051] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-02T20:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,051] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T05:05:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,051] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T05:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,052] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T00:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,052] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-04-30T19:30:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,052] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-03T19:36:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,052] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T00:05:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,053] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T05:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:16,256] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:16,340] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:16,348] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:16,355] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:16,399] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:16,410] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:16,434] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:16,434] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:16,446] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:16,589] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:16,703] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:16,828] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:16,941] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:17,047] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:17,246] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:17,257] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:17,284] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:17,306] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:17,320] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:17,423] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:17,450] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-04T00:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:17,455] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:17,477] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:17,682] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-02T20:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:17,894] {credentials.py:1255} INFO - Found credentials in shared credentials file: ~/.aws/credentials
[2023-05-04 02:28:17,913] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-04T05:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:18,055] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T19:36:00+00:00 [queued]> on host ***
[2023-05-04 02:28:18,196] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-04T00:05:00+00:00 [queued]> on host ***
[2023-05-04 02:28:18,288] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-04-30T19:30:00+00:00 [queued]> on host ***
[2023-05-04 02:28:18,317] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-03T05:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:18,734] {scheduler_job.py:346} INFO - 6 tasks up for execution:
	<TaskInstance: *** scheduled__2023-05-04T01:05:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-04-16T00:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-04-23T00:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T04:30:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T06:20:00+00:00 [scheduled]>
[2023-05-04 02:28:18,735] {scheduler_job.py:411} INFO - DAG *** has 1/50 running and queued tasks
[2023-05-04 02:28:18,735] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:18,735] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:18,735] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:18,735] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:18,735] {scheduler_job.py:411} INFO - DAG *** has 0/50 running and queued tasks
[2023-05-04 02:28:18,735] {scheduler_job.py:497} INFO - Setting the following tasks to queued state:
	<TaskInstance: *** scheduled__2023-05-04T01:05:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-04-16T00:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-04-23T00:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T04:30:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T06:00:00+00:00 [scheduled]>
	<TaskInstance: *** scheduled__2023-05-04T06:20:00+00:00 [scheduled]>
[2023-05-04 02:28:18,812] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-04T01:05:00+00:00', try_number=1, map_index=-1) to executor with priority 4 and queue default
[2023-05-04 02:28:18,812] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T01:05:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:18,813] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-04-16T00:00:00+00:00', try_number=2, map_index=-1) to executor with priority 1 and queue default
[2023-05-04 02:28:18,813] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-04-16T00:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:18,813] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-04-23T00:00:00+00:00', try_number=2, map_index=-1) to executor with priority 1 and queue default
[2023-05-04 02:28:18,813] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-04-23T00:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:18,813] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-04T04:30:00+00:00', try_number=2, map_index=-1) to executor with priority 1 and queue default
[2023-05-04 02:28:18,813] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T04:30:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:18,813] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-04T06:00:00+00:00', try_number=2, map_index=-1) to executor with priority 1 and queue default
[2023-05-04 02:28:18,814] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:18,814] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-04T06:20:00+00:00', try_number=2, map_index=-1) to executor with priority 1 and queue default
[2023-05-04 02:28:18,814] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T06:20:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:18,861] {credentials.py:1255} INFO - Found credentials in shared credentials file: ~/.aws/credentials
[2023-05-04 02:28:18,871] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T01:05:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:18,872] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-04-16T00:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:18,872] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-04-23T00:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:18,872] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T04:30:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:18,873] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T06:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:18,873] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-04T06:20:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:18,983] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,088] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:19,110] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:19,132] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:19,133] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:19,135] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:19,160] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:19,171] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,212] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,286] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,287] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,365] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,431] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,453] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,492] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,499] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,531] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,540] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,580] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,581] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,608] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,648] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,664] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,670] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,680] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,723] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,753] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,765] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,765] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,775] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,786] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-04-23T00:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:19,794] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,803] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,822] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,830] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,874] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-04-16T00:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:19,889] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,963] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:19,998] {credentials.py:1255} INFO - Found credentials in shared credentials file: ~/.aws/credentials
[2023-05-04 02:28:20,029] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,079] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-04T04:30:00+00:00 [queued]> on host ***
[2023-05-04 02:28:20,085] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,128] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,179] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-04T06:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:20,204] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,241] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-04T06:20:00+00:00 [queued]> on host ***
[2023-05-04 02:28:20,240] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,298] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,300] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,327] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,352] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,396] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,406] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,441] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,460] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,489] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,491] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,545] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,545] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,598] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,607] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,660] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,666] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,696] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,737] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,750] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,783] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,829] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,865] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,928] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,955] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:20,989] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:21,014] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:21,064] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:21,091] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:21,107] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-04T05:05:00+00:00 [queued]> on host ***
[2023-05-04 02:28:21,150] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:21,287] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:21,482] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:21,643] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:21,844] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:21,979] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:22,140] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:22,324] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:22,492] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:22,646] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:22,790] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:22,881] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:23,260] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-04T01:05:00+00:00 [queued]> on host ***
[2023-05-04 02:28:23,499] {local_executor.py:130} ERROR - Failed to execute task PID of job runner does not match.
Traceback (most recent call last):
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/executors/local_executor.py", line 126, in _execute_work_in_fork
    args.func(args)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/cli_parser.py", line 52, in command
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/cli.py", line 103, in wrapper
    return f(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 382, in task_run
    _run_task_by_selected_method(args, dag, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 189, in _run_task_by_selected_method
    _run_task_by_local_task_job(args, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 247, in _run_task_by_local_task_job
    run_job.run()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 247, in run
    self._execute()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 135, in _execute
    self.heartbeat()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 228, in heartbeat
    self.heartbeat_callback(session=session)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/session.py", line 72, in wrapper
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 208, in heartbeat_callback
    raise AirflowException("PID of job runner does not match")
airflow.exceptions.AirflowException: PID of job runner does not match
[2023-05-04 02:28:23,629] {scheduler_job.py:588} INFO - Executor reports execution of *** run_id=scheduled__2023-05-04T00:05:00+00:00 exited with status failed for try_number 1
[2023-05-04 02:28:23,627] {local_executor.py:130} ERROR - Failed to execute task PID of job runner does not match.
Traceback (most recent call last):
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/executors/local_executor.py", line 126, in _execute_work_in_fork
    args.func(args)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/cli_parser.py", line 52, in command
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/cli.py", line 103, in wrapper
    return f(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 382, in task_run
    _run_task_by_selected_method(args, dag, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 189, in _run_task_by_selected_method
    _run_task_by_local_task_job(args, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 247, in _run_task_by_local_task_job
    run_job.run()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 247, in run
    self._execute()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 135, in _execute
    self.heartbeat()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 228, in heartbeat
    self.heartbeat_callback(session=session)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/session.py", line 72, in wrapper
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 208, in heartbeat_callback
    raise AirflowException("PID of job runner does not match")
airflow.exceptions.AirflowException: PID of job runner does not match
[2023-05-04 02:28:23,640] {scheduler_job.py:631} INFO - TaskInstance Finished: dag_id=*** task_id=***, run_id=scheduled__2023-05-04T00:05:00+00:00, map_index=-1, run_start_date=2023-05-04 06:28:18.756761+00:00, run_end_date=2023-05-04 06:28:22.505894+00:00, run_duration=3.74913, state=up_for_retry, executor_state=failed, try_number=1, max_tries=3, job_id=277262, pool=default_pool, queue=default, priority_weight=1, operator=SSHOperator, queued_dttm=2023-05-04 06:28:15.998301+00:00, queued_by_job_id=233035, pid=3738404
[2023-05-04 02:28:23,664] {local_executor.py:130} ERROR - Failed to execute task PID of job runner does not match.
Traceback (most recent call last):
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/executors/local_executor.py", line 126, in _execute_work_in_fork
    args.func(args)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/cli_parser.py", line 52, in command
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/cli.py", line 103, in wrapper
    return f(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 382, in task_run
    _run_task_by_selected_method(args, dag, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 189, in _run_task_by_selected_method
    _run_task_by_local_task_job(args, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 247, in _run_task_by_local_task_job
    run_job.run()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 247, in run
    self._execute()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 135, in _execute
    self.heartbeat()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 228, in heartbeat
    self.heartbeat_callback(session=session)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/session.py", line 72, in wrapper
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 208, in heartbeat_callback
    raise AirflowException("PID of job runner does not match")
airflow.exceptions.AirflowException: PID of job runner does not match
[2023-05-04 02:28:23,675] {local_executor.py:130} ERROR - Failed to execute task PID of job runner does not match.
Traceback (most recent call last):
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/executors/local_executor.py", line 126, in _execute_work_in_fork
    args.func(args)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/cli_parser.py", line 52, in command
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/cli.py", line 103, in wrapper
    return f(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 382, in task_run
    _run_task_by_selected_method(args, dag, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 189, in _run_task_by_selected_method
    _run_task_by_local_task_job(args, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 247, in _run_task_by_local_task_job
    run_job.run()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 247, in run
    self._execute()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 135, in _execute
    self.heartbeat()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 228, in heartbeat
    self.heartbeat_callback(session=session)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/session.py", line 72, in wrapper
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 208, in heartbeat_callback
    raise AirflowException("PID of job runner does not match")
airflow.exceptions.AirflowException: PID of job runner does not match
[2023-05-04 02:28:23,696] {local_executor.py:130} ERROR - Failed to execute task PID of job runner does not match.
Traceback (most recent call last):
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/executors/local_executor.py", line 126, in _execute_work_in_fork
    args.func(args)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/cli_parser.py", line 52, in command
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/cli.py", line 103, in wrapper
    return f(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 382, in task_run
    _run_task_by_selected_method(args, dag, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 189, in _run_task_by_selected_method
    _run_task_by_local_task_job(args, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 247, in _run_task_by_local_task_job
    run_job.run()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 247, in run
    self._execute()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 135, in _execute
    self.heartbeat()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 228, in heartbeat
    self.heartbeat_callback(session=session)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/session.py", line 72, in wrapper
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 208, in heartbeat_callback
    raise AirflowException("PID of job runner does not match")
airflow.exceptions.AirflowException: PID of job runner does not match
[2023-05-04 02:28:23,737] {local_executor.py:130} ERROR - Failed to execute task PID of job runner does not match.
Traceback (most recent call last):
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/executors/local_executor.py", line 126, in _execute_work_in_fork
    args.func(args)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/cli_parser.py", line 52, in command
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/cli.py", line 103, in wrapper
    return f(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 382, in task_run
    _run_task_by_selected_method(args, dag, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 189, in _run_task_by_selected_method
    _run_task_by_local_task_job(args, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 247, in _run_task_by_local_task_job
    run_job.run()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 247, in run
    self._execute()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 135, in _execute
    self.heartbeat()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 228, in heartbeat
    self.heartbeat_callback(session=session)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/session.py", line 72, in wrapper
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 208, in heartbeat_callback
    raise AirflowException("PID of job runner does not match")
airflow.exceptions.AirflowException: PID of job runner does not match
[2023-05-04 02:28:23,791] {local_executor.py:130} ERROR - Failed to execute task PID of job runner does not match.
Traceback (most recent call last):
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/executors/local_executor.py", line 126, in _execute_work_in_fork
    args.func(args)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/cli_parser.py", line 52, in command
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/cli.py", line 103, in wrapper
    return f(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 382, in task_run
    _run_task_by_selected_method(args, dag, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 189, in _run_task_by_selected_method
    _run_task_by_local_task_job(args, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 247, in _run_task_by_local_task_job
    run_job.run()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 247, in run
    self._execute()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 135, in _execute
    self.heartbeat()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 228, in heartbeat
    self.heartbeat_callback(session=session)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/session.py", line 72, in wrapper
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 208, in heartbeat_callback
    raise AirflowException("PID of job runner does not match")
airflow.exceptions.AirflowException: PID of job runner does not match
[2023-05-04 02:28:23,801] {local_executor.py:130} ERROR - Failed to execute task PID of job runner does not match.
Traceback (most recent call last):
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/executors/local_executor.py", line 126, in _execute_work_in_fork
    args.func(args)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/cli_parser.py", line 52, in command
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/cli.py", line 103, in wrapper
    return f(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 382, in task_run
    _run_task_by_selected_method(args, dag, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 189, in _run_task_by_selected_method
    _run_task_by_local_task_job(args, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 247, in _run_task_by_local_task_job
    run_job.run()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 247, in run
    self._execute()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 135, in _execute
    self.heartbeat()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 228, in heartbeat
    self.heartbeat_callback(session=session)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/session.py", line 72, in wrapper
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 208, in heartbeat_callback
    raise AirflowException("PID of job runner does not match")
airflow.exceptions.AirflowException: PID of job runner does not match
[2023-05-04 02:28:24,815] {dagrun.py:578} ERROR - Marking run <DagRun *** @ 2023-05-04 05:00:00+00:00: scheduled__2023-05-04T05:00:00+00:00, state:running, queued_at: 2023-05-04 06:00:02.373050+00:00. externally triggered: False> failed
[2023-05-04 02:28:24,816] {dagrun.py:644} INFO - DagRun *** dag_id=*** execution_date=2023-05-04 05:00:00+00:00, run_id=scheduled__2023-05-04T05:00:00+00:00, run_start_date=2023-05-04 06:00:02.574912+00:00, run_end_date=2023-05-04 06:28:24.815624+00:00, run_duration=1702.240712, state=failed, external_trigger=False, run_type=scheduled, data_interval_start=2023-05-04 05:00:00+00:00, data_interval_end=2023-05-04 06:00:00+00:00, dag_hash=4d788176fc57f5eb934f9ab5b04a02db
[2023-05-04 02:28:24,839] {dag.py:3336} INFO - Setting next_dagrun for *** to 2023-05-04T06:00:00+00:00, run_after=2023-05-04T07:00:00+00:00
[2023-05-04 02:28:25,750] {local_executor.py:130} ERROR - Failed to execute task PID of job runner does not match.
Traceback (most recent call last):
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/executors/local_executor.py", line 126, in _execute_work_in_fork
    args.func(args)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/cli_parser.py", line 52, in command
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/cli.py", line 103, in wrapper
    return f(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 382, in task_run
    _run_task_by_selected_method(args, dag, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 189, in _run_task_by_selected_method
    _run_task_by_local_task_job(args, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 247, in _run_task_by_local_task_job
    run_job.run()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 247, in run
    self._execute()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 135, in _execute
    self.heartbeat()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 228, in heartbeat
    self.heartbeat_callback(session=session)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/session.py", line 72, in wrapper
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 208, in heartbeat_callback
    raise AirflowException("PID of job runner does not match")
airflow.exceptions.AirflowException: PID of job runner does not match
[2023-05-04 02:28:25,805] {scheduler_job.py:588} INFO - Executor reports execution of *** run_id=scheduled__2023-05-04T05:00:00+00:00 exited with status failed for try_number 1
[2023-05-04 02:28:25,805] {scheduler_job.py:588} INFO - Executor reports execution of *** run_id=scheduled__2023-05-04T05:00:00+00:00 exited with status failed for try_number 1
[2023-05-04 02:28:25,805] {scheduler_job.py:588} INFO - Executor reports execution of *** run_id=scheduled__2023-05-03T06:00:00+00:00 exited with status failed for try_number 1
[2023-05-04 02:28:25,805] {scheduler_job.py:588} INFO - Executor reports execution of *** run_id=scheduled__2023-05-03T06:00:00+00:00 exited with status failed for try_number 1
[2023-05-04 02:28:25,806] {scheduler_job.py:588} INFO - Executor reports execution of *** run_id=scheduled__2023-05-03T06:00:00+00:00 exited with status failed for try_number 1
[2023-05-04 02:28:25,806] {scheduler_job.py:588} INFO - Executor reports execution of *** run_id=scheduled__2023-05-03T06:00:00+00:00 exited with status failed for try_number 1
[2023-05-04 02:28:25,806] {scheduler_job.py:588} INFO - Executor reports execution of *** run_id=scheduled__2023-05-03T06:00:00+00:00 exited with status failed for try_number 1
[2023-05-04 02:28:25,806] {scheduler_job.py:588} INFO - Executor reports execution of *** run_id=scheduled__2023-05-04T04:05:00+00:00 exited with status failed for try_number 1
[2023-05-04 02:28:25,827] {scheduler_job.py:631} INFO - TaskInstance Finished: dag_id=*** task_id=***, run_id=scheduled__2023-05-04T05:00:00+00:00, map_index=-1, run_start_date=2023-05-04 06:28:18.434524+00:00, run_end_date=2023-05-04 06:28:22.240840+00:00, run_duration=3.80632, state=up_for_retry, executor_state=failed, try_number=1, max_tries=2, job_id=277260, pool=default_pool, queue=default, priority_weight=1, operator=SSHOperator, queued_dttm=2023-05-04 06:28:15.998301+00:00, queued_by_job_id=233035, pid=3738390
[2023-05-04 02:28:25,827] {scheduler_job.py:631} INFO - TaskInstance Finished: dag_id=*** task_id=***, run_id=scheduled__2023-05-04T04:05:00+00:00, map_index=-1, run_start_date=2023-05-04 06:28:15.776811+00:00, run_end_date=2023-05-04 06:28:25.632014+00:00, run_duration=9.8552, state=up_for_retry, executor_state=failed, try_number=1, max_tries=2, job_id=277246, pool=default_pool, queue=default, priority_weight=1, operator=SSHOperator, queued_dttm=2023-05-04 06:28:13.784565+00:00, queued_by_job_id=233035, pid=3738075
[2023-05-04 02:28:25,827] {scheduler_job.py:631} INFO - TaskInstance Finished: dag_id=*** task_id=***, run_id=scheduled__2023-05-04T05:00:00+00:00, map_index=-1, run_start_date=2023-05-04 06:28:15.996686+00:00, run_end_date=2023-05-04 06:28:22.783233+00:00, run_duration=6.78655, state=failed, executor_state=failed, try_number=1, max_tries=0, job_id=277247, pool=default_pool, queue=default, priority_weight=1, operator=SSHOperator, queued_dttm=2023-05-04 06:28:13.784565+00:00, queued_by_job_id=233035, pid=3738153
[2023-05-04 02:28:25,828] {scheduler_job.py:631} INFO - TaskInstance Finished: dag_id=*** task_id=***, run_id=scheduled__2023-05-03T06:00:00+00:00, map_index=-1, run_start_date=2023-05-04 06:28:15.871250+00:00, run_end_date=2023-05-04 06:28:22.188521+00:00, run_duration=6.31727, state=failed, executor_state=failed, try_number=1, max_tries=0, job_id=277245, pool=default_pool, queue=default, priority_weight=2, operator=ExternalTaskSensor, queued_dttm=2023-05-04 06:28:13.784565+00:00, queued_by_job_id=233035, pid=3738084
[2023-05-04 02:28:25,828] {scheduler_job.py:631} INFO - TaskInstance Finished: dag_id=*** task_id=***, run_id=scheduled__2023-05-03T06:00:00+00:00, map_index=-1, run_start_date=2023-05-04 06:28:15.669887+00:00, run_end_date=2023-05-04 06:28:21.537265+00:00, run_duration=5.86738, state=failed, executor_state=failed, try_number=1, max_tries=0, job_id=277239, pool=default_pool, queue=default, priority_weight=2, operator=ExternalTaskSensor, queued_dttm=2023-05-04 06:28:13.784565+00:00, queued_by_job_id=233035, pid=3738064
[2023-05-04 02:28:25,829] {scheduler_job.py:631} INFO - TaskInstance Finished: dag_id=*** task_id=***, run_id=scheduled__2023-05-03T06:00:00+00:00, map_index=-1, run_start_date=2023-05-04 06:28:15.554503+00:00, run_end_date=2023-05-04 06:28:22.238525+00:00, run_duration=6.68402, state=failed, executor_state=failed, try_number=1, max_tries=0, job_id=277240, pool=default_pool, queue=default, priority_weight=2, operator=ExternalTaskSensor, queued_dttm=2023-05-04 06:28:13.784565+00:00, queued_by_job_id=233035, pid=3738047
[2023-05-04 02:28:25,829] {scheduler_job.py:631} INFO - TaskInstance Finished: dag_id=*** task_id=***, run_id=scheduled__2023-05-03T06:00:00+00:00, map_index=-1, run_start_date=2023-05-04 06:28:16.023921+00:00, run_end_date=2023-05-04 06:28:21.406309+00:00, run_duration=5.38239, state=failed, executor_state=failed, try_number=1, max_tries=0, job_id=277253, pool=default_pool, queue=default, priority_weight=2, operator=ExternalTaskSensor, queued_dttm=2023-05-04 06:28:13.784565+00:00, queued_by_job_id=233035, pid=3738156
[2023-05-04 02:28:25,829] {scheduler_job.py:631} INFO - TaskInstance Finished: dag_id=*** task_id=***, run_id=scheduled__2023-05-03T06:00:00+00:00, map_index=-1, run_start_date=2023-05-04 06:28:16.405103+00:00, run_end_date=2023-05-04 06:28:21.631632+00:00, run_duration=5.22653, state=failed, executor_state=failed, try_number=1, max_tries=0, job_id=277252, pool=default_pool, queue=default, priority_weight=2, operator=ExternalTaskSensor, queued_dttm=2023-05-04 06:28:13.784565+00:00, queued_by_job_id=233035, pid=3738180
[2023-05-04 02:28:25,891] {local_executor.py:130} ERROR - Failed to execute task PID of job runner does not match.
Traceback (most recent call last):
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/executors/local_executor.py", line 126, in _execute_work_in_fork
    args.func(args)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/cli_parser.py", line 52, in command
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/cli.py", line 103, in wrapper
    return f(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 382, in task_run
    _run_task_by_selected_method(args, dag, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 189, in _run_task_by_selected_method
    _run_task_by_local_task_job(args, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 247, in _run_task_by_local_task_job
    run_job.run()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 247, in run
    self._execute()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 135, in _execute
    self.heartbeat()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 228, in heartbeat
    self.heartbeat_callback(session=session)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/session.py", line 72, in wrapper
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 208, in heartbeat_callback
    raise AirflowException("PID of job runner does not match")
airflow.exceptions.AirflowException: PID of job runner does not match
[2023-05-04 02:28:26,251] {local_executor.py:130} ERROR - Failed to execute task PID of job runner does not match.
Traceback (most recent call last):
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/executors/local_executor.py", line 126, in _execute_work_in_fork
    args.func(args)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/cli_parser.py", line 52, in command
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/cli.py", line 103, in wrapper
    return f(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 382, in task_run
    _run_task_by_selected_method(args, dag, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 189, in _run_task_by_selected_method
    _run_task_by_local_task_job(args, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 247, in _run_task_by_local_task_job
    run_job.run()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 247, in run
    self._execute()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 135, in _execute
    self.heartbeat()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 228, in heartbeat
    self.heartbeat_callback(session=session)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/session.py", line 72, in wrapper
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 208, in heartbeat_callback
    raise AirflowException("PID of job runner does not match")
airflow.exceptions.AirflowException: PID of job runner does not match
[2023-05-04 02:28:27,011] {dagrun.py:578} ERROR - Marking run <DagRun *** @ 2023-04-16 00:00:00+00:00: scheduled__2023-04-16T00:00:00+00:00, state:running, queued_at: 2023-05-01 00:00:06.474932+00:00. externally triggered: False> failed
[2023-05-04 02:28:27,012] {dagrun.py:644} INFO - DagRun *** dag_id=*** execution_date=2023-04-16 00:00:00+00:00, run_id=scheduled__2023-04-16T00:00:00+00:00, run_start_date=2023-05-01 00:00:06.606220+00:00, run_end_date=2023-05-04 06:28:27.012156+00:00, run_duration=282500.405936, state=failed, external_trigger=False, run_type=scheduled, data_interval_start=2023-04-16 00:00:00+00:00, data_interval_end=2023-05-01 00:00:00+00:00, dag_hash=71706b64a19537a7749aa8af2dd1f8e0
[2023-05-04 02:28:27,021] {dag.py:3336} INFO - Setting next_dagrun for *** to 2023-05-01T00:00:00+00:00, run_after=2023-05-16T00:00:00+00:00
[2023-05-04 02:28:28,203] {scheduler_job.py:588} INFO - Executor reports execution of *** run_id=scheduled__2023-05-03T20:05:00+00:00 exited with status failed for try_number 1
[2023-05-04 02:28:28,203] {scheduler_job.py:588} INFO - Executor reports execution of *** run_id=scheduled__2023-04-16T00:00:00+00:00 exited with status failed for try_number 1
[2023-05-04 02:28:28,212] {scheduler_job.py:631} INFO - TaskInstance Finished: dag_id=*** task_id=***, run_id=scheduled__2023-04-16T00:00:00+00:00, map_index=-1, run_start_date=2023-05-04 06:28:20.053437+00:00, run_end_date=2023-05-04 06:28:25.618675+00:00, run_duration=5.56524, state=failed, executor_state=failed, try_number=1, max_tries=0, job_id=277266, pool=default_pool, queue=default, priority_weight=1, operator=SSHOperator, queued_dttm=2023-05-04 06:28:18.736412+00:00, queued_by_job_id=233035, pid=3738527
[2023-05-04 02:28:28,213] {scheduler_job.py:631} INFO - TaskInstance Finished: dag_id=*** task_id=***, run_id=scheduled__2023-05-03T20:05:00+00:00, map_index=-1, run_start_date=2023-05-04 06:28:16.315525+00:00, run_end_date=2023-05-04 06:28:25.669738+00:00, run_duration=9.35421, state=up_for_retry, executor_state=failed, try_number=1, max_tries=2, job_id=277256, pool=default_pool, queue=default, priority_weight=1, operator=SSHOperator, queued_dttm=2023-05-04 06:28:13.784565+00:00, queued_by_job_id=233035, pid=3738170
[2023-05-04 02:28:29,882] {scheduler_job.py:346} INFO - 1 tasks up for execution:
	<TaskInstance: *** scheduled__2023-05-02T20:00:00+00:00 [scheduled]>
[2023-05-04 02:28:29,882] {scheduler_job.py:411} INFO - DAG *** has 1/50 running and queued tasks
[2023-05-04 02:28:29,882] {scheduler_job.py:497} INFO - Setting the following tasks to queued state:
	<TaskInstance: *** scheduled__2023-05-02T20:00:00+00:00 [scheduled]>
[2023-05-04 02:28:29,887] {scheduler_job.py:536} INFO - Sending TaskInstanceKey(dag_id=*** ***, run_id='scheduled__2023-05-02T20:00:00+00:00', try_number=1, map_index=-1) to executor with priority 1 and queue default
[2023-05-04 02:28:29,887] {base_executor.py:95} INFO - Adding to queue: ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-02T20:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:29,905] {local_executor.py:81} INFO - QueuedLocalWorker running ['airflow', 'tasks', 'run', '***', '***', 'scheduled__2023-05-02T20:00:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/***.py']
[2023-05-04 02:28:30,010] {dagbag.py:537} INFO - Filling up the DagBag from /mnt/alpha/airflow/dags/***.py
[2023-05-04 02:28:31,085] {base.py:71} INFO - Using connection ID ssh_*** for task execution.
[2023-05-04 02:28:31,720] {task_command.py:376} INFO - Running <TaskInstance: *** scheduled__2023-05-02T20:00:00+00:00 [queued]> on host ***
[2023-05-04 02:28:32,005] {scheduler_job.py:588} INFO - Executor reports execution of *** run_id=scheduled__2023-05-02T20:00:00+00:00 exited with status success for try_number 1
[2023-05-04 02:28:32,014] {scheduler_job.py:631} INFO - TaskInstance Finished: dag_id=*** task_id=***, run_id=scheduled__2023-05-02T20:00:00+00:00, map_index=-1, run_start_date=2023-05-04 06:28:18.191068+00:00, run_end_date=2023-05-04 06:28:28.899988+00:00, run_duration=10.7089, state=failed, executor_state=success, try_number=1, max_tries=1, job_id=277259, pool=default_pool, queue=default, priority_weight=3, operator=SSHOperator, queued_dttm=2023-05-04 06:28:15.998301+00:00, queued_by_job_id=233035, pid=3738373
[2023-05-04 02:28:38,357] {scheduler_job.py:588} INFO - Executor reports execution of *** run_id=scheduled__2023-05-02T20:00:00+00:00 exited with status success for try_number 1
[2023-05-04 02:28:38,396] {scheduler_job.py:631} INFO - TaskInstance Finished: dag_id=*** task_id=***, run_id=scheduled__2023-05-02T20:00:00+00:00, map_index=-1, run_start_date=2023-05-04 06:28:31.867672+00:00, run_end_date=2023-05-04 06:28:33.320185+00:00, run_duration=1.45251, state=success, executor_state=success, try_number=1, max_tries=1, job_id=277272, pool=default_pool, queue=default, priority_weight=1, operator=PythonOperator, queued_dttm=2023-05-04 06:28:29.883257+00:00, queued_by_job_id=233035, pid=3739407
[2023-05-04 02:28:40,472] {local_executor.py:130} ERROR - Failed to execute task PID of job runner does not match.
Traceback (most recent call last):
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/executors/local_executor.py", line 126, in _execute_work_in_fork
    args.func(args)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/cli_parser.py", line 52, in command
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/cli.py", line 103, in wrapper
    return f(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 382, in task_run
    _run_task_by_selected_method(args, dag, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 189, in _run_task_by_selected_method
    _run_task_by_local_task_job(args, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 247, in _run_task_by_local_task_job
    run_job.run()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 247, in run
    self._execute()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 135, in _execute
    self.heartbeat()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 228, in heartbeat
    self.heartbeat_callback(session=session)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/session.py", line 72, in wrapper
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 208, in heartbeat_callback
    raise AirflowException("PID of job runner does not match")
airflow.exceptions.AirflowException: PID of job runner does not match
[2023-05-04 02:28:41,951] {dagrun.py:578} ERROR - Marking run <DagRun *** @ 2023-05-02 20:00:00+00:00: scheduled__2023-05-02T20:00:00+00:00, state:running, queued_at: 2023-05-03 20:00:01.228399+00:00. externally triggered: False> failed
[2023-05-04 02:28:41,952] {dagrun.py:644} INFO - DagRun *** dag_id=*** execution_date=2023-05-02 20:00:00+00:00, run_id=scheduled__2023-05-02T20:00:00+00:00, run_start_date=2023-05-03 20:00:01.913706+00:00, run_end_date=2023-05-04 06:28:41.952025+00:00, run_duration=37720.038319, state=failed, external_trigger=False, run_type=scheduled, data_interval_start=2023-05-02 20:00:00+00:00, data_interval_end=2023-05-03 20:00:00+00:00, dag_hash=07a45c48201bfc14afb9d7e4c643bbdb
[2023-05-04 02:28:41,980] {dag.py:3336} INFO - Setting next_dagrun for *** to 2023-05-03T20:00:00+00:00, run_after=2023-05-04T20:00:00+00:00
[2023-05-04 02:28:42,422] {local_executor.py:130} ERROR - Failed to execute task PID of job runner does not match.
Traceback (most recent call last):
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/executors/local_executor.py", line 126, in _execute_work_in_fork
    args.func(args)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/cli_parser.py", line 52, in command
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/cli.py", line 103, in wrapper
    return f(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 382, in task_run
    _run_task_by_selected_method(args, dag, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 189, in _run_task_by_selected_method
    _run_task_by_local_task_job(args, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 247, in _run_task_by_local_task_job
    run_job.run()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 247, in run
    self._execute()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 135, in _execute
    self.heartbeat()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 228, in heartbeat
    self.heartbeat_callback(session=session)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/session.py", line 72, in wrapper
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 208, in heartbeat_callback
    raise AirflowException("PID of job runner does not match")
airflow.exceptions.AirflowException: PID of job runner does not match
[2023-05-04 02:28:42,502] {scheduler_job.py:588} INFO - Executor reports execution of *** run_id=scheduled__2023-05-03T01:03:00+00:00 exited with status failed for try_number 1
[2023-05-04 02:28:42,502] {scheduler_job.py:588} INFO - Executor reports execution of *** run_id=scheduled__2023-05-04T06:20:00+00:00 exited with status failed for try_number 1
[2023-05-04 02:28:42,511] {scheduler_job.py:631} INFO - TaskInstance Finished: dag_id=*** task_id=***, run_id=scheduled__2023-05-03T01:03:00+00:00, map_index=-1, run_start_date=2023-05-04 06:28:16.302772+00:00, run_end_date=2023-05-04 06:28:38.024822+00:00, run_duration=21.722, state=failed, executor_state=failed, try_number=1, max_tries=0, job_id=277255, pool=default_pool, queue=default, priority_weight=2, operator=SSHOperator, queued_dttm=2023-05-04 06:28:13.784565+00:00, queued_by_job_id=233035, pid=3738168
[2023-05-04 02:28:42,511] {scheduler_job.py:631} INFO - TaskInstance Finished: dag_id=*** task_id=***, run_id=scheduled__2023-05-04T06:20:00+00:00, map_index=-1, run_start_date=2023-05-04 06:28:16.282425+00:00, run_end_date=2023-05-04 06:28:41.372880+00:00, run_duration=25.0905, state=failed, executor_state=failed, try_number=1, max_tries=0, job_id=277251, pool=default_pool, queue=default, priority_weight=1, operator=SSHOperator, queued_dttm=2023-05-04 06:28:13.784565+00:00, queued_by_job_id=233035, pid=3738169
[2023-05-04 02:28:42,661] {local_executor.py:130} ERROR - Failed to execute task PID of job runner does not match.
Traceback (most recent call last):
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/executors/local_executor.py", line 126, in _execute_work_in_fork
    args.func(args)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/cli_parser.py", line 52, in command
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/cli.py", line 103, in wrapper
    return f(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 382, in task_run
    _run_task_by_selected_method(args, dag, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 189, in _run_task_by_selected_method
    _run_task_by_local_task_job(args, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 247, in _run_task_by_local_task_job
    run_job.run()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 247, in run
    self._execute()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 135, in _execute
    self.heartbeat()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 228, in heartbeat
    self.heartbeat_callback(session=session)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/session.py", line 72, in wrapper
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 208, in heartbeat_callback
    raise AirflowException("PID of job runner does not match")
airflow.exceptions.AirflowException: PID of job runner does not match
[2023-05-04 02:28:43,636] {dagrun.py:578} ERROR - Marking run <DagRun *** @ 2023-05-04 06:20:00+00:00: scheduled__2023-05-04T06:20:00+00:00, state:running, queued_at: 2023-05-04 06:25:33.747936+00:00. externally triggered: False> failed
[2023-05-04 02:28:43,637] {dagrun.py:644} INFO - DagRun *** dag_id=*** execution_date=2023-05-04 06:20:00+00:00, run_id=scheduled__2023-05-04T06:20:00+00:00, run_start_date=2023-05-04 06:25:33.806284+00:00, run_end_date=2023-05-04 06:28:43.637144+00:00, run_duration=189.83086, state=failed, external_trigger=False, run_type=scheduled, data_interval_start=2023-05-04 06:20:00+00:00, data_interval_end=2023-05-04 06:25:00+00:00, dag_hash=c6c806de8a6d29d37d214803630a2667
[2023-05-04 02:28:43,646] {dag.py:3336} INFO - Setting next_dagrun for *** to 2023-05-04T06:25:00+00:00, run_after=2023-05-04T06:30:00+00:00
[2023-05-04 02:28:44,586] {scheduler_job.py:588} INFO - Executor reports execution of *** run_id=scheduled__2023-05-04T05:05:00+00:00 exited with status failed for try_number 1
[2023-05-04 02:28:44,595] {scheduler_job.py:631} INFO - TaskInstance Finished: dag_id=*** task_id=***, run_id=scheduled__2023-05-04T05:05:00+00:00, map_index=-1, run_start_date=2023-05-04 06:28:21.528300+00:00, run_end_date=2023-05-04 06:28:42.518193+00:00, run_duration=20.9899, state=up_for_retry, executor_state=failed, try_number=1, max_tries=3, job_id=277270, pool=default_pool, queue=default, priority_weight=3, operator=SSHOperator, queued_dttm=2023-05-04 06:28:15.998301+00:00, queued_by_job_id=233035, pid=3738666
[2023-05-04 02:28:46,942] {dagrun.py:578} ERROR - Marking run <DagRun *** @ 2023-05-03 01:03:00+00:00: scheduled__2023-05-03T01:03:00+00:00, state:running, queued_at: 2023-05-04 01:03:04.048892+00:00. externally triggered: False> failed
[2023-05-04 02:28:46,942] {dagrun.py:644} INFO - DagRun *** dag_id=*** execution_date=2023-05-03 01:03:00+00:00, run_id=scheduled__2023-05-03T01:03:00+00:00, run_start_date=2023-05-04 01:03:04.421634+00:00, run_end_date=2023-05-04 06:28:46.942643+00:00, run_duration=19542.521009, state=failed, external_trigger=False, run_type=scheduled, data_interval_start=2023-05-03 01:03:00+00:00, data_interval_end=2023-05-04 01:03:00+00:00, dag_hash=5567f4afd9ffba286e0af33d0abbabd7
[2023-05-04 02:28:46,985] {dag.py:3336} INFO - Setting next_dagrun for *** to 2023-05-04T01:03:00+00:00, run_after=2023-05-05T01:03:00+00:00
[2023-05-04 02:28:47,298] {local_executor.py:130} ERROR - Failed to execute task PID of job runner does not match.
Traceback (most recent call last):
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/executors/local_executor.py", line 126, in _execute_work_in_fork
    args.func(args)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/cli_parser.py", line 52, in command
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/cli.py", line 103, in wrapper
    return f(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 382, in task_run
    _run_task_by_selected_method(args, dag, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 189, in _run_task_by_selected_method
    _run_task_by_local_task_job(args, ti)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/cli/commands/task_command.py", line 247, in _run_task_by_local_task_job
    run_job.run()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 247, in run
    self._execute()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 135, in _execute
    self.heartbeat()
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/base_job.py", line 228, in heartbeat
    self.heartbeat_callback(session=session)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/utils/session.py", line 72, in wrapper
    return func(*args, **kwargs)
  File "/mnt/alpha/miniconda/lib/python3.10/site-packages/airflow/jobs/local_task_job.py", line 208, in heartbeat_callback
    raise AirflowException("PID of job runner does not match")
airflow.exceptions.AirflowException: PID of job runner does not match


@shubhampatel94
Copy link

uranusjr can you add 2.4.3 also as an affected version ?

@shubhampatel94
Copy link

@uranusjr can you add 2.4.3 also as an affected version ?

@potiuk potiuk added the affected_version:2.4 Issues Reported for 2.4 label May 8, 2023
@potiuk
Copy link
Member

potiuk commented May 8, 2023

Could you tell more about you case @shubhampatel94 ? did it happen once, ? Did it start to happen continuously? Did you (or the deployment that you are running) experienced some kind of event (restart, being terminated, or similar?)

I am just trying to see if there is someone who can explain the circumstances it happens. IT does not seem a common occurence, people are experiencing it occasionally and I think it is caused by some race condition involved in starting and TERMINATING processes quickly

If it happened once and it was accompanied by some deployment issue that caused termination of running processes, I would not be surprised to see similar issue.

@kcphila
Copy link

kcphila commented May 8, 2023

@shubhampatel94 and @potiuk -

Note that since (my) patch was applied that fixed the race condition, I have occasionally seen this error when the process was killed for another reason - for example, we have OS monitors that will kill processes that are being bad citizens, or certain times when the task had an unexpected exception and died by itself.

I've verified in these cases that the task failed to complete and Airflow throws this error message, but Airflow is not the ultimate culprit that is terminating the tasks, and this is the message terminating the containing process of the dead task. Is it possible that this is what is happening with you?

At some point I was going to try to dig deeper to verify the situation and propose a better way to identify it and send a better error message, but I haven't had the time.

@potiuk
Copy link
Member

potiuk commented May 8, 2023

Note that since (my) patch was applied that fixed the race condition, I have occasionally seen this error when the process was killed for another reason - for example, we have OS monitors that will kill processes that are being bad citizens, or certain times when the task had an unexpected exception and died by itself.

Precisely. What you explains is what I suspected. Very rare event that is externally triggered. That's how it looks like from the logs. It actually looks like something just killed a bunch of tasks running but the original local task jobs have not been killed and then it complained about those "child" processes missing there. If that is happening only occasionally as a resut of some unbounded killing of processes. I would be for just closing this one. We are not able to handle all the scenarios when somethign randomly kills some processes. Airlfow is not a 99.999% available system that is supposed to handle absolutely all such situations - this is extremely costly to develop such systems, and there is little incentive to spend a lot of time on perfecting it, when there is nice UI and monitoring that can warn in such situations and have a human to fix it by re-running the tasks.

@shubhampatel94
Copy link

@potiuk @kcphila Thanks for looking into what I have pointed out.
It just happen once till now and only happen for a 6 min window and stabilized after that.
The trigger point I am assuming is

DagFileProcessorManager (PID=3732979) exited with exit code 1 - re-launching

What I have observed is that airflow terminated all running tasks within 6 min the Window, and then it was business as usual.

@potiuk
Copy link
Member

potiuk commented May 11, 2023

So I woul dnot really worry about it. I think we can close that one and we might re-open it if we have more reproducible cases other than occasional failures like that (which just might happen).

@potiuk potiuk closed this as completed May 11, 2023
@shubhampatel94
Copy link

Thanks, @potiuk will re-raise again if the observed issue again.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
affected_version:2.1 Issues Reported for 2.1 affected_version:2.2 Issues Reported for 2.2 affected_version:2.3 Issues Reported for 2.3 affected_version:2.4 Issues Reported for 2.4 kind:bug This is a clearly a bug
Projects
None yet
Development

No branches or pull requests