Fwd: SMB2 not respecting mtime values

Steve French smfrench at gmail.com
Tue Jan 22 17:53:48 UTC 2019


I could also reproduce this to Samba

"For the non-empty file, mtime is modified despite being set after
the SMB3 WRITE completed."

---------- Forwarded message ---------
From: Jacob Shivers <jshivers at redhat.com>
Date: Tue, Jan 22, 2019 at 11:36 AM
Subject: SMB2 not respecting mtime values
To: <linux-cifs at vger.kernel.org>, Sergio Mazul <smazul at redhat.com>,
Kenneth Dsouza <kdsouza at redhat.com>


Hello All,

Copied files to a SMB2 share, with `# cp -p`, do not retain the mtime
of the source file.
Copying the same file when the share is mounted as a SMBv1.0 share
does retain the mtime of the source file

This is trivial to reproduce and happens when the SMB server is Samba
or a Windows SMB server.

What I have yet to find is if this is a known protocol implementation
issue and/or if Samba is just copying Windows behavior.

I am emailing the list to see if anyone knows if this is a protocol
issue, but if anyone knows if the Samba behavior is just copying
Windows behavior that would be good to known.

Below are my reproducer steps and a short analysis.
Thanks for any input,

Jacob,

### Reproducer steps

# uname -r
5.0.0-0.rc2.git2.1.fc30.x86_64

# tcpdump -s0 -n -i ens3 -w /root/cp_p-testing-$(uname -r).pcap &
# mount //win2k16-dfs2.example.net/greendale /mnt/greendale -o sec=krb5,vers=2.1
# grep greendale /proc/mounts
//win2k16-dfs2.example.net/greendale /mnt/greendale cifs
rw,relatime,vers=2.1,sec=krb5,cache=strict,username=root,uid=0,noforceuid,gid=0,noforcegid,addr=192.168.124.133,file_mode=0755,dir_mode=0755,soft,nounix,serverino,mapposix,rsize=1048576,wsize=1048576,echo_interval=60,actimeo=1
0 0

# touch test_file-{empty,data}
# echo 'hello world' >> test_file-data
# touch -d "2018-10-31" test_file*

# stat test_file*
  File: test_file-data
  Size: 12              Blocks: 8          IO Block: 4096   regular file
Device: fc04h/64516d    Inode: 8410181     Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Context: unconfined_u:object_r:admin_home_t:s0
Access: 2018-10-31 00:00:00.000000000 -0400
Modify: 2018-10-31 00:00:00.000000000 -0400
Change: 2019-01-22 10:48:04.027169240 -0500
 Birth: -
  File: test_file-empty
  Size: 0               Blocks: 0          IO Block: 4096   regular empty file
Device: fc04h/64516d    Inode: 8409328     Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Context: unconfined_u:object_r:admin_home_t:s0
Access: 2018-10-31 00:00:00.000000000 -0400
Modify: 2018-10-31 00:00:00.000000000 -0400
Change: 2019-01-22 10:48:04.027169240 -0500
 Birth: -

# strace -fvttTyyx -s 4096 -o /root/cp_p-test_file-empty-$(uname
-r)-smb2.strace cp -p test_file-empty /mnt/greendale/test_file-empty
# date ; stat /mnt/greendale/test_file-empty
Tue 22 Jan 2019 10:48:46 AM EST
  File: /mnt/greendale/test_file-empty
  Size: 0               Blocks: 0          IO Block: 16384  regular empty file
Device: 2fh/47d Inode: 6755399441164937  Links: 1
Access: (0755/-rwxr-xr-x)  Uid: (    0/    root)   Gid: (    0/    root)
Context: system_u:object_r:cifs_t:s0
Access: 2018-10-31 00:00:00.000000000 -0400
Modify: 2018-10-31 00:00:00.000000000 -0400
Change: 2019-01-22 10:48:40.085169200 -0500
 Birth: -

