• You are preloading your application.. how does the code ensuring per-worker files look like? Called from gunicorn server hooks?
• Is the number assignment that lead you to the intermediary conclusion about where the bug happens itself thread-safe?
• Were you able to reproduce the effect without the ddtrace integration? (after injection, it will leave a note you can check with getattr(logging, "_datadog_patch", False))
• Do you have a smaller cherrypy application (maybe some part of your tests) that works with your logging config and hooks that you are able to share for reproduction attempts?
• Does inspecting your effective logging configuration produce anything unexpected?

About asking cherrypy to disable its own autoreloading and cleanup its "bus" on shutdown.. we should probably improve documentation, but I don't expect that to be related.

Apologies for the delayed response, I realize I posted the question at a bad time with a long weekend.

1 - This is the code from gunicorn.conf.py, setting env variables for each worker.

And here is the code within the structured logging file that handles consumption of the env variable, and creation of logger.

2 - I believe it is. The code above is being called once within the application initialization, so should be only called once per worker. Then any subsequent calls are logging to only a single file logger per worker so is thread safe within worker.

3 - Unfortunately, much of the assumption that lead us to believe that it is traffic-dependent is because no matter what sort of configuration we try we cannot replicate this issue in any other environment.

4 - I don't believe we do. I can try to get something together but at the moment we don't have much automated testing around this functionality, as for our dev and test environments we manually set the max threads and workers to 1.

5 - With logging tree, among a lot of other stuff that comes up, this is what comes up for this logger in particular.

We have a similar application that isn't experiencing this issue at all (experiences a tenth of the traffic though) and this is what the logging-tree looks like.

Obviously, the second application has propagate set to false, but this was because when implementing this in the second application every single log would be showing twice, so an entirely different issue to what we're experiencing with the first. I'm not exactly sure why we needed to set propagate to false in the second but not the first. There's clearly a chance that that has something to do with this, but given we can get more than 1 duplicate, and that it doesn't follow a similar 'every time' cadence this leads me to the feeling that it's not as related as I'd hope.

Thanks. I still believe the most obviously smoking gun is your mention of "up to the current max workers number of times". I do not understand those smoke signs; so for now, I keep asking:

1. Still exactly one relevant file handle (lsof does list dupes) in the offending worker processes?
2. Does the situation resolve to normal once the target file is manually renamed (consequently: reopened)?
3. Can you reproduce it without the Watched property of your FileHandlers?
4. Any observations timing-wise? e.g. error only triggered after overlapping reload of multiple workers. Feel free to share some larger log excerpt, maybe someone can spot some correlation between PID, logging ID and sequence of events.
5. What is the reasoning behind that w.alive check, any scenario where you need to recycle the logging ID before the worker is gone? (primarily asking because it might indicate you have spent time working around other problems, possibly overlapping open issues not yet properly diagnosed)

For reliable reproduction, you may need not just significant request counts (in relation to) configuration to trigger regular reloads, but also hanging requests, either by client decision or by processing/db bottleneck. Try firing a benchmarking tool and a manually issued "slow" request at the same (multi-processed) test instance.