The Art of Logging | Hacker News Reader

The Art of Logging

medium.com

79 pointskiyanwang46 comments

> correlation_id … microservices

We actually did something slightly different: the correlation ID is generated at the start of a request, where it enters "our stuff" as a whole. But downstream "microservice" style requests get a different correlation ID, but with the original as a prefix. So if you have lots of microservice calls being made this means you can select any subtree with some prefix. The original correlation ID is the entire tree, but you might have,

  b8a0b848-92e6-49e7-bde2-283e165b02e4  # the original request
  b8a0b848-92e6-49e7-bde2-283e165b02e4/authz  # request to authz service
  b8a0b848-92e6-49e7-bde2-283e165b02e4/foo-db/0  # first subrequest to foo-db
  b8a0b848-92e6-49e7-bde2-283e165b02e4/foo-db/1  # second subrequest to foo-db
  b8a0b848-92e6-49e7-bde2-283e165b02e4/foo-db/2  # third subrequest to foo-db
  b8a0b848-92e6-49e7-bde2-283e165b02e4/bar-db/0  # first subrequest to bar-db

etc. So you can pull just the original request with "= 'b8a0b848-92e6-49e7-bde2-283e165b02e4'", a whole subsystem with something like "starts_with 'b8a0b848-92e6-49e7-bde2-283e165b02e4/foo-db/'", so on. Very convenient. (Our graphs weren't even that deep; we really just have "backends for your frontends" and "backends" and that was mostly it, so it was mostly to correlate between the BE and the BE-for-FE.)

You need structured logs first, so if you've not got that, start with that first.

There's this thing called "OpenTracing", which I hear is a sort-of standardization of this, but I've not had time to investigate it.

I've done something similar in the past with a database that had corId, sender and receiver columns to query. Your solution is more elegant.

I think the philosophy for logs is that they are THE user interface for operators of your service. If you are SaaS, that's you! If you provide software for self-hosting, that's your customers. It can't be an afterthought; this is how ordinary people can peer deep into your system to understand what's wrong with it. If they figure it out, they don't page you. If it's useless, you can't fix it after they page you. Be paranoid and make your subsystems show their work. Anything you want to know while debugging, print it, don't make the user "hey just run this and tell me what it returns". I think there is an art here, and many treat it as an afterthought.

I always liked structured logs because it frees my mind from coming up with how I want to format arguments. "New HTTP request for /foobar from 1.2.3.4 with request-id ac31a9e0-5d57-44de-9e98-60fa94d3e866" is a pain to read and maintain. `log.Debug("incoming http request", logger.IP("remote-ip", req.Address), logger.String("request-id", req.ID), logger.String("route", req.Route))` is easy to write, and the resulting logs are easy to analyze!

I do like myself some pretty colorful logs, but prefer JSON as the intermediary. It's pretty easy to post-process the logs into something understandable. I wrote https://github.com/jrockway/json-logs for this task. Give it a stream of JSON logs, get colorful text out. Add/drop fields or select/highlight interesting lines with JQ or regular expressions (with -A -B -C of course). Installable on Linux or Mac with Homebrew ;) It's one of the few pieces of software I wrote for myself that passes the "toothbrush test". I use it twice a day every day. And that's a good day when I'm not pulling my hair out over an obscure issue ;)

Log structurally, have option for human readable output is probably the sane default approach here. Sometimes you just want to run an app from commandline, send a request to it and see what happens

I could go either way on making it optional. I try to avoid configuration complexity and the log format is a piece of complexity that can be removed from your application with post-processing.

For example, I wrote opinionated-server which lets you pick text or JSON logging. Even though it has text logging, when I'm developing a server locally, I just pipe the JSON through jlog because I have super-refined that format to my personal tastes, whereas zap's builtin text format isn't as nice.

But I will say that when I create loggers for unit tests, I use the text formatter if one is available. I have never been interested in parsing JSON logs interspersed among plain text (though it is totally very possible to do).

I parse my team's nginx logs with a script even though they aren't in JSON. I'm fine with it and other people can do as they like. I also do all my application logging as just vanilla logs, and I use grep & less like the cretin I am, plus a tiny bit of bash for helping with gzip and so on.

If you want to go log-crazy with a big elaborate deal and the whole ELK thing and so forth and so on, by all means, if you can afford it - which means afford to see it all the way through. Too many times I've had to deal with teams where everybody says, "Yeah... It would be nice to have logs...." because someone built the Big Elaborate Thing and nobody can figure it out, find it, etc. etc. It becomes a long-term "would be" instead of "is".

