No log output from onUserError in asyncio protocol

[hozn]

This problem is more general than onUserError but this is where I am seeing it. I am using python 3.5 with asyncio.

Specifically, I'm expecting to see an actual message, but instead I see this in the logs:

{msg}: {traceback}

Specifically, this code is the culprit:

self.log.error(
               u'{msg}: {traceback}',
                msg=msg,
                traceback=txaio.failure_format_traceback(fail),
)

Changing this to

self.log.error(
               u'{msg}: {traceback}'.format(
                msg=msg,
                traceback=txaio.failure_format_traceback(fail)),
)

"fixes" the problem; however, the idea of passing kwargs as the args param to the underlying python logger should work. So somewhere in the chain things are going wrong, I guess.

Edit: so after reading python docs, the {}-style strings are not supported for log /messages/ (but they are supported with some non-default configuration for log formatter format strings). More in long-winded comments below.

[meejah]

I think this should have been fixed by #589 -- are you using ApplicationRunner to start? And if so, can you try with master?

[hozn]

Sorry, I should have confirmed it was in master still. I am not using ApplicationRunner but can test my code against master.

[hozn]

This is still broken for me in master. Failing code is here: https://github.com/crossbario/autobahn-python/blob/master/autobahn/wamp/protocol.py#L392

I will see if I can trace through this to understand why the kwargs aren't being used in formatter.

[meejah]

Oh, if you're not using ApplicationRunner you need to arrange for logging to start by calling txaio.start_logging() somewhere...

[hozn]

Oh, weird, ok. I will do that.

Maybe I should be using ApplicationRunner, but I'm in a situation where I need to run several asyncio "services" (e.g. AMQP client, etc.) and it wasn't obvious to me how that'd work w/ ApplicationRunner. (Though I might be overthinking this, coming from doing it in Twisted, where I needed to customize the protocolfactories for inter-component communication.)

On Mon, Feb 8, 2016 at 8:35 PM meejah notifications@github.com wrote:

Oh, if you're not using ApplicationRunner you need to arrange for logging to start by calling txaio.start_logging() somewhere...

— Reply to this email directly or view it on GitHub https://github.com/crossbario/autobahn-python/issues/596#issuecomment-181660632 .

[hozn]

Indeed, starting logging did make it so that the message got logged; however, now it is logging 2 messages. The first is without the tokens replaced, but using my application's already-configured format str, etc. I assume this is because I have already initialized my python loggers. (I'm sure there's a good motivation, but it seems confusing that autobahn isn't simply using the standard python logging configuration -- and maybe setting twisted to use standard logging, assuming that is the problem here?)

