kern/142594: Modification time reset to 1 Jan 1970 after fsync+crash on ZFS root volume ('legacy' mount)

[Henno Schooljan]

>Number:         142594
>Category:       kern
>Synopsis:       Modification time reset to 1 Jan 1970 after fsync+crash on ZFS root volume ('legacy' mount)
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    freebsd-bugs
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Sun Jan 10 21:00:11 UTC 2010
>Closed-Date:
>Last-Modified:
>Originator:     Henno Schooljan
>Release:        8.0-RELEASE-p2
>Organization:
>Environment:
FreeBSD server.schooljan.nl 8.0-RELEASE-p2 FreeBSD 8.0-RELEASE-p2 #0: Thu Jan  7 01:31:27 CET 2010     root at server.schooljan.nl:/usr/obj/usr/src/sys/SERVER  i386
>Description:
I've encountered some strange behavior while testing for correct write cache synchronization on my ZFS installation (full ZFS, using GPT+gptzfsboot and ZFS root partition)

When I change or add files to several directories, then fsync the files and directories, and immediately pull the plug on the machine right after the fsync calls return, I noticed that the modification time on the root (/) partition have reverted to 1 Jan 1970! The contents of the files have been successfully committed, just the mtimes are wrong.
The mtimes and contents of files on my separate ZFS file systems with explicit mount points (like /usr, /tmp and /var) are correct.

This happens on both i386 (modified kernel w/ KVA_PAGES=512) + standard SATA drives+on-board controller, and a non-tuned amd64 GENERIC with 3Ware RAID card w/ BBU on StorSave Protection setting.

Subsequent zpool scrubbing does not reveal any errors.

When I wait a while longer after succesful fsync before pulling the plug, the times are correct (probably synced by the periodic ZFS flush to definitive non-ZIL storage).

As far as I know, an fsync call would at least commit pending writes to the ZIL, to be replayed later if the system goes down before the next ZIL-to-pool sync.
Maybe this is a bug in the ZIL replay code which ignores the modification time when replaying 'legacy' mounts? I'm not sure though how and why they would be handled any differently from regular mountpoints though when this occurs.
>How-To-Repeat:
/var, /tmp and /usr are on separate ZFS file systems with explicit mountpoints, rest is on / with legacy mountpoint (ZFS Boot/Root configuration) 

Put something like this in a script and run it:

echo foo>/root/bar.txt
echo foo>/var/bar.txt
echo foo>/etc/bar.txt
echo foo>/tmp/bar.txt
echo foo>/usr/bar.txt
echo foo>/lib/bar.txt

fsync /root/bar.txt && fsync /root
fsync /var/bar.txt && fsync /var
fsync /etc/bar.txt && fsync /etc
fsync /tmp/bar.txt && fsync /tmp
fsync /usr/bar.txt && fsync /usr
fsync /lib/bar.txt && fsync /lib

Cut machine power as soon as we get our prompt back, then restart system.

The bar.txt file and their parent directories on /root, /etc and /lib have modification time 1 Jan 1970, the ones on the separate filesystems are correct.

>Fix:


>Release-Note:
>Audit-Trail:
>Unformatted: