Making syslog() not block | Hacker News Reader

Making syslog() not block

github.com

37 pointsjamesgpearce20 comments

For new projects that aren't already tied to syslog(), Apache Kafka is also an interesting library to look at.

I've always felt that using UDP is an uneasy tradeoff -- you're solving the problem of blocking, but at the cost of getting no batching whatsoever. When you're logging to disk, TCP, or memory, the fast path call to log just plops your data into a buffer and returns to you. More messages, the bigger your buffer gets. With UDP, each message instead goes straight to the NIC and out.

Kafka makes a different tradeoff -- buffer/batch to disk. Once you have enough data, compress it and ship it off reliably. If your consumer goes away, buffer as much as you can before losing messages; disk is cheap! The cost comes as small additional latency. In the fast path, it's quick (data stays RAM resident, and it's much cheaper to compress & batch send 1000 messages than 1000 UDPs).

The other alternatives specifically for logging are Scribe (which we use here at Facebook) and Apache Flume.

As I understand the use case for this software, it would be talking UDP to a local syslog server, not over the network.

At Facebook, we use scribe, and generally use (in-memory, in-app) batched writes to local scribe, and then batched writes (memory+disk, scribe daemon) from that local scribe to an upstream scribe storage system.

I hate to be that guy, but this software (with a patent, natch) is definitely not the first or best solution to the potential problem of the /dev/log buffer filling up.

If the standard syslogd is inadequate, how about using a different logger? Gerritt Pape's svlogd, an implementation of DJB's daemontools loggers, solves this problem very nicely, is very reliable, can log over UDP and write to disk if desired. Heck, it can even replace syslog and run more reliably.

Not to say that this software is not useful. It is a great solution if the client software insists on using syslog and cannot be modified or reconfigured and syslogd cannot be modified or replaced. However, these are quite specific and generally unusual cases. For more prosaic circumstances, there are simpler and better solutions.

Facebook has its own logging system - http://en.wikipedia.org/wiki/Scribe_(log_server) - which they probably use for in-house systems. I would guess that the library in question might be used when they run third-party applications.

The presence of the grant does not mean there is a patent covering this project. It just means that if there is, you're protected as a developer by a license to use it. (This also what the Apache 2.0 license does)

What happens when a program logs messages faster than the log daemon can process them? Since it's non-blocking, the program no longer pauses to wait for it to catch up.

Does it drop messages in this situation? Is that why you warn that "liblogfaf should not be used in an environment where reliable log message delivery is required."? That is probably the most elegant solution.

Because the log messages are being sent as UDP packets, what's going to happen is that the receiving daemon's socket buffer fills up and the kernel drops packets.

Thus you lose log messages.

It does not, however, affect the application that is sending the log messages because sending the UDP packet is always possible (minus other kernel issues).

Depending on your use-case you might want not start dropping log messages when the load is high enough for a log processor to not be able to process them. My reasoning: At that point, something is seriously wrong and according to Murphy, the message that's going to be dropped is the one that contains the actual reason for the issue amidst all the other log spam caused by the real issue.

What's more, the (receiving) kernel in that case will drop the newest packets, not the oldest. For logging that might be fine, but I worked on at least one project where we had updates coming in every second to the same piece of information (telemetry). There, you want to drop the oldest packets. In fact, you want to drop all packets by the absolute newest at the time you are processing it. The solution of course was to make accepting datagrams and processing them two asynchronous tasks (well, really three: receive, process, write to the data store).

When there are too many messages, rsyslog will drop them in the default configuration, too.

http://www.rsyslog.com/tag/systemlogratelimitinterval/

"liblogfaf is BSD-licensed. We also provide an additional patent grant."

Hi, I am a country bumpkin nerd. What does this mean, please? Thanks.

If they happen to be using any of their patents in this code, you have a right to use the code anyway in the manner specified without fear of being sued.

"Facebook won't sue you over patents in this code."

Unless you sue Facebook first.

There is helpfully a PATENTS file that clarifies this text:

https://github.com/facebook/liblogfaf/blob/master/PATENTS

My knee-jerk reaction is that this is a terrible idea. Why would someone do this?

Is this to workaround programs that respond to logs and can deadlock when logging (e.g. logrotate)? Workaround other broken programs (noncritical logspam at emergency level)?

Because they want to do fine-grained logging in an evented C program, where repeated filesystem access will block and cause the program to stutter.

I would think using an async logging framework is a cleaner and faster approach i.e. something like log4j or glog that does IO in a separate thread.

I suppose such an approach is less ideal when using a language that isn't truly concurrent or if the code doesn't run long enough for it to be efficient to spawn a logging thread.

Or just use stdout in those circumstances? Sysadmins are happy to pipe into grep and logger if they need to. We might prefer it if it is that shortlived

Since when did syslog() perform filesystem access? Every implementation I have seen involved a fifo or stream socket write to syslogd.

Also: Why are they using LD_PRELOAD to do this?

I did not look too closely at the implementation, but are they actually using UDP and just throwing away log entries under load? That is bad engineering.

Losing log data under load (or when your logging system is unavailable) might indeed sound awful, however this is a conscious design decision and the whole purpose of this library.

Imagine you are running an application, which is some sort of a network server - it accepts a connection, parses the query, logs it using syslog(), and then returns some sort of response. If it gets blocked while logging, response might be lost or delayed. If serving the request is more important than logging it (which might not be the case for all applications), you might want to ensure that your logging does not block the request processing flow.

If there is one application like this and it's open source, you can patch it directly. However, if you have several applications with similar logging behavior or if you cannot modify source code, overriding syslog() allows you to de-couple logging without changing the application. Of course, you should have monitoring in place to catch situations when your logging system cannot keep up (or malfunctions), but when that happens your application keeps running and you only lose your log data.

I wish that was easy on Windows too (not the logging, but LD_PRELOAD) - and yes, there are many hooking libraries (vld, google-perflibs, various anti-viruses etc.) - but I can always find failure cases for them.

e.g. I wish there was less magic (or whole mini-industry) behind hooking functions this way.

Reply on news.ycombinator.com