Troubleshooting of systemd and fsck on boot

I investigated some problems with fsck and systemd recently. In the process, I learned quite a few things. And when I finished, I wrote these notes for future reference. Hope somebody finds them useful.

Setup

Open grub config file with:

sudo vi /etc/default/grub

In order to see the system log on boot, remove quiet and splash from the kernel command line. Also, we want as much information as possible about systemd, so add the following params to the kernel command line:

systemd.log_level=debug systemd.log_target=kmsg log_buf_len=2M

log_target=kmsg means output will be logged on the kernel log, so we will be able to read it later by running dmesg if necessary.

Now, regenerate grub configuration with

sudo update-grub

After that, activate the debug service in systemd:

systemctl enable debug-shell.service

By enabling this service, we will be able to use a root shell on tt9 very early in the boot process, to execute more troubleshooting commands.

With all that out of the way, restart the system. Now, as soon as you see a line reporting the progress of fsck, press CTRL+ALT+F9 to access the root shell. In my case there were 2 things that made using this shell a bit annoying:

logs were constantly being written over the shell prompt, which made it difficult to double-check what I was writing; command output is not a problem because it can always be redirected to a file for later reference
the keyboard seemed to be configured differently, i.e. pressing ' wrote -, pressing - wrote /, etc; I guess this is related to my using a Spanish keyboard

Anyway, with a shell at our disposal we can now use strace to gather more clues. First execute

ps -ef > /var/log/psef.txt

for later reference and

ps -ef | grep fsck

to quickly get the PIDs for all the processes related to fsck running at the moment:

systemd-fsck, systemd fsck binary invoked from [email protected]; a wrapper that invokes fsck with the appropriate parameters
systemd-fsckd, systemd fsck daemon invoked from systemd-fsckd.service; daemon that reads fsck progress information from a socket, so it can then be reported to the user through the console, plymouth, etc.
fsck, fsck binary
fsck.ext3, the specific fsck binary for ext3 filesystems; this one could be different in your case, as it depends on the filesystem that is being checked

We can now execute

strace -p <pid1> -p <pid2> -p <pid3> -p <pid4> -o /var/log/strace.txt

with <pid1> through <pid4> being the PIDs of the 4 processes.

After that, we wait for the boot process to finish and we login. We are now ready to start the analysis.

Analysis

First of all, run dmesg | less, and search for fsck entries. Information of interest:

systemd-fsckd and systemd-fsck both exited with code 0, so they died peacefully
fsck exited with error code 8

If we look now at /var/log/strace.txt, we can hopefully gather more information about the error in fsck. For people with experience in systems programming with C, they will probably be able to know what happened just by looking at the strace output. In my case I complemented it with looking at the source code. To get the source code for a particular binary (e.g. fsck), run:

dpkg -S `which fsck`

to get the name of the package (util-linux in this case), and then run

sudo apt-get source util-linux

to get the actual source code.

Anyway, back to the strace output. Starting from the bottom and going up we see that:

systemd-fsck exited with 0 when fsck returned
fsck exited with error code 8 when fsck.ext3 returned
fsck.ext3 was killed by a SIGPIPE

The actual strace lines are these:

write(4, "1 706 1774 /dev/sdb6\n", 21) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=431, si_uid=0} ---
+++ killed by SIGPIPE +++

By digging in the fsck code, we can see that this syscall is performed in the function e2fsck_update_progress in the file e2fsck/unix.c. This is the function that writes fsck progress on the socket defined in systemd-fsck.socket.

Another clue was the file descriptor 4: if we look at the ps output, we can see that fsck and fsck.ext3 were invoked with the argument -C4, which means "report progress through file descriptor 4".

The issue then seems to be that someone has closed the socket when we were still using it. The main suspect of the crime is systemd-fsckd. If we keep going up in the strace output, we see its last words:

<... epoll_wait resumed> [], 2, 30000) = 0
clock_gettime(CLOCK_BOOTTIME, {223, 716862088}) = 0
open("/dev/console", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 7
fstat(7, {st_mode=S_IFCHR|0600, st_rdev=makedev(5, 1), ...}) = 0
ioctl(7, TCGETS, {B38400 opost isig icanon echo ...}) = 0
write(7, "\r                               "..., 51) = 51
close(7)                          = 0
epoll_ctl(5, EPOLL_CTL_DEL, 3, NULL) = 0
close(3)                          = 0
epoll_ctl(5, EPOLL_CTL_DEL, 6, NULL) = 0
close(6)                          = 0
close(5)                          = 0
exit_group(0)                     = ?
+++ exited with 0 +++

The first line tells us that the fsck daemon was waiting for some event with a timeout of 30 seconds. In fact, it waited the whole 30 seconds, after which it stopped waiting and exited.

The related code in systemd source (fsckd.c) confirms that the timeout is hardcoded:

#define IDLE_TIME_SECONDS 30

r = run_event_loop_with_timeout(m->event, IDLE_TIME_SECONDS * USEC_PER_SEC);

This means if there is no progress report in less than 30 seconds, the progress daemon exits, effectively pulling the rug from under fsck.ext3 and making it fail. I don't know about you but to me that doesn't seem to be a sensible approach, especially when we are dealing with filesystem checks.

Now, if we look at systemd's master branch as of June of 2016, the systemd-fsckd service has been removed, and simpler progress reporting has been included in the systemd-fsck binary itself. Unfortunately, Ubuntu 15.10 and 16.04 LTS both use an older version of systemd which still contains systemd-fsckd.

The easiest solution is disabling the fsck daemon, as it is not necessary for the correct working of the system:

systemctl mask systemd-fsckd.service systemd-fsckd.socket

If we reboot again, fsck will then finish correctly.

As a final note, remember to undo the debugging changes we made at the beginning. Especially, make sure that you disable the debug shell with:

systemctl disable debug-shell.service

ebautistabar/systemd-fsck-troubleshooting.md

Troubleshooting of systemd and fsck on boot

Setup

Analysis

mbiebl commented Sep 20, 2016

ebautistabar commented Oct 14, 2016