Add a new interface to twisted.python.log which encourages structured logging

[ashfall]

This interface should make it easy to log everything that is germane to a particular event efficiently. Particularly: where (what module, what class) is it from? It should also make it a little more convenient to actually structure your message and think about it beforehand; in other words it should make it ever so slightly harder to just slap some random text into the log.

Here's a basic sketch of what I mean:

Here are some sketches on how it might be used:

doingSomeStuff = log.Event("doing some stuff to %(a)s and %(b)s", __name__)
def stuff(a, b):
    doingSomeStuff(a=a, b=b)

# or
events = log.Template.forModule(__name__)
doingSomeStuff = events.event("doing some stuff to %(a)s and %(b)s")
doingOtherStuff = events.event("doing other stuff to %(c)s")

# and/or also
class MyFunClass(object):
    logHadFun = log.EventDescriptor("had some fun with %(c)s and %(d)s")
    def haveFun(self, c, d):
       self.logHadFun(c=c, d=d, audience=self.log.coreDeveloper)

Another interesting field is who might want to know about it. Examples of who might want to know:

• administrators running the thing that is doing the logging
• local end users
• developers of the module that is doing the logging (debugging messages)
• developers of code that calls the module doing the logging (like, for example, a deprecation)
• users of a remote system (i.e.; I'm sending email to some server, it's misconfigured)
• authors of the software run on a remote system (i.e.; I'm sending email to some server, it's got a bug where it emits out-of-spec or gibberish protocol messages)

There should be separate tickets filed to make use of this information in various ways as well. For example, we should be able to filter the messages by audience, or by module, or by package (in other words, hierarchically by FQPN). The log could then be configured with assertions like "I'm a developer of txfoo, which uses twisted.bar and twisted.baz", or "I'm a system administrator".

 Here is the mailing list thread that discusses this.

[glyph]

This ticket needs some more detail, even beyond what's in the linked mailing list message.

(Also, I updated the description to refer to gmane, since pipermail is awful and un-navigable and unreadable, especially with regard to messages that have HTML in them, and gmane has relatively nice presentation.)

[exarkun]

It doesn't seem like anything particularly radical is being proposed here, as far as functionality in the twisted.python.log module goes. It looks like it's possible to log exactly these events without adding any new features to twisted.python.log. While some changes to that module might make it easier to do so, since it is already possible, perhaps before doing this, we could try actually writing some code that logs events this way and then see if something useful happens as a result.

In other words, resolving this ticket with some APIs changes in twisted.python.log today would strike me as rather premature.

[glyph]

Replying to exarkun:

It doesn't seem like anything particularly radical is being proposed here, as far as functionality in the twisted.python.log module goes. It looks like it's possible to log exactly these events without adding any new features to twisted.python.log. While some changes to that module might make it easier to do so, since it is already possible, perhaps before doing this, we could try actually writing some code that logs events this way and then see if something useful happens as a result. In other words, resolving this ticket with some APIs changes in twisted.python.log today would strike me as rather premature.

I think we should actually be adding some API to twisted.python.log sooner rather than later in support of this goal. API structure encourages developer behavior, and right now the API we've got is encouraging the wrong sort of behavior (lots of unstructured junk being put into the log).

We can of course try to make some policy, but both following and enforcing policy is tedious, manual work that is easy to screw up. We should do as little of it as possible. A policy that says "use API X instead of API Y" is a lot easier to enforce than one that says "Here is an enumeration of all the things that you put into a log message, and you should really put them in, and here are some code snippets showing how to put them in".

Looking over my sketches in the light of a new day though, I think the only one that is really interesting is "log.event()". Adding that API could serve multiple purposes.

1. As shown above, log.event creates a callable which itself does not take a message argument. This conveys the intent of structured logging rather neatly. I think my other examples are somewhat misguided by comparison.
2. As we add new types of information that should be present in log messages, log.event() could be expanded to automatically emit warnings. This would be a lot easier than grepping around for log.msg calls that are missing certain arguments. Of course, thorough test coverage would fix the problem for Twisted itself, but experience shows that applications don't always have such great coverage, especially for logging. Sticking it at the module level would ensure that if you had any test coverage at all you'd find out about potentially missing log information.
3. Having log.event build an object with some structure would also make it easier to write unit tests for log messages; the format string could be written only in one place, rather than copied into the test. (Comparing to module-level constants is reasonabe testing practice.)

Given that the actual code involved would be extremely simple, I think that this would be a worthwhile modification to make.

[exarkun]

Can we at least wait to implement this until you have a specification that you don't feel like changing twice a day? :)

That is my humorous way of saying that I don't think the difficulty here is the implementation. I'm certain we could introduce an API that will encourage new behavior from developers. Where I think the difficulty lies is selecting an API that encourage useful behavior from developers. log.event looks like an interesting idea, and I like a lot of the things you point out about it. Do you know of any existing libraries that work this way that we could look at? Can we consider what tools we would be able to write to take advantage of the use of such an API? Can we at least think about two or three specific areas of Twisted that would benefit from this (there is no shortage of tickets relating to problems with logging, it shouldn't be hard to find some use cases)?

[glyph]

Replying to exarkun:

Can we at least wait to implement this until you have a specification that you don't feel like changing twice a day? :)

I sure haven't implemented anything yet! Have you? :)

That is my humorous way of saying that I don't think the difficulty here is the implementation. I'm certain we could introduce an API that will encourage new behavior from developers. Where I think the difficulty lies is selecting an API that encourage useful behavior from developers.

Agreed.

log.event looks like an interesting idea, and I like a lot of the things you point out about it.

Do you know of any existing libraries that work this way that we could look at?

 Foolscap,  twiggy. But I don't have a lot of experience with either. I had an impromptu mini-summit about logging with the authors of both of these libraries at PyCon 2011, and everyone was very excited about the possibilities for collaboration, but nothing much came of it.

Can we consider what tools we would be able to write to take advantage of the use of such an API?

Absolutely. The main one that comes to mind immediately is log filtering, both turning down noisy logs (for applications where they don't matter) and turning up informative logs (when a user is trying to track down a bug). But we should discuss others.

Can we at least think about two or three specific areas of Twisted that would benefit from this (there is no shortage of tickets relating to problems with logging, it shouldn't be hard to find some use cases)?

Here's an initial example. I hope someone else will add others.