FS#31416 - [util-linux] causes error "Superblock last mount time is in the future."

Attached to Project: Arch Linux
Opened by Lukas Jirkovsky (6xx) - Wednesday, 05 September 2012, 09:52 GMT
Last edited by Dave Reisner (falconindy) - Sunday, 09 September 2012, 20:23 GMT
Task Type Bug Report
Category Packages: Testing
Status Closed
Assigned To Dave Reisner (falconindy)
Tom Gundersen (tomegun)
Architecture All
Severity Medium
Priority Normal
Reported Version
Due in Version Undecided
Due Date Undecided
Percent Complete 100%
Votes 2
Private No

Details

Description:
After upgrade from util-linux 2.21.2-5 to util-linux 2.22-2 I'm getting following errors for all my partitions (all of them are Ext4) during the boot. The downgrade solves the problem.

Wed Sep 5 09:12:54 2012: :: Checking filesystems [BUSY] /dev/sda1: Superblock last write time is in the future.
Wed Sep 5 09:12:54 2012: (by less than a day, probably due to the hardware clock being incorrectly set). FIXED.
Wed Sep 5 09:12:54 2012: /dev/sda1: clean, 28/589824 files, 74987/2359296 blocks
Wed Sep 5 09:12:54 2012: var: Superblock last write time is in the future.
Wed Sep 5 09:12:54 2012: (by less than a day, probably due to the hardware clock being incorrectly set). FIXED.
Wed Sep 5 09:12:54 2012: var: clean, 20088/659664 files, 944187/2638592 blocks
Wed Sep 5 09:12:54 2012: /dev/sda5: Superblock last write time is in the future.
Wed Sep 5 09:12:54 2012: (by less than a day, probably due to the hardware clock being incorrectly set). FIXED.
Wed Sep 5 09:12:54 2012: /dev/sda5: clean, 355460/6250496 files, 13457772/24999140 blocks
Wed Sep 5 09:12:54 2012: /dev/sda6: Superblock last write time is in the future.
Wed Sep 5 09:12:54 2012: (by less than a day, probably due to the hardware clock being incorrectly set). FIXED.
Wed Sep 5 09:12:54 2012: /dev/sda6: clean, 49459/53305344 files, 149227268/213192582 blocks
Wed Sep 5 09:12:54 2012: [DONE]

Additional info:
util-linux 2.22-2
This task depends upon

Closed by  Dave Reisner (falconindy)
Sunday, 09 September 2012, 20:23 GMT
Reason for closing:  Fixed
Additional comments about closing:  initscripts-2012.08.3-3
Comment by Lukas Jirkovsky (6xx) - Wednesday, 05 September 2012, 09:54 GMT
Sorry, the category should be "Packages: Testing". I wish Flyspray allowed reporter to change it.
Comment by Dave Reisner (falconindy) - Wednesday, 05 September 2012, 12:52 GMT
You get this on _every_ bootup? I can't reproduce this on a VM, but I did notice this once last week when I upgraded to 3.5.3 (I've been running util-linux from git HEAD for the past year). fsck changed fairly dramatically in 2.22, but it's still just a lousy front end that doesn't do a whole lot of world. e2fsck would be the binary that makes the real changes to the FS metadata.
Comment by Lukas Jirkovsky (6xx) - Wednesday, 05 September 2012, 16:56 GMT
So far I got it five times out of five boots with the new util-linux. Otherwise the system seems to be OK.
Comment by Karol Błażewicz (karol) - Wednesday, 05 September 2012, 17:53 GMT
Not sure if it's related, but several hours ago I've noticed that 'date' output is wrong. My hardwareclock is set to UTC and 'date' shows UTC time ... even though I'm in CEST timezone:

$ LC_TIME=C date
Wed Sep 5 17:44:57 CEST 2012
$ LC_TIME=C hwclock --debug
hwclock from util-linux 2.22
Using /dev interface to clock.
Last drift adjustment done at 0 seconds after 1969
Last calibration done at 0 seconds after 1969
Hardware clock is on UTC time
Assuming hardware clock is kept in UTC time.
Waiting for clock tick...
...got clock tick
Time read from Hardware Clock: 2012/09/05 17:45:09
Hw clock time : 2012/09/05 17:45:09 = 1346867109 seconds since 1969
Wed Sep 5 19:45:09 2012 -0.753266 seconds
$ cat /etc/adjtime
0.000000 0 0.000000
0
UTC
$ ls -l /etc/localtime
lrwxrwxrwx 1 root root 33 03-23 05:15 /etc/localtime -> /usr/share/zoneinfo/Europe/Warsaw

