logging.config.dictConfig shuts down socket for existing SysLogHandlers

[flyte]

BPO	43196
Nosy	@vsajip, @jamadden, @sblondon, @tirkarthi, @iritkatriel, @flyte

^{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 = None
created_at = <Date 2021-02-10.20:45:36.729>
labels = ['type-bug', 'library', '3.9', '3.10']
title = 'logging.config.dictConfig shuts down socket for existing SysLogHandlers'
updated_at = <Date 2022-01-22.19:36:11.186>
user = 'https://github.com/flyte'

bugs.python.org fields:

activity = <Date 2022-01-22.19:36:11.186>
actor = 'iritkatriel'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Library (Lib)']
creation = <Date 2021-02-10.20:45:36.729>
creator = 'flyte'
dependencies = []
files = []
hgrepos = []
issue_num = 43196
keywords = []
message_count = 3.0
messages = ['386805', '410832', '411284']
nosy_count = 6.0
nosy_names = ['vinay.sajip', 'jmadden', 'sblondon', 'xtreak', 'iritkatriel', 'flyte']
pr_nums = []
priority = 'normal'
resolution = None
stage = None
status = 'open'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue43196'
versions = ['Python 3.9', 'Python 3.10']

[flyte]

Since b6c1989 dictConfig (and presumably fileConfig) has called logging.shutdown() on the existing handlers.

This causes existing SysLogHandlers' sockets to be closed, which then causes a BadFileDescriptor error when you try to use it:

--- Logging error ---

Traceback (most recent call last):
  File "/usr/lib/python3.8/logging/handlers.py", line 940, in emit
    self.socket.sendto(msg, self.address)
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "/home/flyte/workspaces/python/test.py", line 18, in <module>
    log.warning("Breaks")

Reproduce the error with the following code:

import logging.config
import socket
from logging.handlers import SysLogHandler

log = logging.getLogger("logtest")
syslog_handler = SysLogHandler(("127.0.0.1", 12345), socktype=socket.SOCK_DGRAM)
log.addHandler(syslog_handler)

log.warning("Works")

logging.config.dictConfig(
    {
        "version": 1,
        "disable_existing_loggers": False,
    }
)

log.warning("Breaks")

This causes issues such as benoitc/gunicorn#2073 where gunicorn sets up a SysLogHandler, then when any app (Django does it by default) calls dictConfig() it closes the socket used by gunicorn's SysLogHandler.

Assuming this also affects Python 3.9 and 3.10, but untested.

[iritkatriel]

I'm not getting this error on 3.11 on a Mac. Can you check on versions <= 3.9? Earlier versions are no longer getting bugfixes.

[sblondon]

I can reproduce the error on Debian/testing with:

• Python 3.9.9
• Python 3.10.0

[vsajip]

This was I believe fixed for 3.11 and later in the fix for #88457 by #26490, but I'm not sure it's worth backporting the whole thing to 3.10 (it seemed messy to do it at the time).

[MajorDallas]

Out of curiosity, what is messy about backporting this?

In figuring out that this was the problem, I touched logging.py quite a bit. I don't see any reason why the changes in #26490 couldn't be backported, at least not at the code level... Naturally, my perspective here is limited to my one application and not the entire CPython codebase and its millions of dependent projects, so if that's where the mess is then I understand. Again, just curious 😄

If anyone else ran into this issue, can't upgrade to 3.11 right away, and needs a workaround, I had success with copy/pasting the code out of the PR into a class definition that subclasses SysLogHandler with one small modification and it works fine so far. The only change in my subclass from what's in the PR is to the emit method:

class FixedSysLogHandler(SysLogHandler):
    ...
    def emit(self, record):
        if not self.socket:
            self.createSocket()
        super().emit(record)

The methods createSocket, close, and __init__ are verbatim copies of the PR and everything else is inherited from SysLogHandler. This has at least allowed it to work in iPython (which uses dictConfig and kills the socket on start-up) with 3.8.

[sahilsangani98]

Hey @MajorDallas

can you please explain your solution for Python 3.8 version. I have situation where I can't upgrade to Python 3.11.

Question:
(1) Do I need to copy FixedSysLogHandler and place it to logging.py only?
(2) If possible, can you share entire logging.py file to understand properly ?

Thank you!

[MajorDallas]

@sahilsangani98

I did not modify logging.py (other than for print-debugging while tracking down the problem).

Instead, in a utilities module in my app, I subclassed SysLogHandler and used that subclass as a drop-in replacement. As I said above, most of it is copied (almost) verbatim from Pull Request #26490, specifically the methods named above from the original SysLogHandler class definition that starts at handlers.py:709 in the PR.

YMMV. This worked with the SysLogHandler as defined for Python 3.8; it may or may not work with other versions in the same way and I can't offer any support for it if it doesn't work for you.

# Assume this file is 'app/utils/logging.py'
from logging.handlers import SysLogHandler as OgSysLogHandler

class SysLogHandler(OgSysLogHandler):

    def __init__(
        self,
        address=("localhost", 514),
        facility=OgSysLogHandler.LOG_USER,
        socktype=None,
    ):
        logging.Handler.__init__(self)
        self.address = address
        self.facility = facility
        self.socktype = socktype
        self.socket = None
        self.createSocket()

    def close(self):
        self.acquire()
        try:
            sock = self.socket
            if sock:
                self.socket = None
                sock.close()
            logging.Handler.close(self)
        finally:
            self.release()

    def createSocket(self):
        address = self.address
        socktype = self.socktype

        if isinstance(address, str):
            self.unixsocket = True
            # Syslog server may be unavailable during handler initialisation.
            # C's openlog() function also ignores connection errors.
            # Moreover, we ignore these errors while logging, so it not worse
            # to ignore it also here.
            try:
                self._connect_unixsocket(address)
            except OSError:
                pass
        else:
            self.unixsocket = False
            if socktype is None:
                socktype = socket.SOCK_DGRAM
            host, port = address
            ress = socket.getaddrinfo(host, port, 0, socktype)
            if not ress:
                raise OSError("getaddrinfo returns an empty list")
            for res in ress:
                af, socktype, proto, _, sa = res
                err = sock = None
                try:
                    sock = socket.socket(af, socktype, proto)
                    if socktype == socket.SOCK_STREAM:
                        sock.connect(sa)
                    break
                except OSError as exc:
                    err = exc
                    if sock is not None:
                        sock.close()
            if err is not None:
                raise err
            self.socket = sock
            self.socktype = socktype

    def emit(self, record):
        if not self.socket:
            self.createSocket()
        super().emit(record)

Then, anywhere in your app where you currently have from logging.handlers import SysLogHandler, just change that to from app.utils.logging import SysLogHandler (or whatever you make the module path on your machine). You shouldn't have to change any other code that's already trying to use SysLogHandler.

[sahilsangani98]

Thank you! @MajorDallas