[Twisted-Python] logging

[Christopher Armstrong]

On Sat, Jun 15, 2013 at 2:18 AM, Hynek Schlawack <hs at ox.cx> wrote:
>
> Am 15.06.2013 um 08:18 schrieb Christopher Armstrong <radix at twistedmatrix.com>:
>> What do you think of this for an API that meets in the middle?
>>
>> https://gist.github.com/radeex/5787124
>>
>> This example implementation only concerns itself with the points under
>> debate right now; obviously it's completely unusable in general. But
>> anyway:
>>
>> 1. it supports English logs
>> 2. it doesn't require you to specify a formatting if you want to just
>> log a bunch of data
>> 3. it makes it easy to specify a system (both manually and based on
>> the module your code is in)
>
> I’ve held back from this discussion so far because it seemed to me that I always missed some part of the discussion to fully understand what you’re all talking about. I would like to comment on this concrete proposal though before I hold my peace forever. (NB I’m not replying just to Christopher but try to address everything I saw on the thread so far – I like most of his proposal.)
>
> I find that there’s some kind of false dichotomy brought up in this discussion and API and output are somewhat muddled together a bit (maybe I’m just misunderstanding though – that’s why I didn’t comment until now).

You're right. I didn't make a strong enough point about the fact that
the output formatting isn't important, but I assumed everyone already
knew that. I should have been more clear.


> I personally like my logs 100% structured (except for Exceptions) and still be able to “comment” on events in plain English if I need to.
>
> And I don’t see why comments/events should be special case on output (square brackets in this example). If you have an event called user_error, you can always add a key called error for another “symbol” or just an error_msg if you insist on English. When looking for a certain type of user_error, you simply write an AND clause in your logging software (Kibana or whatever). It’s pretty easy to keep *that* consistent across applications.
>
> For example, *my* log would look like this:
>
> event=user_error peer=127.0.0.1 error=pebkac

The special formatting in the example I gave was only intended for the
dumb file-based format. I thought it was just a nice touch on the spur
of the moment. In practice, I would use this for local logging, but
then set up a log observer that passed raw key/value data to my real
log aggregation/storage/filtering system. I'm making a distinction
between what we show our users (in a twistd.log file) and what we give
to our automated systems (sent over network protocols to logging
systems).

> If the programmer in question hadn’t enough logging pain in their life to see that’s reasonable, they can always do:
>
> event=user_error peer=127.0.0.1 error_msg='Problem exists between keyboard and chair.'
>
> Still perfectly parseable, perfectly readable. And with {!r} easy to achieve. A nice API I would like to have be:
>
> log('user_error', peer=self.transport.getPeer().host, error_msg='Problem exists between keyboard and chair.') – and log figures out itself if it needs to quote. I could also live with them all quoted, i.e.:
>
> event='user_error' peer='127.0.0.1' error='pebkac'
>
> to have less special cases.

It sounds like you're arguing that the human-readable *.log format
should be closer to the simple key/value representation that we use
underneath.

Would you also argue that instead of having a log line that looks like:

2013-06-15 10:24:21-0500 [-] Server Shut Down.

We should actually format them (in twistd.log) like this?

time=1371331461.0 system='-' msg='Server Shut Down.'

> I hope that makes some sense, the point I’m trying to make that events don’t need to be distinct by themselves. If you enforce that, you’re forcing structure on them which you could spread over multiple fields that are *much* more pleasant to parse.

So, if I had my own way, "event" would be a required argument to the
log() function in my example, so that the only thing I'm forcing on
the structure of a log message is that you *have* an event argument.

But I'm pretty sure that's not going to fly. :-) So the only reason I
wanted to support "event" in a special way in my example is to
emphasize and encourage its use.

> Hynek


--
Christopher Armstrong
http://radix.twistedmatrix.com/
http://planet-if.com/