Recorded pid<> does not match the current pid <> #20992

Activity

1. ghost added

   area:core

   on Jan 20, 2022
2. ghost added

   kind:bugThis is a clearly a bugThis is a clearly a bug

   on Jan 20, 2022
3. boring-cyborg commented on Jan 20, 2022

   

   boring-cyborgBot

   on Jan 20, 2022

   More actions

   Thanks for opening your first issue here! Be sure to follow the issue template!
5. PApostol commented on Jan 20, 2022

   

   PApostol

   on Jan 20, 2022

   Contributor

   More actions

   This has also been reported in #17507, there is a long discussion about it in that thread.
7. PApostol commented on Jan 20, 2022

   

   PApostol

   on Jan 20, 2022

   Contributor

   More actions

   I think there's no definite solution yet, since the original issue is still open.
9. potiuk commented on Jan 23, 2022

   

   potiuk

   on Jan 23, 2022

   Member

   More actions

   I think what would be very useful to solve the problem is that everyone who has similar problem, would provide a more detailed information on how they get this error. Rather than "it also is the problem in 2.2.3" or saying "mee too", the best way you can help maintainers to investigate the issue is to prepare a very detailed description of your environment and post as many logs as you can find. This would be really helpful if everyone can do it and - for example - prepare a gist, or gists with their logs and environment descriptions.

   Airflow is a free product and we value that our users (who get it for free) could help us to determine the root causes for the issues.

   For the start - seems that this issue is connected with "default impersonation", so I think if anyone here has this issue without - impersonation, let us know. And if you do use impersonation - please (additionally to logs) make sure that you've followed this https://airflow.apache.org/docs/apache-airflow/stable/security/workload.html#impersonation and provide detailed description on how your impersonated user is configured.

   Ideally if you could provide a step-by-step on how we can reproduce the right configuration and steps to lead to the problem (I guess you must have some details on what has been changed vs. standard airflow configuration). If you could perform some step-by-step recreation of your environment, and trace down when it breaks that could be super-helpful.

   We won't be able to help as maintainers, if we do not get a really reproducible case when it happens - and getting as much information as possible is crucial to diagnose and fix this one.

   Looking forward to getting more details!
10. jcasal-ixl commented on Feb 16, 2022

    

    jcasal-ixl

    on Feb 16, 2022

    More actions

    For what is worth, I do not use "default impersonation", mine is set to blank with source of default, I do not use run_as_user.
    I run only one scheduler. I'm on version 2.1.2 on Cloud Composer. It happens to me intermittently, it isn't a huge problem, but still an annoyance. Seems to me to only happen in Dynamically generated DAGs, wonder if thats the same for everyone else.
11. potiuk commented on Feb 26, 2022

    

    potiuk

    on Feb 26, 2022

    Member

    More actions

    I am not 100% sure but it is very likely it was caused by a race condition i've fixed in #19935 . It's been merged in 2.1.3 so either migrating to 2.1.4 or 2.2.3 (recommended) shoudl solve it - both are now supported in Composer.

    If this is the reason then migration should help @jcasal-ixl - can you please migrate and let us know if the problem is solved.
12. eladkal

    added

    pending-response

    on Feb 28, 2022
13. easontm commented on Mar 2, 2022

    

    easontm

    on Mar 2, 2022

    Contributor

    More actions

    Here's my datapoint. If there are other process logs that matter, please let me know.
    Airflow version: 2.2.3
    Executor: CeleryKubernetes
    Deployment pattern: Other docker-based

    • Using HA scheduling (2)
    • 6 Celery workers
    • RabbitMQ as the message queue (3 replicas, RabbitMQClusterOperator)

    The task in question is a TimeDeltaSensor. After this failure the Celery worker continued to function and has processed other tasks, and this task itself was completed by a different Celery worker. I'm not setting default_impersonation. This issue is also not consistent for me as well -- I cannot repro on demand.

    Task definition, the default args applied to it only concern scheduling, emails, and retries.

    my_sensor = TimeDeltaSensor(
        task_id="my_sensor", delta=timedelta(minutes=30), dag=dag
    )
    

    Celery worker log:

    Details

    [2022-03-01 16:00:07,634: WARNING/ForkPoolWorker-5] Running <TaskInstance: MY_DAG.MY_TASK scheduled__2022-03-01T15:00:00+00:00 [queued]> on host airflow-celery-worker-6bb54c97cb-gks65
    [2022-03-01 16:00:10,831: ERROR/ForkPoolWorker-4] Failed to execute task PID of job runner does not match.
    Traceback (most recent call last):
      File "/usr/local/lib/python3.7/dist-packages/airflow/executors/celery_executor.py", line 121, in _execute_in_fork
        args.func(args)
      File "/usr/local/lib/python3.7/dist-packages/airflow/cli/cli_parser.py", line 48, in command
        return func(*args, **kwargs)
      File "/usr/local/lib/python3.7/dist-packages/airflow/utils/cli.py", line 92, in wrapper
        return f(*args, **kwargs)
      File "/usr/local/lib/python3.7/dist-packages/airflow/cli/commands/task_command.py", line 298, in task_run
        _run_task_by_selected_method(args, dag, ti)
      File "/usr/local/lib/python3.7/dist-packages/airflow/cli/commands/task_command.py", line 105, in _run_task_by_selected_method
        _run_task_by_local_task_job(args, ti)
      File "/usr/local/lib/python3.7/dist-packages/airflow/cli/commands/task_command.py", line 163, in _run_task_by_local_task_job
        run_job.run()
      File "/usr/local/lib/python3.7/dist-packages/airflow/jobs/base_job.py", line 245, in run
        self._execute()
      File "/usr/local/lib/python3.7/dist-packages/airflow/jobs/local_task_job.py", line 134, in _execute
        self.heartbeat()
      File "/usr/local/lib/python3.7/dist-packages/airflow/jobs/base_job.py", line 226, in heartbeat
        self.heartbeat_callback(session=session)
      File "/usr/local/lib/python3.7/dist-packages/airflow/utils/session.py", line 67, in wrapper
        return func(*args, **kwargs)
      File "/usr/local/lib/python3.7/dist-packages/airflow/jobs/local_task_job.py", line 209, in heartbeat_callback
        raise AirflowException("PID of job runner does not match")
    airflow.exceptions.AirflowException: PID of job runner does not match
    

    Slightly abbreviated task logs:

    Details

    --------------------------------------------------------------------------------
    [2022-03-01, 16:00:05 UTC] {taskinstance.py:1239} INFO - Starting attempt 1 of 3
    [2022-03-01, 16:00:05 UTC] {taskinstance.py:1240} INFO - 
    --------------------------------------------------------------------------------
    [2022-03-01, 16:00:05 UTC] {taskinstance.py:1259} INFO - Executing <Task(TimeDeltaSensor): MY_TASK> on 2022-03-01 15:00:00+00:00
    [2022-03-01, 16:00:05 UTC] {standard_task_runner.py:52} INFO - Started process 5939 to run task
    [2022-03-01, 16:00:05 UTC] {standard_task_runner.py:76} INFO - Running: ['airflow', 'tasks', 'run', 'MY_DAG', 'MY_TASK', 'scheduled__2022-03-01T15:00:00+00:00', '--job-id', '6384572', '--raw', '--subdir', 'DAGS_FOLDER/MY_DAG.py', '--cfg-path', '/tmp/tmp84eym25r', '--error-file', '/tmp/tmpyb039unj']
    [2022-03-01, 16:00:05 UTC] {standard_task_runner.py:77} INFO - Job 6384572: Subtask MY_TASK
    [2022-03-01, 16:00:05 UTC] {logging_mixin.py:109} INFO - Running <TaskInstance: MY_DAG.MY_TASK scheduled__2022-03-01T15:00:00+00:00 [running]> on host airflow-celery-worker-6bb54c97cb-gks65
    [2022-03-01, 16:00:05 UTC] {taskinstance.py:1426} INFO - Exporting the following env vars:
    AIRFLOW_CTX_DAG_OWNER=MY_OWNER
    AIRFLOW_CTX_DAG_ID=MY_DAG
    AIRFLOW_CTX_TASK_ID=MY_TASK
    AIRFLOW_CTX_EXECUTION_DATE=2022-03-01T15:00:00+00:00
    AIRFLOW_CTX_DAG_RUN_ID=scheduled__2022-03-01T15:00:00+00:00
    [2022-03-01, 16:00:05 UTC] {time_delta.py:39} INFO - Checking if the time (2022-03-01T16:30:00+00:00) has come
    [2022-03-01, 16:00:10 UTC] {local_task_job.py:207} WARNING - Recorded pid 5949 does not match the current pid 5939
    [2022-03-01, 16:00:10 UTC] {process_utils.py:124} INFO - Sending Signals.SIGTERM to group 5939. PIDs of all processes in the group: [5939]
    [2022-03-01, 16:00:10 UTC] {process_utils.py:75} INFO - Sending the signal Signals.SIGTERM to group 5939
    [2022-03-01, 16:00:10 UTC] {taskinstance.py:1408} ERROR - Received SIGTERM. Terminating subprocesses.
    
    ...
    usual stacktrace
    
14. github-actions commented on Apr 2, 2022

    

    github-actionsBot

    on Apr 2, 2022

    Contributor

    More actions

    This issue has been automatically marked as stale because it has been open for 30 days with no response from the author. It will be closed in next 7 days if no further activity occurs from the issue author.
15. github-actions

    added

    staleStale PRs per the .github/workflows/stale.yml policy fileStale PRs per the .github/workflows/stale.yml policy file

    on Apr 2, 2022
16. github-actions commented on Apr 9, 2022

    

    github-actionsBot

    on Apr 9, 2022

    Contributor

    More actions

    This issue has been closed because it has not received response from the issue author.
17. github-actions

    closed this as completedon Apr 9, 2022
18. potiuk

    reopened this on Jan 9, 2023
19. potiuk

    closed this as completedon Jan 9, 2023
20. shubhampatel94 commented on May 4, 2023

    

    shubhampatel94

    on May 4, 2023

    More actions

    Seeing same issue for 2.4.3
    added details here.
    #17507 (comment)
21. flyrock commented on Jan 5, 2024

    

    flyrock

    on Jan 5, 2024

    More actions

    Everyone, please increase the job_heartbeat_sec from default 5 to your desired value. It should help you