Why is Python logging framework losing messages?

Question

I have a Python 3.4 application that uses logging extensively. I have two FileHandlers and a StreamHandler registered. Everything works as expected except that sometimes, and it seems to happen after the requests library throws an exception, the log files lose all the accumulated messages and start with new messages. I'm assuming that for some reason the FileHandlers reopened the files with mode='w', but I don't understand why. Any ideas?

The main program sets up the loggers as follows:

# Set up root logger - two handlers logging to files
fh_debug = logging.FileHandler('Syncer.debug', mode='w', encoding='utf-8')
fh_debug.setLevel(logging.DEBUG)
fh_log = logging.FileHandler('Syncer.log', mode='w', encoding='utf-8')
fh_log.setLevel(logging.INFO)
fh_formatter = logging.Formatter(
    '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
)
fh_debug.setFormatter(fh_formatter)
fh_log.setFormatter(fh_formatter)
logging.getLogger().addHandler(fh_debug)
logging.getLogger().addHandler(fh_log)

# Add console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.INFO)
ch_formatter = logging.Formatter('%(message)s')
ch.setFormatter(ch_formatter)
logging.getLogger().addHandler(ch)

# Need to set the logging level of the logger as well as the handlers
logging.getLogger().setLevel(logging.DEBUG)

# Set up the logger for this module
logger = logging.getLogger("Syncer")

logger.debug('Logger started.')

The modules simply contain:

logger = logging.getLogger(__name__)

Does something happen in that exception handler like maybe importing the main file for some other purpose? You could keep a rolling set of files (Syncer.debug.0, Syncer.debug.1, etc...) so that you have more history. — tdelaney, Oct 03 '16 at 19:09
I haven't create an exception handler. A quick fix is to open the files with mode='a'. But it would be nice to understand what is happening. — Andrew McLean, Oct 03 '16 at 21:30

score 0 · Answer 1 · edited Apr 01 '22 at 17:08

0

Your issue is that you chose the wrong mode for your FileHandler.

The default mode of FileHandler is a which means appends new lines to the log file.

class logging.FileHandler(filename, mode='a', encoding=None, delay=False)

You modified the default mode to w which truncate file to zero length or create a new file for writing. That's why you lost all accumulated messages.

Change it to mode='a' or just delete mode='w' and then your logger will work.

Read the official python docs here

edited Apr 01 '22 at 17:08

vvvvv

25,404
19
49
81

answered Oct 03 '16 at 22:23

Haifeng Zhang

30,077
19
81
125

3

I was fully expecting the log files to be truncated when the application was started. What I didn't expect was that part way through a single run of the program the log file would "spontaneously" truncate. Any idea why that happens? – Andrew McLean Oct 03 '16 at 23:00

score 0 · Answer 2 · answered Nov 16 '20 at 19:29

This happens on an exception that would cause Python to exit, because the logging module gets (partially) shutdown, causing the log file to be closed, but then requests tries to log something, so the logger reopens the log file - unfortunately, truncating it.

From the source code:

class FileHandler(StreamHandler):
    # [...]

    def close(self):
         # [...]
         self.stream = None
         # [...]

    def _open(self):
        return open(self.baseFilename, self.mode, encoding=self.encoding,
                    errors=self.errors)

    def emit(self, record):
        if self.stream is None:
            self.stream = self._open()
        StreamHandler.emit(self, record)

I think the simplest workaround is to truncate the logfile on program start and tell logging to open the file in append mode:

open('Syncer.debug', mode='w').close() # truncate
fh_debug = logging.FileHandler('Syncer.debug', mode='a', encoding='utf-8')
fh_debug.setLevel(logging.DEBUG)
open('Syncer.log', mode='w').close() # truncate
fh_log = logging.FileHandler('Syncer.log', mode='a', encoding='utf-8')
fh_log.setLevel(logging.INFO)

score 0 · Answer 3 · edited Dec 18 '21 at 23:42

0

This issue was resolved as part of this commit which "fixed log truncation on logging shutdown".

edited Dec 18 '21 at 23:42

Henry Ecker

34,399
18
41
57

answered Nov 26 '21 at 02:59

Rainy

1,066
8
14

Why is Python logging framework losing messages?

3 Answers3