# strace -fvttTyyx -s 4096 -o /root/cp_p-test_file-data-$(uname
-r)-smb2.strace cp -p test_file-data /mnt/greendale/test_file-data
# date ; stat /mnt/greendale/test_file-data
Tue 22 Jan 2019 10:49:09 AM EST
  File: /mnt/greendale/test_file-data
  Size: 12              Blocks: 1          IO Block: 16384  regular file
Device: 2fh/47d Inode: 4222124650769034  Links: 1
Access: (0755/-rwxr-xr-x)  Uid: (    0/    root)   Gid: (    0/    root)
Context: system_u:object_r:cifs_t:s0
Access: 2019-01-22 10:48:45.245674900 -0500
Modify: 2019-01-22 10:48:45.245674900 -0500
Change: 2019-01-22 10:48:45.245674900 -0500
 Birth: -

# rm -f /mnt/greendale/test_file*

# umount /mnt/greendale

# mount //win2k16-dfs2.example.net/greendale /mnt/greendale -o sec=krb5,vers=1.0

# strace -fvttTyyx -s 4096 -o /root/cp_p-test_file-data-$(uname
-r)-smb.strace cp -p test_file-data /mnt/greendale/test_file-data
# date ; stat /mnt/greendale/test_file-data
Tue 22 Jan 2019 10:50:08 AM EST
  File: /mnt/greendale/test_file-data
  Size: 12              Blocks: 1          IO Block: 16384  regular file
Device: 2fh/47d Inode: 7036874417875593  Links: 1
Access: (0755/-rwxr-xr-x)  Uid: (    0/    root)   Gid: (    0/    root)
Context: system_u:object_r:cifs_t:s0
Access: 2018-10-31 00:00:00.000000000 -0400
Modify: 2018-10-31 00:00:00.000000000 -0400
Change: 2019-01-22 10:50:02.926169200 -0500
 Birth: -

# pkill tcpdump


### SMB2

 o Nanosecond timestamps being set
$ grep utimensat *smb2.strace
cp_p-test_file-data-5.0.0-0.rc2.git2.1.fc30.x86_64-smb2.strace:826
10:49:02.689258 utimensat(4</mnt/greendale/test_file-data>, NULL,
[{tv_sec=1540958400, tv_nsec=0} /* 2018-10-31T00:00:00-0400 */,
{tv_sec=1540958400, tv_nsec=0} /* 2018-10-31T00:00:00-0400 */], 0) = 0
<0.007301>
cp_p-test_file-empty-5.0.0-0.rc2.git2.1.fc30.x86_64-smb2.strace:818
10:48:40.086403 utimensat(4</mnt/greendale/test_file-empty>, NULL,
[{tv_sec=1540958400, tv_nsec=0} /* 2018-10-31T00:00:00-0400 */,
{tv_sec=1540958400, tv_nsec=0} /* 2018-10-31T00:00:00-0400 */], 0) = 0
<0.001168>

 o Attributes being sent over the network.
$ tshark -n -r cp_p-testing-5.0.0-0.rc2.git2.1.fc30.x86_64.pcap -Y
'smb2.cmd==setinfo && smb2.flags.response == 0' -T fields -e
frame.number -e smb2.last_write.time -e smb2.last_access.time -e
smb2.last_change.time -e smb2.msg_id -e smb2.filename -E header=y | tr
'\t' '#' | column -t -s '#'
frame.number  smb2.last_write.time
smb2.last_access.time                smb2.last_change.time
   smb2.msg_id  smb2.filename
285           Oct 31, 2018 00:00:00.000000000 EDT  Oct 31, 2018
00:00:00.000000000 EDT  Jan 22, 2019 10:48:40.085169200 EST  21,22,23
   test_file-empty
392           Oct 31, 2018 00:00:00.000000000 EDT  Oct 31, 2018
00:00:00.000000000 EDT  Jan 22, 2019 10:49:02.688169200 EST  34,35,36
   test_file-data

 o The server returns a 0 status.
