See bug 8258 for a more general description of this bug. Sometimes, log messages coming from asyncio ignores our logging format and settings, for example, this line could be seen in vsmserver.log: > Executing <Handle ServerProtocol._callback_done(<Future finis...server.py:309>) created at /opt/thinlinc/modules/thinlinc/vsm/vsmserver.py:391> took 50.051 seconds Ideally, we want these messages to follow the format and settings used by ThinLinc's logging. Some of these log messages are only displayed when running a developer build, while others are displayed regardless.
> EXTRA: > * Use the default exception handler in asyncio with correct formatting instead of our own The default exception handler seems to log everything as a single string with multiple internal newlines, which means the output won't contain the correct format for each line printed to the log. We'll have to keep our custom exception handler for now.
(In reply to Adam Halim from comment #1) > > EXTRA: > > * Use the default exception handler in asyncio with correct formatting instead of our own > The default exception handler seems to log everything as a single string > with multiple internal newlines, which means the output won't contain the > correct format for each line printed to the log. We'll have to keep our > custom exception handler for now. After further investigation, it seems possible to rely on the internal exception handler after all. As long as the log message is split into multiple lines correctly before being passed to the logger, the output will have the correct format. However, as our custom exception handler currently adds some lines separating tracebacks, I think it's worth keeping as the output looks better in my opinion.
I came up with two possible solutions to this problem: 1. We can make the handlers created in our Logger's constructor public members of the class. With the handlers saved, we can expose a method that takes a package as an argument and adds the saved handlers to the package's logger. This way, the output from the package's logger is similar to the format used by our Logger. However, the logs will contain the package's name in the output instead of vsmserver/vsmagent. 2. The second approach is creating our own logging.Handler and passing the mainloggername to its constructor. In the emit() method, we format the message and just pass it to the _LoggerWrapper, mimicking the behaviour of our Logger. Doing it this way, we can make any package's logger go through our Logger whenever it wants to log, which ensures it has the correct format and the correct name. A bonus with this approach is that we could ditch our custom exception handler and rely on asyncio's default one (which I don't think we should, see comment #2). I think the second approach is more suitable. It seems more robust and we get the correct name in the output. By default, loggers are initialized with the level WARNING. In our configs, it is possible to change the logging level for our loggers/subloggers. We could make stdlib packages respect these settings as well (asyncio in this case). But the question is whether we want to handle non-ThinLinc logger levels from our configs? I am not convinced that it is worth the effort, and the level WARNING seems like a sane default.
This should now be fixed. Tested by adding a sleep in check_tcp_port_open() which previously printed the following in the log (in dev mode): > Executing <TimerHandle when=181941.687186774 ReqSessionHandler._wait_on_vnc_port() created at /opt/thinlinc/modules/thinlinc/vsm/handler_reqsession.py:377> took 0.201 seconds Now, the logging message goes through our logging system and gets the correct format: > 2023-11-29 15:46:40 WARNING vsmagent: Executing <TimerHandle when=181865.840520665 ReqSessionHandler._wait_on_vnc_port() created at /opt/thinlinc/modules/thinlinc/vsm/handler_reqsession.py:377> took 0.201 seconds > MUST: > * asyncio log messages follow the logging format used in ThinLinc ✅ > > SHOULD: > * asyncio log messages respect ThinLinc's logging settings ✅ > > EXTRA: > * Use the default exception handler in asyncio with correct formatting instead of our own ❌ All acceptance criteria, except for the last one, are met. See comment #2 for more details. Our config files' debug levels do not affect the log level used by asyncio's logger. This is an active decision, we don't want our used to be concerned about internal details of asyncio. The purpose of debug levels for users is to debug ThinLinc, not the standard library (asyncio is very verbose when using DEBUG log level).
I can verify that log messages from asyncio are now properly formatted. After creating ~50 sessions on an agent, the housekeeping() process started taking a bit of time, and started logging warnings: vsmagent.log (build 3421) Fedora 39: > Executing <TimerHandle when=1472357.916589227 VSMAgent.housekeeping() created at /opt/thinlinc/modules/thinlinc/vsm/vsmagent.py:136> took 0.100 seconds vsmagent.log (build 3434) Fedora 39: > 2023-12-04 14:16:27 WARNING vsmagent: Executing <Handle VSMAgent.housekeeping() created at /opt/thinlinc/modules/thinlinc/vsm/vsmagent.py:124> took 0.118 seconds I can also verify that changing the log level to DEBUG in both vsmserver and vsmagent doesn't affect the logging from asyncio. Lastly, I reviewed the commits and they look good.
