Syslog to a remote syslog ng server stops working after Python version 3.6.6 #2073
Labels
Comments
|
Any success figuring this out? |
|
Unfortunately, no idea where to start in the codebase. The issue is definitely due to some underlying change in Python 3.6.7 :( |
|
I just ran into this problem after going from 3.6.6 to 3.6.8. In my case, it's a flask app. Thanks to the work of @lordradi to narrow the problem down, I did a quick diff between 3.6.6 and 3.6.7. I focused on the logging library. diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py
index e2084f5505..386ed17782 100644
--- a/Lib/logging/__init__.py
+++ b/Lib/logging/__init__.py
@@ -431,7 +431,8 @@ class Formatter(object):
responsible for converting a LogRecord to (usually) a string which can
be interpreted by either a human or an external system. The base Formatter
allows a formatting string to be specified. If none is supplied, the
- default value of "%s(message)" is used.
+ the style-dependent default value, "%(message)s", "{message}", or
+ "${message}", is used.
The Formatter can be initialized with a format string which makes use of
knowledge of the LogRecord attributes - e.g. the default value mentioned
diff --git a/Lib/logging/config.py b/Lib/logging/config.py
index 8a99923bf3..cabddc58cf 100644
--- a/Lib/logging/config.py
+++ b/Lib/logging/config.py
@@ -78,8 +78,8 @@ def fileConfig(fname, defaults=None, disable_existing_loggers=True):
# critical section
logging._acquireLock()
try:
- logging._handlers.clear()
- del logging._handlerList[:]
+ _clearExistingHandlers()
+
# Handlers add themselves to logging._handlers
handlers = _install_handlers(cp, formatters)
_install_loggers(cp, handlers, disable_existing_loggers)
@@ -268,6 +268,14 @@ def _install_loggers(cp, handlers, disable_existing):
# logger.disabled = 1
_handle_existing_loggers(existing, child_loggers, disable_existing)
+
+def _clearExistingHandlers():
+ """Clear and close existing handlers"""
+ logging._handlers.clear()
+ logging.shutdown(logging._handlerList[:])
+ del logging._handlerList[:]
+
+
IDENTIFIER = re.compile('^[a-z_][a-z0-9_]*$', re.I)
@@ -527,8 +535,7 @@ class DictConfigurator(BaseConfigurator):
else:
disable_existing = config.pop('disable_existing_loggers', True)
- logging._handlers.clear()
- del logging._handlerList[:]
+ _clearExistingHandlers()
# Do formatters first - they don't refer to anything else
formatters = config.get('formatters', EMPTY_DICT)It seems like a mostly small refactoring to combine some cleanup code into a new function. But there is also what appears to be a change in behavior inserted with that call to logging.shutdown() in the middle of _clearExistingHandlers(). I already have to build Python for my purposes, so I quickly made a patch against 3.6.8 (there were no changes to that file between 3.6.7 and 3.6.8) commenting out that line. When I install the patched Python, the exceptions go away. When I put back the release version of Python, the exceptions come back. I don't have time to dig in to this further at the moment. For my own purposes, I don't want to run patched versions of anything if I can help it. Instead I found if I removed the --log-syslog option when I launched gunicorn, the exceptions also went away. This is an acceptable workaround in my case. I hope this helps! |
|
Sorry for the bump, but had any luck with this in the last 3 months? I'm trying to get gunicorn logging to a remote server, but without the |
|
Here's a way to reproduce this issue. It only seems to happen with Django, and not Flask. flyte@demosthenes:~/workspaces/gunicorn
$ python3.8 -m venv ve
flyte@demosthenes:~/workspaces/gunicorn
$ . ve/bin/activate
(ve) flyte@demosthenes:~/workspaces/gunicorn
$ pip install django gunicorn
Collecting django
Using cached https://files.pythonhosted.org/packages/75/42/f59a8ebf14be6d17438f13042c775f53d3dfa71fff973e4aef64ca89582c/Django-3.1.6-py3-none-any.whl
Collecting gunicorn
Using cached https://files.pythonhosted.org/packages/69/ca/926f7cd3a2014b16870086b2d0fdc84a9e49473c68a8dff8b57f7c156f43/gunicorn-20.0.4-py2.py3-none-any.whl
Collecting sqlparse>=0.2.2 (from django)
Using cached https://files.pythonhosted.org/packages/14/05/6e8eb62ca685b10e34051a80d7ea94b7137369d8c0be5c3b9d9b6e3f5dae/sqlparse-0.4.1-py3-none-any.whl
Collecting asgiref<4,>=3.2.10 (from django)
Using cached https://files.pythonhosted.org/packages/89/49/5531992efc62f9c6d08a7199dc31176c8c60f7b2548c6ef245f96f29d0d9/asgiref-3.3.1-py3-none-any.whl
Collecting pytz (from django)
Using cached https://files.pythonhosted.org/packages/70/94/784178ca5dd892a98f113cdd923372024dc04b8d40abe77ca76b5fb90ca6/pytz-2021.1-py2.py3-none-any.whl
Requirement already satisfied: setuptools>=3.0 in ./ve/lib/python3.8/site-packages (from gunicorn)
Installing collected packages: sqlparse, asgiref, pytz, django, gunicorn
Successfully installed asgiref-3.3.1 django-3.1.6 gunicorn-20.0.4 pytz-2021.1 sqlparse-0.4.1
(ve) flyte@demosthenes:~/workspaces/gunicorn
$ django-admin startproject log_test
(ve) flyte@demosthenes:~/workspaces/gunicorn
$ cd log_test/
(ve) flyte@demosthenes:~/workspaces/gunicorn/log_test
$ gunicorn --log-syslog --log-syslog-to udp://localhost:55555 log_test.wsgi:application
[2021-02-10 18:51:45 +0000] [2097] [INFO] Starting gunicorn 20.0.4
[2021-02-10 18:51:45 +0000] [2097] [INFO] Listening at: http://127.0.0.1:8000 (2097)
[2021-02-10 18:51:45 +0000] [2097] [INFO] Using worker: sync
[2021-02-10 18:51:45 +0000] [2099] [INFO] Booting worker with pid: 2099
*** visit http://localhost:8000 in your browser ***
--- 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/gunicorn/ve/bin/gunicorn", line 11, in <module>
sys.exit(run())
File "/home/flyte/workspaces/gunicorn/ve/lib/python3.8/site-packages/gunicorn/app/wsgiapp.py", line 58, in run
WSGIApplication("%(prog)s [OPTIONS] [APP_MODULE]").run()
File "/home/flyte/workspaces/gunicorn/ve/lib/python3.8/site-packages/gunicorn/app/base.py", line 228, in run
super().run()
File "/home/flyte/workspaces/gunicorn/ve/lib/python3.8/site-packages/gunicorn/app/base.py", line 72, in run
Arbiter(self).run()
File "/home/flyte/workspaces/gunicorn/ve/lib/python3.8/site-packages/gunicorn/arbiter.py", line 202, in run
self.manage_workers()
File "/home/flyte/workspaces/gunicorn/ve/lib/python3.8/site-packages/gunicorn/arbiter.py", line 545, in manage_workers
self.spawn_workers()
File "/home/flyte/workspaces/gunicorn/ve/lib/python3.8/site-packages/gunicorn/arbiter.py", line 616, in spawn_workers
self.spawn_worker()
File "/home/flyte/workspaces/gunicorn/ve/lib/python3.8/site-packages/gunicorn/arbiter.py", line 583, in spawn_worker
worker.init_process()
File "/home/flyte/workspaces/gunicorn/ve/lib/python3.8/site-packages/gunicorn/workers/base.py", line 140, in init_process
self.run()
File "/home/flyte/workspaces/gunicorn/ve/lib/python3.8/site-packages/gunicorn/workers/sync.py", line 123, in run
self.run_for_one(timeout)
File "/home/flyte/workspaces/gunicorn/ve/lib/python3.8/site-packages/gunicorn/workers/sync.py", line 67, in run_for_one
self.accept(listener)
File "/home/flyte/workspaces/gunicorn/ve/lib/python3.8/site-packages/gunicorn/workers/sync.py", line 29, in accept
self.handle(listener, client, addr)
File "/home/flyte/workspaces/gunicorn/ve/lib/python3.8/site-packages/gunicorn/workers/sync.py", line 134, in handle
self.handle_request(listener, req, client, addr)
File "/home/flyte/workspaces/gunicorn/ve/lib/python3.8/site-packages/gunicorn/workers/sync.py", line 184, in handle_request
self.log.access(resp, req, environ, request_time)
File "/home/flyte/workspaces/gunicorn/ve/lib/python3.8/site-packages/gunicorn/glogging.py", line 344, 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': '[10/Feb/2021:18:56:10 +0000]', 'r': 'GET / HTTP/1.1', 's': '200', 'm': 'GET', 'U': '/', 'q': '', 'H': 'HTTP/1.1', 'b': '16351', 'B': 16351, 'f': '-', 'a': 'curl/7.58.0', 'T': 0, 'D': 7914, 'L': '0.007914', 'p': '<15162>', '{host}i': 'localhost:8000', '{user-agent}i': 'curl/7.58.0', '{accept}i': '*/*', '{content-type}o': 'text/html', '{x-frame-options}o': 'DENY', '{content-length}o': '16351', '{x-content-type-options}o': 'nosniff', '{referrer-policy}o': 'same-origin', '{wsgi.errors}e': <gunicorn.http.wsgi.WSGIErrorsWrapper object at 0x7feeb9928cd0>, '{wsgi.version}e': (1, 0), '{wsgi.multithread}e': False, '{wsgi.multiprocess}e': False, '{wsgi.run_once}e': False, '{wsgi.file_wrapper}e': <class 'gunicorn.http.wsgi.FileWrapper'>, '{wsgi.input_terminated}e': True, '{server_software}e': 'gunicorn/20.0.4', '{wsgi.input}e': <gunicorn.http.body.Body object at 0x7feeb7127fa0>, '{gunicorn.socket}e': <socket.socket fd=3, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 8000), raddr=('127.0.0.1', 51088)>, '{request_method}e': 'GET', '{query_string}e': '', '{raw_uri}e': '/', '{server_protocol}e': 'HTTP/1.1', '{http_host}e': 'localhost:8000', '{http_user_agent}e': 'curl/7.58.0', '{http_accept}e': '*/*', '{wsgi.url_scheme}e': 'http', '{remote_addr}e': '127.0.0.1', '{remote_port}e': '51088', '{server_name}e': '127.0.0.1', '{server_port}e': '8000', '{path_info}e': '/', '{script_name}e': ''} |
|
Here's a much simpler way to reproduce it using Flask. Turns out any call to flyte@demosthenes:~/workspaces/gunicorn2
$ python3.8 -m venv ve
. ve/flyte@demosthenes:~/workspaces/gunicorn2
$ . ve/bin/activate
(ve) flyte@demosthenes:~/workspaces/gunicorn2
$ pip install gunicorn flask
Collecting gunicorn
Using cached https://files.pythonhosted.org/packages/69/ca/926f7cd3a2014b16870086b2d0fdc84a9e49473c68a8dff8b57f7c156f43/gunicorn-20.0.4-py2.py3-none-any.whl
Collecting flask
Using cached https://files.pythonhosted.org/packages/f2/28/2a03252dfb9ebf377f40fba6a7841b47083260bf8bd8e737b0c6952df83f/Flask-1.1.2-py2.py3-none-any.whl
Requirement already satisfied: setuptools>=3.0 in ./ve/lib/python3.8/site-packages (from gunicorn)
Collecting Jinja2>=2.10.1 (from flask)
Using cached https://files.pythonhosted.org/packages/7e/c2/1eece8c95ddbc9b1aeb64f5783a9e07a286de42191b7204d67b7496ddf35/Jinja2-2.11.3-py2.py3-none-any.whl
Collecting itsdangerous>=0.24 (from flask)
Using cached https://files.pythonhosted.org/packages/76/ae/44b03b253d6fade317f32c24d100b3b35c2239807046a4c953c7b89fa49e/itsdangerous-1.1.0-py2.py3-none-any.whl
Collecting click>=5.1 (from flask)
Using cached https://files.pythonhosted.org/packages/d2/3d/fa76db83bf75c4f8d338c2fd15c8d33fdd7ad23a9b5e57eb6c5de26b430e/click-7.1.2-py2.py3-none-any.whl
Collecting Werkzeug>=0.15 (from flask)
Using cached https://files.pythonhosted.org/packages/cc/94/5f7079a0e00bd6863ef8f1da638721e9da21e5bacee597595b318f71d62e/Werkzeug-1.0.1-py2.py3-none-any.whl
Collecting MarkupSafe>=0.23 (from Jinja2>=2.10.1->flask)
Using cached https://files.pythonhosted.org/packages/4b/20/f6d7648c81cb84815d0be935d5c74cd1cc0239e43eadb1a61062d34b6543/MarkupSafe-1.1.1-cp38-cp38-manylinux1_x86_64.whl
Installing collected packages: gunicorn, MarkupSafe, Jinja2, itsdangerous, click, Werkzeug, flask
Successfully installed Jinja2-2.11.3 MarkupSafe-1.1.1 Werkzeug-1.0.1 click-7.1.2 flask-1.1.2 gunicorn-20.0.4 itsdangerous-1.1.0
(ve) flyte@demosthenes:~/workspaces/gunicorn2
$ cat > app.py <<EOF
import logging
from flask import Flask
app = Flask(__name__)
@app.route("/")
def hello_world():
logging.config.dictConfig(
{
"version": 1,
"disable_existing_loggers": False,
}
)
return "Hello, World!"
EOF
(ve) flyte@demosthenes:~/workspaces/gunicorn2
$ gunicorn --log-syslog --log-syslog-to udp://localhost:55555 app:app
[2021-02-10 19:31:25 +0000] [23580] [INFO] Starting gunicorn 20.0.4
[2021-02-10 19:31:25 +0000] [23580] [INFO] Listening at: http://127.0.0.1:8000 (23580)
[2021-02-10 19:31:25 +0000] [23580] [INFO] Using worker: sync
[2021-02-10 19:31:25 +0000] [23607] [INFO] Booting worker with pid: 23607
*** visit http://localhost:8000 in your browser ***
--- 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/gunicorn2/ve/bin/gunicorn", line 11, in <module>
sys.exit(run())
File "/home/flyte/workspaces/gunicorn2/ve/lib/python3.8/site-packages/gunicorn/app/wsgiapp.py", line 58, in run
WSGIApplication("%(prog)s [OPTIONS] [APP_MODULE]").run()
File "/home/flyte/workspaces/gunicorn2/ve/lib/python3.8/site-packages/gunicorn/app/base.py", line 228, in run
super().run()
File "/home/flyte/workspaces/gunicorn2/ve/lib/python3.8/site-packages/gunicorn/app/base.py", line 72, in run
Arbiter(self).run()
File "/home/flyte/workspaces/gunicorn2/ve/lib/python3.8/site-packages/gunicorn/arbiter.py", line 202, in run
self.manage_workers()
File "/home/flyte/workspaces/gunicorn2/ve/lib/python3.8/site-packages/gunicorn/arbiter.py", line 545, in manage_workers
self.spawn_workers()
File "/home/flyte/workspaces/gunicorn2/ve/lib/python3.8/site-packages/gunicorn/arbiter.py", line 616, in spawn_workers
self.spawn_worker()
File "/home/flyte/workspaces/gunicorn2/ve/lib/python3.8/site-packages/gunicorn/arbiter.py", line 583, in spawn_worker
worker.init_process()
File "/home/flyte/workspaces/gunicorn2/ve/lib/python3.8/site-packages/gunicorn/workers/base.py", line 140, in init_process
self.run()
File "/home/flyte/workspaces/gunicorn2/ve/lib/python3.8/site-packages/gunicorn/workers/sync.py", line 123, in run
self.run_for_one(timeout)
File "/home/flyte/workspaces/gunicorn2/ve/lib/python3.8/site-packages/gunicorn/workers/sync.py", line 67, in run_for_one
self.accept(listener)
File "/home/flyte/workspaces/gunicorn2/ve/lib/python3.8/site-packages/gunicorn/workers/sync.py", line 29, in accept
self.handle(listener, client, addr)
File "/home/flyte/workspaces/gunicorn2/ve/lib/python3.8/site-packages/gunicorn/workers/sync.py", line 134, in handle
self.handle_request(listener, req, client, addr)
File "/home/flyte/workspaces/gunicorn2/ve/lib/python3.8/site-packages/gunicorn/workers/sync.py", line 184, in handle_request
self.log.access(resp, req, environ, request_time)
File "/home/flyte/workspaces/gunicorn2/ve/lib/python3.8/site-packages/gunicorn/glogging.py", line 344, 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': '[10/Feb/2021:19:31:27 +0000]', 'r': 'GET / HTTP/1.1', 's': '200', 'm': 'GET', 'U': '/', 'q': '', 'H': 'HTTP/1.1', 'b': '13', 'B': 13, 'f': '-', 'a': 'curl/7.58.0', 'T': 0, 'D': 741, 'L': '0.000741', 'p': '<23607>', '{host}i': 'localhost:8000', '{user-agent}i': 'curl/7.58.0', '{accept}i': '*/*', '{content-type}o': 'text/html; charset=utf-8', '{content-length}o': '13', '{wsgi.errors}e': <gunicorn.http.wsgi.WSGIErrorsWrapper object at 0x7f9137a87310>, '{wsgi.version}e': (1, 0), '{wsgi.multithread}e': False, '{wsgi.multiprocess}e': False, '{wsgi.run_once}e': False, '{wsgi.file_wrapper}e': <class 'gunicorn.http.wsgi.FileWrapper'>, '{wsgi.input_terminated}e': True, '{server_software}e': 'gunicorn/20.0.4', '{wsgi.input}e': <gunicorn.http.body.Body object at 0x7f913653e190>, '{gunicorn.socket}e': <socket.socket fd=11, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 8000), raddr=('127.0.0.1', 59716)>, '{request_method}e': 'GET', '{query_string}e': '', '{raw_uri}e': '/', '{server_protocol}e': 'HTTP/1.1', '{http_host}e': 'localhost:8000', '{http_user_agent}e': 'curl/7.58.0', '{http_accept}e': '*/*', '{wsgi.url_scheme}e': 'http', '{remote_addr}e': '127.0.0.1', '{remote_port}e': '59716', '{server_name}e': '127.0.0.1', '{server_port}e': '8000', '{path_info}e': '/', '{script_name}e': '', '{werkzeug.request}e': None} |
|
...and an even easier way, in pure Python: 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")
|
|
Assuming this is a bug in Python, so I've made an issue there: https://bugs.python.org/issue43196 |
|
Hey @flyte Any luck for above issue with I'm using flask-gunicorn application with Python 3.9 version. It is failing with same error and I can't not upgrade to Python 3.11 for now. Other solution for removing --log-syslog is not applicable for my case. I tracked your raised bug https://bugs.python.org/issue43196, but it seems like it is already closed without proper solution. It will be really appreciated if someone can provide some inputs. |
|
no activity since awhile. closing feel free to create a new ticket if needed. |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
The issue we are experiencing is when we tried to upgrade our wagtail/django project to use Python version 3.6.8 the syslog flow has stopped, throwing an exception:
All we knew it was working with version 3.6.2, so I tried with every version since then, and it works 3.6.6 and breaks with 3.6.7 upwards, it's the same with 3.7.3
Checking the changelog of 3.6.7 only the PEP 519 seemed to be somewhat relevant, but I have no idea how can that cause the issue.
In more general, the error OSError: [Errno 9] Bad file descriptor refers to the fact that the handle (to the file or in this case the socket) was closed by something in the meantime.
Could you please help with this issue?
Thanks
Gabor
The text was updated successfully, but these errors were encountered: