Monitoring your logs is mostly a tarpit
utcc.utoronto.ca
utcc.utoronto.ca
If I see a spike in errors, I can, in real time, count them by user id, group by region, filter out by some other field, then have the table of events generate a live line chart easily showing the error rates over time, and pin pointing the exact moment an error started.
Less than five to ten minutes after detection or report and I can be talking with another team about a change they released at time $x, including a list of affected users for product teams to reach out to if needed.
Logs are often a treasure trove for system invaders.
Do you have any resources/blog posts/keywords for learning more?
As for blog posts - I'm not aware of any. I've actually wanted to show off what we have but have never prioritized the blog post.
Please do, I'm interested in learning as well.
1.2.3.4 - - [08/Aug/2023:12:48:11 +0200] "GET /wp-config.php.bak HTTP/1.1" 404 196 "-" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/47.0.2503.0 Safari/537.36"
2. Apache proceeds to shove all this into a string, destroying the structure, and probably some of the data (it likely knows the timestamp with >1s precision)
3. Then to do some sort of analysis we need to manually reverse this process: write some convoluted regex to match this kind of line, turn an IP address back into a number, turn a timestamp into a number, find the delimiters. We're now undoing the damage Apache did. Why!?
4. For extra fun this adds extra problems to deal with log rotation, log compression, newlines and special characters in fields, and so on. All kinds of problems that are ultimately unproductive to solve and get in the way of actual useful work.
Logging should be structured by nature. I shouldn't be writing weird regexps. I should have every message structured from the start, where I can search by "ip_address is in 1.2.3/24", or "request == 'GET'", or such. Every bit of data should be logged in its pristine form with zero ambiguity, with its original type, and analyzable accordingly.
I think systemd has the beginning of a good idea in here, in that you can actually do this if you care to, and can send arbitrary chunks of data (even binary) to the log if needed.
People who complain about journald not logging in plaintext honestly baffle me, because come on, whose idea of fun is it to do log parsing? And why are we spending CPU cycles on converting timestamps to text and parsing them back?
Eg, maybe I want structured logging for the HTTP headers. No way to get that at present, as far as I can tell.
Because it's better. Because it logs stuff separated by field, doesn't have problems with unusual characters or newlines, supports cursors, deals internally with log rotation and compression, a whole bunch of cool stuff.
> Use Apache customized logging as the parent comment suggested.
That's exactly what I want to avoid, for reasons explained in my original comment.
IMHO, that's not even the right mental model, because it assumes a constant schema. Log entries are more like types: the fields in one entry may look nothing like the next.
The consequence of using the wrong model is its inevitable collapse into 'Shove everything custom we need into a single field that's somewhat appropriate'.
In the base case that devolves into everything in a one line string. Yet even in structured systems you see the behavior in {use of boring, standard fields correctly} + {everything else in an 'error' or 'customdata' field}.
Thankfully, some tools and ecosystems seem to have grokked this and moved forward.
And honestly, it's mostly an ecosystem problem (producers and consumers), so really needs to be solved via more programmatic self-declaration of data structures.
My imagined ideal logging model is logging two things:
1. A structured tree of data. With field names, types, and content in native format.
2. An end-user hint about which of those fields are of most interest to an user. This is used by a log viewer to generate something like a traditional log file by default.
So an HTTP log entry might contain the entire HTTP request with all the headers and metadata, and the hint then says "Of this, the admin probably want to see timestamp, URL and status code".
You get the convenience of paging visually through what looks like a traditional log, but also everything is available for easy analysis.
The producer declares all possible data.
The consumer requests the specific data it wants, at runtime.
Because fundamentally, there's a mismatch of knowledge. Log consumers won't inherently know everything that can be in logs. Ergo, modern API-style ecosystem models are probably better approaches.
So this fails at point one - it is impossible to "declare all possible data".
The problems started when I realized that it was far too large to be feasible... until I discovered that about 80-90% of all data was log tables, which in my case I could just skip and export everything else instead.
Now, the logging implementation there used the EAV pattern and got somewhat complicated after years of development and maintenance... however it was mostly okay (in addition to some traditional logging into files and logrotate).
That said, personally I'd use either a specialized log aggregation solution, or at the very least would store logs in a completely separate data store, both for resiliency and security reasons.
You want your logs to be opaque binary data that requires a special-purpose viewer?
I don't care what format it is, I care about solving problems.
But also I want pristine data. I don't want to be parsing text timestamps to convert them to a number I can then finally use to filter out what happened last Saturday. I want the system to know it is indeed a timestamp, and to natively support date comparisons, and to then be able to output that timestamp in whatever format might be required, if that's needed.
Like this:
journalctl -S '2023-08-06 12:00' -u libvirtd
Or I can also do stuff like:
journalctl _PID=3663
At this point I've used many different proprietary web based cloud log viewer apps that are slow, glitchy, and each have their own special query syntax. Theoretically I can leverage them for super powerful queries against structured logs, but instead I find myself using different ones frequently enough that I never master the syntax and have to read through the docs to do silly basic searches.
Logging natively with journald allows you to add custom fields on top.
It’s probably something I should write about. Even though the idea is not novel, it doesn’t seem to be well supported by any libraries that I’m aware of and causes an impedance mismatch with the ones I knew about several years ago (dropwizard metrics and it’s subsequent derivatives).
JSON format logs?
One pattern I’ve used before - in a Java app with an RDBMS, create an error table, and every unexpected Java exception gets logged to that table. Then have a system to match problems in that table to known errors, or flag new ones for analysis. (I just clone the table from the production DB into a non-production DB, then have a bunch of views I wrote to analyse them - the fact it is cloned to the non-production DB means I don’t need release management approval to update the definitions of my views.)
At a certain scale this may lead to problems with performance or data volumes, but generally not if the app is small to medium scale (as in practice many apps are), and especially if exceptions are sufficiently infrequent (one hopes so!)
{"date":"2023-08-08 10:14:35.129532","log":"... normal unstructured log text ..."}In my limited experience the amount of lines logged correlated with expected or actual activity of the system(s) is perhaps useful for monitoring. Looking into and analyzing the actual log events and their text is then the next step if there seems to be too much or too little information logged.
Since Serilog supports consuming CLEF as well, this makes it trivial to upload the non-.Net logs to Azure Application Insights for example.
Might be other options as well, I didn't look much further as this fit our needs well.
edit: This doesn't completely solve the main point in the article of course, as the variables, error codes etc in the structured log message can change willy-nilly in a general system setting.
It's not that hard to get organized. Here's what I've been doing since the last ten years on most of my projects (Java & Kotlin mostly but you should be bale to do this for anything).
1) log levels matter. Debug/tracing is disabled in production. Info is informational only and should not have a signal to noise ratio that gets annoying (people doing debug logging at info level). Warning frequency should be low. If you are not going to fix it, it's not worthy of a warning. Errors should cause alerts and people to be woken up. Simple rule but only if you enforce it. Don't log at error level unless it really is worth waking somebody up for (e.g. me). An error is not "something totally expected happened but I could not be arsed to think about handling that in a sane way". I've seen projects that routinely log thousands of errors per hour and never fix anything until after customers start yelling on the phone. Log levels are totally irrelevant in such projects. Nobody bothers to look at those errors. They are no longer actionable. If errors are normal and expected behavior, how do you tell when something abnormal and unexpected happens? You can't; unless you make people do something about those errors and create a culture where having errors is simply not an acceptable state for the product to be in. Life is great when you do that. We have zero errors on most days. When they do happen, it's usually because something changed. And then we fix that and it goes quiet again. Simple rule to enforce. Generates very little work. But you have to enforce it.
2) Java logging frameworks have something called a mapped diagnostic context (MDC). This is great. Basically it means every log entry can have a context where you can keep track of things in e.g. your request like headers, user agents, ip addresses, session ids, etc. Why don't other languages have this? I don't know. Seriously, how is this not a thing for any web development framework worthy of the name. Why would you not want to know this information when something happens?
3) Logging messages are structured data. Whether you like it or not. Plain text is a shitty way to represent structured data. If you can, log in json format. You have timestamps, logger names, log levels, attributes in your MDC, attributes coming from your server environment like the host name, service name, etc. All of it is relevant.
4) Tailing and grepping plain text logs simply does not scale. It's what you have to do when your ops team is too incompetent to setup proper logging. Usually goes hand in hand with having snow flake servers that people ssh into. It's actually the #1 excuse to have boxes you can ssh into to begin with. Solution: logs go into a data store that allows you to filter on this data. Not having this is the equivalent of running blind. Completely and utterly unacceptable. Most cloud environments come with a reasonably OK logging console but you might want to upgrade to something with a bit more querying capability. But done right even those default logging consoles can be capable enough.
5) Your logs should have alerts on them. If errors happen, alerts should happen and people should do things about those errors. If logs go silent when they shouldn't be, alerts should happen because something is probably broken. If there's a weird spike in logging volume, alerts should happen. Alerts should be actionable and be exceptional. If something is alerting all the time, nobody will check when something important actually does happen. Tricky to get right but once you do, you can react quickly to any incidents.
Deliberately keeping product names out of this. There are plenty of libraries, tools and products that allow you to do this properly. That most likely includes your preferred software stack. And if it doesn't, use something more production ready that does. Or fix it (not that hard usually).
Alternately, "cost of responding to false positives will be deducted from your bonus."
- I (as the CTO) get grumpy when I get alerted for nothing or spammed with non stop alerts. And I see all the alerts. Basically that means I tell people to get their act together (or lead by example). In fairness, it's quite often me that made the changes that caused me to get alerted and grumpy. This is not about finger pointing but about it genuinely being annoying to have to deal with this. This is a necessary level of pain that you seek to minimize.
- I get more grumpy when I don't get alerted when the thing actually breaks. This means I have to explain to others why shit was broken for hours/days on end without me doing anything about it. The dog ate my homework doesn't quite cut it here. I'm responsible, so I need to know.
The balance here is making sure every error gets logged and then making sure that everything that does get logged gets resolved in a way that makes the problem go away permanently. It's either a bug (fix it), an infrastructure failure (fix it), or something that isn't an error (so fix that it doesn't log a such).
Server state should be exposed through metrics. Metrics have far fewer sharp edges than logs, and it's more obvious how to correctly produce, consume, and alert on them. I've seen (variations of) your 5 action items needed for the logs of every company I've worked at, but they've never applied to metrics.
Executions should be exposed through tracing. I'm kind-of cheating here: I expect the traces to have logs attached. But a well-done tracing system, where a developer can add a flag to their Postman query and their request was traced with the debug level set only for that request is a magical thing.
You can get very far getting to know the operating system's remote logging machinery can get you very far on this. It's amazing how often people basically duplicate this and how often people just write logs to text files or database tables instead of hooking up to the tooling that comes with the OS.
Swift has those [0][1] and other features like jumping to the file and line of code from where the log was generated, but I wish there was a way to easily add extra information to each message in the debug console such as the current frame being rendered etc. Something I've been wrestling to do for the past few days, but if I write a custom logging function, then the IDE's debug console thinks every log message was generated from my custom function.
And god I wish we started making use of COLOR within text-heavy information. Being able to color different words/values in a log message would massively improve readability and comprehension.
FWIW, I have a small diagram for a subset of the taxonomy of logging: https://www.lelanthran.com/chap10/Logging-Guide-Light.png
There's a whole blog post on that that I have been meaning to clean up and post to HN: https://www.lelanthran.com/chap10/content.html
I'm sure that the folks here would enjoy you sharing the post as a submission, too.
I did share it at https://news.ycombinator.com/item?id=37048276, but it didn't get many upvotes. Will try only one more time in a month or so as I don't really want to spam HN.
I thank you for reading the content.
> FYI not everyone find 'handwritten' diagramms cute and more importantly sometimes this cuteness actively interfere with reading comperhension, ie this font is quite shitty for me, esp. on the mobile when I need to actively pan and zoom this big diagramm.
I understand that not everyone finds this sort of diagram as usable (by which I mean legibility, approachability, memorability and understandability).
By the same token, not everyone finds the usual sort of diagram as usable as this. In my experience, I've found that cartoony/sketched images results in the audience being more receptive to, and remembering more of, the message.
I think this is why this sort of thing is more and more popular these days - it mostly works (not for everyone, obviously).
> on the mobile when I need to actively pan and zoom this big diagramm
I'm sorry about that; I chose an image size that would fit most mobile phones in landscape orientation, and set the fontsize to what I personally could read without my glasses.
For reference, on my mobile, HN text is too tiny for me to read without my glasses, so I was fairly sure that, if I could read it with no glasses on, it should be large enough on most screens for most people.
Once again, thank you for reading the content.
Subjectively, I'm inclined to agree. Somehow the "sketched" diagrams just seem more approachable, at least up to a certain complexity: that's why tools like Excalidraw have replaced something like LibreOffice Draw for when I need to create a diagram, at least outside of professional goals.
Fonts are still difficult, though. Excalidraw's "handwritten" font is a bit too hard to read, but most of the sans fonts out there don't mesh well with the diagram style otherwise.
Thankfully there's probably tools out there that support custom fonts with little issues and one can probably find one easily.
Regardless, best of luck!
This font is quite awful, if you need a good hw font - look for what manga scanlators use, and this is quite serious here , those guys spend up to 20 years to hone their skill. In short you you need way more height per glyph.
Regarding the d. Itself: it's good enough on the desktop, it is too big on the mobile. It can be reorg. To be more
Edit: oops, later
The main point he's trying to make is not just about the logs you wrote but about logs coming from other systems or services, e.g. monitoring kernel logs in your OS. As he rightly points out, one of the reasons is that logs are not an API.
> One reason this happens is that almost no one considers log messages to be an API, and so they feel free to change log messages at whim.
create table log (dt timestamp not null primary key, msg text not null)I have seen this being a big issue in medium apps just because it's used blindly.
And if you don't do it asyn out of your request path you add unnecessary latency to your hotpath.
Sending logs to a logging system is really straight forward.
At least use a second database with an independent connection
Well, in my case - the table only logs unexpectedly failed requests (so not “user entered wrong password”, more like “HTTP 500 NullPointerException”.) That’s not on hot path by definition.
I agree logging every single HTTP request to an RDBMS, even a 200 GET, is dumb.
3 years later 10tb and a s3 bill of 200$/month...
I mean literally peanuts to a company
RFC 5424 syslog has a structured key=value component:
So, if your implementation supports it.
But JSON is loads easier to emit and to build random parsers around.
In our case, syslog was then just upstreaming the logs as JSON to a more central collector, so we ended up just cutting it out of the loop.
It logs locally in plain text and in color, for easy visual parsing, but in production - it's in JSON.
It also lets you add arbitrary one-time properties or "sticky" constants (environment, process ID), or dynamic properties based on current context of the logger, such as information specific to a specific user request.
"structured or not" is a valid discussion; but irrelevant to the point. We're not good at watching our logs for the things we wanted to see; nor are we good at emitting the data we want in the logs in the first place. Too many conflicting purposes in the same place.
Made my office sound like a jungle: bird chirps for firewall probes, coin clatters and cash register "Kaching!" for sales page hits and actual "someone gave us money" sales, etc. It was fun.
- application startup and shutdown (at INFO level)
- occurrences that indicate a bug in the system logging (at ERROR level)
- occurrences that indicate a bug in another of your systems (at WARN level)
The last two require a lot of education and discipline to stop people from logging rare but valid circumstances, bad input originating outside your software, and "important" events. The answer to "but don't we want to know when..." arguments should always be, "If it's that important, emit it as a metric or store it in an appropriate datastore." Anything logged at WARN or ERROR should be something that can be addressed by fixing code.
If you stick to this discipline, monitoring logs is valuable and reasonably simple. You can alert on any WARN and ERROR level logging. There's nothing like looking at a month of logs and seeing only actionable information and a handful of application lifecycle events. (There's also nothing like looking at six months of logs from a stable system and only seeing lifecycle events.)
It is hard to stick to this discipline. You need a manager who believes in it and will back it up when engineers want to depart from it, and who will always prioritize fixing violations.
Why is it so hard to make engineers follow these rules? Because initially, it makes them feel incredibly anxious. It feels irresponsible to throw away so much "important" information instead of logging it. After working this way for a while, though, they realize that it actually forces a higher level of responsibility. Logging information in noisy logs might feel better than throwing it away, but it's not. It creates an illusion of having handled the information responsibly. By taking away the illusory option, you force people to make a real decision between throwing it away and saving it in an actionable way, by emitting it as a metric or storing it in a datastore to be processed.
Despite having to managed TBs of logs per day and sift through them at times, I'd rather have too much logs. However, we did not alert on any of them. All alerting was symptoms based via SLOs (error rate, latency). Logs were only used for debugging.
I was taught a perfect solution to this. Only ever return 200-300 from your web server (not applicable for most public APIs, though). My web server is not a gateway, not a resource access mechanism as envisioned by people in the 90s. It’s always an RPC server. REST is RPC. JSON is RPC. I let my outsourced CDN do HTTP code shenanigans, but any apps I develop are 200 all the time. Want to know if it failed? Easy!
{“success”: false, …}“It’s old” isn’t a reason to throw out a working design.
Ethernet > IP > TCP > HTTP > My application
HTTP is a hyper text transfer protocol, designed as such. My application is a RPC front-end for a series of data stores, AI models, etc.
Using HTTP codes for your application's protocol is a mismatch. There are some fairly general-purpose HTTP error codes that can meet many application's use cases, but the overlap is not perfect. You can get greater granularity by ignoring it entirely.
Going HTTP 200-only means any non-200 is now definitively from 3rd party middleware, a router, proxy, etc. The boolean check of "did I hit my application code?" is easy and useful.
4xx: You screwed up
5xx: I screwed up
Easy!
More important, this is generally expected when calling any kind of API over HTTP.
Returning a 200 in an error situation makes it very difficult to diagnose errors. For example, the F12 debugging pane in my browser color-codes errors responses. Fiddler does the same thing too.
More important: Languages / libraries have built-in mechanisms for handling these errors, which make error situations easier to handle (or not handle.) For example, some C# libraries will always throw an exception on a 4xx or 5xx response. If your oddball API returns a 200 in an error situation, it breaks normal error handling patterns. (And could result in making situations where "success": false much harder to track down.)
And finally: Because error situations are unusual, they often aren't encountered in the normal day-to-day debugging of your APIs consumers. As a result, your oddball API's failure situation is probably untested in whoever is calling your API. When your API fails (because it will at some point,) there's a high chance your consumer won't check the success flag and parse the response as if it's successful. (Again, because you're not following normal HTTP semantics.) This will trigger unpredictable failures in your consumers.
And it's always easy for me to override this. I've been doing it this way for years - all of the startups I've worked at do it this way - and it's extremely successful.
> whoever is calling your API
Just internal use. For external use I agree meeting expectations is important. Users will expect a 400/500 for certain issues.
...And, whoever inherits your code probably won't like working with it. Doing weirdo things like that can hurt your reputation in a team.
> ...And, whoever inherits your code probably won't like working with it. Doing weirdo things like that can hurt your reputation in a team.
Well, it explains why web APIs are such a hot mess: the people creating the tools don't know the difference between transport errors and application errors, the developers creating the applications don't know the difference, and the developers calling into the application don't know the difference.
It's a pretty important difference, and it all other protocol stacks care is taken not to side-step any layer and directly fiddle with the transport layers from the application layers.
Right now, a client getting a 5xx response can't tell if the application had an error or if the proxy is misconfigured, because the application developers are sending proxy errors/server errors (5xx) and trampling all over the namespace of the transport medium.
The system appears to be well structured, but the conventions were all set by developers who were all noobs. I don't think, in 25 years of development, I ever saw a sockets program (neither client nor server) where the application detected an error and set error-bits in the IP datagram, and yet in web-development, I see this all the time.
Should you start HTTP responses with "ACK" because it's based on TCP? No. Then why start your HTTP responses with "HTTP/2 500" because your call to OpenAI timed out?
I strongly disagree; let me try to convince you why those tools are correct and why it's still wrong to return non-2xx error codes from the application.
The F12 debugging pane and related tools which color code non-2xx response codes are correct for returned documents, not for API requests. For returned documents, HTTP is the application protocol, for API requests HTTP is the transport medium! These tools are not able to make the distinction (yet) between "calling an API" and "retrieving a document".
In HTTP it's literally called the status code, not the error code.[1]
Look at it this way, when you're in ssh to a remote host, any errors in the transport medium is reported within the TCP stream, not inside the TCP headers or inside the IP headers. Errors from ssh itself don't set error bits in the TCP stream or IP packets. You'd be horrified if, within ssh, a shell error (say, 'cd /non-existent-dir') sent error codes in the error fields of TCP headers or IP headers.
So, yeah, errors in the application layer should not set error fields in the transport medium. When serving static files or documents, HTTP is the application layer, so it should report things like '404 not found'. When GETting an API endpoint results in the application not find (for example) 'web.config', it should not* return a 404. After all, the handler was* found, the URL is correct, so don't overload the 404 for something else.
[1] Even curl handles it properly for the level it is working at. Since it is one layer higher than even the HTTP API (because it returns a result to the shell that called it), no errors are returned for any non-2xx responses, because, from the shell PoV, that's not an error.
I disagree for fully automated applications, for example message-driven ones. Logging key steps is important for situations where you need that post-mortem information after a problem already happened, because you often cannot reproduce the exact environment in which the problem was encountered. Numbers and timing information can be very useful in these systems, as well as information about what path the system will take (tracing) when there are many.
This is a solved problem (at least for the linux kernel) with printk indexing[0]. So you can query the running kernel what log messages it can output. With that your monitoring tool can check when an expected message was changed and you get the messages in printf format so you can parse them if you want.
> But monitoring your logs looks productive and certainly sounds good and proper. You can write some positive matches to find known problems, you can write some negative matches to discard noise, you can 'look for anomalies' and then refine your filtering, and so on. That's what makes it a tarpit; it's quite easy to thoroughly mire yourself in progressively more complex log monitoring.
Nothing surprising here. Spend only the time that's worthwhile and has a point. I don't think I've done any bottom-up (just because) log analysis other than counting logged exception types/sites.
Looking at logs more and you will build a feel of what is important.
Better yet, write your own logs.
Logging can be useful AND a rabbit hole. If you have the horsepower to manage the firehose, knock yourself out.
I have also made the mistake of logging because I could. Logging without a plan I have found to not be worth it. If you are not going to take actions on those logs. Why are you keeping/making them? The flip side is when something breaks you will know you want those logs. Hopefully, you will have what you need in them (usually not). But then you turn on more and more as you need it and eventually find a happy medium.
It is amazing how many people (even ostensibly security people…) don't know that, if you're on the Internet, you're being subjected to a never ending torrent of it.
I found a bug in rsyslog a few years ago, where in certain conditions, log entries were missing. If you know the pattern for what log entries were going missing, then you could craft a very stealthy attack on the system and remain undetected in the logs.
> there's no guarantee that the message you're monitoring for won't change. Maybe someday the Linux kernel developers will decide to put more information in their MCE messages and change the format.
How often do the messages change? How often do you need to re-train the AI? Is it worthwhile?
Not as accurate as string matching though. And more time/compute intensive
How much work does it take to train and maintain a property trained AI, given the three problems mentioned in the essay?
The tricky part - just as with logging - is to figure out what metric make sense and give you signal and what metrics are mostly noise.
Sometimes you can even extract metrics from logs by looking for specific log lines if you know what to expect.
This looks backwards from the app dev's perspective.
- Metrics are strictly structured, documented data. They are a first-class output.
- "Strictly structured logs" is contradiction in terms. These are just events to be sent to a pub/sub, also a first-class output.
- Logs are unstructured, unknown, bleeding-edge, grey-area data, which can potentially become either metrics, or events, or bug tickets.
If I output data as metrics, I don't output it again as logs - that'd be just noise.
But of course other apps/systems can have a wholly different approach and force people to invest a lot into sorting out that dumpster fire. The leverage is on the producer side.
It works best when you are logging structured data in the form of JSON lines though, so you can query the JSON structure.
That way we could centralise all logs and detect different kinds of failures, like unexpected log lines appearing.
the problem with monitoring and alerting derived from logs is that log ingestion pipelines usually have the property that when they get saturated, they get behind in time and catch up later. That’s more or less the opposite of what you want for an alerting pipeline.