Bug 1051226 - Wrong atime updates on a file during write() while using vfs glusterfs CIFS interface
Summary: Wrong atime updates on a file during write() while using vfs glusterfs CIFS i...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Gluster Storage
Classification: Red Hat Storage
Component: samba
Version: 2.1
Hardware: x86_64
OS: Linux
high
high
Target Milestone: ---
: RHGS 2.1.2
Assignee: Ira Cooper
QA Contact: surabhi
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-01-09 21:32 UTC by Harshavardhana
Modified: 2018-12-05 16:53 UTC (History)
11 users (show)

Fixed In Version: samba-3.6.9-167.10
Doc Type: Bug Fix
Doc Text:
Previously when a file on a Samba share was edited, the time of last access (atime) was wrongly set to a future date. With this fix, the last access time of the file is displayed correctly.
Clone Of:
Environment:
Last Closed: 2014-02-25 08:14:44 UTC
Embargoed:


Attachments (Terms of Use)
Proposed patch, with the idea from comment #12 (1.71 KB, patch)
2014-01-10 15:38 UTC, Niels de Vos
no flags Details | Diff


Links
System ID Private Priority Status Summary Last Updated
Red Hat Knowledge Base (Solution) 663903 0 None None None Never
Red Hat Product Errata RHEA-2014:0208 0 normal SHIPPED_LIVE Red Hat Storage 2.1 enhancement and bug fix update #2 2014-02-25 12:20:30 UTC

Description Harshavardhana 2014-01-09 21:32:42 UTC
Description of problem:

To reproduce the error test machines, creat a simple
replicated volume with 2bricks, add a local user, then make 
it as a Samba user with  "smbpasswd -a test"; 

mounted it on a Linux client with

mount -t cifs -o username=test,password=password //testserver/gluster-test /mnt

Please note that the problem does not appear if one simply touches a
non-existent file - one must write data to it, so I have done "echo >
foo"

Version-Release number of selected component (if applicable):
RHS 2.1 Update 1 (samba-glusterfs-3.6.9-160.7.el6rhs.x86_64)

How reproducible:
Always

============ TCPdump analysis done by Niels ============

Looking through the attached file.pcap to verify that the incorrect time is
returned by the brick. This file captured 

The file that is used for testing is called "a". This file seems to have the
following GFID: f48a3fdd-b857-495e-b31b-2566c7c96718
    (found by checking the 'glusterfs.proc == CREATE && glusterfs.bname == "a"')

The times in the stat (or 'ls -l') output are returned by the brick in a
structure called 'IATT'. The CREATE, WRITE and READDIRP replies that contain
the IATT for this "a" file can be listed with this filter:

    ( glusterfs.proc == CREATE || glusterfs.proc == READDIRP || glusterfs.proc == WRITE ) \
        && glusterfs.gfid == f48a3fdd-b857-495e-b31b-2566c7c96718

    Frame 237:
    GlusterFS
        [Program Version: 330]
        [GlusterFS: CREATE (23)]
        ...
        IATT
            GFID: f48a3fdd-b857-495e-b31b-2566c7c96718
    	...
            Time of last access: Jan  9, 2014 15:47:13.127999762 CET
            Time of last modification: Jan  9, 2014 15:47:13.127999762 CET
            Time of last status change: Jan  9, 2014 15:47:13.128999778 CET
    
    Frame 344:
    GlusterFS
        [Program Version: 330]
        [GlusterFS: READDIRP (40)]
        ...
        Entry Path: a
            ...
            IATT
                GFID: f48a3fdd-b857-495e-b31b-2566c7c96718
                ...
                Time of last access: Jan  9, 2014 15:13:47.000000000 CET
                Time of last modification: Jan  9, 2014 15:13:47.000000000 CET
                Time of last status change: Jan  9, 2014 15:47:13.131999862 CET
    	    ...
    
    Frame 523: GlusterFS 184 V330 WRITE Call
    
    Frame 526:
    GlusterFS
        [Program Version: 330]
        [GlusterFS: WRITE (13)]
        ...
        Pre-operation parent IATT
            GFID: f48a3fdd-b857-495e-b31b-2566c7c96718
            ...
            Time of last access: Feb  7, 2106 07:28:15.000000000 CET
            Time of last modification: Jan  9, 2014 15:14:00.000000000 CET
            Time of last status change: Jan  9, 2014 15:47:25.297999976 CET
    
    Frame 595:
    GlusterFS
        [Program Version: 330]
        [GlusterFS: READDIRP (40)]
        ...
        Entry Path: a
            ...
            IATT
                GFID: f48a3fdd-b857-495e-b31b-2566c7c96718
                ...
                Time of last access: Feb  7, 2106 07:28:15.000000000 CET
                Time of last modification: Jan  9, 2014 15:47:25.303000049 CET
                Time of last status change: Jan  9, 2014 15:47:25.303000049 CET
    