Logs are for humans, metrics are for machines.

Metrics tell you there's a problem. They're an application's way of reporting metadata or state. They are designed to be small and frequent and machine readable/writeable, with small bits of useful information that are of themselves quite useless, but are very useful in aggregate.

Logs describe the problem in detail to a human. They're a developer's way of diagnosing problems in an application. They can have machine-readable components to them, but being machine-readable is not the point. The point is for a human to quickly diagnose and fix an arbitrary problem, however you decide to do that. It's extremely annoying if you can't read a log because it was machine-formatted.

From the article:

  Invest time in designing your log structure

Don't. Eventually you will have to deal with logs with a random structure. Invest in telemetry management and distributed tracing.

  Log as much as possible.

Don't. It's about quality, not quantity. Too many logs with too little information leaves you buried and unable to diagnose quickly. And too much information is bad for security; always mask sensitive information. I can't tell you how many giant companies have been hacked because of this. And cost is a factor: I have seen people stop logging because it was costing them too much money, when they should have been logging smarter (fewer messages with more useful info) and utilizing metrics.

  Keeping consistency is everone’s priority

It is guaranteed that you will have to deal with some metrics and logs in arbitrary formats. Do not worry about making them perfect. Invest in telemetry management and distributed tracing.

Yes.

I used to work at a company that invested too much time and effort into an ELK stack that handled specialist log formats sent over a custom UDP service. It was brittle and fell over in all sorts of strange ways. This was all for monitoring a handful of servers.

The only good that came of it was when we realized that the support staff could search the logs and diagnose 95% of customer complaints without bothering developers. ("Your transaction failed because you entered a bad card number.")

But that was because the text logs were more useful than the metrics.

Agreed. I was actually hoping the article would talk about how to log (buffer, async, files or output stream, etc). I’ve seen at least 2 cases of excessive logging causing outages: One was using log4j zip rollover which blocked all threads in the app causing timeouts, the other was using json in an older android vm which couldn’t cope with all the garbage, causing OOM due to fragmentation (before compacting garbage collector was introduced)

To be honest these feel like excuses to avoid structure. Keeping things consistent is something that require dedication and explicit effort. Just saying "everyone just do logging in their preferred format" seems the easiest way. Structured logging gives you lots of benefits. You monitoring will just work out of the box if you keep to the standard. Additional logs won't arbitrarily come up within your system with no anticipation. I'm not saying it will never happen, but you have control over it.

Do you have control over the format that a router uses to send you logs? Or a cloud vendor's services? Probably not. Inconsistency is therefore a certainty. The time you spend on consistency for a small subset of your logs can instead be spent working on a telemetry management system which decomposes and analyses all your logs regardless of format.

The fact that you will have inconsistencies doesn't mean you don't need to thrive for a standard where you have control. It will still significantly simplify things.

I was looking for logfmt mentioned in the article and couldn't find it.

Also stripe's canonical log lines[1] solve this problem nicely

1: https://stripe.com/blog/canonical-log-lines

You can read about logfmt at https://brandur.org/logfmt

It's quite nice at first glance. My main qualm with it is that there is no formal spec and I got bitten a few times by incompatibilities between emitters and parsers especially around quoted values.

(In particular we had a rust binary emitting badly escaped values such that fluentbit emitted structured logs with thousands of fields which in turn caused graylog to explode which was particularly gnarly because at the same time we had a production incident we had to troubleshoot without historical logs)

Stick with JSON. Just slightly less readable than logfmt but highly ubiquitous adaptation and parsing capabilities.

logfmt might be fine for people at Stripe who've built infra around it, but for mortals, stick with JSON so you can send data around.

When you have a million log lines, the question "Did it parse correctly?" shouldn't need to be asked because checking correctness is a huge problem.

TIL - thank you!

Canonical log lines don't solve the exact same problem (they provide all the information for some api call in a single place), but they need to be structured to work.

Logfmt: https://www.cloudbees.com/blog/logfmt-a-log-format-thats-eas...

Storing a human readable format is a amateurish practice with immense performance and resource costs. It conflates the storage format with the visualization/processing format.

In basically every case you should store/log a dense binary dump of your varying data and a ID that uniquely identifies the data format. Then, when a human wants to read the log, you do a post-processing step in your debug environment that formats the data in a human readable way.

This moves string formatting off of the target and prevents the frankly outrageous amount of redundant string duplication when storing human readable logs. It also avoids a roundtrip through stringly-typed logs and allows for efficient binary parsing of your logged data in their natural data format instead of doing brittle string parsing.

