Gunicorn: Bad file descriptor when logging with TCP/IP syslog

Created on 19 Apr 2019  路  6Comments  路  Source: benoitc/gunicorn

When sending logging via syslog over udp an exception is thrown for a bad file descriptor. I've tried using both the syslog config options and logconfig_dict

  • syslog options
bind            = '127.0.0.1:8000'
loglevel        = 'DEBUG'
syslog_address  = 'udp://127.0.0.1:5514'
syslog          = True
syslog_facility = 'local4'
proxy_allow_ips = '127.0.0.1'
workers         = 4
threads         = 2
  • logconfig_dict
import datetime as dt
import logging
import socket
import sys
from functools import partial
from types import ModuleType


class IsoFormatter(logging.Formatter):
    converter = partial(dt.datetime.fromtimestamp, tz=dt.datetime.now().astimezone().tzinfo)

    def formatTime(self, record, datefmt=None):
        ct = self.converter(record.created)

        if datefmt:
            return ct.strftime(datefmt)

        return ct.isoformat()


log_module = ModuleType('log_module')
log_module.IsoFormatter = IsoFormatter

sys.modules['log_module'] = log_module

bind            = '127.0.0.1:8000'
loglevel        = 'DEBUG'
proxy_allow_ips = '127.0.0.1'
workers         = 4
threads         = 2

logconfig_dict = {
    'version':                  1,
    'disable_existing_loggers': False,

    'loggers':                  {
        'root':            {
            'level':    'DEBUG',
            'handlers': ['console', 'syslog']
        },
        'gunicorn.error':  {
            'level':     'DEBUG',
            'handlers':  ['error_console', 'syslog'],
            'propagate': True,
            'qualname':  'gunicorn.error'
        },
        'gunicorn.access': {
            'level':     'DEBUG',
            'handlers':  ['console', 'syslog'],
            'propagate': True,
            'qualname':  'gunicorn.access'
        },
        'gunicorn.http':   {
            'level':     'DEBUG',
            'handlers':  ['console', 'syslog'],
            'propagate': True,
            'qualname':  'gunicorn.http'
        },
    },
    'handlers':                 {
        'syslog':        {
            'level':     'DEBUG',
            'class':     'logging.handlers.SysLogHandler',
            'address':   ('127.0.0.1', 5514),
            'socktype':  socket.SOCK_DGRAM,
            'facility':  'local4',
            'formatter': 'syslog',
        },
        'console':       {
            'class':     'logging.StreamHandler',
            'formatter': 'generic',
            'stream':    'ext://sys.stdout'
        },
        'error_console': {
            'class':     'logging.StreamHandler',
            'formatter': 'generic',
            'stream':    'ext://sys.stderr'
        },
    },
    'formatters':               {
        'generic': {
            'format': '%(asctime)s %(name)s [%(process)d] [%(levelname)s] %(message)s',
            'class':  'log_module.IsoFormatter'
        },
        'syslog':  {
            'format': '1 %(asctime)s gunicorn %(name)s %(process)d - - %(message)s',
            'class':  'log_module.IsoFormatter'
        }
    }
}

I suspect this has something to do with subprocesses or threading, as the initial startup messages are successfully sent and received. It's only when http requests are made that exceptions are generated.

Apr 18 17:05:23 gunicorn gunicorn.error[1] Starting gunicorn 19.9.0
Apr 18 17:05:23 gunicorn gunicorn.error[1] Arbiter booted
Apr 18 17:05:23 gunicorn gunicorn.error[1] Listening at: http://127.0.0.1:8000 (1)
Apr 18 17:05:23 gunicorn gunicorn.error[1] Using worker: threads
Apr 18 17:05:23 gunicorn gunicorn.error[12] Booting worker with pid: 12
Apr 18 17:05:23 gunicorn gunicorn.error[13] Booting worker with pid: 13
Apr 18 17:05:23 gunicorn gunicorn.error[14] Booting worker with pid: 14
Apr 18 17:05:23 gunicorn gunicorn.error[15] Booting worker with pid: 15
Apr 18 17:05:23 gunicorn gunicorn.error[1] 4 workers

2019-04-18T16:51:44.349164-05:00 gunicorn.error [15] [DEBUG] GET /admin/
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.6/logging/handlers.py", line 942, in emit
    self.socket.sendto(msg, self.address)
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "/usr/lib/python3.6/threading.py", line 884, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.6/threading.py", line 864, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.6/concurrent/futures/thread.py", line 69, in _worker
    work_item.run()
  File "/usr/lib/python3.6/concurrent/futures/thread.py", line 56, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/workers/gthread.py", line 279, in handle
    keepalive = self.handle_request(req, conn)
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/workers/gthread.py", line 312, in handle_request
    self.cfg.pre_request(self, req)
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/config.py", line 1699, in pre_request
    worker.log.debug("%s %s" % (req.method, req.path))
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/glogging.py", line 274, in debug
    self.error_log.debug(msg, *args, **kwargs)