In these details, we can see that the "Time of last access" has been changed
to Feb 2106 when the WRITE (reply in frame 526) was done.

Inspecting the WRITE call (frame 523) shows some unexpected parameters. The
file seems to have been opened in read-only mode:

    Frame 523:
    GlusterFS
        [Program Version: 330]
        [GlusterFS: WRITE (13)]
        ...
        Flags: 0, O_RDONLY

Of course, a WRITE in O_RDONLY should never succeed, but that was the case
here. Possibly the flags in the WRITE call are unused (O_RDONLY has value 0,
likely the same as 'unset').

However, the related OPEN call, does not have suitable flags set either:

    Frame 502:
    GlusterFS
        [Program Version: 330]
        [GlusterFS: OPEN (11)]
        GFID: f48a3fdd-b857-495e-b31b-2566c7c96718
        Flags: 010100001000, O_TRUNC, Unused

My current suspicion is that the vfs_gluster plugin for Samba does not set the
open()-flags correctly. If this can result in the weird access-time behavior
is unclear to me.
=============================================================

Comment 5 Harshavardhana 2014-01-09 23:03:09 UTC
glusterfs SETATTR call() 

GlusterFS 
    [Program Version: 330]
    [GlusterFS: SETATTR (38)]
    GFID: f48a3fdd-b857-495e-b31b-2566c7c96718
................
................
        Time of last access: Jan  9, 2014 06:13:47.000000000 PST
        Time of last modification: Jan  9, 2014 06:13:47.000000000 PST
        Time of last status change: Dec 31, 1969 16:00:00.000000000 PST -> This
-------------------------------------------------------------------------------
smb packet reply received! 
          Reserved: 0000
        SET_FILE_INFO Data
            File size: 18446744073709551615
            Number of bytes: 18446744073709551615
            Last status change: Jan  9, 2014 06:13:59.533861000 PST
            Last access: May 27, 60056 22:36:10.955161500 PDT -------> This
            Last modification: Jan  9, 2014 06:13:59.533861000 PST

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

Comment 6 Niels de Vos 2014-01-10 08:50:49 UTC
An extension to comment #5, from the attached file.pcap:

    Frame: 510
    GlusterFS
        [Program Version: 330]
        [GlusterFS: SETATTR (38)]
        GFID: f48a3fdd-b857-495e-b31b-2566c7c96718
        IATT
            ...
            Time of last access: Feb  7, 2106 07:28:15.000000000 CET
            Time of last modification: Jan  9, 2014 15:14:00.000000000 CET
            Time of last status change: Jan  1, 1970 01:00:00.000000000 CET
        Set attributes: 0x00000030, SET_ATTR_ATIME, SET_ATTR_MTIME
            ...

This instructs that only the ATIME and MTIME should be changed. All other
values of the IATT are unset (set to 0).

    Frame: 511
    GlusterFS
        [Program Version: 330]
        [GlusterFS: SETATTR (38)]
        Return value: 0
        Errno: 0 (Success)
        Pre-operation IATT
            GFID: f48a3fdd-b857-495e-b31b-2566c7c96718
            ...
            Time of last access: Jan  9, 2014 15:13:47.000000000 CET
            Time of last modification: Jan  9, 2014 15:47:25.294999924 CET
            Time of last status change: Jan  9, 2014 15:47:25.294999924 CET
        Post-operation IATT
            GFID: f48a3fdd-b857-495e-b31b-2566c7c96718
            ...
            Time of last access: Feb  7, 2106 07:28:15.000000000 CET
            Time of last modification: Jan  9, 2014 15:14:00.000000000 CET
            Time of last status change: Jan  9, 2014 15:47:25.297999976 CET

