Skip to content

print is not thread-safe, so should not be used in signal handler#9222

Merged
Nusnus merged 12 commits into
celery:mainfrom
Zhong-z:reentrant_call_in_safe_say
Sep 8, 2024
Merged

print is not thread-safe, so should not be used in signal handler#9222
Nusnus merged 12 commits into
celery:mainfrom
Zhong-z:reentrant_call_in_safe_say

Conversation

@Zhong-z

@Zhong-z Zhong-z commented Sep 1, 2024

Copy link
Copy Markdown
Contributor

Note: Before submitting this pull request, please review our contributing
guidelines
.

Description

I sometime got RuntimeError: reentrant call inside <_io.BufferedWriter name='<stdout>'> during worker's lifecycle.

see others have similar issue https://stackoverflow.com/questions/45680378/how-to-explain-the-reentrant-runtimeerror-caused-by-printing-in-signal-handlers#comment126485747_56330763

We should not use print inside signal handlers because it's not thread-safe (not actually safe as the name suggested). There might be other cases of print inside signal handlers, but I was only able to identify these obvious ones. 😄

See similar issue and thread in gunicorn.

An alternative solution is not to log/print anything.

@codecov

codecov Bot commented Sep 1, 2024

Copy link
Copy Markdown

Codecov Report

Attention: Patch coverage is 50.00000% with 1 line in your changes missing coverage. Please review.

Project coverage is 78.01%. Comparing base (90feae3) to head (837e90a).
Report is 111 commits behind head on main.

Files with missing lines Patch % Lines
celery/apps/worker.py 50.00% 0 Missing and 1 partial ⚠️
Additional details and impacted files
@@           Coverage Diff           @@
##             main    #9222   +/-   ##
=======================================
  Coverage   78.01%   78.01%           
=======================================
  Files         150      150           
  Lines       18827    18828    +1     
  Branches     3220     3221    +1     
=======================================
+ Hits        14688    14689    +1     
+ Misses       3836     3835    -1     
- Partials      303      304    +1     
Flag Coverage Δ
unittests 77.99% <50.00%> (+<0.01%) ⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@auvipy auvipy left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

please fix the merge conflicts

@Zhong-z
Zhong-z requested a review from auvipy September 4, 2024 09:22

@Nusnus Nusnus left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@Zhong-z the smoke tests are failing on a real issue.

