[Twisted-Python] Persuading Python's Logging to use twisted.logger

Discussion:

Daniel Sutcliffe

2016-05-09 20:50:39 UTC

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 <***@gmail.com>

Jeffrey Ollie

2016-05-09 21:54:34 UTC

Permalink

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])

Post by 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
--
_______________________________________________
Twisted-Python mailing list
http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python

--
Jeff Ollie

Glyph

2016-05-09 22:16:17 UTC

Permalink

Sure, this makes sense.

Post by Daniel Sutcliffe
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.

Post by Daniel Sutcliffe
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

Post by Daniel Sutcliffe
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.

Post by Daniel Sutcliffe
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.

Post by Daniel Sutcliffe
If anyone can enlighten me I would be most appreciative,

Kevin Conway

2016-05-10 01:16:35 UTC

Permalink

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.

Post by Daniel Sutcliffe

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.

Post by Daniel Sutcliffe
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
http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python

Burak Arslan

2016-05-10 05:22:18 UTC

Permalink

hello,

me too :)

Post by Daniel Sutcliffe
'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/neurons/daemon/config.py#L673

best,
burak

Daniel Sutcliffe

2016-05-10 23:23:08 UTC

Permalink

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 <***@gmail.com>

Glyph

2016-05-22 01:44:32 UTC

Permalink

Post by 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.

Fantastic!

Post by Daniel Sutcliffe
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.

Post by Daniel Sutcliffe
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,
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,
}
self._log = Logger()
logging.Handler.__init__(self)
pass
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)
self.handleError(record)
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)])
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

Daniel Sutcliffe

2016-05-24 23:10:56 UTC

Permalink

Post by Glyph

Post by 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.

Fantastic!

[...]

Post by Glyph

Post by Daniel Sutcliffe
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.

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...

[...]

Post by Glyph

Post by Daniel Sutcliffe
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 <***@gmail.com>

Glyph

2016-05-25 00:05:41 UTC

Permalink

Post by Daniel Sutcliffe

Post by Glyph
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 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