[Twisted-Python] Persuading Python's Logging to use twisted.logger
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
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
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
_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
-- Jeff Ollie
On May 9, 2016, at 1:50 PM, Daniel Sutcliffe
wrote: 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.
Sure, this makes sense.
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.
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.
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...
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
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?
No, there's nothing that would make it impossible. If you want to contribute it.
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.
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
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...
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
On May 9, 2016, at 1:50 PM, Daniel Sutcliffe
wrote: 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.
Sure, this makes sense.
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.
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.
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...
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
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?
No, there's nothing that would make it impossible. If you want to contribute it.
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.
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.handlers>) that converts LogRecord objects to event dictionaries, and then emit them to a < https://twistedmatrix.com/documents/16.1.1/api/twisted.logger.ILogObserver.html> and let us know if you hit any problems.
-glyph
_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
hello, On 05/09/16 23:50, Daniel Sutcliffe wrote:
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
me too :)
'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...
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
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
On May 10, 2016, at 4:23 PM, Daniel Sutcliffe
wrote: 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.
Fantastic!
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.
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.
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.
Yep! This is definitely something handy. Would you mind filing an issue for it? -glyph
On May 10, 2016, at 4:23 PM, Daniel Sutcliffe
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.
On Sat, May 21, 2016 at 9:44 PM, Glyph
Fantastic!
[...]
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.
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.
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... [...]
But hopefully this all makes sense and this can be a start of something much more generically useful.
Yep! This is definitely something handy. Would you mind filing an issue for it?
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
On May 24, 2016, at 4:10 PM, Daniel Sutcliffe
wrote: 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.
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 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