New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

/var/log/wtmp is updated to 1970-01-01 before systemd-update-utmp.service (or fake-hwclock) #6057

Open
xanview opened this Issue May 30, 2017 · 17 comments

Comments

5 participants
@ghost

ghost commented May 30, 2017

I have a raspberry pi with fake-hwclock installed and it seems the documented behaviour doesn't work E.g. timesyncd: "ensure clock monotonically advances even if the system lacks a battery-buffered RTC chip" - this doesn't actually happen.

fake-hwclock used to work as expected on SysV but stopped since the adoption of systemd (e.g. https://www.raspberrypi.org/forums/viewtopic.php?f=91&t=148634&p=1172550).

I tried to edit /lib/systemd/system/systemd-update-utmp.service to have:

[Unit]
Description=Update UTMP about System Boot/Shutdown
DefaultDependencies=no
RequiresMountsFor=/var/log/wtmp
Conflicts=shutdown.target
# After=systemd-remount-fs.service systemd-tmpfiles-setup.service auditd.service fake-hwclock.service
After=systemd-timesyncd.service fake-hwclock.service time-sync.target  ## <<< changed line
Before=sysinit.target shutdown.target

[Service]
Type=oneshot
RemainAfterExit=yes
ExecStartPre=/sbin/fake-hwclock load  ## <<< added line
ExecStart=/lib/systemd/systemd-update-utmp reboot
ExecStop=/lib/systemd/systemd-update-utmp shutdown

However on reboot, the wtmp file is still being updated to 1970-01-01 before systemd-update-utmp.service runs:

$ last reboot | head -n 3
reboot   system boot  4.4.0-1055-raspi Thu Jan  1 01:00   still running
reboot   system boot  4.4.0-1055-raspi Thu Jan  1 01:00 - 22:04 (17316+21:04)
reboot   system boot  4.4.0-1055-raspi Thu Jan  1 01:00 - 22:04 (17316+21:04)

Looking at the journalctl I can see my fake-hwclock command runs as expected because of my edit: ExecStartPre=/sbin/fake-hwclock load -- however the time is already set by something else and /var/log/wtmp is already set to 1970-01-01 by something else:

$ sudo journalctl -u systemd-update-utmp
-- Logs begin at Wed 2017-06-07 17:18:08 IST, end at Wed 2017-06-07 17:19:05 IST. --
Jun 07 17:18:14 TimeBox systemd[1]: Starting Update UTMP about System Boot/Shutdown...
Jun 07 17:18:14 TimeBox fake-hwclock[823]: Current system time: 2017-06-07 16:18:14
Jun 07 17:18:14 TimeBox fake-hwclock[823]: fake-hwclock saved clock information is in the past: 2017-06-07 16:18:08
Jun 07 17:18:14 TimeBox fake-hwclock[823]: To set system time to this saved clock anyway, use "force"
Jun 07 17:18:14 TimeBox systemd[1]: Started Update UTMP about System Boot/Shutdown.

So the "Update UTMP about System Boot/Shutdown." doesn't work as expected, the time of wtmp is already set to 1 Jan 1970 by something else.

How do I run a service/command before /var/log/wtmp is touched and set to 1 Jan 1970?

I'm using Ubuntu 16.04 with systemd 229-4ubuntu17 and I tried Raspbian and Debian 9 as well.

@archuserr

This comment has been minimized.

archuserr commented Jun 1, 2017

When you say hardware clock, do you mean the one built-in to the Raspberry Pi, or a separate battery powered RTC?

@zeroxfourc

This comment has been minimized.

zeroxfourc commented Jun 1, 2017

The Raspberry Pi does not have a built-in hardware clock, so @xanview is most likely using a RTC addon module.

@archuserr

This comment has been minimized.

archuserr commented Jun 1, 2017

Why use fake-hwclock when you have a real hardware clock?

@ghost

This comment has been minimized.

ghost commented Jun 1, 2017

@archuserr It is an RTC add-on module as the RPI does not have one. I'd rather not use fake-hwclock, but either/both do not work as wtmp is updated before they get a chance to run.

As the developers may not have an actual RTC add-on module, fake-hwclock allows the issue to be reproduced more easily.

@poettering

This comment has been minimized.

Member

poettering commented Jun 7, 2017

what does "fake-hwclock" do? If it just persists the last clock to disk, then do note that systemd-timesyncd can do that too for you.

@ghost

This comment has been minimized.

ghost commented Jun 7, 2017

fake-hwclock: Save/restore system clock on machines without working RTC hardware

@poettering How to tell systemd-timesyncd to do that? - I tried adding Before=systemd-timesyncd to the fake-hwclock service but wtmp is still updated to 1970-01-01 before it gets a chance to run.

Looking at timesyncd.conf there's no option to make it backup/restore time and if there is no internet, the system time is set to 1970-01-01 on boot and stays there.

@poettering

This comment has been minimized.

Member

poettering commented Jun 7, 2017

@xanview timesyncd does that by default if it is enabled. But there might be a dependency missing there that ensures timesyncd did its deed before the wtmp stuff is done.

@ghost

This comment has been minimized.

ghost commented Jun 7, 2017

@poettering it's not doing it here on Ubuntu 16.04 with systemd 229-4ubuntu17 - any ideas what dependency could be missing? how to troubleshoot? -- nothing in journalctl -u timesyncd or systemd-timesyncd

@poettering

This comment has been minimized.

Member

poettering commented Jun 7, 2017

Most likely adding "After=systemd-timesyncd.service time-sync.target" to the [Unit] section of systemd-update-utmp.service should suffice.

@archuserr

This comment has been minimized.

archuserr commented Jun 7, 2017

Do hwclock -r and hwclock -w work correctly?

@ghost

This comment has been minimized.

ghost commented Jun 7, 2017

@archuserr yes:

root@ubuntu:~# hwclock -r
Wed Jun  7 16:50:55 2017  .017541 seconds
root@ubuntu:~# hwclock -w
root@ubuntu:~# echo $?
0

But probably not at boot because the hwclock requires echo ds1307 0x68 > /sys/class/i2c-adapter/i2c-1/new_device which is ran in /etc/rc.local

In any case, it doesn't explain why fake-hwclock is not being used at least and why wtmp shows reboot 1970-01-01 if systemd-timesyncd is supposed to backup the last known time.

@ghost

This comment has been minimized.

ghost commented Jun 7, 2017

@poettering No change :( - I've edited /lib/systemd/system/systemd-update-utmp.service to this:

[Unit]
Description=Update UTMP about System Boot/Shutdown
Documentation=man:systemd-update-utmp.service(8) man:utmp(5)
DefaultDependencies=no
RequiresMountsFor=/var/log/wtmp
Conflicts=shutdown.target
# After=systemd-remount-fs.service systemd-tmpfiles-setup.service auditd.service fake-hwclock.service
After=systemd-timesyncd.service time-sync.target
Before=sysinit.target shutdown.target

[Service]
Type=oneshot
RemainAfterExit=yes
ExecStart=/lib/systemd/systemd-update-utmp reboot
ExecStop=/lib/systemd/systemd-update-utmp shutdown

Rebooted twice, this is what last shows:

$ last reboot | head -n 3
reboot   system boot  4.4.0-1057-raspi Thu Jan  1 01:00   still running
reboot   system boot  4.4.0-1057-raspi Thu Jan  1 01:00 - 17:00 (17324+16:00)
reboot   system boot  4.4.0-1055-raspi Thu Jan  1 01:00 - 17:00 (17324+16:00)
@ghost

This comment has been minimized.

ghost commented Jun 7, 2017

Update, I tried to edit /lib/systemd/system/systemd-update-utmp.service to:

[Unit]
Description=Update UTMP about System Boot/Shutdown
Documentation=man:systemd-update-utmp.service(8) man:utmp(5)
DefaultDependencies=no
RequiresMountsFor=/var/log/wtmp
Conflicts=shutdown.target
# After=systemd-remount-fs.service systemd-tmpfiles-setup.service auditd.service fake-hwclock.service
After=systemd-timesyncd.service fake-hwclock.service time-sync.target
Before=sysinit.target shutdown.target

[Service]
Type=oneshot
RemainAfterExit=yes
ExecStartPre=/sbin/fake-hwclock load
ExecStartPre=echo > ds1307 0x68 /sys/class/i2c-adapter/i2c-1/new_device
ExecStart=/lib/systemd/systemd-update-utmp reboot
ExecStop=/lib/systemd/systemd-update-utmp shutdown

When I reboot, I can see the change had an effect:

$ sudo journalctl -u systemd-update-utmp
-- Logs begin at Wed 2017-06-07 17:18:08 IST, end at Wed 2017-06-07 17:19:05 IST. --
Jun 07 17:18:14 TimeBox systemd[1]: Starting Update UTMP about System Boot/Shutdown...
Jun 07 17:18:14 TimeBox fake-hwclock[823]: Current system time: 2017-06-07 16:18:14
Jun 07 17:18:14 TimeBox fake-hwclock[823]: fake-hwclock saved clock information is in the past: 2017-06-07 16:18:08
Jun 07 17:18:14 TimeBox fake-hwclock[823]: To set system time to this saved clock anyway, use "force"
Jun 07 17:18:14 TimeBox systemd[1]: Started Update UTMP about System Boot/Shutdown.

However last still shows:

$ last reboot | head -n 3
reboot   system boot  4.4.0-1057-raspi Thu Jan  1 01:00   still running
reboot   system boot  4.4.0-1057-raspi Thu Jan  1 01:00 - 17:18 (17324+16:17)
reboot   system boot  4.4.0-1057-raspi Thu Jan  1 01:00 - 17:14 (17324+16:14)

So /var/log/wtmp is actually updated to 1970-01-01 before systemd-update-utmp.service runs. Any ideas?

@archuserr

This comment has been minimized.

archuserr commented Jun 7, 2017

Have you tried Raspbian? It looks like the DS1307 is officially supported.

https://github.com/raspberrypi/firmware/blob/master/boot/overlays/README

If that works for you, maybe you can copy the settings to Ubuntu.

@ghost

This comment has been minimized.

ghost commented Jun 7, 2017

@archuserr Ubuntu also has full DS1307 support, this used to work with SysV on Raspbian but stopped working since the adoption of systemd. E.g. https://www.raspberrypi.org/forums/viewtopic.php?f=91&t=148634&p=1172550

For simplicity lets forget about hardware clock completely, the issue is systemd should never set wtmp to 1970, it should use the last known time if no other time is available, or should allow some kind of mechanism to set the time with a custom command.

It seems the documented behaviour doesn't work. E.g. from /lib/systemd/system/systemd-timesyncd.service, specifically: "ensure [clock] monotonically advances even if the system lacks a battery-buffered RTC chip" - this doesn't actually happen.

Also systemd-update-utmp.service doesn't appear to actually be responsible for setting /var/log/wtmp time as it is already set to 1970 before it gets a chance to run.

Any ideas?

@xanview xanview changed the title from /var/log/wtmp is updated before the hardware clock (or fake-hwclock) is loaded to /var/log/wtmp is updated before systemd-update-utmp.service (or fake-hwclock) is loaded Jun 7, 2017

@xanview xanview changed the title from /var/log/wtmp is updated before systemd-update-utmp.service (or fake-hwclock) is loaded to /var/log/wtmp is updated to 01-01-1970 before systemd-update-utmp.service (or fake-hwclock) Jun 7, 2017

@xanview xanview changed the title from /var/log/wtmp is updated to 01-01-1970 before systemd-update-utmp.service (or fake-hwclock) to /var/log/wtmp is updated to 1970-01-01 before systemd-update-utmp.service (or fake-hwclock) Jun 7, 2017

@ghost

This comment has been minimized.

ghost commented Jun 7, 2017

Updated the first post to have a more concise description of the issue.

@piotrjurkiewicz

This comment has been minimized.

piotrjurkiewicz commented Nov 2, 2018

The problem is that /lib/systemd/systemd-update-utmp gets UserspaceTimestamp from systemd init, which records CLOCK_REALTIME when the main systemd instance began execution. See:
https://github.com/systemd/systemd/blob/master/src/update-utmp/update-utmp.c#L45
https://github.com/systemd/systemd/blob/master/src/core/main.c#L2306

Therefore, there is no way how restoration of clock by systemd-timesyncd or fake-hwclock can affect this timestamp, because it is being recorded before any of these system services can even start.

So systemd-update-utmp should calculate the real time before writing a record to utmp:

t = CLOCK_REALTIME - (CLOCK_MONOTONIC - UserspaceTimestampMonotonic)

Or rather:

t = CLOCK_REALTIME - (CLOCK_BOOTTIME- UserspaceTimestampMonotonic)

BTW, I think that utmp should record when the kernel first began execution, not when the main systemd instance began execution. So the startup time should be calculated as:

t = CLOCK_REALTIME - CLOCK_BOOTTIME
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment