Bug#824707: systemd: I get fsck's every other boot: due to systemd-timesyncd not updating hwclock?

[Manuel Bilderbeek]

Hi,

On 23-05-16 20:04, Manuel Bilderbeek wrote:

3. My BIOS told me at boot today that no RTC clock time was set. I guess
my RTC battery is dead. Will replace it.


Replaced it last night. Then booted again and set the hwclock. Then 
booted Debian, no fsck, as I still have the e2fsck.conf in place.


Then I removed the file and turned off the PC.

Booted again today and... yet another set of fsck's, but now at least 
the reason is clear:


mei 24 19:08:51 sonata systemd-fsck[326]: /dev/sda1 has filesystem last 
checked time in the future, check forced.
mei 24 19:13:06 sonata systemd-fsck[332]: /dev/sda6 has filesystem last 
checked time in the future, check forced.


Then a bit later the timesync kicks in:

mei 24 19:33:51 sonata dbus[506]: [system] Failed to activate service 
'org.bluez': timed out
mei 24 19:33:52 sonata systemd-timesyncd[462]: Synchronized to time 
server 94.228.220.14:123 (2.debian.pool.ntp.org).

mei 24 19:34:28 sonata realmd[1318]: quitting realmd service after timeout

There is no notification that time changed now, so I guess the hwclock 
is fine now.


Let's see what happens the coming days. I hope that the replaced CMOS 
battery avoids the issues I had.


