2015-03-02

Using OS X’s syslogd to receive log messages from the network

TL;DR: avoid this buggy mess and go with macports & syslog-ng. You'll finish faster and saner.

[Updated 2 times]

This sounds like should be easy, but OS X is a moving target because of all the infrastructure changes they have been making for the last few OS releases. Yes, there is a syslogd, but it is some half-hollowed out thing and “others” do most of the work. Syslogd does NOT open an UDP socket, launchd does and feeds it to syslogd. Syslogd does NOT (really) receive the UDP packets, a plugin does it. Syslog does NOT parse the UDP message, ASL (Apple System Log?) does. Syslogd does NOT filter the messages and store them into “logs”, ASL does.

So why there is a syslogd at all, apart from giving a slight sense of false security? (As in, “c’mon, there’s syslog, can’t be too difficult”). No idea. If I had seen how complicated this was going to get I would have bailed out and used syslog-ng from macports.

Anyway. So the first step is to enable UDP reception. The manpage for syslogd explains what has to be changed and where, but doesn’t mention the intermediate step of converting the syslogd plist into xml. Which is easy with plutil or by using some GUI editor, but the fastest way is to just change things from the command line:
cd /System/Library/LaunchDaemons
sudo /usr/libexec/PlistBuddy -c "add :Sockets:NetworkListener dict" com.apple.syslogd.plist
sudo /usr/libexec/PlistBuddy -c "add :Sockets:NetworkListener:SockServiceName string syslog" com.apple.syslogd.plist
sudo /usr/libexec/PlistBuddy -c "add :Sockets:NetworkListener:SockType string dgram" com.apple.syslogd.plist
sudo launchctl unload com.apple.syslogd.plist
sudo launchctl load com.apple.syslogd.plist

With that, log messages originating from the network will be dumped into the normal ASL message storage. Some of that goes into BSD-style, flat text files. But another part of it does not, and stays in some internal ASL database. So the best way to see everything kind-of-at-once is to use the OS X Console utility.

However, the UDP syslog protocol is supposed to include in the UDP packets some information that is not appearing in my Console. Most importantly, there should be a Host field, which would be perfect to classify the log messages coming from the network; alas, in my usage I am not seeing that. After checking the debug info from syslog and ASL and their dogs, looks like either the Linux side (DD-WRT) is not sending the packets correctly or the Mac side is not parsing them right (no, I didn’t feel like trying Wireshark), and some fields are either swapped or missing-and-not-accounted-for, causing some fields to contain values that should be in other fields. Which results in the log messages coming from the network getting lost among the local log messages… and there is no direct way to distinguish them.

So, next idea: dump the log messages coming from the network into a separate file.
To do this, it’s necessary to add a rule to ASL so it filters out the messages that came from the network and writes them into our file.
The problem is that once the messages are inside ASL, already there is no direct way to know where they came from! Luckily, they can still be indirectly recognized because of some anomalies: for example their GID, UID and PID are nonsensical and always the same: GID = UID = -2, PID = -1.
(note that the GID, UID, PID and other keys are not usually in the BSD-flat-format typical in logs; but ASL does store metadata for every message, and a lot of that metadata is simply ignored when outputing to the BSD format. So the idea of writing the UDP-received messages into a file is not the best solution, and I would have preferred being able to continue using some ASL storage and Console.app to comb through it; alas, I couldn’t find a way)

After some tests, this is what worked for me: put the following into the file /etc/asl/syslog_UDP :
> my_syslog.log mode=0740 format=std rotate=seq compress file_max=5M all_max=50M gid=20
? [N< PID 0] file my_syslog.log

And signaled syslogd to reconfigure:
sudo killall -SIGHUP syslogd

Aaaand it’s working! In /var/log a folder named syslog_UDP will appear, in which logfiles named my_syslog.log will contain log messages with a PID lesser than 0, which should be impossible - but that is what the UDP-originating messages report. Note too that the logfiles will be automatically rotated, compressed and purged after they start taking more than 50 MB. And they are readable by everyone - no sudo needed. (You are not running as an admin, are you?)

This will break when either DD-WRT starts sending correct UDP messages, or when OS X starts parsing them right, or when the syslog/ASL mechanism changes…

One thing that I tried and couldn’t get to work is using “directory my_syslog.log” instead of "file...", but the result seems to be buggy, in that the generated files inside the directory do not honor the mode or UID/GID that I try to set.
And the debug support in ASL (activated by adding a line “= debug 1” in /etc/asl.conf) is less than useful. Finally what helped the most was to use the message inspector in Console.app and the format=raw output flag to see the key values as they are at filtering time - the -1 and -2 values are in fact shown as the decimal value of 0xFFFF and 0xFFFF+1 in the message inspector, which did not work when filtering

In hindsight I’ll bet that using syslog-ng, or even some hackish reverse netcat, would have been much faster. Buuut… well, at least I have learnt a bit about the logging madness in OS X, which in fact had been kind of a to-do for some years…

References:
http://stackoverflow.com/questions/5510563/how-to-start-syslogd-server-on-mac-to-accept-remote-logging-messages/5518597#5518597


UPDATE 3/3/2015: Beware, this seems to stop working after a while. My first troubleshooting shows OS X's syslogd to be buggy when receiving from UDP (in Yosemite at the very least): syslogd stopped working (seemingly at all, not only the UDP reception) after some hours, and lsof shows that syslogd had 255 file descriptors open, most of them to the UDP socket. Sending a SIGHUP didn't do anything. "sudo killall syslogd" restarted it and now seems to be working, but who knows for how long. So I see myself going the syslog-ng/macports route in the near future.

UPDATE 4/3/2015: the UDP file descriptor growth keeps happening. Seems to be related to my WiFi connection going on and off. Nastily unreliable, and a funny way to remotely disable syslog on an OS X system, too. I'll disable the UDP thing and send a bug report. My recommendation: just go with macports & syslog-ng.

2 comments

  1. Apple have confirmed that the leaking of file descriptors by syslogd when listening to the UDP port is a bug. My workaround is this crontab entry:

    # restart syslogd if fds exceeds 200
    15 * * * * [ `lsof -n | awk '$1=="syslogd" && $3=="root" {n++} END {print n}'` -gt 200 ] && { launchctl unload /System/Library/LaunchDaemons/com.apple.syslogd.plist; launchctl load /System/Library/LaunchDaemons/com.apple.syslogd.plist; }

    ReplyDelete
  2. Thanks, Michael. Yes, I also reported the bug when I posted this, and they asked me to check whether the bug had been fixed in El Capitan Beta - but I didn't have the possibility to install it.
    Now I have the El Capitan release installed, but frankly, my current setup is not conductive to go back to test this.

    So, are you in El Capitan? Have you checked whether your workaround is still necessary in it?
    … and why didn't you use Macports' syslog-ng or something else?? ;)

    ReplyDelete