Hacker News Reader

For Python, structlog (https://www.structlog.org/en/stable/index.html) is a good tool for what you want.

But I think you can do better than structlog, with causal/trace-based logging. I built a Python library called Eliot to do so (https://eliot.readthedocs.io).

You can use tracing in a single application just like you can for full distributed systems. This means each log message is part of a causal chain of actions, and you can see what caused it.

Log messages can still be viewed as individual disconnected messages, but you can also get a tree view (see https://eliot.readthedocs.io/en/stable/quickstart.html for the code that resulted in these logs):

    b1cb58cf-2c2f-45c0-92b2-838ac00b20cc
    └── check_links/1 ⇒ started
        ├── timestamp: 2017-10-27 20:42:47.206684
        ├── urls:
        │   ├── 0: http://eliot.readthedocs.io
        │   └── 1: http://nosuchurl
        ├── download/2/1 ⇒ started
        │   ├── timestamp: 2017-10-27 20:42:47.206933
        │   ├── url: http://eliot.readthedocs.io
        │   └── download/2/2 ⇒ succeeded
        │       └── timestamp: 2017-10-27 20:42:47.439203
        ├── download/3/1 ⇒ started
        │   ├── timestamp: 2017-10-27 20:42:47.439412
        │   ├── url: http://nosuchurl
        │   └── download/3/2 ⇒ failed
        │       ├── errno: None
        │       ├── exception: requests.exceptions.ConnectionError
        │       ├── reason: HTTPConnectionPool(host='nosuchurl', port=80): Max retries exceeded with url: / (Caused by NewConnec…
        │       └── timestamp: 2017-10-27 20:42:47.457133
        └── check_links/4 ⇒ failed
            ├── exception: builtins.ValueError
            ├── reason: HTTPConnectionPool(host='nosuchurl', port=80): Max retries exceeded with url: / (Caused by NewConnec…
            └── timestamp: 2017-10-27 20:42:47.457332

I always thought about building something like this. Excellent work! Even serializes to JSON. Really nice.

It would be nice to integrate it with Python's standard logging system similar to how structlog does this.

It can take messages _from_ the standard logging library, and they even show up in the correct place in the tree: https://eliot.readthedocs.io/en/stable/generating/migrating....

This is the preferable method in order to get the semantic model of tracing for all logs.

That is a fantastic library!

I really like the structured / long messages, but they have an issue in comparison. If your sending process fails badly between those phases, you won't know that with a single message. You may not even get any message at all.

Sure, those cases should log something / log exception / something should notice the failure. In practice one day you'll find a case where it doesn't happen.

I wonder if there's a sensible pattern for wrapping a segment in a context that accumulates log calls within until it errors or returns, then concats and dumps.

Probably, but some critical errors like stack overflow or out of memory could prevent the stack from unwinding gracefully or otherwise prevent the accumulated log from being written. And then you’d have nothing.

Conceptually, if you separate out the application generating the log from the one constructing the structure, so that the former is still streaming individual messages with added context information and the latter (probably a log viewing application, so it is completely out of the critical path of recording information) uses context information to provide a structured view, then that's not a problem.

Alternatively, as others have mentioned, log as usual but include an instance id and then use an external service/process to aggregate log entries with the same id together.

That's actually an example, not an alternative (the instance id is the “context information”, the external service/process is the separate component using the context information to construct the structured view.)

Ah, good point.

This is a popular concept. See https://www.npmjs.com/package/bunyan#raw--ringbuffer-stream for example. Many languages have an implementation for something like that.

I did this for a desktop app I wrote. The liver kept an in memory ring buffer and when there was an unexpected error, it would dump all the previous debug level logs to give context to the error.

I suppose you could concat strings and do it in a finally clause? Or use python’s context managers and do the logging in the __exit__().

Exactly my thinking. And the context wraps the view call and therefore the whole transaction.

One thing I try to be careful of, especially in your particular example, is to prefix log lines with session IDs. If my app is sending multiple e-mails simultaneously, I want to know which lines correspond to which sessions if one of them went south, because they're all likely to be jumbled up.

This is doubly true for logging multithreaded processes.

I'm now pushing application logging into a Kinesis Stream that gets firehosed to both S3 and Elastic Search. This includes both request logs and logs of any CRUD operation on my models (including all changed attributes with their old/new values.) There are separate logs for each, but the CRUD events get tagged with the ID of the request that triggered them so it is now trivial to see everything that happened to a given record and which request caused it and which user did it. And since all request logs have the session ID, I can also easily see everything that user did during that session both before and after the event in question. I've been wanting this sort of logging solution since the early 2000s and I now have it and it is even more incredible than I imagined.

Any blog posts or talks that inspired this? How do you handle retention? Any libraries or tools that helped with it?

I can see the use of such logging clearly, but I work at a young startup and implementing that ourselves sounds like infrastructure overkill. Maybe I'm overestimating the work?

Thanks for any thoughts!

Sorry, just saw your reply. I suspect you are overestimating the work. I just added some Rack middleware to handle request logging. Then plugged into the Rails model callbacks to record the CRUD events into a different Kinesis stream. And we're a 3 dev shop and I did this on my own over a few weeks part-time.

As far as retention goes, I just dump to it to S3 for permanent storage. Kinesis Firehose makes that dead simple. I also push each event into AWS hosted Elastic Search and I could theoretically purge older data, but for our volume of data, I'll likely retain it there for years.

Edit: Also, I generate UUID in the Rack middleware and set a Thread Local Storage variable that I can pull out in the CRUD logging so that I can always see what Rack request caused the CRUD model event.

Sounds like I did way overestimate. Thank you for the structure!!

This is what I've done and it works pretty well. You can usually filter out just the "bad" session IDs pretty easily and recover a more or less chronological explanation of what happened.

The problem I see there is that a serious issue party way through the process my man nothing gets logged. Also for a long running process you won't see the line until it is complete - this could even apply to what should be a short process when something is wrong.

A compromise might be to log each part individually as is more usual, but with IDs appended/prepended to each line to group them (which is useful anyway for analysis without this next step) and later process the raw log to produce one with the structured entries.

This gets to one of my... pet peeves? hobbyhorses?..., which is the importance of the APIs you use. The general logging API is something like LogMessage(level, message, params....), assuming some sort of printf-like functionality. A logger object is probably passed around.

This is not a very good API, though, because it tends to afford that sort of logging, on two levels. First, it tends to encourage a lot of little individual lines dumped out, and second, it tends to make it difficult to have any additional context in the log messages. And you very often care about context in log messages. Log messages that look great during dev because you only ever tested one at a time become impossible to understand in production.

You really want an API more like msg = log.GetMessage(), where when "msg" falls out of scope it writes the log line (or when it commits), and you update msg throughout the operation and generate just the one line at the end. You can even make "log" itself something that carries context with it, for the microservice labeling case, and emits "msg"s that already have that context in it.

(Similarly, anytime I start using a cache I always put my own wrapper around it, because the correct interface for a cache layer is not "cache.get(key)", it's "cache.get(key, func() value)"; that is, a get request should be tied to "the code to generate the value". Otherwise, there will eventually be some code path that loads from the cache but doesn't handle the case it's missing, or some other mismanagement brought on by the fact you've detached the generation of the value from the use of the cache. Exceptions as always, but this is a much better default.)

Regarding the need for a tool, I can't say enough good things about [lnav](https://lnav.org). It's like a mini-ETL powertool at your fingertips, w/ an embedded SQLite db and a terrific API. As of mid-2016 when I first used it, querying logs was extremely easy, and reasonably fast (w/ up to several million rows). Highest recommendation.

Many times I've created a log buffer (list of strings) that will get created as part of the unit of work that will blast everything to the actual logger at once so you have all the context surrounded by a "* BEGIN REQUEST *" type message. This keeps the simplicity of plain text with just enough structure to process if needed.

Many companies use structured event logs for data analysis, but still use traditional logs for debugging.

I found it a good practice to create a custome thread factory which translates the request identifier to be appended to the log.

Its actually really easy to filter out everything connected only to that identifier after that.

Tho it may be challenging to debug what was happening in between.

just dump your logs to elasticsearch and search with that stack, trying to eyeball it quickly gets unwieldy even in dev environments