This is one of those frustrating debug stories that makes you pull your hair out until you suddenly figure it out. The relief you feel afterwards is one of the reasons I love programming so much.
We were running an internal implementation of a syslog
server in Go, receiving
the logs of a bunch of machines in the same datacenter (i.e. internal network).
That server was setup to run on boot, receive the logs on UDP port 514, do a
bunch of things with them and eventually writing them down into /var/log/foo.
Nothing complicated nor extraordinary.
We were running happily with that for a few years, until an OS upgrade came
around the corner. Given that the service was doing nothing special, nobody
believed it would cause any issues whatsoever. Building the package for the new
OS was a no brainer, nor was building the machine’s image. Upgrade day comes
and everything is running fine, except that /var/log/foo/foo.log is missing.
Weird.
According to the service’s logs everything was running. Packages were flowing
on that port, according to tcpdump and even the expected occasional CPU
little spikes were there. Directory was still empty, though. Given that this
service is written in Go, sending a mere ABRT
signal caused it to dump useful
stack trace to STDERR and terminate. Judging by the traces - the service was
running fine, multiple goroutines, running fine and doing their job. Where are
the logs, though?
Opening that foo.log file inside /var/log/foo is one of the first things that this program did, so one would even expect it to have that file opened as FD 3 and sure enough, judging by the opened file descriptors by this process, as reported by procfs
, that’s precisely the case:
❯ ls -la /proc/1801/fd
lrwx------ 1 root root 64 Nov 20 09:07 0 -> /dev/null
l-wx------ 1 root root 64 Nov 20 09:07 1 -> 'pipe:[22087]'
l-wx------ 1 root root 64 Nov 20 09:07 2 -> 'pipe:[22087]'
l-wx------ 1 root root 64 Nov 20 09:05 3 -> /var/log/foo/foo.log
lrwx------ 1 root root 64 Nov 20 09:07 4 -> 'anon_inode:[eventpoll]'
lr-x------ 1 root root 64 Nov 20 09:07 5 -> 'pipe:[25179]'
l-wx------ 1 root root 64 Nov 20 09:07 6 -> 'pipe:[25179]'
lrwx------ 1 root root 64 Nov 20 09:07 7 -> 'socket:[24122]'
lrwx------ 1 root root 64 Nov 20 09:07 8 -> 'socket:[41476]'
lrwx------ 1 root root 64 Nov 20 09:07 9 -> 'socket:[41477]'
[..]
Okay, the file is opened properly, but no logs are ever written. Given that remote communication is involved here, it was easy to blame “The network”™. Our working hypothesis at point is just something getting stuck waiting for something to happen. Or probably writing down into the file failed? But where are the error messages about it? strace to the rescue:
❯ strace -p 1801 -f -s 4096 -e write -e fd=3
[pid 1802] write(3, "logline 1...\n", 232 <unfinished ...>
[pid 1801] write(3, "logline 2...\n", 322 <unfinished ...>
[pid 4902] write(3, "logline 3...\n", 581 <unfinished ...>
[pid 4902] write(3, "logline 4...\n", 273 <unfinished ...>
[pid 4902] write(3, "logline 5...\n", 149 <unfinished ...>
[pid 4903] write(3, "logline 6...\n", 485 <unfinished ...>
[..]
Let’s just break down what we’re seeing here, as strace(1) might not be that popular as I seem to believe, based on a few recent conversations outside of this scope:
-p 1801- intercept system calls performed by the process with PID 1801 (our server’s main process)-f- follow all threads of this process and child processes as well. This is a Go program after all, surely there are multiple threads and processes.-s 4096- we are hunting for log messages, so dump strings up to 4096 bytes (instead of the default 32)-e write- trace only write(2) syscalls-e fd=3- trace only syscalls that operate on file descriptor 3, which we know is our empty file, as seen above
I’ve truncated the output and log messages here, but there were pages of those. We are clearly observing log messages being written precisely into that file, from multiple goroutines without a failure, judging by the positive results of the syscalls. Where do they go? Why is the file missing? To make things even more annoying - restarting the service made the issue go away. It’s only observed on first boot. Once everybody’s tools for inspection are in place, things just worked.
Code works, service is available, packets fly, logs are being written. Just… files are missing. Assuming the code is fine. Let’s observe the environment deeper. procfs has way more to tell here.
Could the processes have another idea what is /var/log/foo from the rest of the world? This is what namespaces do in the linux world to begin with. Looking into /proc/{PID}/ns
completely disproved that:
❯ ls -l /proc/1801/ns/mnt
lrwxrwxrwx 1 root root 0 Nov 20 09:16 /proc/1684/ns/mnt -> 'mnt:[4026531841]'
❯ ls -l /proc/$$/ns/mnt
lrwxrwxrwx 1 root root 0 Nov 20 09:16 /proc/6561/ns/mnt -> 'mnt:[4026531841]'
$$ is the PID of the current process of the shell. Clearly it sees the same mount namespace as our service. But how come does the shell see different contents? However, we know that there is disk mounted into /var/log/foo, let’s see the proc’s mountinfo
:
❯ cat /proc/1801/mountinfo | grep /var/log
516 66 8:16 / /var/log/foo rw,relatime shared:192 - ext4 /dev/sdb rw
❯ cat /proc/$$/mountinfo | grep /var/log
516 66 8:16 / /var/log/foo rw,relatime shared:192 - ext4 /dev/sdb rw
Okay, we both see the same mount with ID 516, mounted over / which ID is apparently 66. How come only the process see that ghost file that nobody else is observing? Let’s look into that file a bit more. Apart from /proc/{PID}/fd
which merely lists file descriptors and helps distinguish their type and location, there’s also /proc/{PID}/fdinfo
which gives detailed information about each file descriptor:
❯ cat /proc/1801/fdinfo/3
pos: 218105
flags: 02102001
mnt_id: 66
ino: 132368
Eureka! mnt_id: 66. Remember that this was /, according to mountinfo
? How on earth is that file in the root filesystem, given that there is something else mounted in there, you might ask? Well, as I said - this only happens on first boot. If the service is restarted, everything runs smooth again. Apparently, this service starts way too soon, even before the mount is finished.
And sure enough. It indeed starts too soon… by a single damn second:
❯ journalctl -b | grep '/var/log/foo'
Nov 20 08:28:31 systemd[1]: var-log-foo.mount: Directory /var/log/foo to mount over is not empty, mounting anyway.
Nov 20 08:28:31 systemd[1]: Mounting /var/log/foo...
Nov 20 08:28:34 systemd[1]: Mounted /var/log/foo.
❯ ps -p 1801 -o lstart
Wed Nov 20 08:28:30 2024: 132368
What are the odds of this!?
… you might ask. Well, given that this machine boots from an image, it was happening every single time, we’ve tried. How come it never happened before - I don’t know. Different kernel, different systemd (where backwards compatibility does not mean a lot to begin with), different… who knows what.
The point is to know your tools and running environment well enough to be able to dig into this quick enough, regardless of what time it is.
Good programmers know what they’re doing. Great programmers understand one level deeper.