[Twisted-Python] logging
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 :). Now, back to some explanation of the current problems. 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 have 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. 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. 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. 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) 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. 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: class GenerateOnlyIfNeeded(object): def __str__(self): return doSomethingExpensiveToGenerateAString() log.msg(format="debugging: %(expensive)s", logLevel=debug, expensive=GenerateOnlyIfNeeded()) 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. 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. 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 always ought to be a format string. 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). 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. 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. 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. 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 phenomenally complex makeService, I can tell you that this would definitely be helpful.) 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. 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. 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. 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. 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. 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 every 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 real cause(s) of work being executed. OK, I think that's it for now. (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 should 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.) -glyph
On Thu, Jun 13, 2013 at 5:14 PM, Glyph <glyph@twistedmatrix.com> 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)
There's something that I want to.... not propose, but discuss, that I've discovered through my writing of actual applications that do actual log filtering. 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: 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. 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 :) -- Christopher Armstrong http://radix.twistedmatrix.com/ http://planet-if.com/
On Jun 13, 2013, at 4:16 PM, Christopher Armstrong <radix@twistedmatrix.com> wrote:
On Thu, Jun 13, 2013 at 5:14 PM, Glyph <glyph@twistedmatrix.com> 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 Jun 14, 2013, at 3:43 PM, Glyph <glyph@twistedmatrix.com> 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? -glyph
On Fri, Jun 14, 2013 at 6:40 PM, Glyph <glyph@twistedmatrix.com> wrote:
On Jun 14, 2013, at 3:43 PM, Glyph <glyph@twistedmatrix.com> 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 Jun 14, 2013, at 10:48 PM, Christopher Armstrong <radix@twistedmatrix.com> 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.
The system isn't really that complex at all. It's calling uuid.uuid5 once, and it's even doing that internally in a utility function, so you don't need to understand what it's doing.
I think there's basically no practical benefit over the hierarchical "system" + event-identifier system, where:
I tried to lay out the benefits in my other recent reply.
1. it's trivial to specify a hierarchical, easy-to-read "system" key that has a small-ish scope
The fact that you have to say "trivial" here suggests it's not actually trivial :). I think that the amount of energy people initially put into logging is so low that they will often forget to do something like this. But, even if they remember in the future, we have to deal with the plethora of messages already within Twisted, and every Twisted library, that *don't* do this.
2. you think of a unique event name in that small-ish scope and type it out.
How do you know that your event name is unique though, other than running 'grep'?
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.
This might be a good practice anyway.
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.
The "system" that Twisted currently specifies is supposed to be the reactor event which caused a particular chunk of code to run. This is not related to the subsystem within your application where the functionality that is logging is implemented (which, really, still sounds to me like "module name"). I think this could be quite useful, especially in systems where the same functionality is exposed over multiple protocols and disparate events could cause the same subsystem to eventually get called. However, there are a ton of problems with the way that's implemented; I can't really argue with you here about the current implementation, because it's so poorly done that I think it's next to useless. With Failure's extended "exception caught here" stacks, it doesn't provide any information other than the traceback. However, I'd like to bring it back at some point, especially if we can figure out how to have the causality of an event. Wouldn't it be fantastic to see a trace like this when something went wrong? <SomeProtocol at 0xFFFF>.dataReceived called callLater(x) called callInThread(y) which called callFromThread(z) and that's why your code is running now
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 Jun 15, 2013, at 3:55 AM, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
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 am really, really puzzled by this reaction. I am wondering if you read my message carefully, or if I didn't express myself well. If I were to implement the system that I have proposed, you could completely ignore it. You could never deal with a UUID ever, and process logs based on whatever other attributes you like. There's nothing to translate. Unless when you say "translate" you mean translating the UUID of a currently ad-hoc message (one which doesn't specify or document its own unique attributes) which is something that would just be impossible without this feature. The only overhead that you'd ever incur would be a single call per log event - probably per-process-lifetime, since the result could be cached - to uuid.uuid5, which is not exactly the most expensive function. It would be called internally though; you wouldn't have to call it yourself or be aware that it was being called. If you had the use-case that I believe many people do - which is to evolve a stable identifier for a previously ad-hoc log message - then you could do that. Otherwise this wouldn't affect you. What I've proposed with UUIDs is to identify *specific semantic events* that you might want to do monitoring/alerting on, which may move between systems. Does this explanation make you feel less worried about the inclusion of such a feature?
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.*")
This is already implemented in <http://trac.calendarserver.org/browser/CalendarServer/trunk/twext/python/log...>; see for example setLogLevelForNamespace() <http://trac.calendarserver.org/browser/CalendarServer/trunk/twext/python/log...>. Namespaces are just python module names by default, but nothing requires that; the only requirement is that they're strings separated with dots. You can instantiate a Logger object with whatever 'namespace' argument you want. So: again, you can get what you want exactly and ignore the other stuff.
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.
I am still not seeing the utility of one of these identifiers beyond class/method name, but you can always just pass the namespace explicitly. -glyph
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?
On Jun 15, 2013, at 5:28 AM, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
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.
OK, whew :).
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's right.
That seems fine, though I'm not sure what the UUID *does* in that situation - route/match is via python object access, no?
What it does is it allows *older* monitoring scripts to work. It also holds on to the UUID internally so that if, for example, the module's name is changed in the future, the API name can be re-named and code can be pointed at it via the normal deprecate/redirect mechanism. (Of course, _any_ sort of explicit / unique identifier would work for this latter use-case; it's just that this one has the benefit of not visibly containing the string that has now been changed, and so there's no long-term impulse to "clean it up" further and thus break stuff.)
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?
Sounds like you've got it just about right now. -g
On Thu, Jun 13, 2013 at 5:14 PM, Glyph <glyph@twistedmatrix.com> 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.
I really need to get out of here and go to dinner, but I really quickly wanted to start a list of use cases for logging. 1. "I need to convey a message with complex information to the user of my software" Log files usually aren't good at all for this, but they're unfortunately used quite often for it. This is pretty much the only reason to have English in your log statements, I think. 2. "I want to be able to analyze patterns in the execution of this software" This is where structured data really helps. Keys, values, "systems", and "events" (as I described below) -- things you can filter by, graph, or redirect. 3. "I want to investigate certain events that happened in the execution of this software" Structured data helps just as much here as with #2. It's nice to be able to interactively query databases of logs. "show me all the stuff about this player". "show me everything that happened in this thread". "show me all of the 'frag' events." 4. "I want to accumulate a bunch of extremely verbose data to be logged only if it's really necessary, such as in an error case" This is similar to #3, but there are cases where you have such verbose data that you don't want to to log it all the time. This is basically the OOPS system as some developers are familiar with -- the execution of request-handling can attach data to the request (or some log context object, or whatever) and if the request ever fails, all of that data will be zipped up and saved somewhere for further investigation. If the request succeeds, it'll be thrown out. 5. "I want to be able to track down where this log message came from" the "event" attribute that I described is helpful here, but having the filename and line number is even better. I tried to write a number #6 about including framework-provided data in your application-level log statements (like request ID, client IP, URL etc), but I got too hungry. Sorry for the braindump! -- Christopher Armstrong http://radix.twistedmatrix.com/ http://planet-if.com/
On Thu, Jun 13, 2013 at 7:14 PM, Glyph <glyph@twistedmatrix.com> wrote:
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)
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. Thanks! -- . Facundo Blog: http://www.taniquetil.com.ar/plog/ PyAr: http://www.python.org/ar/ Twitter: @facundobatista
Hi, On Thu, Jun 13, 2013 at 6:41 PM, Facundo Batista <facundobatista@gmail.com> 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 Fri, Jun 14, 2013 at 1:41 AM, Jamu Kakar <jkakar@kakar.ca> wrote:
Hi,
On Thu, Jun 13, 2013 at 6:41 PM, Facundo Batista <facundobatista@gmail.com> 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 :) -- Christopher Armstrong http://radix.twistedmatrix.com/ http://planet-if.com/
On 07:45 pm, radix@twistedmatrix.com wrote:
On Fri, Jun 14, 2013 at 1:41 AM, Jamu Kakar <jkakar@kakar.ca> wrote:
Hi,
On Thu, Jun 13, 2013 at 6:41 PM, Facundo Batista <facundobatista@gmail.com> 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 4:47 PM, <exarkun@twistedmatrix.com> wrote:
On 07:45 pm, radix@twistedmatrix.com wrote:
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
This really should have been a response to my earlier message where I talk about the "event" more directly, instead my post about how to do string formatting, but anyway. That was a very amusing post, but I guess you were trying to make a point :) The event name shouldn't be meaningless; you or your ops team or your users are going to want to type it into their filtering software, and it's nice if they can keep the event name in their head. I find it most valuable when it's a short identifier that I think up with my brain and type into my program. If I'm logging in a call to received_frag(), for example, I'd probably call the event name "frag". If I'm logging a message about an error that occurred during a regularly scheduled database compaction, I would call it "scheduled-db-compact-failed". 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. -- Christopher Armstrong http://radix.twistedmatrix.com/ http://planet-if.com/
On Fri, Jun 14, 2013 at 5:43 PM, Christopher Armstrong <radix@twistedmatrix.com> 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/
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?
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 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... - 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. -wsv
On Fri, Jun 14, 2013 at 6:20 PM, Wilfredo Sánchez Vega <wsanchez@wsanchez.net> 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/
On Sat, Jun 15, 2013 at 12:43 AM, Christopher Armstrong <radix@twistedmatrix.com> wrote:
On Fri, Jun 14, 2013 at 6:20 PM, Wilfredo Sánchez Vega <wsanchez@wsanchez.net> 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.
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) -- Christopher Armstrong http://radix.twistedmatrix.com/ http://planet-if.com/
Am 15.06.2013 um 08:18 schrieb Christopher Armstrong <radix@twistedmatrix.com>:
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 Sat, Jun 15, 2013 at 2:18 AM, Hynek Schlawack <hs@ox.cx> wrote:
Am 15.06.2013 um 08:18 schrieb Christopher Armstrong <radix@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/
On Jun 15, 2013, at 8:33 AM, Christopher Armstrong <radix@twistedmatrix.com> 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 Jun 14, 2013, at 11:18 PM, Christopher Armstrong <radix@twistedmatrix.com> 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 :). 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. 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. -glyph
On Sat, Jun 15, 2013 at 6:37 AM, Glyph <glyph@twistedmatrix.com> wrote:
On Jun 14, 2013, at 11:18 PM, Christopher Armstrong <radix@twistedmatrix.com> 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 15, 2013, at 8:46 AM, Christopher Armstrong <radix@twistedmatrix.com> wrote:
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.
Even if it's not really what you'd intended, I think it's pretty good to keep discussing these issues (avoiding unnecessary formatting, putting the right responsibilities in the right place).
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.
To reiterate a little from my previous reply, I think we should be, as much as possible, moving to make that the default. Now, actually making it the default is a pretty disruptive change, but I think we could get as far as "implement the feature at all" before anyone would start complaining ;). In other words, every developer should not have to realize they should write a JSON(ish) emitter and figure out how to get that to work on their own; we should just provide one that does the right thing. To dial this back to what we actually need to talk about in the proposed log system, the issue is mostly to do with
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.
No problem. This is all good stuff to talk about; we don't discuss operational concerns of managing Twisted services (either server *or* client side) nearly often enough on this list. I wish we had more discussions like this!
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).
Well, "system" was a pretty horrible name for the thing satisfying that intent. We have "log_namespace" in the new logging system, and I think that (in combination with an idiomatic "log_id", that only needs to be unique within that namespace) you could get more or less what you want. I think we're going to drop the "system" key entirely (except in the contexts where it's required for compatibility, of course). Jean-Paul's recent comment in the quote file is apropos. -glyph
On Jun 14, 2013, at 10:43 PM, Christopher Armstrong <radix@twistedmatrix.com> 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 Thu, Jun 13, 2013 at 5:14 PM, Glyph <glyph@twistedmatrix.com> 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. -- Christopher Armstrong http://radix.twistedmatrix.com/ http://planet-if.com/
On Sat, Jun 15, 2013 at 11:09 AM, Christopher Armstrong <radix@twistedmatrix.com> wrote:
On Thu, Jun 13, 2013 at 5:14 PM, Glyph <glyph@twistedmatrix.com> 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 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") -glyph
On Sat, Jun 15, 2013 at 9:38 PM, Glyph <glyph@twistedmatrix.com> 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 Sun, Jun 16, 2013 at 4:38 AM, Glyph <glyph@twistedmatrix.com> wrote:
(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!)
I don't have anything useful to contribute at the moment, but you can add me to the list of people who like that feature. -- mithrandi, i Ainil en-Balandor, a faer Ambar
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. 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. 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. The prime goal, it seems to me, should be exposing features useful for facilities present in existing log systems. 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.
On Mon, Jun 17, 2013 at 7:48 PM, James Y Knight <foom@fuhm.net> 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.
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.
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.
The prime goal, it seems to me, should be exposing features useful for facilities present in existing log systems.
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 proposed logging module does include levels. Also, I have definitely been thinking of real logging systems during this conversation -- in fact, I've been planning on experimenting with some of the popular *structured* logging systems these days and I plan on implementing and contributing log observers for them. I do think the "json file" log format is pretty pointless, though it might be a nifty exercise (unless there is some structured log aggregation system that reads json data from disk files?) I think your accusations of design in a vacuum are too hasty and inflammatory. The whole reason I'm so interested in this discussion is to take advantage of *real* logging systems that can aggregate, filter, and search lots of log streams, based on structured event streams. -- Christopher Armstrong http://radix.twistedmatrix.com/ http://planet-if.com/
On Jun 17, 2013, at 5:48 PM, James Y Knight <foom@fuhm.net> 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 Tue, Jun 18, 2013, at 4:50, Glyph wrote:
On Jun 17, 2013, at 5:48 PM, James Y Knight <foom@fuhm.net> 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! Peter.
On Jun 18, 2013, at 8:25 AM, Peter Westlake <peter.westlake@pobox.com> wrote:
On Tue, Jun 18, 2013, at 4:50, Glyph wrote:
On Jun 17, 2013, at 5:48 PM, James Y Knight <foom@fuhm.net> 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
For your Trac'ing pleasure: https://twistedmatrix.com/trac/ticket/6750 -wsv
On Mon, Jun 17, 2013 at 11:50 PM, Glyph <glyph@twistedmatrix.com> wrote:
On Jun 17, 2013, at 5:48 PM, James Y Knight <foom@fuhm.net> 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 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
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
participants (12)
-
Christopher Armstrong
-
exarkun@twistedmatrix.com
-
Facundo Batista
-
Glyph
-
Hynek Schlawack
-
James Y Knight
-
Jamu Kakar
-
Mikhail Terekhov
-
Peter Westlake
-
Phil Mayers
-
Tristan Seligmann
-
Wilfredo Sánchez Vega