$ tshark -n -r cp_p-testing-5.0.0-0.rc2.git2.1.fc30.x86_64.pcap -Y
'smb2.cmd==setinfo && smb2.flags.response == 1' -T fields -e
frame.number -e smb2.nt_status -e smb2.msg_id -E header=y | tr '\t'
'#' | column -t -s '#'
frame.number  smb2.nt_status  smb2.msg_id
286           0,0,0           21,22,23
393           0,0,0           34,35,36

 o For the empty file, mtime is not mtime is not modified.
$ tshark -n -r cp_p-testing-5.0.0-0.rc2.git2.1.fc30.x86_64.pcap -Y
'smb2.cmd==getinfo && smb2.flags.response == 1 && frame.time >
"2019-01-22 10:48:46" && frame.time < "2019-01-22 10:48:47"' -T fields
-e frame.number -e smb2.last_write.time -e smb2.last_access.time -E
header=y | tr '\t' '-' | column -t -s '-'
frame.number  smb2.last_write.time

smb2.last_access.time
315           Oct 31, 2018 00:00:00.000000000 EDT,Oct 31, 2018
00:00:00.000000000 EDT,Dec 31, 1969 19:00:00.000000000 EST  Oct 31,
2018 00:00:00.000000000 EDT,Oct 31, 2018 00:00:00.000000000 EDT,Dec
31, 1969 19:00:00.000000000 EST

 o For the non-empty file, mtime is modified despite being set after
the WRITE completed.
$ tshark -n -r cp_p-testing-5.0.0-0.rc2.git2.1.fc30.x86_64.pcap -Y
'smb2.cmd==getinfo && smb2.flags.response == 1 && frame.time >
"2019-01-22 10:49:09" && frame.time < "2019-01-22 10:49:10"' -T fields
-e frame.number -e smb2.last_write.time -e smb2.last_access.time -E
header=y | tr '\t' '-' | column -t -s '-'
frame.number  smb2.last_write.time

smb2.last_access.time
421           Jan 22, 2019 10:48:45.245674900 EST,Jan 22, 2019
10:48:45.245674900 EST,Dec 31, 1969 19:00:00.000000000 EST  Oct 31,
2018 00:00:00.000000000 EDT,Oct 31, 2018 00:00:00.000000000 EDT,Dec
31, 1969 19:00:00.000000000 EST


### SMB

 o Nanosecond timestamps being set
$ grep utimensat *smb.strace
842   10:50:02.926848 utimensat(4</mnt/greendale/test_file-data>,
NULL, [{tv_sec=1548172142, tv_nsec=687169240} /*
2019-01-22T10:49:02.687169240-0500 */, {tv_sec=1540958400, tv_nsec=0}
/* 2018-10-31T00:00:00-0400 */], 0) = 0 <0.001564>

 o Attributes being sent over the network.
 o The server returns a 0 status.
$ tshark -n -r cp_p-testing-5.0.0-0.rc2.git2.1.fc30.x86_64.pcap -Y
'smb.trans2.cmd == 8' -T fields -e frame.number -e smb.last_write.time
-e smb.access.time -e smb.mid -e smb.nt_status -E header=y | tr '\t'
'#' | column -t -s '#'
frame.number  smb.last_write.time                  smb.access.time
                 smb.mid  smb.nt_status
628           Oct 31, 2018 00:00:00.000000000 EDT  Jan 22, 2019
10:49:02.687169200 EST  17       0
629
                 17       0
630           Dec 31, 1969 19:00:00.000000000 EST  Dec 31, 1969
19:00:00.000000000 EST  18       0
631
                 18       0

 o When using SMBv1.0, mtime is respected.
$ tshark -n -r cp_p-testing-5.0.0-0.rc2.git2.1.fc30.x86_64.pcap -Y
'smb.trans2.cmd == 5 && frame.time >= "2019-01-22 10:50:08"' -T fields
-e frame.number -e smb.last_write.time -e smb.access.time -e smb.mid
-E header=y | tr '\t' '#' | column -t -s '#'
frame.number  smb.last_write.time                  smb.access.time
                 smb.mid
657
                 20
658           Oct 31, 2018 00:00:00.000000000 EDT  Jan 22, 2019
10:49:02.687169200 EST  20


-- 
Thanks,

Steve



More information about the samba-technical mailing list