On Jun 13, 2013, at 4:16 PM, Christopher Armstrong wrote:

On Thu, Jun 13, 2013 at 5:14 PM, Glyph wrote:

...

Hello everybody. Today I'd like to talk about everyone's favorite subsystem within Twisted: logging.

There are a number of problems with Twisted's logging system.

Thanks for writing up this email. I'd like to help out with this effort.

...

For a long time, there's been consensus among at least a few core Twisted developers that log messages ought to be specified in terms of a format message and several relevant keyword arguments, so that tools can extract the values of the keyword arguments without parsing ad-hoc messages or using regexes. In other words, like this:

log.msg(format="Foo happened. Relevant information includes: " "bar=%(bar)s baz=%(baz)s boz=%(boz)s", bar=bar, baz=baz, boz=boz)

Basically, the conclusion I've come to is that English isn't very useful in logs. It's usually badly written, uninformative, and hard to filter on. The main thing that I find really important is having what I call an "event name", which has the following properties:

So, I confess that one of my long-term goals here is to de-emphasize the english-language log file and eventually get Twisted using a structured log file as standard. However, to just do that immediately would probably break everybody's workflow.

1. human readable 2. computer readable 3. mandatory 4. unique across a codebase, and specific to the physical logging statement that it's being passed to.

I agree with some of these properties and disagree with others, but you didn't really say *why* these properties are useful. So let me see if I can explain the properties I think are good, starting with the use-case rather than the other way 'round: There are several activities that one performs with logging: while one's writing the code, inserting a log message while one's administering a system, reading the history of all logged messages while one's monitoring a system, selecting criteria for future relevant log messages to alert on while one's debugging a system, selecting criteria for past relevant log messages to display while one's documenting a system, explaining what various log messages mean and how they may be used for the other use-cases English (by which I mean "localizable human-readable text") is useful for use-cases 1. and 2. When you're writing the log message, selecting a unique identifier is tedious; you just want to type in what happened and move on. When you're reading the messages, it's easier to puzzle out some english text than to go to the documentation for each and every message. Globally unique identifiers are useful for use-cases 3 and 4. Filtering messages by random snippets of English text is tedious, error-prone and fragile. (It doesn't help if a message is unique "across a codebase" if that codebase is a library and it conflicts with another library that an application uses.) Stable identifiers are particularly useful for use-cases 3 and 5. While human-readability is useful for all cases, that generally conflicts with the long-term stability of an identifier. If you write a monitoring system that looks at log messages. I think that we can satisfy all of these requirements by expanding the notion of an "identifier" a bit. In the interests of not spending ten hours working on each message to this list, I'll leave this one on a cliffhanger, so you can eagerly await the next episode!

So, for example:

def frag_message_received(self, fragger, fragee, weapon): self.log("frag", fragger=fragger, fraggee=fragee, weapon=weapon) ...

Now, your smart log filterer can just filter by event="frag" instead of message="Frag for \w+ received with weapon \w+" or whatever.

This is just how I've done things in practice, and it has worked very well for fairly large projects, but there are improvements that I can think of. For example, the event name should probably be based on a hierarchy of composable logger objects (kinda like the one David Reid wrote) so that it's easier to maintain uniqueness in a large codebase.

(Hey David, you should write an email about that logging class :)

On Fri, Jun 14, 2013 at 6:40 PM, Glyph wrote:

On Jun 14, 2013, at 3:43 PM, Glyph wrote:

I think that we can satisfy all of these requirements by expanding the notion of an "identifier" a bit.

In our last episode, I mentioned that an identifier should have several properties:

human readable (and potentially non-unique) for ease of writing messages and reading them to get a general sense of the behavior of a system globally unique (and potentially hard to read) for ease of filtering and monitoring long-term (and potentially unique to humans) for ease of writing tools to deal with particular messages, whose exact details may change over time

I think we can achieve all of these things by making there be multiple ways to identify a log message. Here's how that could work:

When you are first writing a log message, just do this, as you usually would; toss off some crummy english message:

log.info("hey check it out I just {verb}ed a {noun}", verb=request.method, noun=request.uri)

Asking the author to write a log message with more detail and care than this is basically just a recipe for disappointment :).

Later, someone might want to instrument these messages. We've all agreed that re.findall("hey check it out.*") is a crummy way to do this. The obvious thing would be something like this:

tapEventsLike(myObserver, publisher, log_format="hey check it out I just {verb}ed a {noun}")

That's fine to start with, of course, but it's not very resilient to changes in the code; the developer might later change this line to read:

log.info("hey check it out I just {verb}ed a {noun} and got a {result}", verb=request.method, noun=request.uri, result=request.response.status)

