python logging thread safety

Viewed 1064

I'm trying to understand how exactly python logging is thread safe in the folowing cases: 1. I create different handlers for the same file in the main thread. and then ask a thread to log to it. 2. I create multiple handlers pointing to the same file, from within different threads.

I see in the source code of FileHandler that every Handler created has its own lock, but how does this work in the cases I have mentioned? if I understand it correctly, the lock's scopes is the FileHandler object, meaning that if I create 2 different handlers they don't share the lock, and they might run into a race condition.

So my question is: how is this threadsafe?

here is the relevant code. please note that the FileHandler Class inherits StreamHandler which in turn inherits Handler.


class StreamHandler(Handler):
    """
    A handler class which writes logging records, appropriately formatted,
    to a stream. Note that this class does not close the stream, as
    sys.stdout or sys.stderr may be used.
    """

    terminator = '\n'

    def __init__(self, stream=None):
        """
        Initialize the handler.

        If stream is not specified, sys.stderr is used.
        """
        Handler.__init__(self)
        if stream is None:
            stream = sys.stderr
        self.stream = stream

    def flush(self):
        """
        Flushes the stream.
        """
        self.acquire()
        try:
            if self.stream and hasattr(self.stream, "flush"):
                self.stream.flush()
        finally:
            self.release()

    def emit(self, record):
        """
        Emit a record.

        If a formatter is specified, it is used to format the record.
        The record is then written to the stream with a trailing newline.  If
        exception information is present, it is formatted using
        traceback.print_exception and appended to the stream.  If the stream
        has an 'encoding' attribute, it is used to determine how to do the
        output to the stream.
        """
        try:
            msg = self.format(record)
            stream = self.stream
            stream.write(msg)
            stream.write(self.terminator)
            self.flush()
        except Exception:
            self.handleError(record)

    def __repr__(self):
        level = getLevelName(self.level)
        name = getattr(self.stream, 'name', '')
        if name:
            name += ' '
        return '<%s %s(%s)>' % (self.__class__.__name__, name, level)


class FileHandler(StreamHandler):
    """
    A handler class which writes formatted logging records to disk files.
    """
    def __init__(self, filename, mode='a', encoding=None, delay=False):
        """
        Open the specified file and use it as the stream for logging.
        """
        # Issue #27493: add support for Path objects to be passed in
        filename = os.fspath(filename)
        #keep the absolute path, otherwise derived classes which use this
        #may come a cropper when the current directory changes
        self.baseFilename = os.path.abspath(filename)
        self.mode = mode
        self.encoding = encoding
        self.delay = delay
        if delay:
            #We don't open the stream, but we still need to call the
            #Handler constructor to set level, formatter, lock etc.
            Handler.__init__(self)
            self.stream = None
        else:
            StreamHandler.__init__(self, self._open())

    def close(self):
        """
        Closes the stream.
        """
        self.acquire()
        try:
            try:
                if self.stream:
                    try:
                        self.flush()
                    finally:
                        stream = self.stream
                        self.stream = None
                        if hasattr(stream, "close"):
                            stream.close()
            finally:
                # Issue #19523: call unconditionally to
                # prevent a handler leak when delay is set
                StreamHandler.close(self)
        finally:
            self.release()

    def _open(self):
        """
        Open the current base file with the (original) mode and encoding.
        Return the resulting stream.
        """
        return open(self.baseFilename, self.mode, encoding=self.encoding)

    def emit(self, record):
        """
        Emit a record.

        If the stream was not opened because 'delay' was specified in the
        constructor, open it before calling the superclass's emit.
        """
        if self.stream is None:
            self.stream = self._open()
        StreamHandler.emit(self, record)

    def __repr__(self):
        level = getLevelName(self.level)
        return '<%s %s (%s)>' % (self.__class__.__name__, self.baseFilename, level)

3 Answers

That is a good question that required a bit of reverse engineering.

The simple answer: FileHandler is not thread-safe in this case itself, but one does not create it using constructor. A factory methods are used instead, and they make sure things are thread-safe:

