My biggest quality of life improvement for understanding logs has been lnav (https://lnav.org/) -- does everything mentioned in this post in a single tool with interactive filtering and quick logical and time based navigation.
I don't think multitail really understands logs like lnav does, it's just following the last lines in the file. For example, if you try to follow multiple files in multitail like so:
You get a view with the tail from one file followed by the tail from the other, they are not collated by timestamp. In contrast, if you do the same thing in lnav:
$ lnav /var/log/install.log /var/log/system.log
You will get a single view with all of the log messages from both files and they're sorted by their timestamps. Here is all of what lnav is doing:
* Monitoring files/directories for updates
* Decompressed files/archives
* Detected the log format for each file
* Created SQLite vtables that provide access to log messages
* Built an index of all the log messages in all the files so
you can jump to a certain point in time or to the
next/previous error message.
* Display all log messages with syntax highlighting
I migrated from multitail to lnav. Turned out to be a no-brainer.
I second the above, just one pain point with multitail to add. I often page/search/filter in the scrollback buffer (I typoed "bugger" - Freudian slip?) and in multitail the scrollback is a separate window with a frame and everything, which is a pain (copying whole lines using mouse includes the frame, ugh). The filtering/searching being a separate pain.
One thing I used in multitail and not sure if I migrated wholly to lnav was log file syntax highlighting using regexes.
Until now I thought logview.el[0] is the bee's knees, but now I can feel feature envy set in. There are some seriously powerful ideas listed on the lnav page, and it's also the first time I saw SQLite virtual tables used in the wild.
Huh, I almost posted a duplicate recommendation. My only complaint with lnav was that it had to be built from source on Linux and the build was frigging huge. Apparently they have a pre-compiled linux-musl binary now.
At my current company, we're using pdsh with tail -f piped into sed to follow logs from multiple remote servers at the same time, label them and colorize them. Works okay. Decent solution without needing to install much other software. Not my favourite because it doesn't deal well with SSH sessions timing out and leaves some tail -f processes hanging, and some other quirks. But out of laziness and risk of breaking things in prod, we haven't tried experimenting with much else.
It works by uploading a stub that is an "actually portable executable" to the remote over ssh. lnav then talks to the stub to sync files back to the local host. I don't know the scale of the hosts or files, but if they're not too big, it might work fine.
Yes! lnav (https://lnav.org) is phenomenal.
Embedded SQLite...
easily scriptable...
OOB log formats galore, or define your own...
it's a mini ETL powertool that scales to at least a few million rows and runs in your terminal. Maintainer's a friendly dude, too.
Our Easy Data Transform software is intended for data wrangling and desktop ETL. But it has lots of features useful for browsing and manipulating log files, including:
* powerful filtering (including with regex)
* smooth scrolling of millions of rows of data
* support for csv, text, xml, json, Excel and other formats
I love lnav and use it constantly, but it crashes a lot. I do wish there was something like lnav that was a little simpler to use, and written in a more resilient way that crashed less.
I can cut lnav some slack for the crashes because identifying and parsing arbitrary log formats seems like a messy problem. Still it shouldn't crash 1/3rd of the time I use it.
Sorry for the crashes :( I've been trying to improve it's internals more than adding features as of late. If you haven't already, please file bugs on github and/or submit crash logs to the mailing list. (I've taken a break from working on it lately. So, if you've done that and I haven't gotten back, I apologize.)
> you’ll get overwhelmed by a million irrelevant messages because the log level is set to INFO
I know this happens, but I think it's because programmers are abusing INFO. In principle it's reserved for messages that are informative at a level sys admins and a few others can make sense of and use. Unfortunately abuse often leads to "We turned INFO off" making it much harder to diagnose things after the fact.
I think there should be an counterpart to "log analysis" which is "logging strategies for your app". Which should be WHAT to log and WHEN.
Stuff like, if you are exposing an HTTP endpoint, you should log the request URL and the time it took to serve it. Or if you are invoking an extenral service, you should log the response time of that service.
And you should produce a single line of output for each request that identifies all of the pertinent information. You can have more than one, for e.g. a thread dump, but there should be one that provides a complete summary. I've lived with apps that logged at each stage of the process as separate lines, and that's just not useful data when grepping for anomalies.
I hypothesize it's not useful because you're using grep. If you use a tool that can show you multiple lines all tied by a request ID, it becomes much more helpful.
I am quite often looking for patterns across thousands of requests. As an example, one thing I inherited didn’t even log how long each request took to serve. Sure, you find out how long a single request took, by comparing the first and last log entry, but that’s just not useful 99% of the time.
One thing that's improved my log analysis is learning awk (well actually Perl but I think 95 % of what I do with Perl I could also do with just awk). Often the most useful way to look at logs is statistically, and awk can quickly let you aggregate things like time-between-statements, counts, rates, state transition probabilities, etc for arbitrary patterns.
Yes, always include a request id in every request structure you create and include it also in the response and print it. It would seem something obvious that everyone does by default but instead, no, it's not so obvious it seems.
Not so obvious. How to implement it without passing request id to all the functions, when they are unrelated to request/http ? Especially in languages without thread-locals such as javascript?
Many frameworks solve this with logger context. Add the properties you want to the logging context and all future logs in that context will have that property.
Loosely related: a few years ago I wanted a simpler alternative to some of the more feature-full log viewers out there so I threw together a tiny (50kb) app that might be useful to some folks in here.
All it does is consistently colors the first field in a line from stdin so you can quickly see which log lines have the same first field.
Re timing, logs like nginx access logs have their timestamp from when the request completed, not when the request came in. That's a significant difference for long duration (~10s+) requests, and matters when trying to correlate logs or metrics to a request.
That gets rid of the cat and three greps. Both POSIX and GNU encourage grep -E to be used in preference to egrep.
A pcregrep utility also used to exist, if you want expansive perl-compatible regular expressions. This has been absorbed into GNU grep with the -P option.
> A pcregrep utility also used to exist, if you want expansive perl-compatible regular expressions. This has been absorbed into GNU grep with the -P option.
'pcregrep' still exists. But with PCRE2 supplanting PCRE, it is now spelled 'pcre2grep'.
I don't know the precise history of 'grep -P' and whether 'pcregrep' was actually absorbed into it, but 'pcregrep' is its own thing with its own features. For example, it has a -M/--multiline flag that no standard grep (that I'm aware of) has. (Although there are some work-arounds, e.g., by treating NUL as the line terminator via the -z/--null-data flag in GNU grep.)
Oddly, there are pcre2 packages in RedHat/Alma 9, but they do not include a pcre2grep.
GNU grep is also linked to pcre, not pcre2.
# pcre2grep
bash: pcre2grep: command not found...
# yum install pcre2grep
Last metadata expiration check: 1:58:58 ago on Tue 13 Dec 2022 11:45:44 AM CST.
No match for argument: pcre2grep
Error: Unable to find a match: pcre2grep
# yum whatprovides pcre2grep
Last metadata expiration check: 2:09:25 ago on Tue 13 Dec 2022 11:45:44 AM CST.
Error: No matches found.
# rpm -qa | grep pcre2 | sort
pcre2-10.40-2.0.2.el9.x86_64
pcre2-syntax-10.40-2.0.2.el9.noarch
pcre2-utf32-10.40-2.0.2.el9.x86_64
# which grep
/usr/bin/grep
# ldd /usr/bin/grep | grep pcre
libpcre.so.1 => /lib64/libpcre.so.1 (0x00007efc473c4000)
I once compared the speed of these two approaches, rather accidentally. I did output colorization by adding ANSII sequences. I thought, of course one process must be more efficient than a pipe of processes. After the rewrite, I was disappointed about the slowdown and reverted back to the pipe.
PS I checked back and I used sed rather than grep. I think the result would hold for grep but the morale is that you should verify rather than assume.
I have around 50 seds in the pipe, running in parallel (which is what makes it faster), it would have been a half of that when I tried the rewrite.
1) Fuck grep, use ripgrep, especially if you have to scour over an entire directory.
2) Get good with regex, seriously, it will shave hours off your searching.
3) For whatever application you are using, get to know how the logging is created. Find the methods used where said logs are made, and understand why such a log line exists.
4) Get good with piping into awk if needed if you need some nice readable output.
Piping into AWK feels like a misuse of the tool in all but the simplest of cases. Don't forget that you can write complete AWK scripts and invoke them from a file!
I started using ack about 14 years ago, so theres a lot of inertia there. It is slower than the others, but it was so much faster at the time for searching through source trees than grep.
Also, sometimes logs stretch across multiple lines, and the other lines won't have the identifier you are searching for. For example, Java stack traces. In that case if you are stuck parsing unstructured logs, the simplest thing to do is to look at the entire file and search for the timestamp that found the first line.
I guess it depends, but would you not encounter issues like permission blocks, or there being so much content in the logs that it is slow to find what you need?
Surprised to see that under the section "correlate between different systems" tracing isn't mentioned as an alternative approach. That's what tracing is: logging across different systems and getting that structure all stitched together for you.
Do we still use utilities like grep for searching logs? Are these when we cannot stream logs to tools like Splunk & Loggly and use their search services?
All of our logs are in Kibana, but sometimes I'll `kubectl logs pod > tmp; grep pattern tmp` because Kibana's search and filtering is often annoying. Actually, I'll usually open the logs in vim and use its search, which also get me the ability to eg delete every line not containing the pattern and then search only things matching the first pattern. I'm going to try lnav as mentioned in this thread but I've gotten by fine with judicious use of grep
One problem is that you start using these services and then the bill arrives and you then spend all your time removing stuff from the logs to keep the bill down.
Honestly, the most amazing thing I did with logs was learn how to do subtraction. Any time you have multiple instances of a thing and only some of them are bad, you can easily find the problem (if anyone bothered to log it) by performing bad - good.
The way you do this is by aggregating logs by fingerprints. Removing everything but punctuation is a generic approach to fingerprinting, but is not exactly human friendly. For Java, log4j can use class in your logging pattern, and that plus log level is usually pretty specific.
Once you have a fingerprint, the rest is just counting and division. Over a specific time window, count the number of log events, for every finger print, for both good and bad systems. Then score every fingerprint as (1+ # of bad events) / (1 + # of good events) and everything at the top is most strongly bad. And the more often its logged, the further up it will be. No more lecturing people about "correct" interpretations of ERROR vs INFO vs DEBUG. No more "this ERROR is always logged, even during normal operations".
Isn’t this basically what structured binary logs are? Instead of writing a string like `Error: foo timeout after ${elapsed_amt} ms` to the log, you write a 4-byte error code and a 4 byte integer for elapsed_amt. I know there are libraries like C++’s nanolog that do this for you, under the hood.
Maybe this is a silly question, but is there much value in a 4-byte binary code compared to a human-readable log with human-readable codes? Maybe size, but logfmt especially is not much less compact than binary data.
Glad to see lnav (https://lnav.org) already getting some love in the comments. Hands-down the most reliable source of "thank you! I wish I'd known about this tool sooner!" responses, even from v experienced sysadmins / SREs.
I'm interested in this idea as well. Seems like it would be useful for detecting unusual issues assuming you have a large enough data set of "normal" runs.
I've been mulling this idea over in my head as well. I have a fleet of PCs out in the wild, all running the same software. It would be nice to have an easy way to detect strange behavior like processes that are continually respawning / segfaults / crashes / etc, without explicitly writing a bunch of search terms.
People on HN have varied level of skills, and this is a well structured introduction to diving into logs. It already started conversation about better tooling. Let's celebrate today's lucky 10000 https://xkcd.com/1053/ rather than talk something down for being basic.
Yours is an unhelpful and non-constructive comment. Clearly a lot of people have been getting something out of the content in this post, as it's started several discussions.
We've added a log tailing feature into our product UI which also has a basic find/filter. It's been enormously useful for cases where something weird happens as you can immediately access the last few mins of logs.
As much as I approve of a skillset to analyze local logs, but after a relatively small scale (10-20 systems), a central decent log aggregation like opensearch or ELK just brings so much value even on 1-3 nodes. It'd be one of the first changes I make to an infrastructure because it's so powerful.
And its not just log searching and correlation value. At work, the entire discussion "oh but we need access to all servers because of logs" just died when all logs were accessible via one web interface. I added a log aggregation and suddenly only ops needed access to servers.
Designing that thing with accessibility and discoverability in mind is a whone nother topic though.
Agreed! Centralizing logs is so helpful, but you don't know it until you've done it. Too many people rely upon grep, when a handy tool is just a download away. Plug for said too: https://log-store.com
Just to expand on this more - you don't have to use ELK which is pretty resource and maintenance heavy, there are much easier and faster alternatives that don't need attentive care.
Throw Loki+Grafana on a single VM somewhere (or run it on your Kubernetes/Nomad/ECS/etc. cluster) and it will get you very far, as long as you plan ahead a bit (most notably, indexing happens at ingestion, so you need to have an idea of what you want from your logs or your queries will be slower).
Or use a SaaS like logz.io, AWS OpenSearch, Datadog, etc. Most support OpenTelemetry now, so switching data ingestion is quite easy (unlike dashboards and alerts).
It makes sense to have centralised logs pretty much as soon as you outgrow the "everything runs on this one box and my DR plan is a prayer" stage, IMO.
We went to the trouble of setting up ELK and I was excited, but I never use it any more. You can't scroll/search through the logs as fast as vi and grep. You have to click to see more log lines. And I can write an alias to tail a log so I don't have to log into a UI.
I wrote https://github.com/ljw1004/seaoflogs - an interactive filtering tool, for similar ends to what's described here. I wrote it because my team was struggling to analyze LSP logs (that's the protocol used by VSCode to communicate with language servers). But I made it general-purpose able to analyze more log formats too - for instance, we want to correlate LSP logs with server logs and other traffic logs.
(1) I wanted something where colleagues could easily share links in workplace chat with each other, so we could cooperatively investigate bugs.
(2) For LSP we're often concerned with responsiveness, and I thought the best way to indicate times when viewing a log is with whitespace gaps between log messages in proportion to their time gap.
(3) For LSP we have lots of interleaved activity going on, and I wanted to have visual "threads" connecting related logs.
(4) As the post and lnav say, interactivity is everything. I tried to take it a step further with (1) javascript, (2) playground-style updates as you type, (3) autocomplete which "learns" what fields are available from structured logs.
My tool runs all in the browser. (I spent effort figuring out how people can distribute it safely and use it for their own confidential logs too). It's fast enough up to about 10k lines of logs.
135 comments
[ 3.0 ms ] story [ 245 ms ] threadI second the above, just one pain point with multitail to add. I often page/search/filter in the scrollback buffer (I typoed "bugger" - Freudian slip?) and in multitail the scrollback is a separate window with a frame and everything, which is a pain (copying whole lines using mouse includes the frame, ugh). The filtering/searching being a separate pain.
One thing I used in multitail and not sure if I migrated wholly to lnav was log file syntax highlighting using regexes.
Until now I thought logview.el[0] is the bee's knees, but now I can feel feature envy set in. There are some seriously powerful ideas listed on the lnav page, and it's also the first time I saw SQLite virtual tables used in the wild.
--
[0] - https://github.com/doublep/logview
Seems to be packaged quite widely https://repology.org/project/lnav/versions
It works by uploading a stub that is an "actually portable executable" to the remote over ssh. lnav then talks to the stub to sync files back to the local host. I don't know the scale of the hosts or files, but if they're not too big, it might work fine.
* powerful filtering (including with regex)
* smooth scrolling of millions of rows of data
* support for csv, text, xml, json, Excel and other formats
* available for Window and Mac
1) systemd logs (binary data stored at /var/log/journal)
2) docker logs (from various containers running on the host)
Any hints on getting this working? I don't see this covered in the docs (https://docs.lnav.org/en/latest/formats.html).
I know this happens, but I think it's because programmers are abusing INFO. In principle it's reserved for messages that are informative at a level sys admins and a few others can make sense of and use. Unfortunately abuse often leads to "We turned INFO off" making it much harder to diagnose things after the fact.
Stuff like, if you are exposing an HTTP endpoint, you should log the request URL and the time it took to serve it. Or if you are invoking an extenral service, you should log the response time of that service.
Yes, always include a request id in every request structure you create and include it also in the response and print it. It would seem something obvious that everyone does by default but instead, no, it's not so obvious it seems.
One simple example - Serilog enrichment https://github.com/serilog/serilog/wiki/Enrichment
This does however assume your entire application uses the same logger. But this is generally a requirement in services that require tracing like this.
All it does is consistently colors the first field in a line from stdin so you can quickly see which log lines have the same first field.
I used it in combination with the parallel[0] command to prefix log lines by replica name when tailing logs across machines: https://github.com/jasisk/color-prefix-pipe
[0]: https://www.gnu.org/software/parallel/
A pcregrep utility also used to exist, if you want expansive perl-compatible regular expressions. This has been absorbed into GNU grep with the -P option.
Off the cuff, another way to do it is with awk's index function. I don't know what speed penalty this might impose.
fgrep -v -e THING1 -e THING2 -e THING3 -e THING4
'pcregrep' still exists. But with PCRE2 supplanting PCRE, it is now spelled 'pcre2grep'.
I don't know the precise history of 'grep -P' and whether 'pcregrep' was actually absorbed into it, but 'pcregrep' is its own thing with its own features. For example, it has a -M/--multiline flag that no standard grep (that I'm aware of) has. (Although there are some work-arounds, e.g., by treating NUL as the line terminator via the -z/--null-data flag in GNU grep.)
GNU grep is also linked to pcre, not pcre2.
PS I checked back and I used sed rather than grep. I think the result would hold for grep but the morale is that you should verify rather than assume.
I have around 50 seds in the pipe, running in parallel (which is what makes it faster), it would have been a half of that when I tried the rewrite.
grep -v -e THING1 -e THING2 -e THING3 -e THING4 file
- grep (or ripgrep), sort, uniq, head, tail, cut, colrm, tr
- diff
- jq
- bat
- ministat
- less, more, percol
- Facebook Path Picker (fpp)
I have lots of bad habits on the cli I should correct, now I'm feeling guilty after reading all the comments.
1) Fuck grep, use ripgrep, especially if you have to scour over an entire directory.
2) Get good with regex, seriously, it will shave hours off your searching.
3) For whatever application you are using, get to know how the logging is created. Find the methods used where said logs are made, and understand why such a log line exists.
4) Get good with piping into awk if needed if you need some nice readable output.
https://beyondgrep.com/
Usually it's something like rg > ag > ack > grep and that's overall testimonial, not just speed.
What am I missing?
For log colorizing, I make use of the --color-match and --passthru arguments, like https://powdahound.com/2009/10/colorize-log-output-with-ack/
cd ~/logs
cat * | grep <my string>
It works for simple explanations though.
`journalctl -u myservice -S "5 min ago"`
The way you do this is by aggregating logs by fingerprints. Removing everything but punctuation is a generic approach to fingerprinting, but is not exactly human friendly. For Java, log4j can use class in your logging pattern, and that plus log level is usually pretty specific.
Once you have a fingerprint, the rest is just counting and division. Over a specific time window, count the number of log events, for every finger print, for both good and bad systems. Then score every fingerprint as (1+ # of bad events) / (1 + # of good events) and everything at the top is most strongly bad. And the more often its logged, the further up it will be. No more lecturing people about "correct" interpretations of ERROR vs INFO vs DEBUG. No more "this ERROR is always logged, even during normal operations".
Since that number should be the same (or at least close!) in both good and bad datasets, I'm not sure the extra math matters much.
I've been mulling this idea over in my head as well. I have a fleet of PCs out in the wild, all running the same software. It would be nice to have an easy way to detect strange behavior like processes that are continually respawning / segfaults / crashes / etc, without explicitly writing a bunch of search terms.
And its not just log searching and correlation value. At work, the entire discussion "oh but we need access to all servers because of logs" just died when all logs were accessible via one web interface. I added a log aggregation and suddenly only ops needed access to servers.
Designing that thing with accessibility and discoverability in mind is a whone nother topic though.
Throw Loki+Grafana on a single VM somewhere (or run it on your Kubernetes/Nomad/ECS/etc. cluster) and it will get you very far, as long as you plan ahead a bit (most notably, indexing happens at ingestion, so you need to have an idea of what you want from your logs or your queries will be slower).
Or use a SaaS like logz.io, AWS OpenSearch, Datadog, etc. Most support OpenTelemetry now, so switching data ingestion is quite easy (unlike dashboards and alerts).
It makes sense to have centralised logs pretty much as soon as you outgrow the "everything runs on this one box and my DR plan is a prayer" stage, IMO.
(1) I wanted something where colleagues could easily share links in workplace chat with each other, so we could cooperatively investigate bugs.
(2) For LSP we're often concerned with responsiveness, and I thought the best way to indicate times when viewing a log is with whitespace gaps between log messages in proportion to their time gap.
(3) For LSP we have lots of interleaved activity going on, and I wanted to have visual "threads" connecting related logs.
(4) As the post and lnav say, interactivity is everything. I tried to take it a step further with (1) javascript, (2) playground-style updates as you type, (3) autocomplete which "learns" what fields are available from structured logs.
My tool runs all in the browser. (I spent effort figuring out how people can distribute it safely and use it for their own confidential logs too). It's fast enough up to about 10k lines of logs.
I tried the demo link, it rendered a lonely @ at the top left of the page, the rest was blank. The console said:
This was in Firefox 98.0 in Windows.