Now the log tap is broken, and there's no reasonable way to fix it; the format string doesn't have a place that it could go.

But, the 'log' in the above example is a logger object associated with a class or module, and so has 3 persistent pieces of information it can use to build a long-term identifier that the event tap can use. We could reflect that in an API like this:

from example.module import log tapEventsLike(myObserver, publisher, log_id=log.idForOriginalFormat("hey check it out I just {verb}ed a {noun}"))

which could be computed offline, and then specified like this, to be even more resilient to API changes:

tapEventsLike(myObserver, publisher, log_id='604e45b5-2d41-5ba5-9ae1-7205163c3e3f')

That string, of course, is computed like this:

...

...

...

import uuid from urllib import urlencode uri = "http://twistedmatrix.com/ns/log/?" + urlencode(dict(format="hey check it out I just {verb}ed a {noun}", module="example.module")) uuid.uuid5(uuid.NAMESPACE_URL, uri) UUID('604e45b5-2d41-5ba5-9ae1-7205163c3e3f')

(Although if we decide we like this system, we could of course go with a helpful command-line tool to generate these for you.)

As you evolve your codebase to take logging more seriously, you could change the original 'log.info' call to instead look like this:

verbANoun = log.declare(

"hey check it out I just {verb}ed a {noun} and got a {result}",

log_id='604e45b5-2d41-5ba5-9ae1-7205163c3e3f',

)

# ...

verbANoun(verb=request.method, noun=request.uri, result=request.response.status)

and then monitoring can be accomplished via public API:

from example.module import verbANoun verbANoun.tap(myObserver, theLogPublisher)

So, after some evolution, our message has 3 identifiers:

the original format string, which was easy to come up with on the spot, and need not be unique a UUID, that was automatically generated but can be carried around to allow for cleaning up the codebase and the message without breaking any code doing monitoring an API name that the logger and the logee can use to agree on the semantics of a particular message

Best of all, you can get this even for the plethora of existing log messages within Twisted that aren't even using structured values, as we evolve them to have more metadata. You also now have the ability to localize the format string, if you want to start presenting these log messages in contexts other than log files for system administrators.

Thoughts?

There's... a lot here. I'm overwhelmed by how complex this system would be, and I think that end users would be as well. I don't really want to put UUIDs into my source code, whether I type them or paste them, and I don't want to have to invoke command line tools to figure out what those UUIDs in order to be a good developer. I think there's basically no practical benefit over the hierarchical "system" + event-identifier system, where: 1. it's trivial to specify a hierarchical, easy-to-read "system" key that has a small-ish scope 2. you think of a unique event name in that small-ish scope and type it out. I'm beginning to think #1 is the most important of all, but I think I'll continue to use event-names to describe all my log statements. As I said in my response to Wilfredo, I think it's really important to stop specifying the "system" for application code in Twisted. The application's code should not be considered a part of the HTTP protocol's system. There are also other problems with the way we use system, like putting extra random data like request ID in there. -- Christopher Armstrong http://radix.twistedmatrix.com/ http://planet-if.com/

On 06/15/2013 06:48 AM, Christopher Armstrong wrote:

There's... a lot here. I'm overwhelmed by how complex this system would be, and I think that end users would be as well. I don't really want to put UUIDs into my source code, whether I type them or paste them, and I don't want to have to invoke command line tools to figure out what those UUIDs in order to be a good developer.

+1. I like the general idea of better logging via keyword args and an "id", but I strongly dislike the idea of using UUIDs as log message identifiers. In fact, I'll go so far as to say I defintely wouldn't use such a system, and for Twisted to migrate to it would actually reduce the utility of the in-built logging, because I'd have to build and maintain something to translate Twisted log messages I cared about into whatever system I built to do my own logging :o(

I think there's basically no practical benefit over the hierarchical "system" + event-identifier system, where:

+1. Hierarchial IDs also permit prefix-based wildcarding: log.observe("twisted.factory.*") log.exclude("twisted.factory.http.*") log.observe("myapp.thing") log.observe("txSomeProject.event.*") Obviously this is just an example; I haven't put any real thought into it.

1. it's trivial to specify a hierarchical, easy-to-read "system" key that has a small-ish scope 2. you think of a unique event name in that small-ish scope and type it out.

I'm beginning to think #1 is the most important of all, but I think I'll continue to use event-names to describe all my log statements.

I pretty much agree with all of this.

On 06/15/2013 12:13 PM, Glyph wrote:

I am really, really puzzled by this reaction. I am wondering if you read my message carefully, or if I didn't express myself well.