The SETATTR was a success, and the ATIME + MTIME match what has been
requested. This proves that the problem is not on the brick-side, but on the
GlusterFS-client (CIFS-client, samba, vfs_glusterfs or libgfapi).

The same file.pcap contains the SMB traffic as well. We can see that before
the GlusterFS/SETATTR in Frame 510 is done, there is a SMB/SET_FILE_INFO. In
this frame we can see what the CIFS-client sends to the Samba service:

    Frame: 509
    SMB (Server Message Block Protocol)
        ...
        Trans2 Request (0x32)
            ...
            SET_FILE_INFO Parameters
                FID: 0x3b00
                Level of Interest: Set File Unix Basic (512)
                Reserved: 0000
            SET_FILE_INFO Data
                File size: 18446744073709551615
                Number of bytes: 18446744073709551615
                Last status change: Jan  9, 2014 15:13:59.533861000 CET
                Last access: May 28, 60056 07:36:10.955161500 CEST
                Last modification: Jan  9, 2014 15:13:59.533861000 CET
                UID: 18446744073709551615
                GID: 18446744073709551615
                File type: File (0)
                Major device: 0x0000000000000000
                Minor device: 0x0000000000000000
                Unique ID: 0x0000000000000000
                File permissions: 0xffffffffffffffff
                Num links: 0

    Fram: 521
    SMB (Server Message Block Protocol)
        SMB Header
            Server Component: SMB
            [Response to: 509]
            [Time from request: 0.004667000 seconds]
            SMB Command: Trans2 (0x32)
            NT Status: STATUS_SUCCESS (0x00000000)

To me this suggests that the problem is somewhere in the (samba,
vfs_glusterfs, libgfapi) area. The CIFS-client sends the correct timestamp,
and the GlusterFS-client part of the Samba service sends the wrong timestamp
(that gets set correctly/unmodified on the brick).

Comment 8 Niels de Vos 2014-01-10 12:12:24 UTC
Created attachment 848155 [details]
systemtap script for debugging setting atime and mtime

The actual script used in the previous comment

Comment 9 Niels de Vos 2014-01-10 12:19:55 UTC
For completeness, also the output of the command that were used to generate
the tracing in comment #7:

# touch /mnt/cifs/guest
# stat /mnt/cifs/guest
  File: `/mnt/cifs/guest'
  Size: 0               Blocks: 0          IO Block: 16384  regular empty file
Device: 13h/19d Inode: 9938989981068025034  Links: 1
Access: (0644/-rw-r--r--)  Uid: (   99/  nobody)   Gid: (   99/  nobody)
Access: 2014-01-10 18:09:07.000000000 +0530
Modify: 2014-01-10 18:09:07.000000000 +0530
Change: 2014-01-10 18:09:07.000000000 +0530
# echo hello > /mnt/cifs/guest
# stat /mnt/cifs/guest
  File: `/mnt/cifs/guest'
  Size: 6               Blocks: 1          IO Block: 16384  regular file
Device: 13h/19d Inode: 9938989981068025034  Links: 1
Access: (0644/-rw-r--r--)  Uid: (   99/  nobody)   Gid: (   99/  nobody)
Access: 2106-02-07 11:58:15.000000000 +0530
Modify: 2014-01-10 18:09:21.000000000 +0530
Change: 2014-01-10 18:09:21.000000000 +0530

Comment 10 Niels de Vos 2014-01-10 12:35:33 UTC
In fact, my interpretation from the SMB/SET_FILE_INFO in comment #7 seems to be wrong, the atime is being requested with a weird value:

    Last access: May 28, 60056 07:36:10.955161500 CEST

Maybe it is a CIFS-client (Linux kernel) problem after all!

Comment 11 Niels de Vos 2014-01-10 13:58:53 UTC
Some more debugging/stap'ing shows this when doing a write:

    cifs_fill_unix_set_info: args->atime = -1
    cifs_fill_unix_set_info: args->mtime = 130338374851600000
    vfs_gluster_ntimes: atime->tv_sec=-1
    vfs_gluster_ntimes: atime->tv_nsec=0
    vfs_gluster_ntimes: mtime->tv_sec=1389363885
    vfs_gluster_ntimes: mtime->tv_nsec=0
    glfs_utimens: atime->tv_sec=-1
    glfs_utimens: atime->tv_nsec=0
    glfs_utimens: mtime->tv_sec=1389363885
    glfs_utimens: mtime->tv_nsec=0
    glfs_utimens: atime->tv_sec=-1
    glfs_utimens: atime->tv_nsec=0
    glfs_utimens: mtime->tv_sec=1389363885
    glfs_utimens: mtime->tv_nsec=0