It is frankly challenging to come up with even a single case where you should not do it this way as long as your tooling is mature enough to manage the separated encoding/decoding pipeline. Even if it is not, you could always just run the post-processing step on all your new raw logs and store that afterwards as your “official logs” which still gives you the performance advantages on your production systems while being no worse than any existing scheme.

> It is frankly challenging to come up with even a single case where you should not do it this way

One use case for human readable format: your service/whatever that output logs doesn't output TBs of output every month and you can easily handle the amount on commodity hardware. Why complicate something that doesn't need it?

Both methods have their place.

> tooling is mature enough to manage the separated encoding/decoding pipeline

Is there a library for it?

This sounds like something I can't justify DIYing in the kinds of software that I work on.

I'd recommend trying SQLite for logging. We've been doing this for a half decade and it's fantastic.

There's an index on our trace/correlation column, so we can instantly pull all log entries for a specific user interaction with a query like:

  SELECT * 
  FROM LogEntries
  WHERE TraceId = @TraceId

We also use a single connection and WAL, so we can write many thousands of entries per second if necessary.

Some good advice here. I would also suggest adding a build ID to the log message along with the other optional fields, this being the version of the software that logged the message. It can help track down incompatibility issues, especially those that happen during the deployment of server-side software.

For example if you're on version X and in the process of deploying version Y, when service A sends a request to service B you have 4 distinct possibilities regarding the versions running on these two instances (X→X, X→Y, Y→X, Y→Y). If in version Y you've made changes to the request in its protocol/format/payload, you'll need to deal with all 4 cases to avoid encountering errors during the deployment. If the instances log all messages with their version, it'll help track down these transient incompatibility bugs, e.g.

  {
    "service": "B",
    "build": "X",
    "request_service": "A",
    "message": "unknown field in request: 'new_field'"
  }

Der @thamer thanks for the advice. I have added it to the article :) Much appreciated

For structured logging I recently came across https://messagetemplates.org/ which seems like a reasonable approach that also provides a human readable format.

I, personally, would argue against such a verbose JSON logging format purely for human readability purposes - the log format presented as an example has several human-unreadable IDs that could likely just be shoved in a fixed position in the string since people won't be able to decode them anyways and that would produce a more concise set of logs that would be easier to parse en masse visually with word wrap turned off while searching for the anomalous event.

JSON makes a lot of sense to me in logging if it's specifically something complex that you want a user to grab with copy-paste and dump into an interpreter for further inspection so having some supplemental detail fields be compacted in the JSON isn't a bad idea - but for the majority of the fields I'd prefer either fixed position or a more simplistic key=value (or key="value") format that can be more trivially read and is just as easy to parse.

Of course in a perfect world you want to ingest these logs into some better searching tool that lets you run SQL or some other standard query language over the set to prune them by date and pull out specific fields but there are times when you'll be hanging on by your nails with nothing to help diagnose the issue except an SSH connection to the server and the log file open in vi.

> Of course in a perfect world you want to ingest these logs into some better searching tool that lets you run SQL or some other standard query language over the set to prune them by date and pull out specific fields but there are times when you'll be hanging on by your nails with nothing to help diagnose the issue except an SSH connection to the server and the log file open in vi.