2024-09-04T12:47:28.6884582Z ------------------- default_worker_container: silly_villani --------------------
2024-09-04T12:47:28.6885146Z Changed worker configuration: {
2024-09-04T12:47:28.6885584Z     "worker_pool_restarts": true,
2024-09-04T12:47:28.6885984Z     "task_acks_late": true
2024-09-04T12:47:28.6886344Z }
2024-09-04T12:47:28.6886680Z  
2024-09-04T12:47:28.6887193Z  -------------- smoke_tests_worker@be6028dd6fb3 v5.5.0b2 (immunity)
2024-09-04T12:47:28.6887678Z --- ***** ----- 
2024-09-04T12:47:28.6888279Z -- ******* ---- Linux-6.5.0-1025-azure-x86_64-with-glibc2.36 2024-09-04 12:46:12
2024-09-04T12:47:28.6888823Z - *** --- * --- 
2024-09-04T12:47:28.6889251Z - ** ---------- [config]
2024-09-04T12:47:28.6889732Z - ** ---------- .> app:         celery_test_app:0x7f050969dcd0
2024-09-04T12:47:28.6890303Z - ** ---------- .> transport:   sqs://b09f0037a174:4566//
2024-09-04T12:47:28.6890970Z - ** ---------- .> results:     redis://161584cfa3c5/0
2024-09-04T12:47:28.6891510Z - *** --- * --- .> concurrency: 4 (prefork)
2024-09-04T12:47:28.6892274Z -- ******* ---- .> task events: OFF (enable -E to monitor tasks in this worker)
2024-09-04T12:47:28.6892899Z --- ***** ----- 
2024-09-04T12:47:28.6893222Z  -------------- [queues]
2024-09-04T12:47:28.6893852Z                 .> smoke_tests_queue exchange=smoke_tests_queue(direct) key=smoke_tests_queue
2024-09-04T12:47:28.6894479Z                 
2024-09-04T12:47:28.6894649Z 
2024-09-04T12:47:28.6894810Z [tasks]
2024-09-04T12:47:28.6895158Z   . pytest_celery.vendors.worker.tasks.add
2024-09-04T12:47:28.6895716Z   . pytest_celery.vendors.worker.tasks.add_replaced
2024-09-04T12:47:28.6896243Z   . pytest_celery.vendors.worker.tasks.fail
2024-09-04T12:47:28.6896741Z   . pytest_celery.vendors.worker.tasks.identity
2024-09-04T12:47:28.6897300Z   . pytest_celery.vendors.worker.tasks.noop
2024-09-04T12:47:28.6897797Z   . pytest_celery.vendors.worker.tasks.ping
2024-09-04T12:47:28.6898242Z   . pytest_celery.vendors.worker.tasks.sleep
2024-09-04T12:47:28.6898802Z   . pytest_celery.vendors.worker.tasks.xsum
2024-09-04T12:47:28.6899323Z   . t.integration.tasks.add
2024-09-04T12:47:28.6899790Z   . t.integration.tasks.add_chord_to_chord
2024-09-04T12:47:28.6900275Z   . t.integration.tasks.add_ignore_result
2024-09-04T12:47:28.6900686Z   . t.integration.tasks.add_not_typed
2024-09-04T12:47:28.6901176Z   . t.integration.tasks.add_pydantic
2024-09-04T12:47:28.6901620Z   . t.integration.tasks.add_replaced
2024-09-04T12:47:28.6902046Z   . t.integration.tasks.add_to_all
2024-09-04T12:47:28.6902558Z   . t.integration.tasks.add_to_all_to_chord
2024-09-04T12:47:28.6903143Z   . t.integration.tasks.build_chain_inside_task
2024-09-04T12:47:28.6903627Z   . t.integration.tasks.chain_add
2024-09-04T12:47:28.6904128Z   . t.integration.tasks.chord_add
2024-09-04T12:47:28.6904611Z   . t.integration.tasks.collect_ids
2024-09-04T12:47:28.6905065Z   . t.integration.tasks.delayed_sum
2024-09-04T12:47:28.6905564Z   . t.integration.tasks.delayed_sum_with_soft_guard
2024-09-04T12:47:28.6906062Z   . t.integration.tasks.errback_new_style
2024-09-04T12:47:28.6906540Z   . t.integration.tasks.errback_old_style
2024-09-04T12:47:28.6907040Z   . t.integration.tasks.fail
2024-09-04T12:47:28.6907445Z   . t.integration.tasks.fail_replaced
2024-09-04T12:47:28.6907870Z   . t.integration.tasks.fail_unpickleable
2024-09-04T12:47:28.6908379Z   . t.integration.tasks.identity
2024-09-04T12:47:28.6908797Z   . t.integration.tasks.ids
2024-09-04T12:47:28.6909242Z   . t.integration.tasks.mul
2024-09-04T12:47:28.6909713Z   . t.integration.tasks.print_unicode
2024-09-04T12:47:28.6910137Z   . t.integration.tasks.raise_error
2024-09-04T12:47:28.6910629Z   . t.integration.tasks.rebuild_signature
2024-09-04T12:47:28.6911072Z   . t.integration.tasks.redis_count
2024-09-04T12:47:28.6911763Z   . t.integration.tasks.redis_echo
2024-09-04T12:47:28.6912462Z   . t.integration.tasks.redis_echo_group_id
2024-09-04T12:47:28.6912930Z   . t.integration.tasks.replace_with_chain
2024-09-04T12:47:28.6913446Z   . t.integration.tasks.replace_with_chain_which_raises
2024-09-04T12:47:28.6914051Z   . t.integration.tasks.replace_with_empty_chain
2024-09-04T12:47:28.6914581Z   . t.integration.tasks.replace_with_stamped_task
2024-09-04T12:47:28.6915073Z   . t.integration.tasks.replaced_with_me
2024-09-04T12:47:28.6915614Z   . t.integration.tasks.retry
2024-09-04T12:47:28.6916031Z   . t.integration.tasks.retry_once
2024-09-04T12:47:28.6916466Z   . t.integration.tasks.retry_once_headers
2024-09-04T12:47:28.6917015Z   . t.integration.tasks.retry_once_priority
2024-09-04T12:47:28.6917491Z   . t.integration.tasks.retry_unpickleable
2024-09-04T12:47:28.6917929Z   . t.integration.tasks.return_exception
2024-09-04T12:47:28.6918538Z   . t.integration.tasks.return_nested_signature_chain_chain
2024-09-04T12:47:28.6919123Z   . t.integration.tasks.return_nested_signature_chain_chord
2024-09-04T12:47:28.6919793Z   . t.integration.tasks.return_nested_signature_chain_group
2024-09-04T12:47:28.6920373Z   . t.integration.tasks.return_nested_signature_chord_chain
2024-09-04T12:47:28.6921091Z   . t.integration.tasks.return_nested_signature_chord_chord
2024-09-04T12:47:28.6922192Z   . t.integration.tasks.return_nested_signature_chord_group
2024-09-04T12:47:28.6922994Z   . t.integration.tasks.return_nested_signature_group_chain
2024-09-04T12:47:28.6923878Z   . t.integration.tasks.return_nested_signature_group_chord
2024-09-04T12:47:28.6924582Z   . t.integration.tasks.return_nested_signature_group_group
2024-09-04T12:47:28.6925108Z   . t.integration.tasks.return_priority
2024-09-04T12:47:28.6925537Z   . t.integration.tasks.return_properties
2024-09-04T12:47:28.6926104Z   . t.integration.tasks.second_order_replace1
2024-09-04T12:47:28.6926593Z   . t.integration.tasks.second_order_replace2
2024-09-04T12:47:28.6927079Z   . t.integration.tasks.sleeping
2024-09-04T12:47:28.6927643Z   . t.integration.tasks.soft_time_limit_must_exceed_time_limit
2024-09-04T12:47:28.6928133Z   . t.integration.tasks.tsum
2024-09-04T12:47:28.6928594Z   . t.integration.tasks.write_to_file_and_return_int
2024-09-04T12:47:28.6929219Z   . t.integration.tasks.xsum
2024-09-04T12:47:28.6929633Z   . t.smoke.tasks.long_running_task
2024-09-04T12:47:28.6930100Z   . t.smoke.tasks.noop
2024-09-04T12:47:28.6930443Z   . t.smoke.tasks.replace_with_task
2024-09-04T12:47:28.6930920Z   . t.smoke.tasks.self_termination_delay_timeout
2024-09-04T12:47:28.6931506Z   . t.smoke.tasks.self_termination_exhaust_memory
2024-09-04T12:47:28.6931996Z   . t.smoke.tasks.self_termination_sigkill
2024-09-04T12:47:28.6932485Z   . t.smoke.tasks.self_termination_system_exit
2024-09-04T12:47:28.6933202Z   . t.smoke.tasks.soft_time_limit_lower_than_time_limit
2024-09-04T12:47:28.6933793Z   . t.smoke.tasks.soft_time_limit_must_exceed_time_limit
2024-09-04T12:47:28.6934151Z 
2024-09-04T12:47:28.6935231Z [2024-09-04 12:46:12,254: WARNING/MainProcess] /celery/celery/worker/consumer/consumer.py:508: CPendingDeprecationWarning: The broker_connection_retry configuration setting will no longer determine
2024-09-04T12:47:28.6936601Z whether broker connection retries are made during startup in Celery 6.0 and above.
2024-09-04T12:47:28.6937407Z If you wish to retain the existing behavior for retrying connections on startup,
2024-09-04T12:47:28.6938093Z you should set broker_connection_retry_on_startup to True.
2024-09-04T12:47:28.6938623Z   warnings.warn(
2024-09-04T12:47:28.6938859Z 
2024-09-04T12:47:28.6939275Z [2024-09-04 12:46:12,270: INFO/MainProcess] Found credentials in environment variables.
2024-09-04T12:47:28.6940133Z [2024-09-04 12:46:14,407: INFO/MainProcess] Connected to sqs://b09f0037a174:4566//
2024-09-04T12:47:28.6941612Z [2024-09-04 12:46:14,407: WARNING/MainProcess] /celery/celery/worker/consumer/consumer.py:508: CPendingDeprecationWarning: The broker_connection_retry configuration setting will no longer determine
2024-09-04T12:47:28.6942880Z whether broker connection retries are made during startup in Celery 6.0 and above.
2024-09-04T12:47:28.6943873Z If you wish to retain the existing behavior for retrying connections on startup,
2024-09-04T12:47:28.6944564Z you should set broker_connection_retry_on_startup to True.
2024-09-04T12:47:28.6945092Z   warnings.warn(
2024-09-04T12:47:28.6945326Z 
2024-09-04T12:47:28.6945787Z [2024-09-04 12:46:14,420: INFO/MainProcess] Found credentials in environment variables.
2024-09-04T12:47:28.6946620Z [2024-09-04 12:46:14,491: INFO/MainProcess] smoke_tests_worker@be6028dd6fb3 ready.
2024-09-04T12:47:28.6947644Z [2024-09-04 12:46:15,032: INFO/MainProcess] Task t.smoke.tasks.long_running_task[b7bc79db-cba2-408e-8c29-66239c1204e3] received
2024-09-04T12:47:28.6949042Z [2024-09-04 12:46:15,034: INFO/ForkPoolWorker-2] t.smoke.tasks.long_running_task[b7bc79db-cba2-408e-8c29-66239c1204e3]: Starting long running task
2024-09-04T12:47:28.6950378Z [2024-09-04 12:46:15,038: CRITICAL/MainProcess] Unrecoverable error: AttributeError("'LoggingProxy' object has no attribute 'fileno'")
2024-09-04T12:47:28.6951916Z Traceback (most recent call last):
2024-09-04T12:47:28.6952633Z   File "/celery/celery/worker/worker.py", line 203, in start
2024-09-04T12:47:28.6953180Z     self.blueprint.start(self)
2024-09-04T12:47:28.6953700Z   File "/celery/celery/bootsteps.py", line 116, in start
2024-09-04T12:47:28.6954257Z     step.start(parent)
2024-09-04T12:47:28.6954794Z   File "/celery/celery/bootsteps.py", line 365, in start
2024-09-04T12:47:28.6955339Z     return self.obj.start()
2024-09-04T12:47:28.6955675Z            ^^^^^^^^^^^^^^^^
2024-09-04T12:47:28.6956225Z   File "/celery/celery/worker/consumer/consumer.py", line 340, in start
2024-09-04T12:47:28.6956852Z     blueprint.start(self)
2024-09-04T12:47:28.6957322Z   File "/celery/celery/bootsteps.py", line 116, in start
2024-09-04T12:47:28.6957822Z     step.start(parent)
2024-09-04T12:47:28.6958404Z   File "/celery/celery/worker/consumer/consumer.py", line 758, in start
2024-09-04T12:47:28.6958982Z     c.loop(*c.loop_args())
2024-09-04T12:47:28.6959437Z   File "/celery/celery/worker/loops.py", line 97, in asynloop
2024-09-04T12:47:28.6959997Z     next(loop)
2024-09-04T12:47:28.6960821Z   File "/usr/local/lib/python3.11/site-packages/kombu/asynchronous/hub.py", line 317, in create_loop
2024-09-04T12:47:28.6961527Z     events = poll(poll_timeout)
2024-09-04T12:47:28.6961975Z              ^^^^^^^^^^^^^^^^^^
2024-09-04T12:47:28.6962674Z   File "/usr/local/lib/python3.11/site-packages/kombu/utils/eventio.py", line 83, in poll
2024-09-04T12:47:28.6963540Z     return self._epoll.poll(timeout if timeout is not None else -1)
2024-09-04T12:47:28.6964099Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-09-04T12:47:28.6964906Z   File "/celery/celery/apps/worker.py", line 303, in _handle_request
2024-09-04T12:47:28.6965702Z     safe_say(f'worker: {how} shutdown (MainProcess)', sys.stdout)
2024-09-04T12:47:28.6966363Z   File "/celery/celery/apps/worker.py", line 83, in safe_say
2024-09-04T12:47:28.6966969Z     os.write(fd.fileno(), f'\n{msg}\n'.encode())
2024-09-04T12:47:28.6967537Z              ^^^^^^^^^
2024-09-04T12:47:28.6968093Z AttributeError: 'LoggingProxy' object has no attribute 'fileno'
2024-09-04T12:47:28.6969106Z [2024-09-04 12:46:15,049: ERROR/MainProcess] Error on stopping Pool: AttributeError("'LoggingProxy' object has no attribute 'fileno'")
2024-09-04T12:47:28.6970003Z Traceback (most recent call last):
2024-09-04T12:47:28.6970529Z   File "/celery/celery/worker/worker.py", line 203, in start
2024-09-04T12:47:28.6971117Z     self.blueprint.start(self)
2024-09-04T12:47:28.6971671Z   File "/celery/celery/bootsteps.py", line 116, in start
2024-09-04T12:47:28.6972124Z     step.start(parent)
2024-09-04T12:47:28.6972600Z   File "/celery/celery/bootsteps.py", line 365, in start
2024-09-04T12:47:28.6973164Z     return self.obj.start()
2024-09-04T12:47:28.6973529Z            ^^^^^^^^^^^^^^^^
2024-09-04T12:47:28.6974137Z   File "/celery/celery/worker/consumer/consumer.py", line 340, in start
2024-09-04T12:47:28.6974940Z     blueprint.start(self)
2024-09-04T12:47:28.6975425Z   File "/celery/celery/bootsteps.py", line 116, in start
2024-09-04T12:47:28.6976005Z     step.start(parent)
2024-09-04T12:47:28.6976537Z   File "/celery/celery/worker/consumer/consumer.py", line 758, in start
2024-09-04T12:47:28.6977099Z     c.loop(*c.loop_args())
2024-09-04T12:47:28.6977647Z   File "/celery/celery/worker/loops.py", line 97, in asynloop
2024-09-04T12:47:28.6978159Z     next(loop)
2024-09-04T12:47:28.6978882Z   File "/usr/local/lib/python3.11/site-packages/kombu/asynchronous/hub.py", line 317, in create_loop
2024-09-04T12:47:28.6979682Z     events = poll(poll_timeout)
2024-09-04T12:47:28.6980029Z              ^^^^^^^^^^^^^^^^^^
2024-09-04T12:47:28.6980789Z   File "/usr/local/lib/python3.11/site-packages/kombu/utils/eventio.py", line 83, in poll
2024-09-04T12:47:28.6981679Z     return self._epoll.poll(timeout if timeout is not None else -1)
2024-09-04T12:47:28.6982248Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-09-04T12:47:28.6982922Z   File "/celery/celery/apps/worker.py", line 303, in _handle_request
2024-09-04T12:47:28.6983639Z     safe_say(f'worker: {how} shutdown (MainProcess)', sys.stdout)
2024-09-04T12:47:28.6984266Z   File "/celery/celery/apps/worker.py", line 83, in safe_say
2024-09-04T12:47:28.6984880Z     os.write(fd.fileno(), f'\n{msg}\n'.encode())
2024-09-04T12:47:28.6985334Z              ^^^^^^^^^
2024-09-04T12:47:28.6985844Z AttributeError: 'LoggingProxy' object has no attribute 'fileno'
2024-09-04T12:47:28.6986214Z 
2024-09-04T12:47:28.6986587Z During handling of the above exception, another exception occurred:
2024-09-04T12:47:28.6986977Z 
2024-09-04T12:47:28.6987156Z Traceback (most recent call last):
2024-09-04T12:47:28.6987748Z   File "/celery/celery/bootsteps.py", line 148, in send_all
2024-09-04T12:47:28.6988290Z     fun(parent, *args)
2024-09-04T12:47:28.6988728Z   File "/celery/celery/bootsteps.py", line 369, in stop
2024-09-04T12:47:28.6989222Z     return self.obj.stop()
2024-09-04T12:47:28.6989647Z            ^^^^^^^^^^^^^^^
2024-09-04T12:47:28.6990118Z   File "/celery/celery/concurrency/base.py", line 121, in stop
2024-09-04T12:47:28.6990701Z     self.on_stop()
2024-09-04T12:47:28.6991334Z   File "/celery/celery/concurrency/prefork.py", line 143, in on_stop
2024-09-04T12:47:28.6992040Z     self._pool.join()
2024-09-04T12:47:28.6992849Z   File "/usr/local/lib/python3.11/site-packages/billiard/pool.py", line 1619, in join
2024-09-04T12:47:28.6993525Z     stop_if_not_current(self._result_handler)
2024-09-04T12:47:28.6994425Z   File "/usr/local/lib/python3.11/site-packages/billiard/pool.py", line 144, in stop_if_not_current
2024-09-04T12:47:28.6995179Z     thread.stop(timeout)
2024-09-04T12:47:28.6996016Z   File "/usr/local/lib/python3.11/site-packages/billiard/pool.py", line 525, in stop
2024-09-04T12:47:28.6996644Z     self.on_stop_not_started()
2024-09-04T12:47:28.6997294Z   File "/celery/celery/concurrency/asynpool.py", line 360, in on_stop_not_started
2024-09-04T12:47:28.6997941Z     iterate_file_descriptors_safely(
2024-09-04T12:47:28.6998628Z   File "/celery/celery/concurrency/asynpool.py", line 215, in iterate_file_descriptors_safely
2024-09-04T12:47:28.6999374Z     hub_method(fd, *hub_args, **hub_kwargs)
2024-09-04T12:47:28.7000014Z   File "/celery/celery/concurrency/asynpool.py", line 390, in _flush_outqueue
2024-09-04T12:47:28.7000649Z     sleep(0.5)
2024-09-04T12:47:28.7001155Z   File "/celery/celery/apps/worker.py", line 303, in _handle_request
2024-09-04T12:47:28.7001893Z     safe_say(f'worker: {how} shutdown (MainProcess)', sys.stdout)
2024-09-04T12:47:28.7002583Z   File "/celery/celery/apps/worker.py", line 83, in safe_say
2024-09-04T12:47:28.7003189Z     os.write(fd.fileno(), f'\n{msg}\n'.encode())
2024-09-04T12:47:28.7003634Z              ^^^^^^^^^
2024-09-04T12:47:28.7004211Z AttributeError: 'LoggingProxy' object has no attribute ‘fileno'

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants