SocketHandler + multiprocessing doesn't work on Windows

8 Aug 2017

I've encountered the case where SocketHandler on windows under a separate multiprocessing.Process doesn't seem to work.

The proof of concept here takes a significant part of code from: https://docs.python.org/2.4/lib/network-logging.html

Here is client.py:

import logging import logging.handlers import multiprocessing import time def main(): rootLogger = logging.getLogger('') rootLogger.setLevel(logging.INFO) rootLogger.addHandler( logging.handlers.SocketHandler( 'localhost', logging.handlers.DEFAULT_TCP_LOGGING_PORT)) logger = logging.getLogger('testLogger') logger.info('Log from the main process.') process = multiprocessing.Process(target=log) process.start() time.sleep(1000) def log(): logger = logging.getLogger('testLogger') logger.info('Log from a separate multiprocessing.Process.') print 'Finish log().' if __name__ == "__main__": main()

Here's server.py:

import SocketServer import cPickle import logging import logging.handlers import struct class LogRecordStreamHandler(SocketServer.StreamRequestHandler): def handle(self): while 1: chunk = self.connection.recv(4) if len(chunk) < 4: break slen = struct.unpack(">L", chunk)[0] chunk = self.connection.recv(slen) while len(chunk) < slen: chunk = chunk + self.connection.recv(slen - len(chunk)) obj = cPickle.loads(chunk) record = logging.makeLogRecord(obj) print 'Server: %s' % record.msg class LogRecordSocketReceiver(SocketServer.ThreadingTCPServer): """simple TCP socket-based logging receiver suitable for testing. """ def __init__(self): SocketServer.ThreadingTCPServer.__init__( self, ('localhost', logging.handlers.DEFAULT_TCP_LOGGING_PORT), LogRecordStreamHandler) self.abort = 0 self.timeout = 1 def serve_until_stopped(self): import select abort = 0 while not abort: rd, wr, ex = select.select([self.socket.fileno()], [], [], self.timeout) if rd: self.handle_request() abort = self.abort def main(): tcpserver = LogRecordSocketReceiver() print "About to start TCP server..." tcpserver.serve_until_stopped() if __name__ == "__main__": main()

On Linux, the output is:

$ python client.py Server: Log from the main process. Finish log(). Server: Log from a separate multiprocessing.Process.

But, on windows, the output is:

C:\>python server.py About to start TCP server... Server: Log from the main process. C:\>python client.py Finish log().

You can see that Server: Log from a separate multiprocessing.Process. is missing.

Now we can re-initialize the logger again… but, on Linux, there will be two handlers; this results in sending an entry twice.


Another note is that, if we use FileHandler, then we get an Access denied error instead:

Traceback (most recent call last): File "client.py", line 31, in <module> main() File "client.py", line 13, in main rootLogger.addHandler(logging.FileHandler('test.log')) File "C:\Python27\python-2.7.12.amd64\lib\logging\__init__.py", line 913, in __init__ StreamHandler.__init__(self, self._open()) File "C:\Python27\python-2.7.12.amd64\lib\logging\__init__.py", line 943, in _open stream = open(self.baseFilename, self.mode) IOError: [Errno 13] Permission denied: 'C:\\test.log'

Even, with no handler, using logging.info doesn't work on a separate multiprocessing.Process.