Skip to content

Conversation

@dstandish
Copy link
Contributor

@dstandish dstandish commented Feb 6, 2024

At shutdown, a trigger may emit a "close" signal around the same time as logging.shutDown is called, so the handler may have been removed from the handlers by one thread when the other tries to delete it.

Example

[2024-02-06 11:39:26 +0000] [24] [INFO] Handling signal: term
[2024-02-06 11:39:26 +0000] [28] [INFO] Worker exiting (pid: 28)
[2024-02-06 11:39:26 +0000] [27] [INFO] Worker exiting (pid: 27)
[2024-02-06T11:38:08.264+0000] {triggerer_job_runner.py:623} INFO - trigger log_deferred_timestamp/manual__2024-02-06T11:33:03.922859+00:00/wait_for_time_348/-1/1 (ID 1051) completed
[2024-02-06 11:39:26 +0000] [24] [INFO] Shutting down: Master
Exception in thread Thread-1 (_monitor):
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/threading.py", line 1045, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.11/threading.py", line 982, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.11/logging/handlers.py", line 1582, in _monitor
    self.handle(record)
  File "/usr/local/lib/python3.11/logging/handlers.py", line 1563, in handle
    handler.handle(record)
  File "/usr/local/lib/python3.11/site-packages/airflow/utils/log/trigger_handler.py", line 102, in handle
    self.close_one(record.trigger_id)
  File "/usr/local/lib/python3.11/site-packages/airflow/utils/log/trigger_handler.py", line 113, in close_one
    del self.handlers[trigger_id]
        ~~~~~~~~~~~~~^^^^^^^^^^^^
KeyError: 1052

At shutdown, a trigger may emit a "close" signal around the same time as logging.shutDown is called, so the handler may have been removed from the handlers by one thread when the other tries to delete it.
@jedcunningham jedcunningham merged commit e24f0a9 into apache:main Feb 6, 2024
@jedcunningham jedcunningham deleted the handle-race-condition-trigger-handler-close branch February 6, 2024 23:11
@ephraimbuddy ephraimbuddy added this to the Airflow 2.8.2 milestone Feb 19, 2024
@ephraimbuddy ephraimbuddy added the type:bug-fix Changelog: Bug Fixes label Feb 19, 2024
ephraimbuddy pushed a commit that referenced this pull request Feb 20, 2024
At shutdown, a trigger may emit a "close" signal around the same time as logging.shutDown is called, so the handler may have been removed from the handlers by one thread when the other tries to delete it.

(cherry picked from commit e24f0a9)
ephraimbuddy pushed a commit that referenced this pull request Feb 22, 2024
At shutdown, a trigger may emit a "close" signal around the same time as logging.shutDown is called, so the handler may have been removed from the handlers by one thread when the other tries to delete it.

(cherry picked from commit e24f0a9)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

area:logging type:bug-fix Changelog: Bug Fixes

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants