A timesyncd total failure and systemd's complete lack of debugability

August 8, 2018

Last November, I wrote an entry about how we were switching to using systemd's timesyncd on our Ubuntu machines. Ubuntu 18.04 defaults to using timesyncd just as 16.04 does, and when we set up our standard Ubuntu 18.04 environment we stuck with that default behavior (although we customize the list of NTP servers). Then today I discovered that timesyncd had silently died on one of our 18.04 servers back on July 20th, and worse it couldn't be restarted.

Specifically, it reported:

systemd-timesyncd[10940]: Failed to create state directory: Permission denied

The state directory it's complaining about is /var/lib/systemd/timesync, which is actually a symlink to /var/lib/private/systemd/timesync (at least on systems that are in good order; if the symlink has had something happen to it, you can apparently get other errors from timesyncd). I had a clever informed theory about what was wrong with things, but it turns out strace says I'm wrong.

(To my surprise, doing 'strace -f -p 1' on this system did not produce either explosions or an impossibly large amount of output. This would have been a very different thing on a system that was actually in use; this is basically an almost idle server being used as part of our testing of 18.04 before we upgrade our production servers to it.)

According to strace, what is failing is timesyncd's attempts to access /var/lib/private/systemd/timesync as its special UID (and GID) 'systemd-timesync'. This is failing for the prosaic reason that /var/lib/private is owner-only and owned by root. Since this works on all of our other Ubuntu 18.04 machines, presumably the actual failure is somewhere else.

The real problem here is that it is impossible to diagnose or debug this situation. Simply to get this far I had to read the systemd source code (to find the code in timesyncd that printed this specific error message) and then search through 25,000 lines of strace output. And I still don't know what the problem is or how to fix it. I'm not even confident that rebooting the server will change anything, especially when all the relevant pieces on this server seem to be just the same as the pieces on other, working servers.

(I do know that according to logs this failure started happening immediately after the systemd package was upgraded and re-executed itself. On the other hand, the systemd upgrade also happened on other Ubuntu 18.04 machines, and they didn't have their timesyncds explode.)

Since systemd has no clear diagnostic information here, I spent a great deal of time chasing the red herring that if you look at /var/lib/private/systemd/timesync on such a failing system, it will be owned by a numeric UID and GID, while on working systems it will be the magically special login and group 'systemd-timesync'. This is systemd's 'dynamic user' facility in action, combined with systemd itself creating the /var/lib/private/systemd/timesync directory (with the right login and group) before exec'ing the timesyncd binary. When timesyncd fails to start, systemd removes the login and group but leaves the directory behind, now not owned by any existing login or group.

(You might think that the 'failed to create state directory' error message would mean that timesyncd was the one actually creating the state directory, but strace says otherwise; the mkdir() happens before the exec() does, while the new process that will become timesyncd is still in systemd's code. timesyncd's code does try to create the directory, but presumably the internal systemd functions it's using are fine if the directory is already there with the right ownership and so on.)

I am rather unhappy about this situation, and I am even unhappier that there is effectively nothing that we can do about any aspect of it except to stop using timesyncd (which is now something that I will be arguing for, especially since this server drifted more than half a second out of synchronization before I found this issue entirely by coincidence). Reporting a bug to either systemd or to Ubuntu is hopeless (systemd will tell me to reproduce on the latest version, Ubuntu will ignore it as always). This is simply what happens when the systemd developers produce a design and an implementation that doesn't explain how it actually works and doesn't contain any real support for field diagnosis. Once again we get to return to the era of 'reboot the server, maybe that will fix it'. Given systemd's general current attitude, I don't expect this to change any time soon. Adding documentation of systemd's internals and diagnosis probes would be admitting that the internals can have bugs, problems, and issues, and that's just not supposed to happen.

PS: The extra stupid thing about the whole situation is that the only thing /var/lib/systemd/timesync is used for is to hold a zero-length file whose timestamp is used to track the last time the clock was synchronized, and non-root users can't even see this file on Ubuntu 18.04.

Update: I've identified the cause of this problem, which is described in my new entry on how systemd's DynamicUser feature is dangerous. The short version is that systemd silently failed to set up a custom namespace that would have given timesyncd access to /var/lib/private because it could not deal with FUSE mounts in NFS mounted user home directories that were not world-accessible.


Comments on this page:

By Danny84 at 2018-08-08 11:40:47:

Does systemd-timesync user exist in /etc/passwd ? If yes it may interfere with DynamicUser and you have to delete it from /etc/passwd.

You may also need to delete /var/lib/systemd/timesync and /var/lib/private/systemd/timesnc and restart systemd-tinmesyncd service

By cks at 2018-08-08 12:11:41:

The systemd-timesync user doesn't exist in /etc/passwd, and I've tried deleting /var/lib/private/systemd/timesync before a restart. The problem turns out to be multiple issues in systemd with handling setup for DynamicUser private namespaces and what systemd does if there are problems; the details are sufficiently tangled that it will require another entry (or see my Twitter thread on it for now).

What did journalctl -u systemd-timesyncd say? systemctl status systemd-timesyncd only shows journal messages starting after the service is started, meaning you won't see any errors related to starting the service. The reason I say that is because systemd is supposed to be properly managing the state directories, so this seems like an issue there...

BTW do you have AppArmor/SELinux or anything similar enabled?

By cks at 2018-08-08 17:07:52:

journalctl -u systemd-timesyncd has no extra messages, which doesn't surprise me given the apparent root cause, and we have no AppArmor or SELinux or the like enabled (we specifically disable Ubuntu's AppArmor setup because it doesn't play well with our environment).

From 78.58.206.110 at 2018-08-08 18:46:33:

They eventually reverted the dependency on DynamicUser= in networkd/resolved/timesyncd.

If the account is present in /etc/passwd, that's not a problem -- it just implicitly disables DynamicUser= for that service. (Indeed the revert just re-adds accounts to /etc/passwd without changing .service units themselves.)

According to strace, what is failing is timesyncd's attempts to access /var/lib/private/systemd/timesync as its special UID (and GID) 'systemd-timesync'. This is failing for the prosaic reason that /var/lib/private is owner-only and owned by root. Since this works on all of our other Ubuntu 18.04 machines, presumably the actual failure is somewhere else.

It seems that the magic here is StateDirectory= implicitly creating a new mount namespace for the service, mounting an accessible tmpfs on /var/lib/private, and binding only that single service's state directory into it.

Can't say I see the point of this rain dance, and certainly not for systemd's own services. Perhaps for daemons that you kinda trust except not?... Certainly one of my least favourite features.

Ack, there goes that idea... I was suggesting checking journalctl since I recently ran into a bug in Fedora's SELinux policies that was interfering with DynamicUser=true + StateDirectory=, but since systemd was failing to access the file, it was dropping the message straight into the journal, so it didn't show up in the status output.

I know you know this already, but for future, curious visitors, a bug report has been filed: https://github.com/systemd/systemd/issues/9835

By cks at 2018-08-08 19:05:32:

I believe that the reasoning behind the /var/lib/private rain dance is explained in the article on dynamic users. If I'm understanding it right, it's necessary because if the service goes away so does its dynamic UID and GID but its state directory remains, and systemd doesn't want to have accessible now-unowned directories sitting around.

By Mike at 2018-08-09 02:19:37:

To counteract "silently failing" aspect, same as on any previous init systems, I've been using a script that dumps a list of running services to a file and diff's it with previous one, reporting any discrepancies via email, so that any new or failed-and-not-restarted service will be detected.

Rebooting the system and starting something different that was running earlier (e.g. timesyncd failed to start, forgot to enable something, etc) will be reported that way as well.

(particular script I use is https://github.com/mk-fg/fgtk/blob/master/systemd-dashboard btw, apparently since 2011)

Usefulness of such 3rd-party "state tracking" is not new to systemd by any means, though I do agree that latter is more complex and harder to learn/debug than most other inits, as indeed demonstrated here :)

From 45.72.239.115 at 2018-08-10 15:50:12:

I generally don't trust any code written by the systemD developers, and so do not use it where I do not have to.

We still use the old school NTPd on our internal time servers, but have been moving to chrony(d) for clients, both virtual and physical.

Written on 08 August 2018.
« Link: Where Vim Came From
Systemd's DynamicUser feature is (currently) dangerous »

Page tools: View Source, View Normal, Add Comment.
Search:
Login: Password:
Atom Syndication: Recent Comments.

Last modified: Wed Aug 8 01:52:59 2018
This dinky wiki is brought to you by the Insane Hackers Guild, Python sub-branch.