That tool is the Logfile Navigator (https://lnav.org). It's a TUI that reads plaintext logs, JSON-lines logs, and others. It will collate messages from all the files into a single log view that you can filter and search. The logs are also plumbed through SQLite virtual tables, so you can do fancy queries.

When setting up ELK or paying for Splunk/Sumologic is too much, lnav is a pretty good alternative.

There is an opinionated vision of logs, for a particular use case and available resources.

For simple enough logs (like the nginx/apache example shown) having so simple format enables a quick and dirty search and information extraction with common unix command line tools (like grep, cut, sort, uniq, tail and sometimes rev or awk). It is not an approach that works for all logs and all situations, but sometimes is enough. And simplicity is a good thing to have.

Plus it's virtually impossible to visually scan log messages as they go by when they're 10 lines long per entry vs 1 or 2 lines long.

I agree with the simplicity approach I like it too. However, I think sometimes we do not have a choice especially in distributed sytems or "micro"services environement. I think with great "complexity" comes great responsibility.

This is called "Structured Logging" and there's lots of articles already about it, and libraries to support it.

For example, a great structured logging logging library for Python:

https://www.structlog.org/en/stable/

Notes from the author:

This story is not a push for a standard but rather an attempt to create a logically organized log format optimized for log parsing systems like newRelic or ELK etc. It will help you generate useful dashboards, metrics and event notifications (example: trigger an alert if the percentage of errors exceeds 5%).

Implementing a standardized log system in your applications will cost you time and money. Debugging will costs you too, especially in edge cases where information is key. Your decision should consider both sides of the equation.

Logging is a very opinionated and sometimes divisive conversation. However, no matter which format you will use, it is always better than no logs at all.

Logs for machines should probably be expressed as metrics instead, because one can actually take the output of metrics for easy higher order analysis. Logs can do the same, but it takes more human effort to get there.

Logs should be the input to generate metrics (in addition to any metrics published directly).

Otherwise, it's hard to convert a stack trace into a metric ;) But you can process the logs to generate a metric about the frequency of stack traces.

Ditto for logs telling you "user Foo doesn't have permissions for that operation". Again, you can make a metric about "user permissions failure" but you still need the log to know that it was user Foo.

If you need a metric on the frequency of stack traces, you have a way more serious problem than structuring your logs.

Or you are working for people with such a problem.

Until you want to know which query is slow, which metrics won't tell you.

Being able to do "where query_time_ms > 5000" and then seeing the query has made some of my systems incredibly debuggable¹.

Or just finding a failing request with "where response_code = 500". Yeah, I can "grep 500", but you would be shocked at how often those characters occur by happenstance in logs "grep ' 500 '" is a bit closer but … you're just dancing around a solution engineered to do the job: structured logs.

¹and then finding out someone drew a rather large bounding box that managed to be centered precisely between and encapsulate both Philly & NYC. This kills the DB.

Most metric systems include tags, which allows you to have infinite dimensions of data correlation at your finger tips. Want the full query, or just a normalized version of the query? It should take a couple minutes in most metric engines to add such a simple requirement.

> Most metric systems include tags, which allows you to have infinite dimensions of data correlation at your finger tips.

Unfortunately with most SaaS metric services, your credit card does not scale to support infinite dimensions of data correlation.

Tagging a high cardinality value like a customer ID for example would quickly blow out your bill.

A mergable data type “sample values” would be awesome for these things. Host is dc1b001, api called is /whatever, p99 latency is 117 ms, status is 4xx, sample_corr_id is 0xfafedd12346

This is an attempt to create a logically organized log format optimized for log parsing systems like newRelic or ELK etc. It will help you generate useful dashboards, metrics and event notifications (example: trigger an alert if the percentage of errors exceeds 5%). You can still turn logs into metrics and with that hit 2 birds with one stone.

I've got several small enough projects that would benefit from an automated sort of logging: ALL impure function calls and their outputs are logged, and then (almost?) everything else about program execution (i.e. all other function calls and parameters passed to them) can be deduced from that. I've seen similar solutions being called "time-travel debugging", but I haven't found anything that's just "plug-and-play" for any major language. Any recommendations?

I use a similar system. But level is also used to switch writing events to the log.

Usually only events that alert of a severe error are logged.

Once we know something's not working, the settings for level are modified so, without even stopping the service, much more detailed information is written and we have a more precise idea of what exactly is failing and why.

It works nicely.

Sometimes you face an edge case that cannot be reproduced easily even while waiting for this enhanced logs level. I would 1/ still log as much as possible, 2/ implement a smaller logs rotation period (upload logs to glacier or S3 after a week), 3/ tune down the verbosity if you want to avoid some unwanted noise later. Use a return of experience approach to get the perfect level for you!

i've consistently been improving performance by removing logging.

feels bad, but getting a 55 hour job down to 12 hours by removing logging was worth it.

yes, we log asynchronously and without blocking. but it is a constant tax on everything that happens and it adds up.

I am extremely curious how asyncronous logging was multiplying the job execution by 4x - are you able to share a bit more information about what particular portions of the logging were costing time? If it was done asynchronously I assume you're collecting to-be-logged records in memory with occasional batch dumps to disk/other persistence but were you spending time collecting auxiliary information that was costing a lot of cycles? Like fetching relevant information from the DB that was useful only for logging and not for the actual job?

I've seen some time jumps with logging removal but I don't think I've ever seen anything exceed about 20% of execution time (at least on the scale you're talking about, there were some scripts I revised logging on that were constructing huge logging infrastructures for an otherwise sub-milisecond job) 40 hours is a lot of hours.

oh no - introducing asynchronous logging made it better. but not nearly enough.

it was far, far worse than that.

I would do the same if I was you. I will still have a log whenever we catch an error because it will help debugging this cron or job or even identify an issue in the provided data. No matter how divisive the opinions about logging are, I still think that mini logs are better than no logs at all.

Reply on news.ycombinator.com