The cifs kernel module really passes -1. This seems to be a define for
NO_CHANGE_64. From fs/cifs/inode.c:

2068         if (attrs->ia_valid & ATTR_ATIME)
2069                 args->atime = cifs_UnixTimeToNT(attrs->ia_atime);
2070         else
2071                 args->atime = NO_CHANGE_64;

So, -1 is a value that instructs Samba/vfs_glusterfs to NOT change the ATIME.
I'll write a patch for the vfs_glusterfs module that fixes this.

Comment 12 Niels de Vos 2014-01-10 15:18:53 UTC
The solution is to modify source3/modules/vfs_glusterfs.c and only set the
MTIME when the ATIME->tv_sec is set to -1:

 669 static int vfs_gluster_ntimes(struct vfs_handle_struct *handle,
 670                               const struct smb_filename *smb_fname,
 671                               struct smb_file_time *ft)
 672 {
 673         struct timespec times[2];
 674  
 675         times[0].tv_sec = ft->atime.tv_sec;
 676         times[0].tv_nsec = ft->atime.tv_nsec;
 677         times[1].tv_sec = ft->mtime.tv_sec;
 678         times[1].tv_nsec = ft->mtime.tv_nsec;
 679  
 680         return glfs_utimens(handle->data, smb_fname->base_name, times);
 681 }

It is very unfortunate that libgfapi does not have a function that can be used
to only set the mtime :-/ The internal glfs_setattr() is not exported (and
neither is the internal 'struct iatt').

The ulgy (but correct) workaround, is to get the atime of the file with
glfs_stat() when it is not set, and use that...

On the other hand, there is little sense in updating the mtime without
modifying the atime too. The practical solution is to use the mtime for the
atime as well, but only in the case the atime->tv_sec is set to -1.

Comment 13 Niels de Vos 2014-01-10 15:38:39 UTC
Created attachment 848259 [details]
Proposed patch, with the idea from comment #12

Comment 22 Pavithra 2014-01-30 06:06:19 UTC
Hi Ira Cooper,

Can you please fill out the doc text for this bug fix?

Comment 23 surabhi 2014-02-03 06:47:31 UTC
Tried the test on following build and verified the BZ:

glusterfs-3.4.0.58rhs-1.el6rhs.x86_64
samba-glusterfs-3.6.9-167.10.el6rhs.x86_64

[root@RHEL6 ~]# cd /mnt/samba/test-vol
[root@RHEL6 test-vol]# touch file1
[root@RHEL6 test-vol]# stat file1
  File: `file1'
  Size: 0         	Blocks: 0          IO Block: 16384  regular empty file
Device: 16h/22d	Inode: 10008377126523535801  Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2014-02-03 01:39:49.000000000 -0500
Modify: 2014-02-03 01:39:49.000000000 -0500
Change: 2014-02-03 01:39:32.000000000 -0500

[root@RHEL6 test-vol]# echo hello > /mnt/samba/test-vol/file1
[root@RHEL6 test-vol]# stat file1
  File: `file1'
  Size: 6         	Blocks: 1          IO Block: 16384  regular file
Device: 16h/22d	Inode: 10008377126523535801  Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2014-02-03 01:41:07.000000000 -0500
Modify: 2014-02-03 01:41:06.000000000 -0500
Change: 2014-02-03 01:41:06.000000000 -0500


Atime gets updated when write happened on a file.
Also verified with the commands like cat,grep,sort,head and tail,whenever the file is getting accessed the atime is getting updated.Verified on both windows and Linux client.Moving the bz to verified.

Comment 24 Pavithra 2014-02-04 05:59:45 UTC
Hi Ira, 

I spoke to Raghavendra Talur and came up with a doc text. can you please verify it for technical accuracy?

Comment 26 errata-xmlrpc 2014-02-25 08:14:44 UTC
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.

http://rhn.redhat.com/errata/RHEA-2014-0208.html


Note You need to log in before you can comment on or make changes to this bug.