# see here: https://github.com/python/cpython/blob/586be6f3ff68ab4034e555f1434a4427e129ad0b/Lib/logging/__init__.py#L1985
 if handlers is None:
                filename = kwargs.pop("filename", None)
                mode = kwargs.pop("filemode", 'a')
                if filename:
                    if 'b'in mode:
                        errors = None
                    h = FileHandler(filename, mode,
                                    encoding=encoding, errors=errors)
                else:
                    stream = kwargs.pop("stream", None)
                    h = StreamHandler(stream)
                handlers = [h]

and:

# https://github.com/python/cpython/blob/586be6f3ff68ab4034e555f1434a4427e129ad0b/Lib/logging/__init__.py#L1272
    def getLogger(self, name):
        """
        Get a logger with the specified name (channel name), creating it
        if it doesn't yet exist. This name is a dot-separated hierarchical
        name, such as "a", "a.b", "a.b.c" or similar.
        If a PlaceHolder existed for the specified name [i.e. the logger
        didn't exist but a child of it did], replace it with the created
        logger and fix up the parent/child references which pointed to the
        placeholder to now point to the logger.
        """
        rv = None
        if not isinstance(name, str):
            raise TypeError('A logger name must be a string')
        _acquireLock()
        try:
            if name in self.loggerDict:
                rv = self.loggerDict[name]
                if isinstance(rv, PlaceHolder):
                    ph = rv
                    rv = (self.loggerClass or _loggerClass)(name)
                    rv.manager = self
                    self.loggerDict[name] = rv
                    self._fixupChildren(ph, rv)
                    self._fixupParents(rv)
            else:
                rv = (self.loggerClass or _loggerClass)(name)
                rv.manager = self
                self.loggerDict[name] = rv
                self._fixupParents(rv)
        finally:
            _releaseLock()
        return rv

Please pay attention to two things happening here:
1) lock is acquired before new Handler is created
2) If logger for a name is already created - it is returned. So, for the same file, one should get only one FileHandler instance.

I have already implemented logging which is thread safe. The goal was to collect tweets with different tags in parallel using threading.

Here is my implementation of logging:

import sys
import logging
import threading


class Singleton:
    __lock = threading.Lock()
    __instance = None

    def __init__(self):
        if self.__class__.__instance:
            raise Exception('Tried to allocate a second instance of a singleton.\nUse getInstance() instead.')
            sys.exit(-1)

    @classmethod
    def get_instance(cls):
        if cls.__instance is None:
            with cls.__lock:
                if cls.__instance is None:
                    cls.__instance = cls()
        return cls.__instance


class Logger(Singleton):
    __FORMAT = '%(asctime)s - %(levelname)s - [%(threadName)s] - %(message)s'

    def __init__(self, name: str = __name__):
        super().__init__()

        logger = logging.getLogger(name)
        logger.setLevel(logging.DEBUG)

        log_formatter = logging.Formatter(self.__class__.__FORMAT)

        console_handler = logging.StreamHandler(sys.stdout)
        console_handler.setFormatter(log_formatter)
        console_handler.setLevel(logging.DEBUG)

        file_handler = logging.FileHandler('log.log')
        file_handler.setFormatter(log_formatter)
        file_handler.setLevel(logging.INFO)

        if logger.handlers:
            logger.handlers = []


        logger.addHandler(file_handler)
        logger.addHandler(console_handler)

        self.__logger = logger

        self.__class__.__instance = self

    @property
    def logger(self):
        return self.__logger

    def debug(self, message: str):
        self.__logger.debug(message)

    def info(self, message: str):
        self.__logger.info(message)

    def warn(self, message: str):
        self.__logger.warning(message)

    def error(self, message: str):
        self.__logger.error(message)

    def critical(self, message: str):
        self.__logger.critical(message)

    def exception(self, message: str):
        self.__logger.exception(message)

Then in your threads, you just have to call get_instance method of Logger class.

Logger.get_instance().info(f'Your log here')

I hope this will help you!

So in other words, in both cases you get handlers which can end up opening the file at the same time, and writing to it at the same time.

This means it is not "safe" in the sense that messages can be "mixed up" in the file (e.g. starting to write msg1, then starting to write msg2, then continue to write msg1).

Other than that, I don't see any other harm. Separate FileHandler instances don't interfere with each other.

So to summarize, the content of the log file might not be perfect, but nothing else really breaks.

Related