'hwclock --utc -s' fixes 'date' until restart. Upon boot-up, I got 'Superblock last write time is in the future.' message. I'm using ext3.
Comment by Dave Reisner (falconindy) - Wednesday, 05 September 2012, 17:59 GMT
So then perhaps hwclock is at fault, not fsck (which makes a lot more sense).

If you felt like rebuilding with 839be2ba6b44fa9dc reverted, it seems relevant.
Comment by Karol Błażewicz (karol) - Wednesday, 05 September 2012, 18:26 GMT
> If you felt like rebuilding with 839be2ba6b44fa9dc reverted, it seems relevant.
Errr, what? ;P
I've already upgraded to util-linux 2.22-3 and I have no idea where to look for the (commit?) 839be2ba6b44fa9dc.
I can do a decent job at copy-pasting commands.


Firefox shows some warnings too:
Fontconfig warning: Directory/file mtime in the future. New fonts may not be detected

(this line printed multiple times)

I'm using testing so I'm not sure if it's clock or http://mailman.archlinux.org/pipermail/arch-dev-public/2012-September/023513.html -related.
Comment by Lukas Jirkovsky (6xx) - Thursday, 06 September 2012, 07:50 GMT
Now I disabled ntpdate and checked the "date" output. It reported UTC time instead of local time, as it did for Carol.

Reverting the commit 839be2ba6b44fa9dc fixes both the issue with the date and the "Superblock last write time is in the future." problem.
Comment by Dave Reisner (falconindy) - Thursday, 06 September 2012, 17:00 GMT
Great, thanks for confirming. I think this is just an initscripts bug then.
Comment by Dave Reisner (falconindy) - Thursday, 06 September 2012, 18:12 GMT
I'm still not able to reproduce this reliably, but I have a suspicion I know what the problem is. Could you try the attached patch? You may need to reboot an extra time. Please make sure your clock is correct (time _and_ timezone) as well.

@Lukas: are you using localtime or UTC on your hwclock?
Comment by Lukas Jirkovsky (6xx) - Thursday, 06 September 2012, 19:34 GMT
Nope, this patch didn't help. I'm using UTC clock (checked in BIOS).

Here's what I have in my rc.conf:
HARDWARECLOCK="UTC"
TIMEZONE="Europe/Prague"

Output of "hwclock -r" (correct):
[lukas@orochi ~]$ hwclock -r
Thu 06 Sep 2012 09:30:24 PM CEST -0.781701 seconds

Output of "date" (incorrect, shows UTC instead of localtime):
[lukas@orochi ~]$ date
Thu Sep 6 19:31:19 CEST 2012

Let's try what date says about the UTC:
[root@orochi man]# date -u
Thu Sep 6 17:34:56 UTC 2012

Executing the hwclock according to the patch manually:
[root@orochi man]# hwclock -u
Thu 06 Sep 2012 09:33:55 PM CEST -0.062885 seconds
[root@orochi man]# hwclock --systz
[root@orochi man]# date
Thu Sep 6 19:34:04 CEST 2012

Again the output of date is incorrect.
Comment by Lukas Jirkovsky (6xx) - Friday, 07 September 2012, 06:13 GMT
Anyway, here's the output with 839be2ba6b44fa9dc reverted.

[lukas@orochi ~]$ hwclock -r
Fri 07 Sep 2012 08:12:58 AM CEST -0.828653 seconds
[lukas@orochi ~]$ date
Fri Sep 7 08:12:58 CEST 2012
[lukas@orochi ~]$ date -u
Fri Sep 7 06:13:12 UTC 2012

[lukas@orochi ~]$ hwclock -u
Fri 07 Sep 2012 08:13:34 AM CEST -0.953535 seconds
[root@orochi lukas]# hwclock --systz
[root@orochi lukas]# date
Fri Sep 7 08:14:01 CEST 2012
Comment by Dave Reisner (falconindy) - Friday, 07 September 2012, 12:38 GMT
Does /etc/adjtime exist? Does it say UTC or LOCAL on the third line?

