Logging content of a dict just prints '1970-01-01T01:00:00'

[aberres]

Stumbled upon this in my application which uses autobahn-python.

See the following sample code:

import logging

txaio.use_asyncio()
txaio.start_logging(level='debug')

logging.info('Working dict output: %s', str({'a': 1}))

logging.info('Broken dict output: %s', {'a': 1})

Expectation is that the content of the dict is logged in both cases.

Actual output:

2017-09-19T11:54:41 Working dict output: {'a': 1} 1970-01-01T01:00:00

Expected output:

2017-09-19T11:54:41 Working dict output: {'a': 1} 2017-09-19T11:54:41 Broken dict output: {'a': 1}

[meejah]

That's "interesting" output, but also that's not how the logging should be used -- you should use the {name} syntax, like so:

logging.info('Some dict output: {a}', a=1)

[meejah]

(That said, I can't explain what happens in the second case ;) )

[aberres]

Thanks for the reply.

I've never seen the name syntax in a logging call. And does not seem to work in a quick test of mine.

{'a': 1} is just an example in my case. It could be any more or less complex dict. Without starting txaio logging this works as expected.

[meejah]

That syntax is a new string-interpolation syntax in python; the names in {}'s correspond to keyword args. Even with the other syntax, you wouldn't typically pass a dict -- instead a tuple. Anyway, this is based on Twisted's new logger syntax to provide semi-structured logging.

(How does the dict syntax ever work? dicts don't have order, so without naming the strings it can't possibly work...?)

[meejah]

I think we should leave this bug open as an "improve documentation" bug; we don't explicitly describe this syntax (even though it sort-of appears in the examples): http://txaio.readthedocs.io/en/latest/programming-guide.html#logging

[dol-sen]

you can do the same with %s syntax

eg: logging.debug("foo bar: %(foo)s, %(bar)s", {'foo': 'asdf', 'bar': 'qwerty'})

the .format equivalent of his original code would be to just replace the %s with {} as the .format method does not require variable names be filled in. In that case, just like %s syntax, the substitutions must be in the correct order.

the .format system is just a newer form of %s imho. Personally I have been sticking with %s. I only use .format form when working on someone else's code that is using that method.

I find it is very useful to log the contents of various variables at points in your code to help debug/monitor how things are working. I often add similar logging statements to log a list or dictionary's contents. But I have normally wrapped them in str(foo) to ensure proper conversion. Logging is not the same as the print command that will always output the str(foo) form.

[aberres]

I am a bit confused. This is valid Python, isn't it?

import logging

logging.warning('My state is messed up: %s', {'a': 1})

The docs state

When you’re using libraries that are already doing logging, but not using the txaio APIs, you shouldn’t need to do anything.

When I use the above code with txaio, e.g., because I start to use autoboahn-python, it will stop working. Not a big problem but more than missing documentation IMHO.

[meejah]

txaio is a compatibility library so we can write "the same" code across asyncio and Twisted. The logging system in here is built as a mostly-thin wrapper over Twisted's new logging system, giving us semi-structured logging -- that is, you can completely ignore the format string and just log the kwargs you get (which will be objects).

This also has speed benefits: because the string interpolation is delayed, un-logged levels (e.g. .trace or .debug) never get interpolated into strings.

If you really do want to do your own string-interpolation stuff, you can follow a pattern like this: log.info("{msg}", msg="some %s" % ("thing",))

[meejah]

Hmm, actually perhaps I glossed over the original report too quickly -- that code is indeed using the logging library (that is not txaio). So what's happening is this: it is creating a string which has { and } characters in it (because it repr'd a dict) and then the txaio (or Twisted) logger is trying to do string-interpolation on that.

So, either that statement from the docs can't be true, or something has to be done to txaio logging in the case of getting a single string containing "{" characters but no kwargs at all. Is there something that can be done here ...?