Careful re-reading of the very last bit of your message suggests I may have misunderstood. I think I understand the "final" stage, and in that situation the UUID is invisible, correct? It's hidden behind the declaration of a "log event" object which can be called to emit or observe said events. That seems fine, though I'm not sure what the UUID *does* in that situation - route/match is via python object access, no? I *think* I now understand the intermediate stage, where the log events are emitted by old code, and observed by UUID. You're suggesting calculating the UUID from the module name and static data (format string). I guess that's no worse than any other solution - until the log emitter is converted to a newer/better API, there's no great way to observe it. Before we proceed, can you confirm I've understood your proposal correctly?

Hi, On Thu, Jun 13, 2013 at 6:41 PM, Facundo Batista wrote:

Mmm... which is the problem with doing:

log.msg("Foo happened. Relevant information includes: " "bar=%s baz=%s boz=%s", bar, baz, boz)

Is way more readable, and in the practice the code will just need to do something like:

def msg(format_string, *args): try: line = format_string % args except: # something clever

No regexes involved, and very cheap in the case where it works.

And this is a personal opinion: the "working way" (where programmed coded all ok) should be as cheap as possible. If something is wrong with the logging line, it must not crash, and I don't care if it's expensive, but that line will be fixed, and will work ok, and from there to the future it will be cheap.

You might be interested in logfmt (which has implementations for Ruby, Javascript and Go at least): https://github.com/jkakar/logfmt-python The example above could be written in a logfmt-compatible way as: log.msg("message=Foo happened bar=%s baz=%s boz=%s", bar, baz, boz) This is as readable as what you have above while being a touch easier to parse. The main point that logs are data and should emitted in a way that makes consuming them easy is a good one regardless of the format you choose. I do wonder if logfmt is unnecessary and if simply dumping JSON objects would be just as good... logfmt is slightly prettier but the JSON approach has the advantage of having a parser available in basically every language anyone would ever care about. Thanks, J.

On 07:45 pm, radix@twistedmatrix.com wrote:

On Fri, Jun 14, 2013 at 1:41 AM, Jamu Kakar wrote:

...

Hi,

On Thu, Jun 13, 2013 at 6:41 PM, Facundo Batista wrote:

...

Mmm... which is the problem with doing:

log.msg("Foo happened. Relevant information includes: " "bar=%s baz=%s boz=%s", bar, baz, boz)

Is way more readable, and in the practice the code will just need to do something like:

The example above could be written in a logfmt-compatible way as:

log.msg("message=Foo happened bar=%s baz=%s boz=%s", bar, baz, boz)

This is as readable as what you have above while being a touch easier to parse. The main point that logs are data and should emitted in a way that makes consuming them easy is a good one regardless of the format you choose. I do wonder if logfmt is unnecessary and if simply dumping JSON objects would be just as good... logfmt is slightly prettier but the JSON approach has the advantage of having a parser available in basically every language anyone would ever care about.

I think both of these should be avoided because they require the user to specify string interpolation themselves. I'd prefer to avoid that entirely, by default.

log.msg("Foo happened**", bar=bar, baz=baz, boz=boz)

This is better because:

1. it keeps the data structured 2. it is a lot less typing

** I would prefer this part to be "foo", but I'll keep these discussions separate :)

I think that I agree with this, except I wonder if you could supply some more realistic examples here. Let's say I have a somewhat complex 50kloc application with a log event emitted around once every 10 lines. After I use up "foo", "bar", "baz", and "quux" I start having to refer to the hacker dictionary. This doesn't get me very close to the 5000 event identifiers I'll need. How does someone come up with this in the real world? Jean-Paul

On Fri, Jun 14, 2013 at 5:43 PM, Christopher Armstrong wrote:

If you're concerned about universal uniqueness, there are two ways I can think of doing it, both of which should basically have a similar API as far as where concerns are in your code:

- make the event name hierarchical with a root being identifier by your project

"SpaceCombat.server.db.scheduled-compaction-failed"

(you shouldn't need to type out this full event name every time you type a log.msg() statement; that's not a hard problem to solve)

- put a hierarchical designator into the "system" field

log("scheduled-compaction-failed", system="SpaceCombat.server.db")

I think I like the idea of using "system" for this, since that basically seems like the original intent.

Sorry, let me clarify. You shouldn't need to type out "SpaceCombat.server.db" multiple times in your log statements *ever*, in either case above. I imagine a system like the following: spacecombat/server/db.py: from twisted.python import log logger = log.BoundLogger(log, system="SpaceCombat.server.db") logger.msg("scheduled-compaction-failed") -- Christopher Armstrong http://radix.twistedmatrix.com/ http://planet-if.com/