Comment by Lukas Jirkovsky (6xx) - Friday, 07 September 2012, 16:29 GMT
It's here, but mtime is more than a year ago.

It's whole content is following:
-124.136072 1307800507 0.000000
1307800507
UTC

Removing it doesn't change anything either.
Comment by Heinrich Siebmanns (Harvey) - Saturday, 08 September 2012, 13:48 GMT
Same as the original report here with my partitions.

root@obelix# cat /proc/driver/rtc
rtc_time : 13:44:25
rtc_date : 2012-09-08
alrm_time : 08:50:11
alrm_date : 2012-09-09
alarm_IRQ : no
alrm_pending : no
update IRQ enabled : no
periodic IRQ enabled : no
periodic IRQ frequency : 1024
max user IRQ frequency : 64
24hr : yes
periodic_IRQ : no
update_IRQ : no
HPET_emulated : yes
BCD : yes
DST_enable : no
periodic_freq : 1024
batt_status : okay

root@obelix# date
Sa 8. Sep 15:44:43 CEST 2012

root@obelix# hwclock -r
Sa 08 Sep 2012 15:44:53 CEST -0.770591 Sekunden
Comment by Dave Reisner (falconindy) - Saturday, 08 September 2012, 13:57 GMT
Please do not post "me too" if you have nothing new to add.
Comment by Aleksey Rybalkin (rybalkin) - Sunday, 09 September 2012, 11:26 GMT
I also had this problem and made git bisect for util-linux from v2.21.2 (good) to current master (bad). Bisect confirmed that problem was introduced with 839be2ba6b44fa9dc:

839be2ba6b44fa9dc927f081d547ebadec9de19c is the first bad commit
commit 839be2ba6b44fa9dc927f081d547ebadec9de19c
Author: Karel Zak <kzak@redhat.com>
Date: Wed Jul 4 13:40:01 2012 +0200

hwclock: don't set time for --systz

Not sure why, but the current --systz uses non-NULL timeval for
settimeofday(). It means that build-in kernel warp clock mechanism is
not used and the system time is always modified.

The built-in kernel implementation allows to move the clock by
timezone only for very first settimeofday() call.

Signed-off-by: Karel Zak <kzak@redhat.com>

:040000 040000 9a41de5eeca8c13b7ea23b81103d171f39f436a0 af5653fcf383fcda24e9a88a7559d6d833a04c6b M sys-utils

Additional info about my system:
$ ls -al /etc/localtime
lrwxrwxrwx 1 root root 33 Mar 22 16:26 /etc/localtime -> /usr/share/zoneinfo/Europe/Moscow
$ cat /etc/adjtime
-0.058660 1320855483 0.000000
1311694754
UTC

Hope this helps and ready to help more.
Comment by Aleksey Rybalkin (rybalkin) - Sunday, 09 September 2012, 11:50 GMT
Also, patch for /etc/rc.sysinit fixes problem for me with latest util-linux package in testing (2.22-4).
Comment by Lukas Jirkovsky (6xx) - Sunday, 09 September 2012, 18:06 GMT
I gave it another try with the 2.22-4 and patched /etc/rc.sysinit and still no luck (and it's not just one system, my laptop suffers from this issue too).

UPDATE 1: I think I found the culprit. It's somehow connected with using ntpdate instead of hwclock. I don't know why is that a problem, since time in BIOS is correct in both cases.

UDATE 2: I give up. I can't fight it anymore. I don't understand how, why, or what, but when I had following DAEMONS in rc.conf:
DAEMONS=(!hwclock syslog-ng network iptables fcron dbus alsa sensors ntpdate @mysqld)
I was able to reproduce this problem every time. For some reason I decided to test what happens when using hwclock (it's the default setting after all):
DAEMONS=(hwclock syslog-ng network iptables fcron dbus alsa sensors !ntpdate @mysqld)
And the problem disappeared. So I reverted the changes to check whether it reappears with ntpdate. It didn't. I'm no longer able to reproduce this problem (with patched rc.sysinit).

I guess this bug can be closed after the patch to rc.sysinit gets its way into initscripts.
Comment by Dave Reisner (falconindy) - Sunday, 09 September 2012, 18:25 GMT
Great, thanks for digging into this more. I'm tired of seeing util-linux in testing, so I'm going to roll up a patched initscripts.

Loading...