Logging practices I follow
16elt.com
16elt.com
If the timestamp is in a weird format (or, god help you, multiple formats since some libraries log shit in a special way), it'll be just about impossible to tell when things actually happened instead of just when the logging server saw them. In a perfect world these would be milliseconds apart, but lots of bad stuff can happen.
Your log-grepping-guy will thank you.
It seems the author is putting a heavy emphasis on trying to create readable logs. Finding the signal in the noise. I am biased, but I think this is a failure of the tools used to read the logs rather than the logs themselves. This is why I wrote LogViewPlus (https://www.logviewplus.com/).
Log retention starts to mess with what's considered reasonable. For example, despite the fact that it'd be actually legitimately useful to store 180 days of pcaps, that's just cost prohibitive.
> It seems the author is putting a heavy emphasis on trying to create readable logs. Finding the signal in the noise. I am biased, but I think this is a failure of the tools used to read the logs rather than the logs themselves. This is why I wrote LogViewPlus (https://www.logviewplus.com/).
Well, it's failure on many levels. "informational" logs, like say your traditional access.log are mostly used for metrics/analytics but also server as context to any warning or error that app returns during processing of the request. But at same time you kinda want them to have be encoded in something more structured than "a piece of formatted text" (say, a JSON line), while at the same this approach reduces glancability of logs to near zero.
On other side having hundreds lines of code just to decode logs into something searchable is also pretty bad and most importantly very fragile to code changes.
"Just do everything in machine format then send it to collector" like Jaeger (with bonus being ability to do distributed tracing) is a solution but very obese one and needs every app supporting distributed tracing
Unrelated: I live in the Pacific north west and I clicked on this expecting to find a list like "don't log old growth for timber, don't log the entire area", fun how your brain can associate a word with a concept and ignore the more context-relevant meaning.
In languages when the context is implicitly passed (e.g. via thread-local storage / MDC in Java) Otel automatically injects trace id and span id in the logs emitted using your regular logging library (e.g. log4j). Then in your log backend you can make queries like "show me all log records of all services in my distributed system that were part of this particular user request".
Disclosure: I am an Otel contributor, working on logs (work-in-progress, not for production use yet).
- What happened - When it happened? - Where it happened? - Why it happened? - What's the next step?
If your log doesn't answer at least the first 3 questions, then it's useless. If you don't answer "why", then you should think harder whether that is useful or not.
If I had a cent for every time I see "Something went wrong" optionally followed by stack trace that is nearly entirely in 3rd party code with zero information to correlate it with anything - I would have retired to homestead ages ago.
Over time I've actually found myself logging less just because having to sorta mentally elide logging lines added to the cognitive overhead of reading & understanding code.
The measure of logs is whether you can put them in front of a smart but unfamiliar persons and have them figure out what's happening. At a minimum, they should understand generally what's happening and specifically what each message is saying (though perhaps not its significance).
(i.e., same as when writing code)
I liken errors and debugs all related to heart beat and breathing rate but without information like "climbing stairs" or "changed medication", it may be hard to understand context or understand why new errors are being seen. The first question I would expect to ask when seeing logged issues, is what has changed recently that could be related to the new errors. Curious to hear thoughts on this?
I actually built software/startup related to the logging of changes (architecture change/software change/server restarts) but just didn't get traction and curious to know why it's not more interesting to people.
Theres a difficult cognitive dissonance for looking at a logged event and know that it's unusual or not. Some signals are in fact positively correlated with a failure, and some times it's just noise. Good tooling hopefully makes the distinction of these two options as easy as possible.
- most devs have lost the concept of logging levels, considering normal spitting out crappy giants backtraces and wall of meaningless text;
- most devs have lost the idea of "being quiet" or "frugality", also have NEVER tried to read logs like an application user who do not have nor want to pass gazillion of lines of sources often crappily arranged.
In the classic *nix world skimming log for "alerting patterns" was easy, for modern crapplications it's a bit of a nightmare. Similarly using logs for debug and mere health check is sometimes useless since many messages should at maximum be debug level logs, others are meaningless and even looking at them from the sources does NOT clarify until you read much more.
I absolutely loathe reinventing global state by passing "context" objects and the like everywhere. It's the dumbest thing in the world but no one ever questions it.
Mostly I just wish more languages had Lisp-style dynamic binding / "special variables". Logging is one of the perfect use cases for dynamic scope - you'd have your normal logger object/configuration as the top-level value of a global, and then let-bind it whenever you need to alter its value for all code executed within that specific scope.
Alas, about the only widely-used form of dynamic binding today is environment variables.
It's not perfect, since it uses JVM's thread-local storage under the hood; this can break when e.g. evaluating Futures in a ThreadPool. For variables which are rarely-overridden, like loggers, I do so with a wrapper that also switches the ExecutionContext to a new ThreadPool (urgh, multithreading...)
PS: I do the same for env vars too ;) http://www.chriswarbo.net/blog/2021-04-08-env_vars.html
As for the HN comment that prompted your blog article, I did a double-take reading it, because I could've sworn I wrote the exact same thing around the same time - turns out I did, though on a different thread :).
And if you did want tooling to help, then typically the formats were regular and so you could use ordinary text processing tools to help. sed, awk, grep. With structured logging putting everything into nested balanced expressions, you need parsing. Parsing works until you run across something the parser can't figure out. Say you have some Go code with a JSON logger object you're passing around. What if you want to log something but your logging object isn't passed to that function. (you could pass it everywhere but that increases the arity of every single method by 1, and are also reinventing global state poorly) You're SOL, now you're stuck with fmt.Println() and you just broke jq. No, jq does not handle this failure mode. No, Golang does not let you just spit out arbitrary JSON. Thy must use the logging object.
The only thing it helps is ingestion into databases for heavy machine processing. Which is fine, but don't make it the only or even default way software tools spit out logs. In every other way, introducing parsing into your workflow just slows it all down. The only way I can see structured logging making anyone's job easier is if they never understood how it all worked before.
You could also, you know, run your own infrastructure and log to your heart's content.
It's usually only when you involve ELK or something like that your logs start to get big. Which in turn is typically necessitated by over-complicated distributed software design.
If you're at the scale where this actually matters and you're serving millions or requests per second from a worldwide user-base, then affording storage for the logs really shouldn't be a problem anymore (idk, with the possible exception of Twitter)
This is a good point - a RAID array of a few HDDs/SSDs scales surprisingly far and is cheaper than many of the cloud services out there, though whether you can or can't use either approach probably relies on compliance requirements and such.
I will definitely add that logs can compress really well - to the point where it's been close to a year since I added Logrotate to a project that didn't have it before, for a pretty basic setup, and I haven't had the need to even look at how many archives are currently retained, given that the disk usage has changed very slightly. And that's for multiple systems that filled up the available storage in months previously.
Of course, my personal gripe is that most of the logging solutions out there are rather complex - something like Graylog feels like one of the simpler self-hostable options while still being fully featured, but in my experience anything that runs ES is really resource hungry. Sometimes it feels like MariaDB/PostgreSQL would be good enough for most of the simpler low logging volume setups out there - if you don't want to manage logs as files, want to ship them somewhere, but don't want the receiving system to be too complex either.
Once you face the fact that the performance of a single SATA disk means you can't search the logs in any quick time, and nobody can possibly read that much log data, so nobody will use it, you start to see it as a hoarding disorder not a useful tool.
Is it audit logs for security or due to some regulatory requirement? Then huge blobs are fine. Desirable, even.
Transaction logs for machine-loading so you're able to replay an application's state at any given moment in time? Yeah probably gonna end up with huge blobs again.
On top of that, mechanical hard drives are pretty cheap these days. Like it's a dozen dollars per terabyte, if not less.
I don't know, you're either producing just absurd amounts of logs, on the order of a hundred gigabytes a day plain text, at which sure, I guess you could probably log a bit less. Either that or you're operating at a scale with many millions of users where you should have income and be able to afford it.
... well, either that, or you're being fleeced.
Services like CloudWatch are an excellent way to burn through money, though it's usually the time series storage and ingestion costs that balloon out of control.
You can pay less for equivalent on-prem infrastructure but it drives costs quite differently. For example, it tends to be hard to refresh that infrastructure because it doesn't make you money, so it gets worse over time. The unit cost of storage is very low, often because you make availability/durability tradeoffs that aren't even available to you from the SaaS provider or cloud service. But you will find that the Opex associated with it can be either quite high or poor, and this is hard to reflect in terms of investment by P&L owners.
You can do either approach well or poorly. The way SaaS sucks when doing it poorly is mostly that you are paying a huge amount of money. The way on-prem sucks when doing it poorly is much more complicated and is reflected by toil and tech debt across an organization (which is money but harder to tie to what would fix it), poor visibility, lack of insights, and possibly spending too much in Opex or licenses, depending on the technology. The cost of having a bunch of people do on-prem logging "right" is hard to justify, even for these "large organizations" where I guess, people think, money is free. And even if you've correctly identified and wish to fund the cost of delivering the infrastructure (which as you point out has hardware as only part of its cost), it's not like you can necessarily find the five quality engineers to run the thing. And if you could--do you really want these FTEs working on logging infrastructure or do you want them delivering revenue features?
Don't move the goalposts to hundreds of TB--this user is giving advice to everyone based on a perspective that you're doing something wrong if all of your logs don't fit on a single hard drive; that you should "log less" if you have the "absurd" quantity of "hundreds of gigabytes" a day of logs, and who seems to think individual hard drive costs is an important driver of the cost of managing logs. Their words, not mine.
There's nothing interesting to be gained from hot takes based on naïve conceptions and lack of experience. Pointing out that giving overly-general advice based on your inexperienced best guesses and the NewEgg price list is not very useful is not "unnecessarily dismissive."
Now count that for queryable data source so running a database of some sort (Elasticsearch probably for logs) 24/7 at fast enough speeds that it is ops-useful
Metrics are significantly cheaper tho, at least if you use some dedicated TSDB with good storage engine like Victoriametrics or influxdb.
- It will need much lower amounts of disk space, disk IO, CPU and RAM comparing to ElasticSearch during data ingestion.
- It will provide fast logs' querying and tailing via easy-to-use query language (LogsQL), with the ability to calculate advanced stats over the selected logs.
- It will accept data in ElasticSearch format, so existing Filebeat and Logstash setups can be switched from ElasticSearch to VictoriaLogs in a few seconds.
If you cannot search quickly in the logs, at least the "hot" ones (i.e. most recent) they don't make too much sense. Well, they still make sense but for other reasons, but you lose many interesting feature of logs. At $DAYJOB we *surely* needs to trim and shave a lot the logs apps are sending to the centralized ELK - which is one of the points of TFA - but we cannot just gzip the text files and be done, we need to be able to search for patterns anbd data in the logs to understand what the app is doing in certain cases (besides having metrics).
P.S. We also store them as gzipped files in an S3 bucket using warm/cold tiers, and it is certainly cheaper than using even magnetic disks.
IMO, the entire point of logs is to be able to ask questions of and reason about the current state of your application. If you're only logging errors that you can't recover from you may as well just throw and exception and restart.
Unironically tho this is a good decision if you design for it from the beginning crash-only software style. Most of what I log is INFO and WARN level because unexpected combinations of business-level state are where the real subtle nasty bugs are. Nil reference or whatever can just crash who cares.
I would add that there can be value in having 2 log levels: verbose and non-verbose. It is helpful if you can selectively switch on verbose logging by user or by API endpoint.
In one application which I maintain, when verbose logging is switched on for a particular user, TCP/UDP socket objects are automatically wrapped and packet captures are logged, only for packets sent/received while servicing that particular user's requests. This has been a lifesaver when debugging things like weird, transient authentication problems stemming from upstream providers.
We currently use two log levels:
- When 'debug = true', debug logs are printed immediately (like a DEBUG log level)
- When 'debug = false', debug logs go into a buffer: if the request-handler succeeds, its debug buffer gets discarded. If it catches an exception, the buffer gets printed.
This avoids the main problem of log levels, which is having to guess up-front which level we might want (and inevitably get it wrong, and have to try re-creating a problem with more verbose logging!)
I have found the extra structure and familiar semantics make it a lot easier to talk about what we log, how we log it and why.
* Are you working on a SAAS product or embedded/IoT project or hobby project?
* How do you aggregate the SQLite logs together from disparate machines? Seems like you probably can't use fluentbit/filebeat/etc.
* Where do you query these logs?
* How do you structure these logs? (timestamp, machine, message) or something with more columns?
* Are you able to capture stacktraces?
I _love_ the idea of leveraging SQLite for this kind of scenario and possibly skipping a lot of messy plumbing or pricy vendors, but I'm uncertain how this works.
Stack traces, user actions, 3rd party logs, et. al. are meticulously tracked in a schema we thought most appropriate for our business.
I also can’t stand: “You’re doing logging wrong” / “you’ve been doing logging wrong”
But then again as an industry we seem to like confident bullshitters