On Fri, Jun 14, 2013 at 6:20 PM, Wilfredo Sánchez Vega wrote:

Christopher Armstrong wrote:

logger.msg("scheduled-compaction-failed")

I'm confused. You don't want to use English, but… why not change your hyphens to spaces and call it a day? Also, why did it fail?

Because as soon as you introduce spaces, you're probably going to introduce capitalization and punctuation as well, and then all of a sudden your log statements are a lot harder to filter.

Here's a fuller example, modified to fit the API I'm using:

from twisted.python.log import Logger

log = Logger()

try: scheduleCompaction(…) except Exception as e: log.error("Scheduled compaction failed: {why}", why=e, id=2C09A260-184C-44F9-B11F-E12B26B26C9C)

Some things to note about this:

- `log = Logger()` does some magic so that log.namespace is the name of your module "spacecombat.server.db". So, your "system" identifier is perhaps covered by that, with no typing.

I like making it trivial to specify the system, but I don't think it's a good idea to do it based on the module name. Code moves around a lot, and you may have lots of implementation modules for one logical system. I think it's fine to just have people say 'log = Logger("spacecombat.server.db")' at the top of their file.

- I have a format string instead of a fixed string. An observer emitting text can emit something informative. I know you think that text logs aren't useful, but a lot of us do. And you can use observers that ignore this format. Maybe there's an argument for making the format optional...

I think the argument about English is separate from the argument about whether we should require specifying the interpolation in the strings.

- Formatting isn't done here, so... cheap if you don't use it in any observers.

- I added a GUID id argument since you seem keen, I think on a unique key to identify the code point at which the message is logged. It's not used in the format, but an observer storing things in a DB could use that to take you straight to the relevant code, or identify multiple instances of that message, etc. if the format string isn't how you want to do that.

I don't think it's worth coming up with some kind of GUID-based system, because I don't think anyone's going to go to the trouble to use it, and I think it basically offers no practical benefit over simple event names. So, again, I want to reiterate that I wasn't really proposing mandating an event name and enforcing these rules on it. As far as actual *proposals* go, I have these ones, that are all independent: 1. include all keyword arguments in log output without requiring specifying the formatting in the string 2. make it really easy to specify the "system" 3. stop affecting the "system" of application code based on the framework code that's running the application code (i.e., don't use callWithContext to specify the system any more) Of these, I think #2 and #3 have the most benefit; I can do #1 with my own logging statements just fine, and while IMO it'd be nice if the whole world adopted a nice identifier-based system, the lion's share of the benefit comes from my use of it consistently in the application's codebase. -- Christopher Armstrong http://radix.twistedmatrix.com/ http://planet-if.com/

Am 15.06.2013 um 08:18 schrieb Christopher Armstrong :

...

As far as actual *proposals* go, I have these ones, that are all independent:

1. include all keyword arguments in log output without requiring specifying the formatting in the string 2. make it really easy to specify the "system" 3. stop affecting the "system" of application code based on the framework code that's running the application code (i.e., don't use callWithContext to specify the system any more)

Of these, I think #2 and #3 have the most benefit; I can do #1 with my own logging statements just fine, and while IMO it'd be nice if the whole world adopted a nice identifier-based system, the lion's share of the benefit comes from my use of it consistently in the application's codebase.

This conversation has gotten pretty sprawling; time to reel it in with some code.

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). 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 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. 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. Regards, Hynek P.S. For convenience, I usually write a log method in Twisted protocols that prepends the messages with state data, peer IP etc, but that JFTR.

On Jun 15, 2013, at 8:33 AM, Christopher Armstrong wrote:

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'm actually arguing that, in the log *file* it should look like this: {"log_format": "{service} service shut down.", "log_system": "-", "log_time": 1371331461.0, "service": "dns"} When a human actually reads it (with, as a straw man, 'python -m twisted.python.log read twistd.log.json'), I'd rather it still read somewhat like the above starting '2013...': except, for example, with the time translated into their local timezone (or the timezone of the computer where they're reading the logs, at least). But I'm not saying that we should change the default twistd.log format for now; I'm sure there's tons of tooling built up around the ad-hoc text-based nature of it as it is and I wouldn't want to break that. I'm just saying that we should add additional options for logging to things other than plain text files, and those are the things that we should build tools to get information back out of. -glyph

On Sat, Jun 15, 2013 at 6:37 AM, Glyph wrote:

On Jun 14, 2013, at 11:18 PM, Christopher Armstrong wrote:

This conversation has gotten pretty sprawling; time to reel it in with some code.

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)

First off, thanks again for taking the time to correspond about this, I'm very happy for this conversation to be attracting attention and making progress :).

