Regression in 1.18.1 causing logging.config.dictConfig to hang

[paltman]

After upgrading from 1.18.0, we noticed running our celery worker hanging and tracked it down to this:

from logging.config import dictConfig
from django.conf import settings
from celery.signals import setup_logging

@setup_logging.connect
def config_loggers(*args, **kwargs):
    dictConfig(settings.LOGGING)

Double-checking and removing celery from the picture, we could get a hang by just calling dictConfig from the shell.

Downgrading to 1.18.0 resolved the issue.

Breaking the manual hang in the shell results in this stack trace:

>>> dictConfig(settings.LOGGING)
^CTraceback (most recent call last):
  File "/app/.heroku/python/lib/python3.9/code.py", line 90, in runcode
    exec(code, self.locals)
  File "<console>", line 1, in <module>
  File "/app/.heroku/python/lib/python3.9/logging/config.py", line 809, in dictConfig
    dictConfigClass(config).configure()
  File "/app/.heroku/python/lib/python3.9/logging/config.py", line 537, in configure
    _clearExistingHandlers()
  File "/app/.heroku/python/lib/python3.9/logging/config.py", line 274, in _clearExistingHandlers
    logging.shutdown(logging._handlerList[:])
  File "/app/.heroku/python/lib/python3.9/logging/__init__.py", line 2142, in shutdown
    h.close()
  File "/app/.heroku/python/lib/python3.9/site-packages/logdna/logdna.py", line 265, in close
    self.request_thread_pool.shutdown(wait=True)
  File "/app/.heroku/python/lib/python3.9/concurrent/futures/thread.py", line 235, in shutdown
    t.join()
  File "/app/.heroku/python/lib/python3.9/threading.py", line 1053, in join
    self._wait_for_tstate_lock()
  File "/app/.heroku/python/lib/python3.9/threading.py", line 1073, in _wait_for_tstate_lock
    if lock.acquire(block, timeout):
KeyboardInterrupt

[ersinpw]

I am experiencing the same problem. I'm using uvicorn in combination with logdna and the shell command hangs when it reaches the dictConfig (see this method: https://github.com/encode/uvicorn/blob/master/uvicorn/config.py#L376). It works if I set log_dna to None, but that is not the right solution for me.

[0x962]

In addition to reverting to 1.18.0, I had to get rid of all logging.debug, and change my Django LOGGING config to match.

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "handlers": {
        "logdna": {
            "level": logging.INFO,
            "class": "logging.handlers.LogDNAHandler",
            "key": os.getenv("LOG_DNA_INGESTION_KEY"),
            "options": {
                "app": LOG_DNA_APP_NAME,
                "env": ENVIRONMENT,
                "index_meta": False,
                "verbose": True,
                "hostname": LOG_DNA_HOST_NAME,
            },
        },
        "console": {
            "level": logging.INFO,
            "class": "logging.StreamHandler",
        },
    },
    "loggers": {"django": {"handlers": ["logdna"], "level": logging.INFO}},
    "root": {"handlers": ["logdna", "console"], "level": logging.INFO},
}

logging.DEBUG has been replaced with logging.INFO, and we've got rid of logging.debug from our celery tasks.

[dkhokhlov]

@paltman wondering if this is still reproducible with 1.18.2 on your side?

[gjanco]

@paltman does this still happen for you in the latest version?

[manycoding]

In 1.18.8 this is causing pytest hang with thread lock, making this version useless Using 1.18.7 solves it

[shawkinsmezmo]

Hi @manycoding. Can you share a little but more about what you tried? All current unit tests are verified as working. The key difference is that there is a timer thread that is instantiated upon Handler creation, and it must be shut down by calling the handler's close() method, otherwise the thread will join with the main thread upon shutdown and hang. The existing unit tests were all modified to invoke setup() and teardown() of the handler. This is not an issue in a production use case because the python logging library is guaranteed to call close() during shut down.

As a note, I would not recommend using version 1.18.7, as based on the testing that I did, that version of the library drops approximately 2 - 3% of all logs.

[shawkinsmezmo]

Hmm. After some additional testing, I see that there is an issue on shutdown if the loggers close() method is not explicitly called. A fix for this is en route.

[dbartenstein]

In 1.18.8 this is causing pytest hang with thread lock, making this version useless Using 1.18.7 solves it

1.18.8 and 1.18.9 cause Django to not even start:

 File "/opt/zemtu/.local/lib/python3.10/site-packages/django/utils/log.py", line 71, in configure_logging
    logging.config.dictConfig(DEFAULT_LOGGING)
  File "/usr/local/lib/python3.10/logging/config.py", line 811, in dictConfig
    dictConfigClass(config).configure()
  File "/usr/local/lib/python3.10/logging/config.py", line 538, in configure
    _clearExistingHandlers()
  File "/usr/local/lib/python3.10/logging/config.py", line 275, in _clearExistingHandlers
    logging.shutdown(logging._handlerList[:])
  File "/usr/local/lib/python3.10/logging/__init__.py", line 2183, in shutdown
    h.close()
  File "/opt/zemtu/.local/lib/python3.10/site-packages/logdna/logdna.py", line 352, in close
    self.request_thread_pool.shutdown(wait=True)
  File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 235, in shutdown
    t.join()
  File "/usr/local/lib/python3.10/threading.py", line 1096, in join
    self._wait_for_tstate_lock()
  File "/usr/local/lib/python3.10/threading.py", line 1116, in _wait_for_tstate_lock
    if lock.acquire(block, timeout):
KeyboardInterrupt

[shawkinsmezmo]

Hi @dbartenstein. Can you please share the code that you are using to reproduce this? We’ll get right on addressing it.

[dbartenstein]

In 1.18.8 this is causing pytest hang with thread lock, making this version useless Using 1.18.7 solves it

@manycoding does version 1.18.9 solve the issue for you?

[dbartenstein]

Hi @dbartenstein. Can you please share the code that you are using to reproduce this? We’ll get right on addressing it.

@shawkinsmezmo we can try to compile something. And yes, we’re also using Celery. Btw, the following issue was opened by us: https://github.com/logdna/python/issues/103

[shawkinsmezmo]

@dbartenstein I saw. Let's continue the conversation over there.

[shawkinsmezmo]

Closing this issue since we've moved the discussion to 103 and 105