RotatingFileHandler rotates empty logfile if it emits a large string

[poddster]

BPO	29372
Nosy	@vsajip, @Poddster

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2017-02-07.18:35:03.311>
created_at = <Date 2017-01-25.16:03:44.347>
labels = ['invalid', '3.7', 'library', 'performance']
title = 'RotatingFileHandler rotates empty logfile if it emits a large string'
updated_at = <Date 2017-02-07.18:35:03.310>
user = 'https://github.com/Poddster'

bugs.python.org fields:

activity = <Date 2017-02-07.18:35:03.310>
actor = 'vinay.sajip'
assignee = 'none'
closed = True
closed_date = <Date 2017-02-07.18:35:03.311>
closer = 'vinay.sajip'
components = ['Library (Lib)']
creation = <Date 2017-01-25.16:03:44.347>
creator = 'Poddster'
dependencies = []
files = []
hgrepos = []
issue_num = 29372
keywords = []
message_count = 2.0
messages = ['286265', '286272']
nosy_count = 2.0
nosy_names = ['vinay.sajip', 'Poddster']
pr_nums = []
priority = 'normal'
resolution = 'not a bug'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'resource usage'
url = 'https://bugs.python.org/issue29372'
versions = ['Python 2.7', 'Python 3.7']

[poddster]

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

[vsajip]

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.