mtail: unable to read from unix socket

Great news here, I’ve figured out why mtail isn’t creating sockets to receive logs at all, it’s protected by a code path that is trying to stat the file first so if no socket exists it never gets to the point of trying to listen on it.

I’m going to fix this by requiring the user to specify a prefix like “unixgram:” before the pathname.

Here’s a quick summary of what I’ve learned while building socket support.

traditional syslog() sends to /dev/log, which is a unix domain datagram socket, and normally a syslogd listens on it for logs to then write to whereever.

Nowadays on Linux, the systemd-journal process handles logs from userspace, kernel, and keeps them in the journal. journalctl lets you poke around with them, and systemd-journal will also forward them on to a syslogd if one is listening on the correct unix-dgram socket.

To receive logs directly from systemd-journal, one must be able to read from a unix domain socket. mtail now does this, although I kind of regret it. Socket support for both datagram and stream families was tricky and likely has many future bugs.

Normally your distro will have one of syslog-ng or rsyslogd acting as that syslogd, though.

I strongly do not recommend mtail being the direct listener of /dev/log or the systemd journal. mtail does not perform any ordinary syslog functions, it merely matches text file inputs and increments counters. The interoperation of systemd and the syslogd appears to be a rich API and tools like syslog-ng automatically support systemd-journal in the normal course of their role. mtail doesn’t want to be in the business of specific API interoperation, for at least two reasons: one is binary size as a result of features, and the other is maintenance cost.

So, if you want to interoperate mtail with syslog, then I suggest using the above syslog daemons to “tee” off the logs you’re interested in:

• rsyslog supports forwarding to a named pipe and to a unix domain socket

• syslog-ng supports output to named pipe and unix domain socket

Configure mtail to listen on that pipe or unix domain socket, and you’ll get what you want.

mtail’s filtering is not great – you have to get to the match program before yuo end up discarding log entries, which is expensive in terms of memory copies. With both the above tools you have lots of power for filtering which input gets sent to the mtail pipe.

1: Do not replace your syslog with mtail, you will lose a lot of functionality and reliability.

I also wouldn’t recommend using mtail to receive cross-network log traffic. Firstly it’s not lossless, for all the reasons that the rsyslog’s RELP protocol exists. mtail isn’t that smart; mtail doesn’t want to be in the business of reliable network transport; it just wants to tail a log stream as fast as possible and turn that into metrics.

If I wanted a single mtail central service reading logs from multiple remote nodes, I’d use rsyslogd to perform the log transport, and a local named pipe to funnel the bytes from the receiver rsyslogd to mtail.

2: Do not let mtail listen on a network for logs, prefer a reliable log transport option and then a local forward over a Unix named pipe.

Why would I recommend a pipe over a socket? The overhead is lower, so the bytes move faster. The read semantics are nearly identical to a file and thus well tested. Sockets are OK but the connection oriented stream now incurs an API cost (we’re now listening on an address anyone can connect to) and complexifies the implementation (multiple connection handlers are possible) and the datagram socket violates the interface by not having any concept of “end of transmission”, though the workaround is a neat hack.

Aha.

The problem is that mtail reads from named pipes, not unix sockets. The code is failing because it’s attempting to open the unix socket /run/systemd/journal/syslog as a named pipe, which fails because there is “no such device or address” called that.

The clue was eventually I read man 7 pipe and then thought “Am I sure the s at the start of the ls before is in fact a named pipe?” and then the ls info page revealing to me it’s in fact a socket…

I have a funny feeling I deleted some code about two years ago that did this.

On Wed, 18 Dec 2019 at 16:24, Jamie Wilkinson jaq@spacepants.org wrote:

OK thanks, I can reproduce this locally.

https://www.freedesktop.org/wiki/Software/systemd/syslog/ suggests reading from this socket isn’t correct, though. I can’t decipher what is supposed to be correct.

On Wed, 18 Dec 2019 at 08:04, Felix Ehrenpfort notifications@github.com wrote:

$ sudo mtail --logs /run/systemd/journal/syslog --progs . --logtostderr -vmodule=file=2,log_watcher=2 I1217 21:03:23.931100 8447 main.go:100] mtail version v3.0.0-rc33 git revision aedde73f9c304e4d558a53ece22a5472c87a7fdb go version go1.12.7 go arch amd64 go os linux I1217 21:03:23.931241 8447 main.go:101] Commandline: [“mtail” “–logs” “/run/systemd/journal/syslog” “–progs” “.” “–logtostderr” “-vmodule=file=2,log_watcher=2”] I1217 21:03:23.933492 8447 log_watcher.go:268] Adding a watch on resolved path “/home/ubuntu” I1217 21:03:23.933601 8447 log_watcher.go:248] No abspath in watched list, added new one for /home/ubuntu I1217 21:03:23.933822 8447 log_watcher.go:268] Adding a watch on resolved path “/run/systemd/journal” I1217 21:03:23.933921 8447 log_watcher.go:248] No abspath in watched list, added new one for /run/systemd/journal I1217 21:03:23.934009 8447 log_watcher.go:268] Adding a watch on resolved path “/run/systemd/journal/syslog” I1217 21:03:23.934079 8447 log_watcher.go:248] No abspath in watched list, added new one for /run/systemd/journal/syslog I1217 21:03:23.934130 8447 log_watcher.go:268] Adding a watch on resolved path “/run/systemd/journal” I1217 21:03:23.934178 8447 log_watcher.go:253] Found this processor in watched list I1217 21:03:23.934237 8447 file.go:52] file.New(/run/systemd/journal/syslog, false) I1217 21:03:23.934294 8447 file.go:111] open failed all retries W1217 21:03:23.935320 8447 mtail.go:101] attempting to tail “/run/systemd/journal/syslog”: open /run/systemd/journal/syslog: no such device or address I1217 21:03:23.935721 8447 store.go:136] Starting metric store expiry loop every 1h0m0s I1217 21:03:23.935779 8447 tail.go:435] Starting log handle expiry loop every 1h0m0s I1217 21:03:23.935844 8447 mtail.go:321] Listening on [::]:3903 ^CI1217 21:03:30.396320 8447 mtail.go:349] Received SIGTERM, exiting… I1217 21:03:30.396339 8447 mtail.go:363] Shutdown requested. I1217 21:03:30.401359 8447 log_watcher.go:218] Shutting down log watcher. I1217 21:03:30.401373 8447 loader.go:376] Shutting down loader. I1217 21:03:30.401429 8447 mtail.go:386] END OF LINE

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/google/mtail/issues/276?email_source=notifications&email_token=AAXFX64DUFX523GWGOGS56LQZE5GLA5CNFSM4JKXMTNKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEHD6JFQ#issuecomment-566748310, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAXFX67V7NPS3YB723AONPLQZE5GLANCNFSM4JKXMTNA .