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

Do not log in signal handler #6590

Merged
merged 1 commit into from
Jun 17, 2022

Conversation

fjetter
Copy link
Member

@fjetter fjetter commented Jun 16, 2022

I was working on our CLI tests to make them reliably use different ports and allow them to be run in parallel (#6591)

After succeeding, I ran test_dashboard_port_zero a hundred times in parallel and encountered this exception

--- Logging error ---
Traceback (most recent call last):
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/logging/__init__.py", line 1103, in emit
    stream.write(msg + self.terminator)
RuntimeError: reentrant call inside <_io.BufferedWriter name='<stderr>'>
Full traceback
--- Logging error ---
Traceback (most recent call last):
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/logging/__init__.py", line 1103, in emit
    stream.write(msg + self.terminator)
RuntimeError: reentrant call inside <_io.BufferedWriter name='<stderr>'>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/logging/__init__.py", line 1103, in emit
    stream.write(msg + self.terminator)
  File "/Users/fjetter/workspace/distributed/distributed/_signals.py", line 23, in handle_signal
    logger.info("Received signal %s (%d)", signal.Signals(signum).name, signum)
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/logging/__init__.py", line 1477, in info
    self._log(INFO, msg, args, **kwargs)
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/logging/__init__.py", line 1624, in _log
    self.handle(record)
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/logging/__init__.py", line 1634, in handle
    self.callHandlers(record)
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/logging/__init__.py", line 1696, in callHandlers
    hdlr.handle(record)
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/logging/__init__.py", line 968, in handle
    self.emit(record)
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/logging/__init__.py", line 1108, in emit
    self.handleError(record)
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/logging/__init__.py", line 1021, in handleError
    sys.stderr.write('--- Logging error ---\n')
RuntimeError: reentrant call inside <_io.BufferedWriter name='<stderr>'>
Call stack:
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/bin/dask-scheduler", line 33, in <module>
    sys.exit(load_entry_point('distributed', 'console_scripts', 'dask-scheduler')())
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/site-packages/click/core.py", line 1130, in __call__
    return self.main(*args, **kwargs)
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/site-packages/click/core.py", line 1055, in main
    rv = self.invoke(ctx)
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/site-packages/click/core.py", line 1404, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/site-packages/click/core.py", line 760, in invoke
    return __callback(*args, **kwargs)
  File "/Users/fjetter/workspace/distributed/distributed/cli/dask_scheduler.py", line 227, in main
    asyncio.run(run())
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/asyncio/base_events.py", line 633, in run_until_complete
    self.run_forever()
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/asyncio/base_events.py", line 600, in run_forever
    self._run_once()
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/asyncio/base_events.py", line 1896, in _run_once
    handle._run()
  File "/Users/fjetter/mambaforge/envs/dask-distributed-310/lib/python3.10/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/Users/fjetter/workspace/distributed/distributed/scheduler.py", line 4600, in add_client
    self.remove_client(client=client, stimulus_id=f"remove-client-{time()}")
  File "/Users/fjetter/workspace/distributed/distributed/scheduler.py", line 4618, in remove_client
    logger.info("Remove client %s", client)
Message: 'Remove client %s'
Arguments: ('Client-783447e2-ed98-11ec-af9f-4e7b98dead46',)
2022-06-16 19:19:27,073 - distributed.scheduler - INFO - Close client connection: Client-783447e2-ed98-11ec-af9f-4e7b98dead46

Indeed, after removing this log message, I was able to run the test concurrently many times without issues.

There is some explanation about this in https://stackoverflow.com/questions/45680378/how-to-explain-the-reentrant-runtimeerror-caused-by-printing-in-signal-handlers

Closes #6395 🤞

@fjetter fjetter changed the title Do not log during signal handler Do not log in signal handler Jun 16, 2022
@fjetter fjetter force-pushed the maybe_fix_dashboard_port_zero branch from 17e95c7 to c20294d Compare June 16, 2022 17:57
@github-actions
Copy link
Contributor

Unit Test Results

See test report for an extended history of previous test failures. This is useful for diagnosing flaky tests.

       14 files  +       14         14 suites  +14   5h 55m 16s ⏱️ + 5h 55m 16s
  2 878 tests +  2 878    2 794 ✔️ +  2 794    83 💤 +  83  1 +1 
20 120 runs  +20 120  19 213 ✔️ +19 213  906 💤 +906  1 +1 

For more details on these failures, see this check.

Results for commit c20294d. ± Comparison against base commit d7d52a4.

@crusaderky crusaderky merged commit 8d21040 into dask:main Jun 17, 2022
@gjoseph92
Copy link
Collaborator

I would imagine this should fix all the tests listed in #6483 (comment)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

distributed/cli/tests/test_dask_scheduler.py::test_dashboard_port_zero
3 participants