classification
Title: RotatingFileHandler rotates empty logfile if it emits a large string
Type: resource usage Stage: resolved
Components: Library (Lib) Versions: Python 3.7, Python 2.7
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: Poddster, vinay.sajip
Priority: normal Keywords:

Created on 2017-01-25 16:03 by Poddster, last changed 2017-02-07 18:35 by vinay.sajip. This issue is now closed.

Messages (2)
msg286265 - (view) Author: Lee Griffiths (Poddster) Date: 2017-01-25 16:03
If you write a really big string to an empty file, and that string is > maxBytes, then `RotatingFileHandler` (or even `BaseRotatingHandler`) will roll that empty file into the backup queue.

I think it should instead use that empty file for the mega-string. By not doing so it "wastes" a slot in the backup queue.

It's a very minor issue: I doubt it really happens IRL, but I noticed it when extending RotatingFileHandler in py2.7 to add gzip stuff and my test cases used a really small size (16 bytes!)


Here's a test file:

    #!/usr/bin/env python3
    # coding=utf-8
    
    import logging
    import os
    import tempfile
    
    from logging.handlers import RotatingFileHandler
    
    
    class MockRecord(object):
        def __init__(self, msg):
            self.msg = msg
            self.stack_info = None
            self.exc_info = None
            self.exc_text = None
    
        def getMessage(self):
            return self.msg
    
    
    def test_file_rollover_from_mega_string(temp_dir_path):
        # This is a pretty weird test.
        # It tests that writing a huge string to a blank file causes the blank
        # file to be archived and the huge string written to the next log file.
        #
        # Normally the log files would have a large max bytes so we'd have to
        # be writing a giant string to an empty file for this to happen.
        # But, even if it does, it's what BaseRotatingHandler does, so...
    
        log_path = os.path.join(temp_dir_path, "mylog.log")
    
        handler = RotatingFileHandler(log_path, maxBytes=16, backupCount=5)
        handler.setFormatter(logging.Formatter())
        with open(log_path) as log:
            assert log.read() == ""
    
        # ----------------------------------------------
        handler.emit(MockRecord("There once was a test from bitbucket"))
        with open(log_path) as log:
            log_read = log.read()
            assert log_read == "There once was a test from bitbucket\n"
    
        with open(log_path + ".1") as log:
            log_read = log.read()
            assert log_read == ""
    
        # ----------------------------------------------
        handler.emit(MockRecord("11 chars"))
        with open(log_path) as log:
            log_read = log.read()
            assert log_read == "11 chars\n"
    
        with open(log_path + ".1") as log:
            log_read = log.read()
            assert log_read == "There once was a test from bitbucket\n"
    
        with open(log_path + ".2") as log:
            log_read = log.read()
            assert log_read == ""
    
        handler.close()
    
    
    test_file_rollover_from_mega_string(tempfile.mkdtemp())


and here's a patch that I think will fix it:

~/src/others/cpython (master *%=)$ cat empty_rollover.patch 
diff --git a/Lib/logging/handlers.py b/Lib/logging/handlers.py
index 7d77973..0dabfd7 100644
--- a/Lib/logging/handlers.py
+++ b/Lib/logging/handlers.py
@@ -186,7 +186,11 @@ class RotatingFileHandler(BaseRotatingHandler):
         if self.maxBytes > 0:                   # are we rolling over?
             msg = "%s\n" % self.format(record)
             self.stream.seek(0, 2)  #due to non-posix-compliant Windows feature
-            if self.stream.tell() + len(msg) >= self.maxBytes:
+            size = self.stream.tell()
+            if size == 0:
+                # No point rolling-over an empty file
+                return 0
+            elif size + len(msg) >= self.maxBytes:
                 return 1
         return 0
msg286272 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2017-01-25 19:00
I don't see the point - your proposed solution only works if the log file is completely empty at rollover time, but if the file contains a few bytes from an earlier "short" log message, it might seem just as wasteful of a backup slot as if it had zero bytes. I think the understanding is that maxBytes should be large compared to the size of an average log message, and that if that isn't the case, the user will live with the consequences because it's a contrived scenario (for tests, etc.) rather than a real-life one. There's always the option of subclassing if a user really does need bespoke rollover behaviour.
History
Date User Action Args
2017-02-07 18:35:03vinay.sajipsetstatus: open -> closed
resolution: not a bug
stage: resolved
2017-01-25 19:00:51vinay.sajipsetmessages: + msg286272
2017-01-25 16:03:44Poddstercreate