Moving right along...

This code is relying on the semantics of the existing log.msg() call (which are bad, for the reasons I enumerated in the start of this thread), right down to the dependence on %-formatting. The main thing I'm interested in at the moment is actually fixing those semantics to be more useful; the specific thing we're talking about here, persistent log identifiers, is interesting to me at the moment mostly as it relates to that.

I realize you might just be relying on it for familiarity, you might not have had time to read the whole new thing, so I'm not trying to tear down your idea based on that alone :).

Yeah... I feel like a lot of the things you say in this email aren't related to the point I was trying to get across, which was the interface and effect, not the implementation of it.

But Wilfredo already implemented a thing which addresses the namespacing-of-log-messaages issue, and it does about 2/3 of what your proposal already does (except it has, like, tests and stuff). Right down to the _getframe() hack (although http://trac.calendarserver.org/browser/CalendarServer/trunk/twext/python/log... uses inspect.currentframe() which has a public-sounding name at least :)). As I mentioned in my immediately-previous reply, the logger's 'namespace' does not need to be the same as your module name, so it can be a "more persistent" identifier if you have one.

More significantly, you're actually going to the trouble of constructing a format string. This produces output in an ad-hoc format: '='-separated str()s of your log keys (although only the ones you pass directly in your message; those annotating or augmenting the message at subsequent points by other publishers / observers are ignored), which you are presumably relying upon being smooshed into a plain-text log file, right along side many other messages which do not fit this format. Presumably this could lead to issues like traceback lines with '=' assignments in them showing up in whatever kind of ad-hoc log-analysis you want to do later, and ambiguous unparseable results if any fields in the log message have a '=' and a space in their repr.

Let's not make it the responsibility of the emitter, or the format string, to get those values into a text log file that can be scanned with a regex (albeit in the case of your proposal, a much-simplified regex). Let's push that responsibility down into the log observer, and actually save it as structured data and *parse* it later.

As all the hip young kids will tell you, this type of data should be persisted with JSON, but we should probably have code to support multiple formats. Another advantage of serializing and parsing the logs as structured data would allow tools written to work on a "live" log observer to also analyze persistent logs in at least a similar way, if not entirely the same way.

(An object that has survived the grim ordeal of translation to and from JSON will surely be made less by the process, and can't be treated quite the same way by a log observer; but, as I'm sure you'll agree, this is probably better than the alternative of Pickle. An unpickled object will be brought fully back to life, but, in the words of the recent NIN release, it will have "came back haunted".)

Maybe we could even do a SQLite observer. Honestly I'm not sure which format is best.

So, I responded to Hynek about this confusion already, so I'll let you read that. I have always assumed that twistd.log would continue to be vaguely human-readable, with special formatting for several of the keys. I also assume that developers will be able to hook up additional observers to save out .concatenated-json files, or stream to some network protocol, or whatever. The little bit of formatting my example does is just a minor convenience for the people still logging at twistd.log files. The arguments you're making now sounds ilke you want to et rid of that ad-hoc formatting; is that true? So, instead of 2013-06-15 10:24:21-0500 [-] Server Shut Down. we should have this? time=1371331461.0 system='-' msg='Server Shut Down.'

Since it's also important to be able to *filter* logs, and avoid the work of formatting or serializing them at all, it would be best to push this work as far down the line as possible. The construction of the format string is itself a whole ton of string-copying, the sort of thing I'd really like to avoid. (Last I measured, dictionary operations that don't cause a reallocation - and most don't, unless you're inserting in a long loop - are cheaper than even apparently small string copies.)

In fact, it strikes me that perhaps *this* is the feature we should be talking about implementing: writing a structured log observer and parser, firming up the contract between emitters and observers so it's clear what to do with data that can't be serialized - more than exactly which fields we use to identify messages that are interesting to us.

Relatedly, we could make log analysis a first-class task; instead of assuming someone will grep the log file later, actually provide a simple log-query tool that users can plug their code into, presuming they're using a log format which is cleanly parseable. Maybe have a little web resource that serves up nicely formatted views of your logs.

I can implement the UUID thing as a completely separate ticket and we can discuss it on its own merits; meanwhile, you can happily add log IDs to everything in your applications. I'd be quite happy to table this part of the conversation for a separate ticket; I just thought it would be a nice thing that could fall out of some of the other parts of a new logging system.

Yeah, I'm sorry that this has gotten so much scope-creep. I'll reiterate that I think redoing what I've been speaking about as the "system" key is most important (but maybe it should be called something other than "system", since you've clarified what its intent was in another email). -- Christopher Armstrong http://radix.twistedmatrix.com/ http://planet-if.com/

On Jun 14, 2013, at 10:43 PM, Christopher Armstrong wrote:

I don't think it's worth coming up with some kind of GUID-based system, because I don't think anyone's going to go to the trouble to use it, and I think it basically offers no practical benefit over simple event names.

Here are the benefits over simple event names: It's opaque, so as code moves around, it doesn't look dated or wrong. Your 'system' argument looks a whole lot like a FQPN, but as you keep saying, code moves around a lot. Having a *second* dotted identifier that looks a lot like the module name is going to look a lot like cruft to someone when it stops matching a module name, they're going to be motivated to "clean it up", and then the "cleaned up" version is going to break everyone's logging instrumentation. Since UUIDs can be derived from other information, you can start off without one and add one later. If you didn't feel like specifying one in the first place with your log messages, then you're stuck until the monitoring and application code that comes to some agreement. My view of our present disagreement seems to come down to this: I believe that nobody is going to bother to do logging right in the first place (particularly, they are not going to take the time to specify or enumerate the types of events that are interesting that their system emits), and will only realize they need to extract interesting stuff from their logs later. I think we need to provide the best possible support for the developer "later" (the opaque UUID they can associate with an API symbol) and the monitoring folks "now" (the derived UUID that they can use in place of a gross and broken-in-the-future regex). This doesn't mean that the UUID magically makes monitoring always work in the future; developers can still change their format strings willy-nilly. But, it at least provides a mechanism that they *could* use to avoid breakage if everyone believes it should be avoided. I understand your point to be that you think that people should, and that they therefore will, go to the trouble to categorize every thing that gets logged as they're writing the logging stuff. In support of my argument, I offer as evidence the unfortunate mess that is Twisted's current ad-hoc usage of logging, plus the existence of Splunk, a publicly-traded company whose whole reason for existing is that they can run regexes over poorly-structured logs to extract useful information and statistics from them :-). To be fair, one element in support of your argument is that you managed to write a system that used this idiom and it worked well in practice. I'm sure that it did, and I think it's a good thing for people to adopt. My concern is that lots of useful log-worthy events are coming out of an open-source library that won't be exposed to the discipline that a particular team adopts for logging. Finally, it's worth noting that GUID-based identifiers and textual, hierarchical identifiers are not mutually exclusive. You can have log.info(log_guid="98185C94-57D7-439A-8206-1D4A2ACBD983", log_system="spaceships.combat.explosion") in a single event. We could provide both tools to the developer, and they're not obliged to use either. (I see you've written some other messages, so more forthcoming...) -glyph

On Sat, Jun 15, 2013 at 11:09 AM, Christopher Armstrong wrote:

On Thu, Jun 13, 2013 at 5:14 PM, Glyph wrote:

...

Hello everybody. Today I'd like to talk about everyone's favorite subsystem within Twisted: logging.

There are a number of problems with Twisted's logging system.

The general theme of these problems is that Twisted log system was designed with some intended use-cases in mind, but its implementation was stopped halfway through and none of those use-cases were really well satisfied.

At various conferences, and in person at various times, we've gotten together to express frustration at the logging system, but I don't think that the problems with it have ever been really thoroughly written down.

Wilfredo has been working on logging here: http://trac.calendarserver.org/browser/CalendarServer/trunk/twext/python/log.... This began as an attempt to just address some issues with our own logging wrappers, but has been growing into a design that is more fully capable of replacing logging within Twisted wholesale. I hope one of us can contribute it to Twisted soon, but in the meanwhile, please feel free to provide feedback - hopefully if some people can provide a bit of informal feedback now, the formal review process can be shorter and more pleasant :).

I like it. Let's merge it.

I think I would just want one more feature:

...

...

Logger().emit(dudelog.LogLevel.warn, a="hi")

Right now, this doesn't spit out anything into my log file, with default observers. I want it to emit some simple representation of the keys and values. On the other hand, the same is true of log.msg(a="hi"), but maybe this should be implemented (somehow) in Logger() codepath to avoid breaking compatibility? -- Christopher Armstrong http://radix.twistedmatrix.com/ http://planet-if.com/

On Sat, Jun 15, 2013 at 9:38 PM, Glyph wrote:

On Jun 15, 2013, at 9:17 AM, Christopher Armstrong < radix@twistedmatrix.com> wrote:

I think I would just want one more feature:

Logger().emit(dudelog.LogLevel.warn, a="hi")

Right now, this doesn't spit out anything into my log file, with default observers. I want it to emit some simple representation of the keys and values.

On the other hand, the same is true of log.msg(a="hi"), but maybe this should be implemented (somehow) in Logger() codepath to avoid breaking compatibility?

I keep going back and forth on this.

On the one hand, the main thing I want to do is to just say "if you want your message to appear in the log file, let's just implement a structured log file and you can read it from there. If you have no human-readable format string to explain your message, clearly you didn't intend for a human to read it."

On the other hand, we already implement log filtering, so filtering the message out of the log based on the absence of the format string is a little overloaded. And we should really be encouraging people to populate messages with useful structured data.

(I was going to say that without a format string I couldn't have my stand-in UUID feature, but then I realized that namespace + set of keys is probably good enough to generate that too, so never mind. Also it seems like I'm the only one who likes that feature so maybe it doesn't matter!)

How would you feel about a special token that you have to pass explicitly?

Logger().warn(ALL_KEYS, a="hi")

I'm not wild about the need for an extra constant I'd have to import, but I'd like to understand why you think the arbitrary keys shouldn't be included in the message. Can you elaborate on why? -- Christopher Armstrong http://radix.twistedmatrix.com/ http://planet-if.com/

On Jun 17, 2013, at 5:48 PM, James Y Knight wrote:

I'm surprised that a thread with 32 messages about logging doesn't seem to have once mentioned windows events, osx structured syslog, or systemd journal as important design points.

As it happens I was discussing exactly that! In a sense, they're just observers, and it's just a matter of persisting whatever fields are present to the various backend systems.

Maybe people are thinking about such things in the background but it looks a lot like this is being designed in a vacuum when there's plenty of air around.

So yes, I, at least, have been thinking about them, abstractly. But you raise a good point: we should be talking about them concretely and making sure that we could at least take advantage of the facilities they offer before we finalize anything. However, then you fail to discuss them concretely :). Do you have any practical experiences with these systems that would indicate what features would be useful to abstract over or how they should be exposed?

And, no sane sysadmin should ever want a twisted-specific log file format or to write custom python log filters. That's crazy. Gimme a verbosity knob and the ability to emit structured log events to existing systems, with a fallback plain text file format. Great.

There is a reason why we should support such a thing, by which I mean a "Twisted specific" format in the sense of something like line-delimited JSON (or whatever). We have an API for emitting log messages, and an API for observing log messages as they occur. If someone were to use the latter API to produce some software that does a useful thing, it would be very good to have a built-in, platform-independent format for logs that could easily be reconstituted into something that is a reasonable enough facsimile of the information available at runtime. That way log analysis using our log-analysis API would be possible offline without rewriting your online analysis tool to consume input from systemd, ASL, and windows event log instead of a Twisted observer. I agree that our existing text format is basically pointless, but there are two reasons to keep it around. First, it seem to be something that some sysadmins expect; there's definitely an archetype of sysadmin who prefers everything to be in "plain text" so they can run their perl scripts over it; someone more comfortable with regexes than structured data. Maybe you wouldn't characterize these people as sane, but they're definitely extant, and some of them, at least, run Twisted services. The second reason to keep the text format around is that even sysadmins who would _prefer_ structured data in an existing log facility have probably written some gross hacks to deal with twistd.log by now because we haven't previously exposed it in any meaningful way, so we need to preserve the existing format for some amount of compatibility. My hope is that we can convince them to upgrade to some sort of structured system on its own merits, at the very least a log file that can be parsed reliably.

The prime goal, it seems to me, should be exposing features useful for facilities present in existing log systems.

That's certainly a goal, but it's a little longer term than the prime goal, which is to present a logging API that encourages any structure (and filtering based on that structure) to be expressed at all. It would of course be much better if that structure were aligned with existing logging systems. If we had logging with structured messages already, there'd at least be a hope of writing a somewhat useful translator to these back-end systems. As it is, sadly, we're going to have to touch almost every log.msg() call within Twisted to get any useful information out.

And having a logging system which doesn't even support a basic log level is just silly. Hopefully the new system can at least have that.

The new system being proposed does have log levels. (And, for that matter, so does Twisted currently; we've had log levels for compatibility with stlib Python logging forever.) I still don't think that log levels are a particularly useful bit of structured information, and this is one reason I want to have our own structured format, to make sure that the other bits of more useful information hang around for longer in a useful form. I've been convinced that it's unhelpful to be contrarian and omit information which can be useful to a whole bunch of other systems and existing practices. (Also, the effort described therein is way too ambitious to do in any reasonable time frame unless someone wanted to make logging in Twisted their full-time job for at least a year.) Plus, I've seen some utility in Calendar Server from the use of the intersection of "level" and "namespace", although blanket application of log levels is still a crapshoot. (So, other than those caveats, everything I said about identifying the audience and intent of messages in http://glyph.twistedmatrix.com/2009/06/who-wants-to-know.html still applies.) Do all the systems you mentioned have the same set of log levels, or will there be some need to harmonize them? -glyph

On Jun 18, 2013, at 8:25 AM, Peter Westlake wrote:

On Tue, Jun 18, 2013, at 4:50, Glyph wrote:

...

On Jun 17, 2013, at 5:48 PM, James Y Knight wrote: ...

...

And having a logging system which doesn't even support a basic log level is just silly. Hopefully the new system can at least have that.

The new system being proposed does have log levels. (And, for that matter, so does Twisted currently; we've had log levels for compatibility with stlib Python logging forever.)

It's quite well hidden, though. Looking at http://twistedmatrix.com/documents/current/api/twisted.python.log.html, there is no mention of logging levels. For that matter it doesn't mention twisted.python.log.msg() either!

Yes; in general, the current logging system's documentation is atrocious. Part of this new effort should be to completely re-vamp how we explain things. -glyph

On Mon, Jun 17, 2013 at 11:50 PM, Glyph wrote:

On Jun 17, 2013, at 5:48 PM, James Y Knight wrote:

And having a logging system which doesn't even support a basic log level is just silly. Hopefully the new system can at least have that.

+1

The new system being proposed does have log levels. (And, for that matter, so does Twisted currently; we've had log levels for compatibility with stlib Python logging forever.)

But it is impossible to use them in Twisted currently without Python logging or without writing your own observer AFAICS. If the system being proposed does have log levels then it is good. I still don't think that log levels are a particularly useful bit of

structured information, and this is one reason I want to have our own structured format, to make sure that the *other* bits of *more* useful information hang around for longer in a useful form.

I think you are mixing "structured information" and "structured format" here. Anyway, current practice proves that log level is one of the most useful pieces of whatever structured or unstructured information in the log files. IMHO applies of course.

I've been convinced that it's unhelpful to be contrarian and omit information which can be useful to a whole bunch of other systems and existing practices. (Also, the effort described therein is way too ambitious to do in any reasonable time frame unless someone wanted to make logging in Twisted their full-time job for at least a year.) Plus, I've seen some utility in Calendar Server from the use of the *intersection* of "level" and "namespace", although blanket application of log levels is still a crapshoot.

That is usually true for any somewhat complex phenomena - there is no silver bullet, everything should be used in concert. Take gender for example - taken alone it doesn't tell everything about a person but still is a very important piece of information :) Frankly I do not remember a program or a system where log level was not used in one form or another if logging was used at all. (So, other than those caveats, everything I said about identifying the

audience and intent of messages in < http://glyph.twistedmatrix.com/2009/06/who-wants-to-know.html> still applies.)

I agree. It is so tempting to design something that will rule them all :) Unfortunately such a generic project usually is destined not to be completed :( (like Lore to Sphinx conversion ::() (I hope that the number of smiles is enough to indicate the level of seriousness in the above paragraphs ;} ) Seriously, the only things that could probably be general enough to provide ready made interface among gazillions of applications/domains are the time stamp and the log level. The third one - the source of the message is also general but its values are very application specific. Everything else is too application specific to hard code into generic library like Twisted. There should be a way to implement them if needed of course. Among these only log level is missing in Twisted and logPrefix should be fixed to always show correct names.

From the practical POV the most welcomed first step in updating the Twisted log system would be introduction of ready made log levels (with an ability to filter on them in observers), fix of logPrefix thing and somewhat extended set of available observers (syslog, email, socket, etc.) Everything else could wait more detailed design etc.

Do all the systems you mentioned have the same set of log levels, or will there be some need to harmonize them?

IMHO the level of consensus in the set of log levels is not all that bad. The ones used in Python logging together with ability to add custom levels is good enough for almost anything. Regards, Mikhail Terekhov

On Jun 20, 2013, at 4:03 PM, exarkun@twistedmatrix.com wrote:

On 18 Jun, 08:58 pm, termim@gmail.com wrote:

...

From the practical POV the most welcomed first step in updating the Twisted log system would be introduction of ready made log levels (with an ability to filter on them in observers), fix of logPrefix thing and somewhat extended set of available observers (syslog, email, socket, etc.) Everything else could wait more detailed design etc.

Is there an obstacle preventing this from being done with twisted.python.log?

A completely new system written from scratch from the ground up might be great, but it doesn't seem necessary for something as simple as log level support.

Jean-Paul

Nope. Anyone who wants to start adding log levels to any existing messages is welcome to do so. There's no particular conflict with the new system, either; more information in log messages will just be even easier to utilize with some of its improvements. -glyph