Message: 'GET /admin/'
Arguments: ()
--- Logging error ---
2019-04-18T16:51:44.530272-05:00 gunicorn.access [15] [INFO] 127.0.0.1 - - [18/Apr/2019:21:51:44 +0000] "GET /admin/ HTTP/1.0" 200 14065 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"
Traceback (most recent call last):
  File "/usr/lib/python3.6/logging/handlers.py", line 942, in emit
    self.socket.sendto(msg, self.address)
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "/usr/lib/python3.6/threading.py", line 884, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.6/threading.py", line 864, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.6/concurrent/futures/thread.py", line 69, in _worker
    work_item.run()
  File "/usr/lib/python3.6/concurrent/futures/thread.py", line 56, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/workers/gthread.py", line 279, in handle
    keepalive = self.handle_request(req, conn)
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/workers/gthread.py", line 338, in handle_request
    self.log.access(resp, req, environ, request_time)
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/glogging.py", line 353, in access
    self.access_log.info(self.cfg.access_log_format, safe_atoms)
Message: '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"'
Arguments: {'h': '127.0.0.1', 'l': '-', 'u': '-', 't': '[18/Apr/2019:21:51:44 +0000]', 'r':...............

If I use a unix socket (/dev/log) it does work, but greatly complicates things since I have to run a syslog daemon in my container.

picture djlambert
👍1

Most helpful comment

This issue was premature. Django is closing all the handlers when it starts up. I added the gunicorn logconfig_dict to my Django LOGGING config and no more exceptions. Closing.

picture djlambert on 19 Apr 2019
🎉2

All 6 comments

Seeing the same thing using tcp syslog.

Using the SyncWorkeralso has the same issue.

2019-04-19T08:42:11.333912-05:00 gunicorn.error [14] [DEBUG] GET /admin/
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.6/logging/handlers.py", line 942, in emit
    self.socket.sendto(msg, self.address)
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "/gunicorn/venv/bin/gunicorn", line 10, in <module>
    sys.exit(run())
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/app/wsgiapp.py", line 61, in run
    WSGIApplication("%(prog)s [OPTIONS] [APP_MODULE]").run()
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/app/base.py", line 223, in run
    super(Application, self).run()
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/app/base.py", line 72, in run
    Arbiter(self).run()
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 203, in run
    self.manage_workers()
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 545, in manage_workers
    self.spawn_workers()
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 616, in spawn_workers
    self.spawn_worker()
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 583, in spawn_worker
    worker.init_process()
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/workers/base.py", line 134, in init_process
    self.run()
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/workers/sync.py", line 124, in run
    self.run_for_one(timeout)
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/workers/sync.py", line 68, in run_for_one
    self.accept(listener)
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/workers/sync.py", line 30, in accept
    self.handle(listener, client, addr)
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/workers/sync.py", line 135, in handle
    self.handle_request(listener, req, client, addr)
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/workers/sync.py", line 164, in handle_request
    self.cfg.pre_request(self, req)
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/config.py", line 1699, in pre_request
    worker.log.debug("%s %s" % (req.method, req.path))
  File "/gunicorn/venv/lib/python3.6/site-packages/gunicorn/glogging.py", line 274, in debug
    self.error_log.debug(msg, *args, **kwargs)
Message: 'GET /admin/'
Arguments: ()
djlambert picture djlambert on 19 Apr 2019

This issue was premature. Django is closing all the handlers when it starts up. I added the gunicorn logconfig_dict to my Django LOGGING config and no more exceptions. Closing.

djlambert picture djlambert on 19 Apr 2019
🎉2

I'm getting this exact same problem, but I have no logconfig_dict in my configuration file. Is there something I need to copy from Gunicorn into Django's settings.LOGGING?

greyhare picture greyhare on 25 Jun 2019

I added the gunicorn.error and gunicorn.access loggers
https://github.com/benoitc/gunicorn/blob/dc7b5d5c4876b49f86ea2460698a335d0f5ef7c9/gunicorn/glogging.py#L54
https://github.com/benoitc/gunicorn/blob/dc7b5d5c4876b49f86ea2460698a335d0f5ef7c9/gunicorn/glogging.py#L61 to my Django settings.LOGGING. The config will need to be adjusted to use whatever handler(s) that are defined.

djlambert picture djlambert on 25 Jun 2019
👍1

The above didn't work for me. I think my issue is related to https://github.com/benoitc/gunicorn/issues/2073

flyte picture flyte on 21 Jan 2020

I have this problem as well with TCP syslog in gunicorn

emr-arvig picture emr-arvig on 9 Nov 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

lordmauve picture lordmauve  路  3Comments
thomasjungblut picture thomasjungblut  路  3Comments
vaibhavpatil123 picture vaibhavpatil123  路  4Comments
agilezebra picture agilezebra  路  4Comments
twosigmajab picture twosigmajab  路  4Comments