fix(utils): prevent duplicate log messages (#339) #366
Conversation
Acquire a lock in utils.configure_logging. Otherwise this function has a race where two threads can both call logger.remove(), and then both call logger.add(), creating two identical sinks.
configure_logging is already called at the module level so there's no need to call it with identical arguments in various functions.
|
Thanks for the contribution! One small thing: looks like the logger's colours are lost 🥲
vs main
|
|
Seems you are using me but didn't get OPENAI_API_KEY seted in Variables/Secrets for this repo. you could follow readme for more information |
|
Oops, I took the colors out for ease of grepping while I was debugging, and forgot to put them back. It's fixed now. I used a fixup commit -- let me know if I should squash that before merging. |
| @@ -134,7 +134,6 @@ def process_events( | |||
| terminate_event: An event to signal the termination of the process. | |||
| """ | |||
|
|
|||
| utils.configure_logging(logger, LOG_LEVEL) | |||
There was a problem hiding this comment.
Thanks @nweston !
Can you please clarify why it was necessary to remove these calls to utils.configure_logging?
There was a problem hiding this comment.
It's not strictly necessary -- adding the lock is sufficient to fix the bug. But these calls appear to be redundant (utils.configure_logging is already called at module level with the same arguments), and it's possible that there could be other race conditions, e.g. if one thread is outputting log messages while another is configuring. So removing them seemed like the safest option.
But if there's a reason to keep them, we can do that and the duplicate log messages will still be fixed.
|
Thanks @nweston ! Please grab some time on my calendar: https://www.getclockwise.com/c/richard-abrich/quick-meeting |
…ptAI#366) * fix(utils): prevent duplicate log messages (OpenAdaptAI#339) Acquire a lock in utils.configure_logging. Otherwise this function has a race where two threads can both call logger.remove(), and then both call logger.add(), creating two identical sinks. * refactor(record): remove redundant configure_logging calls configure_logging is already called at the module level so there's no need to call it with identical arguments in various functions. * fixup! fix(utils): prevent duplicate log messages (OpenAdaptAI#339)
What kind of change does this PR introduce?
Fixes a race condition in
utils.configure_loggingwhich leads to duplicate log messages.Summary
Fixes #339.
The duplicate messages are caused by multiple threads calling
configure_loggingconcurrently. This function had a race condition where two threads could both calllogger.remove()and then both calllogger.add(), creating two identical sinks.Adding a lock prevents this bug although I don't think it makes
configure_loggingentirely thread-safe. In particular, if thread A tries to log something after thread B has calledlogger.remove(), but before it callslogger.add(), the message might get dropped (though I haven't observed this in practice).I also removed some redundant
configure_loggingcalls inrecord.py. This isn't necessary to fix the bug, but it seemed like a worthwhile cleanup. It's in a separate commit so it can easily be dropped if not desired.Checklist
How can your code be run and tested?
python -m openadapt.record foowill reproduce the original issue and validate the fix.Other information
I saw your post on Hacker News and I might be interested in paid work on OpenAdapt. How can I learn more?