Skip to content

Do not log in signal handler#6590

Merged
crusaderky merged 1 commit intodask:mainfrom
fjetter:maybe_fix_dashboard_port_zero
Jun 17, 2022
Merged

Do not log in signal handler#6590
crusaderky merged 1 commit intodask:mainfrom
fjetter:maybe_fix_dashboard_port_zero

Conversation

@fjetter
Copy link
Member

@fjetter fjetter commented Jun 16, 2022 •
edited
Loading

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

github-actions bot commented Jun 16, 2022

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

gjoseph92 commented Jun 17, 2022

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

@fjetter fjetter mentioned this pull request Jun 23, 2022
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@crusaderky crusaderky Awaiting requested review from crusaderky

@gjoseph92 gjoseph92 Awaiting requested review from gjoseph92

@graingert graingert Awaiting requested review from graingert

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

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

3 participants

@fjetter @gjoseph92 @crusaderky