My log output (as a result of raise RuntimeError('foo.bar.baz') from my WAMP method:

02-08 20:52:44,564 ERROR    MainThread [root] {msg}: {traceback}
2016-02-08T20:52:44 RuntimeError: foo.bar.baz: Traceback (most recent call last):
  File "/Users/hans/workspace/boss/boss-rating/env/lib/python3.5/site-packages/txaio-2.2.1-py3.5.egg/txaio/aio.py", line 349, in done
    res = f.result()
  File "/usr/local/Cellar/python3/3.5.1/Frameworks/Python.framework/Versions/3.5/lib/python3.5/asyncio/futures.py", line 274, in result
    raise self._exception
  File "/usr/local/Cellar/python3/3.5.1/Frameworks/Python.framework/Versions/3.5/lib/python3.5/asyncio/tasks.py", line 239, in _step
    result = coro.send(None)
  File "/usr/local/Cellar/python3/3.5.1/Frameworks/Python.framework/Versions/3.5/lib/python3.5/asyncio/coroutines.py", line 121, in send
    return self.gen.send(value)
  File "/Users/hans/workspace/boss/boss-rating/boss/rating/wamp.py", line 88, in heartbeat
    raise RuntimeError("foo.bar.baz")
RuntimeError: foo.bar.baz

[meejah]

Hmm, yeah if you've already set up logging elsewhere it should "play nicely" with that too. This is probably actually a txaio bug ...

[meejah]

How exactly are you starting the logging, so I can do a test-case that's the same?

[hozn]

Ok, I now understand better what's going on. In standard python logging, you cannot use str.format-style braces (i.e. {msg}: {traceback}) in log messages. Only positional arguments are supported. So my loggers play nicely as far as emitting the pretty colors and styles I have configured outside of txaio; but the messages do not get values interpolated -- hence only seeing {msg}: {traceback} in my logs.

The txaio.aio._TxaioFileHandler stream handler has a custom emit() method that does not behave like standard python loggers and does interpolate using str.format(). This is why it "works" when i call txaio.start_logging() -- though I really don't want to do this, since I want my application's logging configuration to be honored.

So my recommendation would be to either use %s type formatters in log messages or to simply call .format() on the string and not leave it to the log handler/LogRecord to do the interpolation. Hopefully that makes sense?

[hozn]

I am starting logging by initializing using an old-school logging properties file. My code for initializing logging is something like this:

# ----------------------------------------------------------------------------
# Logging configuration
# ----------------------------------------------------------------------------

[loggers]
keys=root,myapp,autobahn

[handlers]
keys=console

[formatters]
keys = generic,notime

[logger_root]
level=NOTSET
handlers=console

[logger_autobahn]
level=DEBUG
handlers=
qualname=autobahn

[logger_myapp]
level=DEBUG
handlers=
qualname=myapp

[handler_console]
class=StreamHandler
formatter=generic
args=(sys.stdout,)

[handler_syslog]
class = handlers.SysLogHandler
args = ('/dev/log',)
formatter = notime

[formatter_notime]
format = %(threadName)s %(levelname)-5.5s [%(name)s] %(message)s
datefmt = %H:%M:%S

[formatter_generic]
format=%(asctime)s,%(msecs)03d %(levelname)-8s %(log_color)s%(threadName)s [%(name)s] %(message)s
datefmt = %m-%d %H:%M:%S
class = colorlog.ColoredFormatter

And then simply in my app startup:

logging.config.fileConfig('/path/to/logging.ini')

The same problem would happen with a programmatic logging initialization; I can come up with one in a couple minutes.

[hozn]

Here is a simpler version of logging initialization (no config file); I confirmed this also exhibits the same problematic behavior:

    import logging

    ch = logging.StreamHandler()
    ch.setLevel(logging.DEBUG)

    formatter = logging.Formatter("%(levelname)-8s [%(name)s] %(message)s")

    ch.setFormatter(formatter)

    loggers = [logging.getLogger('autobahn'), logging.root]

    for l in loggers:
        l.setLevel(logging.DEBUG)
        l.addHandler(ch)

(It could be even simpler, to just configure the root logger, but hopefully that is clear enough.)

So my proposal was that the log lines could change to:

self.log.error("%s: %s", msg, traceback)

Or maybe better:

self.log.error("{msg}: {traceback}".format(msg=errormessage, traceback=gettraceback()})

I think there might also be a fairly simple way to solve this by creating a LoggerAdapter for txaio .... if you'd like I could probably create a pull request for that concept. I'm sure I don't fully understand the reasoning behind current logging decisions, though.

Actually, the EagerFormattingAdapter from this module probably would meet the needs perfectly: https://github.com/hozn/ensconce/blob/master/ensconce/autolog.py

(Additionally I tend to use the AutoLogger functionality defined there; however, the adapter is reusable on its own and may be useful if you want to transparently support {}-style interpolation.)

[meejah]

@hozn regarding the interpolation, you're partially right, but there's also the fact that autobahn-python supports Twisted and asyncio (and their different default logging systems) from one codebase. We're doing logging more-like Twisted's new logger, which allows delaying the string interpolation as long as possible so that e.g. if you're not printing .debug() messages, then you don't pay the price to format any of those strings. So, no, we won't do .format() ahead of time. But, the aio flavour of txaio does need to hook into the default logging properly so it works with your use-case.

[hozn]

Yup, that makes sense. I believe the logging adapter linked above is designed for that same deferred interpolation; perhaps an adapter is the most compatible approach.

[oberstet]

@hozn just for background: the logging used in Autobahn and Crossbar.io is "structured logging" - this "new" logging system originally comes from Twisted, and because Autobahn supports Twisted and asyncio, supporting/adapting code is in txaio.

The structured logging has a couple of advantages over "classic" logging (that is, logging performatted log messages), and interpolating away structured information before the logger sees it would void the whole point.

So I guess what @meejah says is the actual solution:

.. the aio flavour of txaio does need to hook into the default logging properly so it works with your use-case.

Note: not all code within Autobahn and Crossbar.io has been adjusted to use the new structured logging - but that is a bug also;)

[hozn]

@oberstet, @meejah, Yeah I understand the desire for deferred interpolation. I'm happy to provide a PR for LoggerAdapter solution (I think it would be a full solution), if you like. I don't see an easier option for retrofitting {}-style escape chars into standard logging.

OTOH, standard logging does support deferred interpolation, just using the less-cool, %-based positional args -- i.e. log.debug("My expensive message: %s", traceback) should accomplish the same thing from a performance perspective.

[meejah]

@hozn If you want to dig into this, great!

You'll see in txaio/aio.py that we already have a _TxaioFileHandler and do a logging.getLogger().addHandler(handler) in start_logging -- the trick will be figuring out where/how to do this so that a) your use-case works but b) things still work for people who only call start_logging (and never start Python's "built-in" logging by hand).

[hozn]

Ok, I will take a stab. I can't promise when, but I'm certainly motivated to see it fixed! :)

On Tue, Feb 9, 2016 at 11:37 AM meejah notifications@github.com wrote:

@hozn https://github.com/hozn If you want to dig into this, great!

You'll see in txaio/aio.py that we already have a _TxaioFileHandler and do a logging.getLogger().addHandler(handler) in start_logging -- the trick will be figuring out where/how to do this so that a) your use-case works but b) things still work for people who only call start_logging (and never start Python's "built-in" logging by hand).

— Reply to this email directly or view it on GitHub https://github.com/crossbario/autobahn-python/issues/596#issuecomment-181946919 .

[hozn]

Thanks, guys!