SysLogHandler closes connection before using it #62181
Comments
|
I have a script that close its socket to /dev/log immediatly before using it, causing it to fail, here is the code : logger = logging.getLogger('twitterCounter')
logger.addHandler(logging.handlers.SysLogHandler(address='/dev/log'))
logger.setLevel(logging.DEBUG)
logger.info("Hello")
with daemon.DaemonContext():
logger.info("World !")
}}}and here is an strace : close(3) = 0
|
JulienPalard
added
stdlib
|
Isn't this a case of handles being closed in the child after a fork, by the daemon module? Have you investigated the files_preserve option in DaemonContext? |
|
Ironically, I ran into this same exact issue today, and I have investigated the If you try to add the syslog handler to the files_preserve list it has no effect. It seems to need a stream, and SysLogHandler doesn't have the stream attribute. # This works for FileHandler's
log = logging.getLogger('MyLog')
fh = logging.FileHandler('/some/file')
with daemon.DaemonContext(files_preserve=[fh.stream, ]):
log.warn("In the belly of the beast.") |
|
The python-daemon documentation states, about files_preserve: "Elements of the list are file descriptors (as returned by a file object's Notice that file objects are just a convenience - filenos() can be passed. The following, slightly modified script works as expected: import logging
import logging.handlers
import daemon
logger = logging.getLogger('twitterCounter')
handler = logging.handlers.SysLogHandler(address='/dev/log')
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)
logger.info("Hello, ")
with daemon.DaemonContext(files_preserve=[handler.socket.fileno()]):
logger.info("world!")Output in syslog after running the above: May 16 10:58:42 eta-oneiric64 Hello, |
|
I understand the files_preserve parameter, the bug I'm filling is the innability of SysLogHandler to reopen the socket, although it tries : // DaemonContext closing all FDs: [...] // Trying to send "World !" to the closed socket (developper missusing files_preserve // Reopening socket, with good parameters // WTF ? For me, the bug is here, why do we close it ? // Trying to connect to a closed socket ... will fail )o: // Reclosing it ? ok ... why not as we don't know that it were closed. // Trying another socket type, cause first try failed, but failed cause the close(), it may have not been closed and have succeed. So this try may no apprear normally : |
|
I see what you're saying now, but there's no explicit close in logging, so it's coming from somewhere lower down. Let's examine what happens when we try to emit the record: -> def emit(self, record):
==============================================================
To summarise: line 738 is a call to socket.socket(AF_UNIX, SOCK_DGRAM) There is no close() called by logging between socket.socket() and socket.connect(), so the close seems to be coming from inside one of those two calls to the socket module. |
|
We'll try this with a simple script which doesn't use logging at all: import os
import socketMSG1 = '<14>Hi, \x00' sock = socket.socket(socket.AF_UNIX, socket.SOCK_DGRAM)
sock.connect('/dev/log')
sock.send(MSG1)
os.close(sock.fileno()) # what daemonizing does
try:
sock.send(MSG2)
except socket.error as e:
print(e)
print('Trying to reconnect:')
sock = socket.socket(socket.AF_UNIX, socket.SOCK_DGRAM)
try:
sock.connect('/dev/log')
except socket.error as e:
print('Oh look, reconnecting failed: %s' % e)When we run this, we get: [Errno 9] Bad file descriptor And the strace output looks like this: socket(PF_FILE, SOCK_DGRAM, 0) = 3 =================================================== So, while it seems to be a bug, it's not a logging bug. It seems to be |
|
The line sock = socket.socket(socket.AF_UNIX, socket.SOCK_DGRAM)overwrites the old broken socket with a new one with the same fd. The old socket's destructor closes the fd of the new socket. |
Aha! Nice one. But what's the correct fix? I suppose a self.sock = Nonebefore every self.sock = socket.socket call would fix seem this, and while I can certainly make this change in SysLogHandler, isn't this a more general problem? |
|
Rather than self.sock = NoneI would do self.sock.close()which should work better for non-refcounted Pythons. Of course it would be better to do this immediately after forking (i.e. before any more fds are created), otherwise you could still accidentally zap the fd of some other object. If you can't do this immediately after forking then maybe it is better to move inherited potentially broken objects to a garbage list to prevent garbage collection. |
|
New changeset d91da96a55bf by Vinay Sajip in branch '2.7': New changeset 590b865aa73c by Vinay Sajip in branch '3.3': New changeset f2809c7a7c3c by Vinay Sajip in branch 'default': |
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:
bugs.python.org fields:
The text was updated successfully, but these errors were encountered: