The log/event processing pipeline you can't have - apenwarr

It's a bird, it's a plane, it's

Everything here is my opinion. I do not speak for your employer.

← February 2019

March 2019 →

2019-02-16 "

The log/event processing pipeline you can't have

Let me tell you about the still-not-defunct real-time log processing<br>pipeline we built at my now-defunct last job. It handled logs from a large<br>number of embedded devices that our ISP operated on behalf of residential<br>customers. (I wrote and presented previously about some of the cool wifi<br>diagnostics that were possible with this data set.)

Lately, I've had a surprisingly large number of conversations about logs<br>processing pipelines. I can find probably 10+ already-funded, seemingly<br>successful startups processing logs, and the Big Name Cloud providers all<br>have some kind of logs thingy, but still, people are not satisfied. It's<br>expensive and slow. And if you complain, you mostly get told that you<br>shouldn't be using unstructured logs anyway, you should be using<br>event streams.

That advice is not wrong, but it's incomplete.

Instead of doing a survey of the whole unhappy landscape, let's just ignore<br>what other people suffer with and talk about what does work. You can<br>probably find, somewhere, something similar to each of the components I'm<br>going to talk about, but you probably can't find a single solution that<br>combines it all with good performance and super-low latency for a reasonable<br>price. At least, I haven't found it. I was a little surprised by this,<br>because I didn't think we were doing anything all that innovative.<br>Apparently I was incorrect.

The big picture

Let's get started. Here's a handy diagram of all the parts we're going to<br>talk about:

The ISP where I worked has a bunch of embedded Linux devices (routers,<br>firewalls, wifi access points, and so on) that we wanted to monitor. The<br>number increased rapidly over time, but let's talk about a nice round<br>number, like 100,000 of them. Initially there were zero, then maybe 10 in<br>our development lab, and eventually we hit 100,000, and later there were<br>many more than that. Whatever. Let's work with 100,000. But keep in mind<br>that this architecture works pretty much the same with any number of<br>devices.

(It's a "distributed system" in the sense of<br>scalability, but it's also the simplest thing that really works for any<br>number of devices more than a handful, which makes it different from many<br>"distributed systems" where you could have solved the problem much more<br>simply if you didn't care about scaling. Since our logs are coming from<br>multiple sources, we can't make it non-distributed, but we can try to<br>minimize the number of parts that have to deal with the extra complexity.)

Now, these are devices we were monitoring, not apps or services or<br>containers or whatever. That means two things: we had to deal with lots of<br>weird problems (like compiler/kernel bugs and hardware failures), and most<br>of the software was off-the-shelf OS stuff we couldn't easily control (or<br>didn't want to rewrite).

(Here's the good news: because embedded devices have all the problems from<br>top to bottom, any solution that works for my masses of embedded devices will<br>work for any other log-pipeline problem you might have. If you're lucky, you<br>can leave out some parts.)

That means the debate about "events" vs "logs" was kind of moot. We didn't<br>control all the parts in our system, so telling us to forget logs and use<br>only structured events doesn't help. udhcpd produces messages the way it<br>wants to produce messages, and that's life. Sometimes the kernel panics and<br>prints whatever it wants to print, and that's life. Move on.

Of course, we also had our own apps, which means we could also produce our<br>own structured events when it was relevant to our own apps. Our team had<br>whole never-ending debates about which is better, logs or events, structured<br>or unstructured. In fact, in a move only overfunded megacorporations can<br>afford, we actually implemented both and ran them both for a long time.

Thus, I can now tell you the final true answer, once and for all: you want<br>structured events in your database.

...but you need to be able to produce them from unstructured logs.<br>And once you can do that, exactly how those structured events are produced<br>(either from logs or directly from structured trace output) turns out to be<br>unimportant.

But we're getting ahead of ourselves a bit. Let's take our flow diagram,<br>one part at a time, from left to right.

Userspace and kernel messages, in a single stream

Some people who have been hacking on Linux for a while may know about<br>/proc/kmsg: that's the file good old (pre-systemd) klogd reads kernel<br>messages from, and pumps them to syslogd, which saves them to a file.<br>Nowadays systemd does roughly the same thing but with more d-bus and<br>more corrupted binary log files. Ahem. Anyway. When you run the dmesg<br>command, it reads the same kernel messages (in a slightly different way).

What you might not know is that you...