<html><body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space;"><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">Hello everybody. Today I'd like to talk about everyone's favorite subsystem within Twisted: logging.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">There are a number of problems with Twisted's logging system.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">The general theme of these problems is that Twisted log system was designed with some <i>intended</i> use-cases in mind, but its implementation was stopped halfway through and none of those use-cases were really well satisfied.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">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.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">Wilfredo has been working on logging here: <a href="http://trac.calendarserver.org/browser/CalendarServer/trunk/twext/python/log.py"><span style="color: rgb(4, 46, 238);">http://trac.calendarserver.org/browser/CalendarServer/trunk/twext/python/log.py</span></a>. 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 :).</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">Now, back to some explanation of the current problems.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">The main intended use-case for Twisted's logging system is to avoid doing unnecessary work in the case where it is not required. One of the reasons we even still <i>have</i> our own logging system is that the stdlib logging module is notorious for doing too much work per log message, and doing it too prematurely.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">One aspect of this is that logging would just use the existing 'kwargs' dictionary as its message type, and not actually do any formatting; that is, string-copying, until the message was logged. On Python 1.5.2, that meant no need to allocate anything since the interpreter needed a dict for the kwargs anyway! Woohoo premature optimization! Obviously, at least on PyPy, that optimization is no longer relevant (and we don't have performance tests for logging anyway). But, I don't think we should change that because a dict is still a good object for the sort of extensibility that log messages need.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">But, we have never written any filtering logic, nor have we instrumented any of our existing log messages with formatting stuff. Every message with a format string just goes to the log.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">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:</font></p><blockquote style="margin: 0 0 0 40px; border: none; padding: 0px;"><div style="margin: 0px;"><font face="Bitstream Vera Sans Mono">log.msg(format="Foo happened. Relevant information includes: "</font></div><div style="margin: 0px;"><font face="Bitstream Vera Sans Mono"> "bar=%(bar)s baz=%(baz)s boz=%(boz)s",</font></div><div style="margin: 0px;"><font face="Bitstream Vera Sans Mono"> bar=bar, baz=baz, boz=boz)</font></div></blockquote><div style="margin: 0px;"><font face="Bitstream Vera Sans Mono"><br></font></div><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">Yet, nothing within Twisted itself does this. There's a bit of a chicken and egg problem: since we have no tools for filtering log messages based on their structured values, there's no obvious motivation to break the structured contents of a message out into those values. And since no messages break out their values into nice structured fields, there's no motivation to write filtering tools that inspect those fields.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">And, even if we did have filtering, we don't have a facility to easily defer work. You could, of course, just do something like this:</font></p><blockquote style="margin: 0 0 0 40px; border: none; padding: 0px;"><div style="margin: 0px;"><font face="Bitstream Vera Sans Mono">class GenerateOnlyIfNeeded(object):</font></div><div style="margin: 0px;"><font face="Bitstream Vera Sans Mono"> def __str__(self):</font></div><div style="margin: 0px;"><font face="Bitstream Vera Sans Mono"> return doSomethingExpensiveToGenerateAString()</font></div><div style="margin: 0px;"><font face="Bitstream Vera Sans Mono">log.msg(format="debugging: %(expensive)s",</font></div><div style="margin: 0px;"><font face="Bitstream Vera Sans Mono"> logLevel=debug, expensive=GenerateOnlyIfNeeded())</font></div></blockquote><div style="margin: 0px;"><br></div><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">But that's an awful lot of thinking for a single log message, not to mention the temporary class and the method you needed to allocate. Such deferral of work should be easy.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">And, speaking of the things that one might filter on, log messages don't typically include information about what module and class they're from; or, for that matter, what object is logging them. This information should be included by default in idiomatic usage of the API, so that a filtering system can inspect them.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">Another reason that we - both Twisted itself and Twisted users - don't typically pass keyword arguments and a format string, is that the default argument to msg is, simply, a "message". (It also does a dumb thing where it tries to emulate the argument-passing convention of 'print' and stringify its arguments and join them with spaces; we should get rid of that.) Instead, that argument <i>always</i> ought to be a format string.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">We should also have a log writer within Twisted that preserves structure, and dumps the logs using JSON (or similar, perhaps more than one of these; AMP would be another good thing).</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">It's also not possible to use format strings when you are writing an error log message in Twisted; instead, 'why' is treated completely differently than 'message'. The 'why' argument to 'err', which should be mandatory (what were you doing when you tried to log a message?) is optional, which means that error messages are even more inscrutable.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">The portions of the dictionary used by the logging system are not namespaced in any way, even by convention. Therefore it's easy for a user to conflict with the keys used by the system. If users of Twisted actually used the system as intended more pervasively, I'm pretty sure that we would end up seeing people conflict with 'time' and 'system' arguments often.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">Speaking of those keys: the 'time' key is unconditionally overwritten by log.msg, which means that re-publishing an event that happened previously is destructive; there's no way to track historical time.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">Messages logged before the logging system starts are just lost. It would be good for the initial log observer to keep a (limited-size, of course) buffer of log messages which could be dumped upon failing. This would make it easier, for example, to debug tap plugins that use the log system to report something about their state during makeService. (And, as the maintainer of a <i>phenomenally</i> complex makeService, I can tell you that this would definitely be helpful.)</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">The naming of methods is bad and confusing. msg? err? Easy to type, but hard to understand. We could have equally short names that are not confusing.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">The contract between parts of the system is poorly specified. For example, trial -j has a hard time with log output that includes any non-bytes keys. I imagine this will only become worse when trial actually supports Python 3.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">And speaking of encoding, the log system is written in terms of bytes instead of in terms of unicode. Now, there's good reason to be particularly permissive of garbage data in the logging system (logging a message should never provoke an error), but at some point - probably before the data gets to user-written observers - everything should be normalized into a structure that has enough properties that the user can depend on it.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">On that note, when presented with unicode encoding errors, Twisted's logger will directly raise an exception back to application code, something that it will otherwise only do when presented with KeyboardInterrupt. That I just don't understand.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">We use old, semi-deprecated '%' formatting style. If we're going to introduce a new API, we should use PEP 3101 formatting; in addition to being new and improved instead of old and inferior, it's a lot easier to type {foo} correctly than to type %(foo)s without forgetting the s.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">The whole LogContext thing is poorly designed. Mea culpa; this was entirely my fault. One problem with its design was that it was somewhat poorly explained, and so its intent has not carried over years of maintenance. The idea was supposed to be that <i>every</i> event-source within Twisted would provide a useful system key, which would indicate what event-source object (TCP connection, listening port, timed event, UDP port) was being activated when the given message was logged. However, a lot of factors conspire to make this information less than useful. For one thing, especially in database-backed applications, or those that are careful about rate-limiting or flow-control, nothing ever happens except in response to a callFromThread or a callLater; this means that the system argument is always "-". I think that the feature this is trying to support needs to be fundamentally re-thought (and in the intervening decade I've had a lot of ideas about how it might work better). Maybe we can build on some of Chris Armstrong's recent work on Deferred debugging in tracking asynchronous context in Deferreds to help identify the <i>real</i> cause(s) of work being executed.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">OK, I think that's it for now.</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">(NB: The implementation linked above doesn't address all of the issues I've enumerated in this message, and I don't think that it <i>should</i> address every single one of them before being added to Twisted; writing this one message took me long enough, but we should possibly also discuss which ones are fundamental issues with the logging system and which are features that should be considered separately.)</font></p><p style="margin: 0px 0px 12px;"><font face="Bitstream Vera Sans Mono">-glyph</font></p><div><br></div></body></html>