[Twisted-Python] Persuading Python's Logging to use twisted.logger
![](https://secure.gravatar.com/avatar/ad5d35adba8666840c8ce22c1a43ef1f.jpg?s=120&d=mm&r=g)
The project I am working on uses pymodbus which I am sure shares a fairly common attribute with many other modules of using Python's standard Logging mechanism - a very reasonable choice even for a module that supports Twisted, the library can also be used entirely synchronously and thus would not want a required dependency of Twisted. It struck me that it would be great to be able to redirect the standard logging library to use twisted.logger by some sort of 'Clever Monkey Patching' and that this may be a relatively common requirement... however after extensive searching, and asking on the pymodbus list, I can't find any evidence that such a thing has ever been attempted or discussed. The reverse mechanism of sending twisted.logger's output to the standard library is of course handled by the twisted.logger.STDLibLogObserver (and similar in twisted legacy logging) but the documentation for this even suggests why this is a bad idea: 'Warning: specific logging configurations (example: network) can lead to this observer blocking.' which seems to me why it would be better to attempt this the other way around... Am I crazy to even think this? is it just the rambling of Python/Twisted newb? Or is there something I'm missing that would make this impossible to do generically, and awkward to provide a vague recipe of how to do? I do appreciate that twisted.logger offers a more feature rich (structured) API and the Logging API would only be able to provide level and text but it would be better than loosing any possibly useful log messages from used modules in my mind. If anyone can enlighten me I would be most appreciative, Cheers /dan -- Daniel Sutcliffe <dansut@gmail.com>
![](https://secure.gravatar.com/avatar/7964a0aa5fb0960a920694fde1e787f2.jpg?s=120&d=mm&r=g)
Here's a snippet that shows how I've handled it. This example uses the new style of logging in Twisted but would work just as well in the old style. I'm not sure if there's a label that you can supply to the logging.Handler to handle all messages but that's probably just a matter of digging into the source code. import sys import logging from twisted.logger import Logger from twisted.logger import globalLogBeginner from twisted.logger import textFileLogObserver class TxLogHandler(logging.Handler): log = Logger() def __init__(self, label): self.label = label logging.Handler.__init__(self) self.level = logging.DEBUG def flush(self): pass def emit(self, record): try: msg = self.format(record) self.log.debug('{msg:}', msg = '\n'.join(map(lambda line: '{}: {}'.format(self.label, line), msg.split('\n')))) except: self.handleError(record) tx = TxLogHandler('FastAGI') logger = logging.getLogger('FastAGI') logger.addHandler(tx) logger.setLevel(logging.DEBUG) tx = TxLogHandler('AMI') logger = logging.getLogger('AMI') logger.addHandler(tx) logger.setLevel(logging.DEBUG) output = textFileLogObserver(sys.stderr) globalLogBeginner.beginLoggingTo([output]) On Mon, May 9, 2016 at 3:50 PM, Daniel Sutcliffe <dansut@gmail.com> wrote:
-- Jeff Ollie
![](https://secure.gravatar.com/avatar/e1554622707bedd9202884900430b838.jpg?s=120&d=mm&r=g)
Sure, this makes sense.
You shouldn't need monkey patching; the standard library logger does have facilities for setting up custom handlers. We just need to make one. Honestly it would be great if this were featured within Twisted itself; it would make a great contribution to twisted.logger proper.
I would very much like to see this :). The standard library logging mechanism is in common use, and until we can spin it out into a separate project, `twisted.logger´ is unlikely to
No, there's nothing that would make it impossible. If you want to contribute it.
I think you might even be able to claw back some structured information out of the stdlib logging machinery? LogRecord does have 'args' and 'msg', and we could convert that into a twisted.logger format string. This would be more expensive than using twisted.logger directly of course, but it would still provide a lot more useful information.
If anyone can enlighten me I would be most appreciative,
I think just try to write a Handler (<https://docs.python.org/2.7/library/logging.handlers.html#module-logging.han...>) that converts LogRecord objects to event dictionaries, and then emit them to a <https://twistedmatrix.com/documents/16.1.1/api/twisted.logger.ILogObserver.h...> and let us know if you hit any problems. -glyph
![](https://secure.gravatar.com/avatar/12f8ad89084afabd2769ad2ef8c10e12.jpg?s=120&d=mm&r=g)
The warning in the documentation about the potential blocking behaviour of the StdLibLogObserver is correct, but it does tip a little close to FUD. If you are using the Syslog or File based log observers then there is no change in "blocking" behaviour between Twisted and the standard lib. The Syslog observer and the standard library syslog facility both use exactly the same standard library syslog module which is known to block under certain system configurations. The File observer in Twisted and the standard library both use regular Python file objects that don't leverage the reactor in any way. Likewise, logging to STDIN/STDERR in both logging frameworks treats the streams like normal file objects which, when subjected to back pressure, become a source of blocking time. The only cases where Twisted and the standard lib differ would be network based logging. My recommendation is to use the STdLibLogObserver. This will allow you to use the twisted.logger in your Twisted code, merge Twisted and non-Twisted logs into a single stream regardless of their origin, and allow you to tap into things like the standard lib RotatingFileHandler and file based configuration system. Should you actually need to pipe logs over the network it would not be overly difficult to implement a standard lib logging transport that leverages the reactor when sending data. On Mon, May 9, 2016 at 5:18 PM Glyph <glyph@twistedmatrix.com> wrote:
![](https://secure.gravatar.com/avatar/63756693d9b79ff633f86ff5672652e9.jpg?s=120&d=mm&r=g)
hello, On 05/09/16 23:50, Daniel Sutcliffe wrote:
me too :)
as discussed, it's possible. you additionally need to make sure to clean other handlers if you are integrating with third party libraries who may be adding esoteric targets for log entries behind your back. with that said, here's my take at it: https://github.com/plq/neurons/blob/40dff6134330aeadbefd3973d5d40aa4bfac4b78... best, burak
![](https://secure.gravatar.com/avatar/ad5d35adba8666840c8ce22c1a43ef1f.jpg?s=120&d=mm&r=g)
Thanks for all the hints and suggestions guys, this was far simpler than I thought it would be and the results are exactly what I imagined without too much effort. Jeff: Have to admit I started with your code and had it working with in my scenario in no time at all, this was a great bump start, but I couldn't help tweaking... Glyph: The code below is I'm sure far from perfect, and it doesn't take your advice and convert the msg into a twisted format string, it takes the simpler approach of letting the Logging record pre-format using the getMessage() method. I'm sure there are loads of edge cases it could cope with better with maybe it is a start of something that could be included in Twisted. Kevin: I appreciate your input and understand the need to always be aware of what you are call/using may be blocking for various reasons - I will eventually want to redirect to syslog so will need to deal with this later. I still think it makes sense to have a relatively easy option of redirecting STDLib logging from used modules to twisted.logger available, as well as the opposite. When twistd is handling most of logging setup it seems the simpler path to have everything using twisted.logger. Burak: Your code was especially helpful - it goes much further than I even considered is useful so I just borrowed what I thought was essential for the needs of this first pass. Will be glad to hear of any cases you think will break this code to help make it even more general. So here's the code I dropped into a logfudger.py in my test dir. All feedback encouraged as I really am just finding my way around Python, and appreciate all critique of what I could do better: from twisted.logger import Logger, LogLevel import logging LEVEL_SYS2TWISTED = { logging.DEBUG: LogLevel.debug, logging.INFO: LogLevel.info, logging.WARN: LogLevel.warn, logging.ERROR: LogLevel.error, logging.CRITICAL: LogLevel.critical, } class TwistedLoggerHandler(logging.Handler): def __init__(self): self._log = Logger() logging.Handler.__init__(self) def flush(self): pass def emit(self, record): try: self._log.namespace=record.name self._log.source=record.pathname self._log.emit( LEVEL_SYS2TWISTED[record.levelno], record.getMessage(), lineno=record.lineno, args=record.args) except: self.handleError(record) When I use this with pymodbus I then just need to include this with my code: import logging from logfudger import TwistedLoggerHandler sysliblog = logging.getLogger("pymodbus") sysliblog.addHandler(TwistedLoggerHandler()) sysliblog.setLevel(logging.DEBUG) from twisted.logger import Logger, globalLogBeginner, textFileLogObserver import sys globalLogBeginner.beginLoggingTo([textFileLogObserver(sys.stderr)]) Which gives me a stderr output like: 2016-05-10T18:48:52-0400 [pymodbus#info] Informational 2016-05-10T18:48:52-0400 [__main__.MBClientFactory#info] Starting factory <__main__.MBClientFactory instance at 0x0000000001212ae0> 2016-05-10T18:48:52-0400 [__main__.MBClientProtocol#debug] Protocol connectionMade 2016-05-10T18:48:52-0400 [pymodbus.client.async#debug] Client connected to modbus server 2016-05-10T18:48:52-0400 [pymodbus.transaction#debug] adding transaction 1 I don't deal with exceptions logged through the STDLib logging at all, and the log_namespace, log_source could probably be set in ways that cover more use cases. But hopefully this all makes sense and this can be a start of something much more generically useful. Cheers /dan -- Daniel Sutcliffe <dansut@gmail.com>
![](https://secure.gravatar.com/avatar/e1554622707bedd9202884900430b838.jpg?s=120&d=mm&r=g)
Fantastic!
The main reason I wanted to do the format-string translation is that it would allow the key/value pairs to be stored according to the same idiom that Twisted uses, and therefore be serialized to jsonFileLogObserver and consequently things like LogStash / ElasticSearch.
Yep! This is definitely something handy. Would you mind filing an issue for it? -glyph
![](https://secure.gravatar.com/avatar/ad5d35adba8666840c8ce22c1a43ef1f.jpg?s=120&d=mm&r=g)
On May 10, 2016, at 4:23 PM, Daniel Sutcliffe <dansut@gmail.com> wrote:
On Sat, May 21, 2016 at 9:44 PM, Glyph <glyph@twistedmatrix.com> wrote:
Fantastic!
[...]
I kept the format-string args within a dictionary under the args kwarg to emit() for exactly the reasons you gave above but felt that translating a %-encoded string into the new-style that twisted.logger uses was likely to make the example much more complicated, and was frankly beyond my limited needs. There's probably a simple way to do this in Python that I am not aware of yet though... [...]
I've created issue #8358 https://twistedmatrix.com/trac/ticket/8358 Which is hopefully what you were after - spent a bunch of time reading your impressive process and standards docs so I'm already sure that anything that finds itself in Twisted from this will probably be quite significantly different to this initial suggestion but I don't mind a bit of learning if someone is willing to give me a bit of mentoring me to get this into shape so it can be done as a PR. Cheers /dan -- Daniel Sutcliffe <dansut@gmail.com>
![](https://secure.gravatar.com/avatar/e1554622707bedd9202884900430b838.jpg?s=120&d=mm&r=g)
I wrote a function to do this some time ago, and I forget the exact derivation, but somehow it ended up here: https://github.com/moreati/formatist -glyph
![](https://secure.gravatar.com/avatar/7964a0aa5fb0960a920694fde1e787f2.jpg?s=120&d=mm&r=g)
Here's a snippet that shows how I've handled it. This example uses the new style of logging in Twisted but would work just as well in the old style. I'm not sure if there's a label that you can supply to the logging.Handler to handle all messages but that's probably just a matter of digging into the source code. import sys import logging from twisted.logger import Logger from twisted.logger import globalLogBeginner from twisted.logger import textFileLogObserver class TxLogHandler(logging.Handler): log = Logger() def __init__(self, label): self.label = label logging.Handler.__init__(self) self.level = logging.DEBUG def flush(self): pass def emit(self, record): try: msg = self.format(record) self.log.debug('{msg:}', msg = '\n'.join(map(lambda line: '{}: {}'.format(self.label, line), msg.split('\n')))) except: self.handleError(record) tx = TxLogHandler('FastAGI') logger = logging.getLogger('FastAGI') logger.addHandler(tx) logger.setLevel(logging.DEBUG) tx = TxLogHandler('AMI') logger = logging.getLogger('AMI') logger.addHandler(tx) logger.setLevel(logging.DEBUG) output = textFileLogObserver(sys.stderr) globalLogBeginner.beginLoggingTo([output]) On Mon, May 9, 2016 at 3:50 PM, Daniel Sutcliffe <dansut@gmail.com> wrote:
-- Jeff Ollie
![](https://secure.gravatar.com/avatar/e1554622707bedd9202884900430b838.jpg?s=120&d=mm&r=g)
Sure, this makes sense.
You shouldn't need monkey patching; the standard library logger does have facilities for setting up custom handlers. We just need to make one. Honestly it would be great if this were featured within Twisted itself; it would make a great contribution to twisted.logger proper.
I would very much like to see this :). The standard library logging mechanism is in common use, and until we can spin it out into a separate project, `twisted.logger´ is unlikely to
No, there's nothing that would make it impossible. If you want to contribute it.
I think you might even be able to claw back some structured information out of the stdlib logging machinery? LogRecord does have 'args' and 'msg', and we could convert that into a twisted.logger format string. This would be more expensive than using twisted.logger directly of course, but it would still provide a lot more useful information.
If anyone can enlighten me I would be most appreciative,
I think just try to write a Handler (<https://docs.python.org/2.7/library/logging.handlers.html#module-logging.han...>) that converts LogRecord objects to event dictionaries, and then emit them to a <https://twistedmatrix.com/documents/16.1.1/api/twisted.logger.ILogObserver.h...> and let us know if you hit any problems. -glyph
![](https://secure.gravatar.com/avatar/12f8ad89084afabd2769ad2ef8c10e12.jpg?s=120&d=mm&r=g)
The warning in the documentation about the potential blocking behaviour of the StdLibLogObserver is correct, but it does tip a little close to FUD. If you are using the Syslog or File based log observers then there is no change in "blocking" behaviour between Twisted and the standard lib. The Syslog observer and the standard library syslog facility both use exactly the same standard library syslog module which is known to block under certain system configurations. The File observer in Twisted and the standard library both use regular Python file objects that don't leverage the reactor in any way. Likewise, logging to STDIN/STDERR in both logging frameworks treats the streams like normal file objects which, when subjected to back pressure, become a source of blocking time. The only cases where Twisted and the standard lib differ would be network based logging. My recommendation is to use the STdLibLogObserver. This will allow you to use the twisted.logger in your Twisted code, merge Twisted and non-Twisted logs into a single stream regardless of their origin, and allow you to tap into things like the standard lib RotatingFileHandler and file based configuration system. Should you actually need to pipe logs over the network it would not be overly difficult to implement a standard lib logging transport that leverages the reactor when sending data. On Mon, May 9, 2016 at 5:18 PM Glyph <glyph@twistedmatrix.com> wrote:
![](https://secure.gravatar.com/avatar/63756693d9b79ff633f86ff5672652e9.jpg?s=120&d=mm&r=g)
hello, On 05/09/16 23:50, Daniel Sutcliffe wrote:
me too :)
as discussed, it's possible. you additionally need to make sure to clean other handlers if you are integrating with third party libraries who may be adding esoteric targets for log entries behind your back. with that said, here's my take at it: https://github.com/plq/neurons/blob/40dff6134330aeadbefd3973d5d40aa4bfac4b78... best, burak
![](https://secure.gravatar.com/avatar/ad5d35adba8666840c8ce22c1a43ef1f.jpg?s=120&d=mm&r=g)
Thanks for all the hints and suggestions guys, this was far simpler than I thought it would be and the results are exactly what I imagined without too much effort. Jeff: Have to admit I started with your code and had it working with in my scenario in no time at all, this was a great bump start, but I couldn't help tweaking... Glyph: The code below is I'm sure far from perfect, and it doesn't take your advice and convert the msg into a twisted format string, it takes the simpler approach of letting the Logging record pre-format using the getMessage() method. I'm sure there are loads of edge cases it could cope with better with maybe it is a start of something that could be included in Twisted. Kevin: I appreciate your input and understand the need to always be aware of what you are call/using may be blocking for various reasons - I will eventually want to redirect to syslog so will need to deal with this later. I still think it makes sense to have a relatively easy option of redirecting STDLib logging from used modules to twisted.logger available, as well as the opposite. When twistd is handling most of logging setup it seems the simpler path to have everything using twisted.logger. Burak: Your code was especially helpful - it goes much further than I even considered is useful so I just borrowed what I thought was essential for the needs of this first pass. Will be glad to hear of any cases you think will break this code to help make it even more general. So here's the code I dropped into a logfudger.py in my test dir. All feedback encouraged as I really am just finding my way around Python, and appreciate all critique of what I could do better: from twisted.logger import Logger, LogLevel import logging LEVEL_SYS2TWISTED = { logging.DEBUG: LogLevel.debug, logging.INFO: LogLevel.info, logging.WARN: LogLevel.warn, logging.ERROR: LogLevel.error, logging.CRITICAL: LogLevel.critical, } class TwistedLoggerHandler(logging.Handler): def __init__(self): self._log = Logger() logging.Handler.__init__(self) def flush(self): pass def emit(self, record): try: self._log.namespace=record.name self._log.source=record.pathname self._log.emit( LEVEL_SYS2TWISTED[record.levelno], record.getMessage(), lineno=record.lineno, args=record.args) except: self.handleError(record) When I use this with pymodbus I then just need to include this with my code: import logging from logfudger import TwistedLoggerHandler sysliblog = logging.getLogger("pymodbus") sysliblog.addHandler(TwistedLoggerHandler()) sysliblog.setLevel(logging.DEBUG) from twisted.logger import Logger, globalLogBeginner, textFileLogObserver import sys globalLogBeginner.beginLoggingTo([textFileLogObserver(sys.stderr)]) Which gives me a stderr output like: 2016-05-10T18:48:52-0400 [pymodbus#info] Informational 2016-05-10T18:48:52-0400 [__main__.MBClientFactory#info] Starting factory <__main__.MBClientFactory instance at 0x0000000001212ae0> 2016-05-10T18:48:52-0400 [__main__.MBClientProtocol#debug] Protocol connectionMade 2016-05-10T18:48:52-0400 [pymodbus.client.async#debug] Client connected to modbus server 2016-05-10T18:48:52-0400 [pymodbus.transaction#debug] adding transaction 1 I don't deal with exceptions logged through the STDLib logging at all, and the log_namespace, log_source could probably be set in ways that cover more use cases. But hopefully this all makes sense and this can be a start of something much more generically useful. Cheers /dan -- Daniel Sutcliffe <dansut@gmail.com>
![](https://secure.gravatar.com/avatar/e1554622707bedd9202884900430b838.jpg?s=120&d=mm&r=g)
Fantastic!
The main reason I wanted to do the format-string translation is that it would allow the key/value pairs to be stored according to the same idiom that Twisted uses, and therefore be serialized to jsonFileLogObserver and consequently things like LogStash / ElasticSearch.
Yep! This is definitely something handy. Would you mind filing an issue for it? -glyph
![](https://secure.gravatar.com/avatar/ad5d35adba8666840c8ce22c1a43ef1f.jpg?s=120&d=mm&r=g)
On May 10, 2016, at 4:23 PM, Daniel Sutcliffe <dansut@gmail.com> wrote:
On Sat, May 21, 2016 at 9:44 PM, Glyph <glyph@twistedmatrix.com> wrote:
Fantastic!
[...]
I kept the format-string args within a dictionary under the args kwarg to emit() for exactly the reasons you gave above but felt that translating a %-encoded string into the new-style that twisted.logger uses was likely to make the example much more complicated, and was frankly beyond my limited needs. There's probably a simple way to do this in Python that I am not aware of yet though... [...]
I've created issue #8358 https://twistedmatrix.com/trac/ticket/8358 Which is hopefully what you were after - spent a bunch of time reading your impressive process and standards docs so I'm already sure that anything that finds itself in Twisted from this will probably be quite significantly different to this initial suggestion but I don't mind a bit of learning if someone is willing to give me a bit of mentoring me to get this into shape so it can be done as a PR. Cheers /dan -- Daniel Sutcliffe <dansut@gmail.com>
![](https://secure.gravatar.com/avatar/e1554622707bedd9202884900430b838.jpg?s=120&d=mm&r=g)
I wrote a function to do this some time ago, and I forget the exact derivation, but somehow it ended up here: https://github.com/moreati/formatist -glyph
participants (5)
-
Burak Arslan
-
Daniel Sutcliffe
-
Glyph
-
Jeffrey Ollie
-
Kevin Conway