The main thing of this bug report is still the following: if a 'simple' 
user runs into this problem (hwclock starts failing, but BIOS doesn't 
report it's bad yet), he's doomed to end up in getting fsck's all the 
time. Such a 'simple' user won't understand and probably run away from 
Debian. What could be done for such user?


A little more advanced user would check the logs, but as I posted in my 
original report: the log did NOT mention any reason why the fsck was done.
He could probably find out that something is wrong with his hwclock 
though, due to the time changes that show up in the logs. But I don't 
think he could reasonably know that he could work around it with that 
e2fsck.conf. (But he should fix his hwclock anyway.) He may think of 
installing fake-hwclock though.


Anyway, thanks for your help so far.

--
Kind regards,

Manuel

Bug#824707: systemd: I get fsck's every other boot: due to systemd-timesyncd not updating hwclock?

[Manuel Bilderbeek]

Hi,

After a few days, reporting here what's going on now...

1. I haven't seen an fsck of my HDD's ever since I added that 
e2fsck.conf file
2. When booting, I do get a message that superblock timestamps of my SSD 
(/dev/sdf1) are too far in the future and I get a very quick fsck of the 
SDD. It takes only a few seconds though, so I'm not sure what's going 
on... It's not shown anywhere in the journalctl output.
3. My BIOS told me at boot today that no RTC clock time was set. I guess 
my RTC battery is dead. Will replace it.


--
Kind regards,

Manuel

Bug#824707: systemd: I get fsck's every other boot: due to systemd-timesyncd not updating hwclock?

[Michael Biebl]

On Thu, 19 May 2016 23:31:29 +0200 Manuel Bilderbeek
 wrote:
> Hi,
> 
> On 19-05-16 23:04, Michael Biebl wrote:
> >> Looks like I need to have systemd-timesync run *before* systemd-fsck!?
> >
> > If your hwclock drifts that much, maybe
> > /etc/e2fsck.conf:
> >  [options]
> >  broken_system_clock=1
> >
> > (as referenced in my earlier reply) is an option.
> > Can you try that?
> 
> Sure, but won't that effectively disable fsck'ing based on 'time since 
> last check'?

Dunno, the e2fsck.conf man page doesn't say anything in that regard.

> Also, is it normal that that config file doesn't exist yet?

Yes, this configuration file doesn't exist by default but you can easily
create it.

Let us know if that fixes your issue.

Michael

-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?



signature.asc
Description: OpenPGP digital signature

Bug#824707: systemd: I get fsck's every other boot: due to systemd-timesyncd not updating hwclock?

[Manuel Bilderbeek]

Hi,

On 19-05-16 23:04, Michael Biebl wrote:

Looks like I need to have systemd-timesync run *before* systemd-fsck!?


If your hwclock drifts that much, maybe
/etc/e2fsck.conf:
 [options]
 broken_system_clock=1

(as referenced in my earlier reply) is an option.
Can you try that?


Sure, but won't that effectively disable fsck'ing based on 'time since 
last check'?


Also, is it normal that that config file doesn't exist yet?

--
Kind regards,

Manuel

Bug#824707: systemd: I get fsck's every other boot: due to systemd-timesyncd not updating hwclock?

[Michael Biebl]

Am 19.05.2016 um 21:30 schrieb Manuel Bilderbeek:
> 
> -- Logs begin at ma 2028-05-22 12:37:10 CEST, end at do 2016-05-19
> 21:22:23 CEST. --
> 
> Looks like I need to have systemd-timesync run *before* systemd-fsck!?

If your hwclock drifts that much, maybe
/etc/e2fsck.conf:
[options]
broken_system_clock=1

(as referenced in my earlier reply) is an option.
Can you try that?


Regards,
Michael

-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?



signature.asc
Description: OpenPGP digital signature

Bug#824707: systemd: I get fsck's every other boot: due to systemd-timesyncd not updating hwclock?

[Manuel Bilderbeek]

Hi,

Thanks for taking interest in this annoying problem. Today I again got 
an fsck at boot...


On 18-05-16 23:35, Michael Biebl wrote:

fsck.ext[234] should no longer run an fsck because of that.
Which version of e2fsprogs have you installed?


Should be latest in testing:

ii  e2fsprogs1.43~WIP.2016.03.15-2 
  amd64ext2/ext3/ext4 file system utilities




What are the contents of /etc/adjtime?


$ cat /etc/adjtime
0.00 1463602260 0.00
1463602260
UTC


In any case, that sounds like a e2fsprogs related problem.


Anything else I can do to gather more information to find the source of 
the problem?


On 19-05-16 00:03, Martin Pitt wrote:
> timesyncd does *not* write to the hw clock directly. The kernel has
> done that by itself now every 11 minutes for a fair while now, if the
> hw clock is in UTC. (If it's not, then timesyncd tells the kernel to
> not sync). See manager_adjust_clock() in
>
> 
https://github.com/systemd/systemd/blob/master/src/timesync/timesyncd-manager.c#L314


How can I tell that the kernel should sync it?

Perhaps this:

$ timedatectl
  Local time: do 2016-05-19 21:21:30 CEST
  Universal time: do 2016-05-19 19:21:30 UTC
RTC time: do 2016-05-19 19:21:30
   Time zone: Europe/Amsterdam (CEST, +0200)
 Network time on: yes
NTP synchronized: yes
 RTC in local TZ: no


FYI, this is the log entry of today's boot:

mei 22 12:37:10 sonata systemd-fsck[343]: /dev/sda1 has gone 4385 days 
without being checked, check forced.


... well at least now it logs why it's doing the fsck...

mei 22 12:41:25 sonata systemd-fsck[343]: /dev/sda1: 858066/3055616 
files (7.5% non-contiguous), 8046780/12207384 blocks

mei 22 12:41:26 sonata systemd[1]: Started File System Check on /dev/sda1.
mei 22 12:41:26 sonata systemd[1]: Mounting /media/olddisk1...
mei 22 12:41:26 sonata systemd[1]: Mounted /media/olddisk1.
mei 22 12:41:26 sonata kernel: EXT4-fs (sda1): mounted filesystem with 
ordered data mode. Opts: (null)
mei 22 12:41:26 sonata systemd-fsck[348]: /dev/sda6 has gone 4385 days 
without being checked, check forced.
mei 22 13:01:33 sonata systemd-fsck[348]: /dev/sda6: 974019/30523392 
files (8.8% non-contiguous), 114529416/122069894 blocks

mei 22 13:01:34 sonata systemd[1]: Started File System Check on /dev/sda6.
mei 22 13:01:34 sonata systemd[1]: Mounting /media/olddisk6...

...

mei 22 13:02:02 sonata systemd[1420]: Startup finished in 18ms.
mei 22 13:02:02 sonata systemd[1]: Started User Manager for UID 1000.
mei 19 18:54:52 sonata systemd[1]: Time has been changed
mei 19 18:54:52 sonata systemd[1420]: Time has been changed
mei 19 18:54:52 sonata systemd[1175]: Time has been changed
mei 19 18:54:52 sonata systemd-timesyncd[478]: Synchronized to time 
server 83.98.201.134:123 (2.debian.pool.ntp.org).
mei 19 18:54:52 sonata systemd[1]: apt-daily.timer: Adding 4h 20min 
45.246388s random time.


I don't know what's happening, but my RTC tends to get ahead A LOT. 
Although I can't match the 4385 days with the 3 days difference I saw in 
this boot log.


Oh, wait, I can... check the start of the log:

-- Logs begin at ma 2028-05-22 12:37:10 CEST, end at do 2016-05-19 
21:22:23 CEST. --


Looks like I need to have systemd-timesync run *before* systemd-fsck!?

--
Grtjs, Manuel

PS: MSX FOR EVER! (Questions? http://faq.msxnet.org/ )
PPS: Visit my homepage at http://manuel.msxnet.org/

Bug#824707: systemd: I get fsck's every other boot: due to systemd-timesyncd not updating hwclock?

[Martin Pitt]

Manuel Bilderbeek [2016-05-18 23:06 +0200]:
> The whole thing reminds me of bug #755722. But that says that 
> systemd-timesyncd
> does write to the hwclock apparently not?

timesyncd does *not* write to the hw clock directly. The kernel has
done that by itself now every 11 minutes for a fair while now, if the
hw clock is in UTC. (If it's not, then timesyncd tells the kernel to
not sync). See manager_adjust_clock() in

  
https://github.com/systemd/systemd/blob/master/src/timesync/timesyncd-manager.c#L314

Martin
-- 
Martin Pitt| http://www.piware.de
Ubuntu Developer (www.ubuntu.com)  | Debian Developer  (www.debian.org)

Bug#824707: systemd: I get fsck's every other boot: due to systemd-timesyncd not updating hwclock?

[Michael Biebl]

Am 18.05.2016 um 23:35 schrieb Michael Biebl:
> fsck.ext[234] should no longer run an fsck because of that.
> Which version of e2fsprogs have you installed?
> 
> What are the contents of /etc/adjtime?


See also /usr/share/doc/initramfs-tools/NEWS.Debian.gz

initramfs-tools (0.119) unstable; urgency=medium

  * The initramfs will now run fsck on the root filesystem before
mounting it.  If the chosen init program is systemd and there is a
separate /usr filesystem, it will also fsck and mount /usr.
  * If /usr is a separate filesystem on a RAID device and the INITRDSTART
setting in /etc/default/mdadm is not 'all', you will need to change it
to include that device.
  * If /usr is a separate filesystem on an LVM logical volume, and the
line for /usr in /etc/fstab specifies the device by UUID or LABEL,
you must change this line to specify the device using the format
/dev/mapper/VG-LV or /dev/VG/LV.
  * It is no longer possible to bind-mount the /usr filesystem.
  * If the RTC (real time clock) is set to local time and the local time is
ahead of UTC, e2fsck will print a warning during boot about the time
changing backward (bug #767040).  You can disable this by putting the
following lines in /etc/e2fsck.conf:
[options]
broken_system_clock=1
[As of e2fsprogs version 1.42.13 this message is informational, and
 no configuration change is required.]

-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?



signature.asc
Description: OpenPGP digital signature

Bug#824707: systemd: I get fsck's every other boot: due to systemd-timesyncd not updating hwclock?

[Michael Biebl]

Am 18.05.2016 um 23:06 schrieb Manuel Bilderbeek:
> Package: systemd
> Version: 229-5
> Severity: important
> 
> Dear Maintainer,
> 
> Before I start: I'm doing a daily dist-upgrade in testing.
> 
> Since about a week I'm getting fsck's every other boot. I see this when 
> booting:
> 
> (notice that the system time is incorrect, see below when it's corrected)
> 
> mei 19 16:42:35 sonata systemd-fsck[341]: /dev/sda1: Superblock last write 
> time (Fri Jul 29 10:54:06 2016,
> mei 19 16:42:35 sonata systemd-fsck[341]: now = Thu May 19 16:42:35 
> 2016) is in the future.
> mei 19 16:42:35 sonata systemd-fsck[341]: FIXED.
> 
> ... 4 minutes fsck ...
> 
> mei 19 16:46:49 sonata systemd-fsck[341]: /dev/sda1: 858066/3055616 files 
> (7.5% non-contiguous), 8046780/12207384 blocks
> mei 19 16:46:50 sonata systemd[1]: Started File System Check on /dev/sda1.
> ei 19 16:46:50 sonata systemd[1]: Mounting /media/olddisk1...
> mei 19 16:46:50 sonata systemd[1]: Mounted /media/olddisk1.
> mei 19 16:46:50 sonata kernel: EXT4-fs (sda1): mounted filesystem with 
> ordered data mode. Opts: (null)
> mei 19 16:46:50 sonata systemd-fsck[346]: /dev/sda6: Superblock last mount 
> time (Fri Jul 29 10:54:06 2016,
> mei 19 16:46:50 sonata systemd-fsck[346]: now = Thu May 19 16:46:50 
> 2016) is in the future.
> mei 19 16:46:50 sonata systemd-fsck[346]: FIXED.


fsck.ext[234] should no longer run an fsck because of that.
Which version of e2fsprogs have you installed?

What are the contents of /etc/adjtime?

In any case, that sounds like a e2fsprogs related problem.

Regards,
Michael


-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?



signature.asc
Description: OpenPGP digital signature