| msg184061 - (view) |
Author: James Kesser (James.Kesser) |
Date: 2013-03-12 23:57 |
| I believe I have come across a bug with RotatingFileHandler in logging/handlers.py The attached script shows that when you are logging using RotatingFileHandler pointed at the same file from multiple logger instances, it works at first showing logging events from each. However, after the first rotation occurs, the events seem to be "group" together and do not get logged in order. Instead they are logged in groups according to which instance is performing the logging. NOTE: While searching for a bug report of this issue I was flooded with issues relating to multiple processes. This is not the case here. I have attached a script and the log files that are generated when running this as a single process / thread. first log file contains: a aaa... b bbb... a aaa... b bbb... a aaa... b bbb... a aaa... b bbb... a aaa... subsequent log files contain events all from either a or b only, not intertwined like you would expect. I first noticed this using v2.4.3 of the logging library, however I was able to reproduce this on 2.7 and 3.3 as well. |
|
|
| msg184156 - (view) |
Author: Vinay Sajip (vinay.sajip) *  |
Date: 2013-03-14 10:23 |
| I don't believe this is logging-related - it relates to how you can rename open files on POSIX. Both loggers use the same file, until rollover - thereafter, they use different files, resulting in the behaviour you saw. To illustrate, run the following script on your system, which has no logging code: # rotest.py import os FN = 'dummy-%s.log' % os.getpid() print('Using %s' % FN) fa = open(FN, 'a') fb = open(FN, 'a') aline = 'a' * 40 + '\n' bline = 'b' * 40 + '\n' for i in range(5): if i == 2: # simulate rollover of a fa.write('Rolling over - a\n'); fa.flush() fa.close() os.rename(FN, FN + '.1') fa = open(FN, 'a') fa.write('Rolled over - a\n'); fa.flush() if i == 3: # simulate rollover of b fb.write('Rolling over - b\n'); fa.flush() fb.close() os.rename(FN + '.1', FN + '.2') os.rename(FN, FN + '.1') fb = open(FN, 'a') fb.write('Rolled over - b\n'); fa.flush() fa.write(aline); fa.flush() fb.write(bline); fb.flush() When run, I get the following results: $ python rotest.py Using dummy-2320.log $ cat dummy-2320.log Rolled over - b bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb $ cat dummy-2320.log.1 Rolled over - a aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa $ cat dummy-2320.log.2 aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb Rolling over - a bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb Rolling over - b As in your case, the oldest file contains both 'a' and 'b' lines, but after rollover, 'a' and 'b' lines are segregated. Note that the script (and your approach) won't work on Windows, because there you can't rename open files (one handler has the file open even when the other has closed it). Based on the above, I'm marking this issue as invalid. For obvious reasons, the approach you are using here is not recommended. |
|
|
| msg184157 - (view) |
Author: Vinay Sajip (vinay.sajip) * |
Date: 2013-03-14 10:25 |
| BTW in the example script I do fa.flush() a couple of times when I meant to do fb.flush() (in the i == 3 clause). The result is the same after correcting this. |
|
|
| msg184169 - (view) |
Author: James Kesser (James.Kesser) |
Date: 2013-03-14 15:46 |
| My approach was just as outlined in the first few paragraphs here, just naming loggers for each module using __name__: http://docs.python.org/2/howto/logging.html#logging-advanced-tutorial If this is not recommended the documentation should be updated to reflect this. In my project, I can work around this by having all modules use the same logger instance and just printing the module name in the Formatter instead of the logger name. |
|
|
| msg184170 - (view) |
Author: James Kesser (James.Kesser) |
Date: 2013-03-14 15:47 |
| Thanks for quick response! |
|
|
| msg184196 - (view) |
Author: Vinay Sajip (vinay.sajip) * |
Date: 2013-03-14 22:01 |
| > My approach was just as outlined in the first few paragraphs The not-recommended approach I'm referring to is that of having a two RotatingFileHandlers *with the same filename* attached to two loggers. It's perfectly OK to follow the recommendation of naming multiple loggers in multiple modules using __name__ - that doesn't lead to the problem you described in this issue. If you use different file names for the different handlers, that should be OK too. |
|
|