Bug 1144766

Note: this is not urgent - I can just add a workaround to the disk image generation script to walk the repository and use utimes() instead of utimensat().

Pino, commit 99d6e2c84ef490feb6ff2e37e4b0684f34bac554 fixes
this doesn't it?

Colin - you might want to try the RHEL 7.1 packages (in general,
not just here - I'd be interested in how well they work for you).
You can get them from brew, or by following the instructions here:
https://www.redhat.com/archives/libguestfs/2014-May/msg00090.html

Downstream workaround: https://github.com/projectatomic/rpm-ostree-toolbox/commit/80fc2dcfa2cd0066ae55adf5afbfd53e59278b78

I tried your updated packages, didn't appear to help.  Here's a quick test program that uses all the different calls:

#include <sys/statvfs.h>
#include <sys/stat.h>
#include <utime.h>
#include <sys/time.h>
#include <errno.h>
#include <time.h>
#include <fcntl.h>
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>

int
main (int argc, char **argv)
{
  const char *path = argv[1];
  int fd;
  struct stat stbuf;
  struct timespec ts[2];

  ts[0].tv_sec = 0;
  ts[0].tv_nsec = UTIME_OMIT;
  ts[1].tv_sec = ts[1].tv_nsec = 0;

  fd = open (path, O_WRONLY);
  if (fd == -1)
    {
      perror ("open: ");
      exit (1);
    }
  
  if (lstat (path, &stbuf) != 0)
    {
      perror ("lstat: ");
      exit (1);
    }

  printf ("orig mtime: %llu\n", (unsigned long long)stbuf.st_mtime);
  
  if (futimens (fd, ts) == -1)
    {
      perror ("futimens: ");
      exit (1);
    }

  if (lstat (path, &stbuf) != 0)
    {
      perror ("fstat: ");
      exit (1);
    }

  printf ("after futimens: %llu\n", (unsigned long long)stbuf.st_mtime);

  if (utimensat (AT_FDCWD, path, ts, AT_SYMLINK_NOFOLLOW) == -1)
    {
      perror ("futimens: ");
      exit (1);
    }

  if (lstat (path, &stbuf) != 0)
    {
      perror ("fstat: ");
      exit (1);
    }

  printf ("after utimensat: %llu\n", (unsigned long long)stbuf.st_mtime);

  {
    struct timeval tvs[2];
    tvs[0].tv_sec = 0;
    tvs[0].tv_usec = 0;
    tvs[1].tv_sec = 0;
    tvs[1].tv_usec = 0;

    if (utimes (path, tvs) == -1)
      {
	perror ("utimes: ");
	exit (1);
      }
  }
  if (lstat (path, &stbuf) != 0)
    {
      perror ("fstat: ");
      exit (1);
    }

  printf ("after utimes: %llu\n", (unsigned long long)stbuf.st_mtime);

  (void) close (fd);

  exit (0);
}

With Fedora 21 / libguestfs 1.27.50:

orig mtime: 1411295583
after futimens: 1411295583
after utimensat: 1411295583
after utimes: 0

So if I understand the test, only utimes has an effect.

Same with guestmount debugging enabled:

libguestfs: trace: utimens "/testfile" 0 0 0 0
libguestfs: trace: utimens = 0
libguestfs: trace: lstat "/testfile"
libguestfs: trace: lstat = <struct guestfs_stat *>

It looks as if futimens and utimensat don't even get translated
into FUSE calls, so we could be missing those callbacks from the
struct fuse_operations.  I'll have to look into this in more
detail at work.

In a few hours of after-lunch boredom, I rewrote our FUSE test
shell script in C.  This gives us finer control over how we
test system calls.

https://github.com/libguestfs/libguestfs/commit/aca076e2e2b3e03f4cf5b09cf7766925f97e4b68

This reveals two bugs in utimens: firstly the bug shown here,
but a second bug which is that our stat call throws away the
nanosecond fields (actually, both guestfs_stat AND the FUSE layer).

I added this patch upstream which was just for fixing bug 1144891:

https://www.redhat.com/archives/libguestfs/2014-September/msg00162.html

Miraculously this has also fixed this (futimens no-op) bug too.

Here is a patch which enables the test, demonstrating that it is working:

https://www.redhat.com/archives/libguestfs/2014-September/msg00165.html

I have no idea at the moment why this has fixed it ...

Upstream fixes:

https://github.com/libguestfs/libguestfs/commit/8664337cc39c8575ccb60abb8c6e30f92828ea51
https://github.com/libguestfs/libguestfs/commit/58eaf258c143c0b8321d8b7cbc9b96e73e82536f

Reproduce with c4
libguestfs-1.27.52-1.1.el7.x86_64

# guestmount -a /tmp/WinXP-32-hvm.raw -m /dev/sda1 /mnt/
# cd /mnt/
# touch test
# ~/a.out test 
orig mtime: 1411457531
after futimens: 1411457531
after utimensat: 1411457531
after utimes: 0


Rich,
  Is my test steps wrong?

(In reply to Wei Shi from comment #9)
> Reproduce with c4
> libguestfs-1.27.52-1.1.el7.x86_64
> 
> # guestmount -a /tmp/WinXP-32-hvm.raw -m /dev/sda1 /mnt/
> # cd /mnt/
> # touch test
> # ~/a.out test 
> orig mtime: 1411457531
> after futimens: 1411457531
> after utimensat: 1411457531
> after utimes: 0
> 
> 
> Rich,
>   Is my test steps wrong?

The tests demonstrate the bug.  However:

 - Don't use a Windows guest for testing, because I don't know if it
   supports nanosecond-resolution timestamps.

 - Don't need to run the test as root!

To create an ext4 image which supports nanosecond timestamps, do:

guestfish -N disk mkfs ext4 /dev/sda inode:256 : mount /dev/sda / : touch /test

By the way we also test this as part of the test suite (fuse/test-fuse).

<wshi> $ export LIBGUESTFS_ATTACH_METHOD=appliance
<wshi> $ guestfish -N disk mkfs ext4 /dev/sda inode:256 : mount /dev/sda / : touch /test
<wshi> $ guestmount -a test1.img -m /dev/sda /tmp/tmp/
<wshi> $ touch /tmp/tmp/test
<wshi> $ ~/a.out /tmp/tmp/test 
<wshi> orig mtime: 1411463547
<wshi> after futimens: 1411463547
<wshi> after utimensat: 1411463547
<wshi> after utimes: 0

Created attachment 940433 [details]
utimensat.c

First of all, we need a simple, reliable test for this problem:

(1) Create a disk image in a format which is known to support nanosecond
timestamps:

guestfish -N disk mkfs ext4 /dev/sda inode:256 : mount /dev/sda / : touch /test

(2) Mount the disk image on /tmp/mnt:

mkdir -p /tmp/mnt
guestmount -a test1.img -m /dev/sda /tmp/mnt

(3) Verify the current timestamp of the test file:

stat /tmp/mnt/test

(4) Run utimensat system call (see attached C program):

./utimensat /tmp/mnt/test

(5) Repeat step (3):

stat /tmp/mnt/test

(6) Clean up:

guestunmount /tmp/mnt
rm test1.img

---------------

* In step (3) you should always see output that looks something like this.  The
exact time will depend on when you run the test of course:

Access: 2014-09-23 14:12:47.785707604 +0100
Modify: 2014-09-23 14:12:47.785707604 +0100

* Incorrect output (test failed).  In step (5) you will EITHER see the same
as step (3), OR you will see:

Access: 1970-01-01 01:02:03.000000000 +0100
Modify: 1970-01-01 01:01:18.000000000 +0100

Note the incorrect thing here is there is no nanosecond part (ie. 000000000).

* Correct output (bug is fixed).  In step (5) you will see:

Access: 1970-01-01 01:02:03.000000456 +0100
Modify: 1970-01-01 01:01:18.000000090 +0100

Note the nanosecond field is not all zeroes.

Using the steps in comment 12, I am able to verify this bug is fixed
in RHEL 7.

Wei Shi -- can you try the test again with guestmount 1.27.52?

Colin -- would be useful if you could sanity check the program and
steps used in comment 12.

(In reply to Richard W.M. Jones from comment #12)
> * Correct output (bug is fixed).  In step (5) you will see:
> 
> Access: 1970-01-01 01:02:03.000000456 +0100
> Modify: 1970-01-01 01:01:18.000000090 +0100
> 
> Note the nanosecond field is not all zeroes.

As it's not very clear.  The bug is ONLY fixed when those EXACT
times are shown.  It's not just that the nanosecond part is != 0.

Verified with libguestfs-1.27.52-1.1.el7:

guestfish -N disk mkfs ext4 /dev/sda inode:256 : mount /dev/sda / : touch /test

mkdir -p /tmp/mnt
guestmount -a test1.img -m /dev/sda /tmp/mnt

stat /tmp/mnt/test
  File: ‘/tmp/mnt/test’
  Size: 0               Blocks: 0          IO Block: 1024   regular empty file
Device: 28h/40d Inode: 2           Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Context: system_u:object_r:fusefs_t:s0
Access: 2014-09-24 13:40:22.266000000 +0800
Modify: 2014-09-24 13:40:22.266000000 +0800
Change: 2014-09-24 13:40:22.266000000 +0800
 Birth: -

./utimensat /tmp/mnt/test

stat /tmp/mnt/test
  File: ‘/tmp/mnt/test’
  Size: 0               Blocks: 0          IO Block: 1024   regular empty file
Device: 28h/40d Inode: 2           Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Context: system_u:object_r:fusefs_t:s0
Access: 1970-01-01 08:02:03.000000456 +0800
Modify: 1970-01-01 08:01:18.000000090 +0800
Change: 2014-09-24 13:40:47.155000000 +0800
 Birth: -

guestunmount /tmp/mnt
rm test1.img

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHBA-2015-0303.html