[issue38674] RotatingFileHandler issue: logs in the file are printed in incorrect order.

[Vinay Sajip]

Vinay Sajip  added the comment:

You're doing it wrong. I inserted a print statement just before the 
RotatingFileHandler for email.log is created. Here's what was printed:

Creating RFH email.log
Creating RFH email.log
Creating RFH email.log
Creating RFH email.log
Creating RFH email.log

In the above, RFH is short for RotatingFileHandler. You're creating five 
handlers for the same file. Because you are doing this, things won't work as 
expected - you're not supposed to have multiple handlers pointing to the same 
file. They will trample over each other and the resulting behaviour will be 
ill-defined.

In future, I suggest you post your problem on Stack Overflow, python-list or 
some similar forum to establish whether there is really a Python bug or whether 
it's a problem in your own code. Posting a new issue when there isn't actually 
one wastes volunteer time that could be better spent on actual bugs - time 
spent on triaging, investigating and updating the issue.

--
resolution:  -> not a bug
stage:  -> resolved
status: open -> closed

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue38674] RotatingFileHandler issue: logs in the file are printed in incorrect order.

[Akshay Indalkar]

New submission from Akshay Indalkar :

I am using RotatingFileHandler library for saving the logs in the email.log 
file. Issue is logs are not saved in the correct order in the log file.

For Example: The latest logs are always needs to be saved in 
email.log file, then email.log.1, then email.log.2 and so on 

Correct Order:
email.log.3  > older than email.log.2
email.log.2  > older than email.log.1
email.log.1  > older than email.log
email.log> Latest logs always saved here

But now the logs are randomly saved in the log file like
email.log.2  
email.log.1  
email.log  
email.log.3

or
email.log.2  
email.log.3  
email.log.1  
email.log

Log are been saved randomly in incorrect order.

I have attached the evidence image also instructions to replicate.

To give you jist:
Using linux environment.
Basically I am just logging into the file every 5 seconds, and printing the 
files which are modified in the order.

To replicate ,just run 
python abc.py

--
components: Library (Lib)
files: RotatingFIleHandler.zip
messages: 355905
nosy: akshay_indalkar, vinay.sajip
priority: normal
severity: normal
status: open
title: RotatingFileHandler issue: logs in the file are printed in incorrect 
order.
versions: Python 2.7, Python 3.6
Added file: https://bugs.python.org/file48691/RotatingFIleHandler.zip

___
Python tracker 
<https://bugs.python.org/issue38674>
___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue17407] RotatingFileHandler issue when using multiple loggers instances (but one process/thread) to the same file

[Vinay Sajip]

Vinay Sajip added the comment:

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


$ cat dummy-2320.log.1
Rolled over - a



$ cat dummy-2320.log.2




Rolling over - a

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.

--
resolution:  - invalid
status: open - closed

___
Python tracker rep...@bugs.python.org
http://bugs.python.org/issue17407
___
___
Python-bugs-list mailing list
Unsubscribe: 
http://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue17407] RotatingFileHandler issue when using multiple loggers instances (but one process/thread) to the same file

[Vinay Sajip]

Vinay Sajip added the comment:

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.

--

___
Python tracker rep...@bugs.python.org
http://bugs.python.org/issue17407
___
___
Python-bugs-list mailing list
Unsubscribe: 
http://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue17407] RotatingFileHandler issue when using multiple loggers instances (but one process/thread) to the same file

[James Kesser]

James Kesser added the comment:

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.

--

___
Python tracker rep...@bugs.python.org
http://bugs.python.org/issue17407
___
___
Python-bugs-list mailing list
Unsubscribe: 
http://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue17407] RotatingFileHandler issue when using multiple loggers instances (but one process/thread) to the same file

[James Kesser]

James Kesser added the comment:

Thanks for quick response!

--

___
Python tracker rep...@bugs.python.org
http://bugs.python.org/issue17407
___
___
Python-bugs-list mailing list
Unsubscribe: 
http://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue17407] RotatingFileHandler issue when using multiple loggers instances (but one process/thread) to the same file

[Vinay Sajip]

Vinay Sajip added the comment:

 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.

--

___
Python tracker rep...@bugs.python.org
http://bugs.python.org/issue17407
___
___
Python-bugs-list mailing list
Unsubscribe: 
http://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue17407] RotatingFileHandler issue when using multiple loggers instances (but one process/thread) to the same file

[James Kesser]

New submission from James Kesser:

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.

--
components: Library (Lib)
files: rotating_file_handler_test.tar
messages: 184061
nosy: James.Kesser
priority: normal
severity: normal
status: open
title: RotatingFileHandler issue when using multiple loggers instances (but one 
process/thread) to the same file
versions: Python 2.6, Python 2.7, Python 3.1, Python 3.2, Python 3.3
Added file: http://bugs.python.org/file29393/rotating_file_handler_test.tar

___
Python tracker rep...@bugs.python.org
http://bugs.python.org/issue17407
___
___
Python-bugs-list mailing list
Unsubscribe: 
http://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue17407] RotatingFileHandler issue when using multiple loggers instances (but one process/thread) to the same file

[Ned Deily]

Changes by Ned Deily n...@acm.org:


--
nosy: +vinay.sajip

___
Python tracker rep...@bugs.python.org
http://bugs.python.org/issue17407
___
___
Python-bugs-list mailing list
Unsubscribe: 
http://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

Re: RotatingFileHandler issue

[Max Lynch]

I never got a response back from this, but I'm noticing even more odd
behavior, see inline:

On Wed, Sep 30, 2009 at 4:38 PM, Max Lynch ihas...@gmail.com wrote:

 Hi.
 I have a RotatingFileHandler for my logging system.  I have it set to
 rotate once the file becomes 5MB in size.  Here is the conf line I have in
 my logging config file:

 [handler_fileHandlerDebugNoRequest]
 class=handlers.RotatingFileHandler
 formatter=formatterNoRequest
 args=('/web/logs/gobuzz_debug.log', 'a', 5242880, 8)

 However, my logging folder contains these files:
 -rw-r--r-- 1 www-data www-data 566K Sep 30 16:35 gobuzz_debug.log
 -rw-r--r-- 1 www-data www-data 4.2M Sep 30 16:35 gobuzz_debug.log.1
 -rw-r--r-- 1 www-data www-data 572K Sep 30 16:36 gobuzz_debug.log.2
 -rw-r--r-- 1 www-data www-data 558K Sep 30 16:35 gobuzz_debug.log.3
 -rw-r--r-- 1 www-data www-data 3.7K Sep 29 20:52 gobuzz_debug.log.4
 -rw-r--r-- 1 www-data www-data 3.7K Sep 29 20:52 gobuzz_debug.log.5
 -rw-r--r-- 1 www-data www-data 566K Sep 30 16:36 gobuzz_debug.log.6
 -rw-r--r-- 1 www-data www-data 1.6M Sep 30 16:36 gobuzz_debug.log.7
 -rw-r--r-- 1 www-data www-data  45K Sep 29 20:50 gobuzz_debug.log.8
 -rwxrwxrwx 1 www-data www-data 691K Sep 28 09:39 gobuzz_error.log

 Clearly, the files are rotating far before they hit 5MB.  The consequence
 of such being that I'm losing a lot of log data.  What gives?  Am I doing
 something wrong?


For some reason, my Apache2/mod_wsgi/django system is writing to all of the
separate rotated files at once.  I can't detect a pattern, but some times,
for example, logging data goes into gobuzz_debug.log.8 and some times they
go into gobuzz_debug.log.5, rather than only going to gobuzz_debug.log and
rotating after 5MB.

Does anyone have any ideas? Here are my formatter sections if it matters:
[formatter_formatterNoRequest]
format=%(asctime)s - %(mymodule)s:%(mylineno)d - %(levelname)s - %(message)s
datefmt=%a, %d %b %Y %I:%M:%S %p




 Thanks,
 Max




-- 
http://mail.python.org/mailman/listinfo/python-list

RotatingFileHandler issue

[Max Lynch]

Hi.
I have a RotatingFileHandler for my logging system.  I have it set to rotate
once the file becomes 5MB in size.  Here is the conf line I have in my
logging config file:

[handler_fileHandlerDebugNoRequest]
class=handlers.RotatingFileHandler
formatter=formatterNoRequest
args=('/web/logs/gobuzz_debug.log', 'a', 5242880, 8)

However, my logging folder contains these files:
-rw-r--r-- 1 www-data www-data 566K Sep 30 16:35 gobuzz_debug.log
-rw-r--r-- 1 www-data www-data 4.2M Sep 30 16:35 gobuzz_debug.log.1
-rw-r--r-- 1 www-data www-data 572K Sep 30 16:36 gobuzz_debug.log.2
-rw-r--r-- 1 www-data www-data 558K Sep 30 16:35 gobuzz_debug.log.3
-rw-r--r-- 1 www-data www-data 3.7K Sep 29 20:52 gobuzz_debug.log.4
-rw-r--r-- 1 www-data www-data 3.7K Sep 29 20:52 gobuzz_debug.log.5
-rw-r--r-- 1 www-data www-data 566K Sep 30 16:36 gobuzz_debug.log.6
-rw-r--r-- 1 www-data www-data 1.6M Sep 30 16:36 gobuzz_debug.log.7
-rw-r--r-- 1 www-data www-data  45K Sep 29 20:50 gobuzz_debug.log.8
-rwxrwxrwx 1 www-data www-data 691K Sep 28 09:39 gobuzz_error.log

Clearly, the files are rotating far before they hit 5MB.  The consequence of
such being that I'm losing a lot of log data.  What gives?  Am I doing
something wrong?

Thanks,
Max
-- 
http://mail.python.org/mailman/listinfo/python-list