Uploaded image for project: 'Data Management'
  1. Data Management
  2. DM-37594

SalLogHandler: reduce "coroutine not awaited" messages at shutdown

    XMLWordPrintable

    Details

    • Story Points:
      1
    • 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

          Hide
          rowen Russell Owen added a comment - - edited

          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

          Show
          rowen Russell Owen added a comment - - edited 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
          Hide
          wvreeven Wouter van Reeven added a comment -

          Reviewed on GitHub.

          Show
          wvreeven Wouter van Reeven added a comment - Reviewed on GitHub.
          Hide
          rowen Russell Owen added a comment -

          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.

          Show
          rowen Russell Owen added a comment - 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.

            People

            Assignee:
            rowen Russell Owen
            Reporter:
            rowen Russell Owen
            Reviewers:
            Wouter van Reeven
            Watchers:
            Russell Owen, Wouter van Reeven
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved:

                Jenkins

                No builds found.