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. =============================================================
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 -------------------------------------------------------------------------------
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).
Created attachment 848155 [details] systemtap script for debugging setting atime and mtime The actual script used in the previous comment
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
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!
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.
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.
Created attachment 848259 [details] Proposed patch, with the idea from comment #12
Hi Ira Cooper, Can you please fill out the doc text for this bug fix?
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.
Hi Ira, I spoke to Raghavendra Talur and came up with a doc text. can you please verify it for technical accuracy?
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