Details
-
Type:
Story
-
Status: Done
-
Resolution: Done
-
Fix Version/s: None
-
Component/s: ts_middleware
-
Labels:
-
Story Points:1
-
Epic Link:
-
Sprint:TSSW Sprint - Jan 16 - Jan 30
-
Team:Telescope and Site
-
Urgent?:No
Description
The SalLogHandler is issues a large number "coroutine not awaited" messages after running unit tests. We think this is because logging is synchronous but SalLogHandler writes asynchronously, so it has to create a coroutine for each message it emits, and the fact that it uses asyncio.run_coroutine_threadsafe to do this, so that logging can be done from background threads.
Try to fix this by keeping track of unfinished concurrent.futures.Futures returned by asyncio.run_coroutine_threadsafe and closing them in the close method of SalLogHandler.
Attachments
Activity
| Field | Original Value | New Value |
|---|---|---|
| Status | To Do [ 10001 ] | In Progress [ 3 ] |
| Reviewers | Wouter van Reeven [ wvreeven ] | |
| Status | In Progress [ 3 ] | In Review [ 10004 ] |
| Summary | SalLogHandler: eliminate "coroutine not awaited" messages at shutdown | SalLogHandler: reduce "coroutine not awaited" messages at shutdown |
| Description |
The SalLogHandler is prone to issuing "coroutine not awaited" messages at shutdown, because logging is synchronous but SalLogHandler writes asynchronously, so it has to create a coroutine for each message it emits.
Fix by keeping track of those coroutines (actually concurrent.futures.Future, so threads can also log to SAL) closing unfinished ones at the end. |
The SalLogHandler is issues a large number "coroutine not awaited" messages after running unit tests. We think this is because logging is synchronous but SalLogHandler writes asynchronously, so it has to create a coroutine for each message it emits, and the fact that it uses asyncio.run_coroutine_threadsafe to do this, so that logging can be done from background threads.
Try to fix this by keeping track of unfinished concurrent.futures.Futures returned by asyncio.run_coroutine_threadsafe and closing them in the {{close}} method of {{SalLogHandler}}. |
Reviewed on GitHub.
| Status | In Review [ 10004 ] | Reviewed [ 10101 ] |
Merged to develop. Since the change is not critical, and it is too late to get this code into the pending cycle build, I propose to hold off tagging until the next cycle build or we have additional changes.
| Resolution | Done [ 10000 ] | |
| Status | Reviewed [ 10101 ] | Done [ 10002 ] |
It turns out that cancelling concurrent.futures.Futures doesn't help – they are already done by the time "SalLogHandler.close" is called. This is as expected because SalLogHandler is created by Controller, which waits for some time at shutdown to give final SAL messages time to be sent. So the underlying problem is not due to these concurrent futures still running at shutdown.
What did help immensely is using asyncio tasks (instead of concurrent futures) to emit messages whenever SalLogHandler is called from the main thread. That avoids the warning messages. Logging is very rarely done from a thread, so this dramatically reduces the number of warnings. The new code also keeps track of unfinished tasks and cancels them in the close method, just in case, even though it should not be necessary in practice, as explained above.
For future reference: I filed https://stackoverflow.com/questions/75090778/making-a-logging-handler-with-async-emit and perhaps someday that will get a useful answer. It is also conceivable that it is a bug in Python causing the messages for messages emitted using asyncio.run_coroutine_threadsafe, in which case the problem may go away with a future version of Python. If I get a better solution I'll use a new ticket to apply it.
Pull request: https://github.com/lsst-ts/ts_salobj/pull/265