I finally got around to making some time for this and I this is indeed
a server side issue.
The SMB client is using the appropriate file handles when setting
atime and mtime and the server initially reports the desired mtime.
The server only slightly later reports a mtime matching that of ctime.
$ tshark -tad -n -r cp_p-testing-3.16.66.pcap -Y 'smb2.pid == 0xf2d'
-T fields -e frame.number -e smb2.fid -e smb2.last_access.time -e
smb2.last_write.time -e _ws.col.Info -E header=y | tr '\t' '#' |
column -t -s '#'
frame.number smb2.fid
smb2.last_access.time smb2.last_write.time
_ws.col.Info
170
Create Request
File: test_file-data
171
Create
Response, Error: STATUS_OBJECT_NAME_NOT_FOUND
173 00000000-0000-0000-0000-000000000000
Create Request
File: test_file-data
174 5981ad82-0000-0000-1d86-2dcf00000000 May 27, 2019
20:16:03.862513400 EDT May 27, 2019 20:16:03.862513400 EDT Create
Response File: test_file-data
175 5981ad82-0000-0000-1d86-2dcf00000000
GetInfo Request
FILE_INFO/SMB2_FILE_INTERNAL_INFO File: test_file-data
176
GetInfo
Response
177 5981ad82-0000-0000-1d86-2dcf00000000
Write Request
Len:12 Off:0 File: test_file-data
178
Write Response
179
Create Request
File: test_file-data
180 b8fa5b2d-0000-0000-d86e-38bf00000000 May 27, 2019
20:16:03.862513400 EDT May 27, 2019 20:16:03.862513400 EDT Create
Response File: test_file-data
181 b8fa5b2d-0000-0000-d86e-38bf00000000 Oct 31, 2018
00:00:00.000000000 EDT Oct 31, 2018 00:00:00.000000000 EDT SetInfo
Request FILE_INFO/SMB2_FILE_BASIC_INFO File: test_file-data
182
SetInfo
Response
183 b8fa5b2d-0000-0000-d86e-38bf00000000
Close Request
File: test_file-data
184 Dec 31, 1969
19:00:00.000000000 EST Dec 31, 1969 19:00:00.000000000 EST Close
Response
185
Create Request
File: test_file-data
186 f7323833-0000-0000-5d04-6e1d00000000 Oct 31, 2018
00:00:00.000000000 EDT Oct 31, 2018 00:00:00.000000000 EDT Create
Response File: test_file-data
187 f7323833-0000-0000-5d04-6e1d00000000 Dec 31, 1969
19:00:00.000000000 EST Dec 31, 1969 19:00:00.000000000 EST SetInfo
Request FILE_INFO/SMB2_FILE_BASIC_INFO File: test_file-data
188
SetInfo
Response
189 f7323833-0000-0000-5d04-6e1d00000000
Close Request
File: test_file-data
190 Dec 31, 1969
19:00:00.000000000 EST Dec 31, 1969 19:00:00.000000000 EST Close
Response
191 5981ad82-0000-0000-1d86-2dcf00000000
Close Request
File: test_file-data
192 Dec 31, 1969
19:00:00.000000000 EST Dec 31, 1969 19:00:00.000000000 EST Close
Response
$ tshark -tad -n -r cp_p-testing-3.16.66.pcap -Y 'smb2.cmd == find' -O
smb2 | sed '/test_file-data/,/test_file-data/ !d'
FileIdBothDirectoryInfo: test_file-data
Next Offset: 0
File Index: 0x00000000
Create: May 27, 2019 20:16:03.862513400 EDT
Last Access: Oct 31, 2018 00:00:00.000000000 EDT
Last Write: May 27, 2019 20:16:03.872393500 EDT
Last Change: May 27, 2019 20:16:03.872393500 EDT
End Of File: 12
Allocation Size: 1048576
File Attributes: 0x00000020
.... .... .... .... .... .... .... ...0 = Read
Only: NOT read only
.... .... .... .... .... .... .... ..0. = Hidden: NOT hidden
.... .... .... .... .... .... .... .0.. = System:
NOT a system file/dir
.... .... .... .... .... .... .... 0... = Volume
ID: NOT a volume ID
.... .... .... .... .... .... ...0 .... =
Directory: NOT a directory
.... .... .... .... .... .... ..1. .... = Archive:
Modified since last ARCHIVE
.... .... .... .... .... .... .0.. .... = Device:
NOT a device
.... .... .... .... .... .... 0... .... = Normal:
Has some attribute set
.... .... .... .... .... ...0 .... .... =
Temporary: NOT a temporary file
.... .... .... .... .... ..0. .... .... = Sparse:
NOT a sparse file
.... .... .... .... .... .0.. .... .... = Reparse
Point: Does NOT have an associated reparse point
.... .... .... .... .... 0... .... .... =
Compressed: Uncompressed
.... .... .... .... ...0 .... .... .... = Offline: Online
.... .... .... .... ..0. .... .... .... = Content
Indexed: NOT content indexed
.... .... .... .... .0.. .... .... .... =
Encrypted: This is NOT an encrypted file
Filename Length: 28
EA Size: 60
Reserved: 00000000
File Id: 0x0000000000052b02
Filename: test_file-data
I've added additional notes, strace, and pcap data to both kenel and
samba bugzillas that seem applicable to this:
** Bug 198967 - Modification times not preserved correctly **
https://bugzilla.kernel.org/show_bug.cgi?id=198967
** Bug 13594 - smbd write time handling differs compared to recent
Windows releases **
https://bugzilla.samba.org/show_bug.cgi?id=13594
The earlier comments about filehandle do not apply as the atime used
the same filehandle and the filehandle used is what should be used for
compound operations.
For context, Samba is matching behavior in Windows 2k16.
On Thu, Jan 24, 2019 at 5:49 PM Jeremy Allison <jra@xxxxxxxxx> wrote:
>
> On Thu, Jan 24, 2019 at 05:47:24PM -0500, Jacob Shivers wrote:
> > On Thu, Jan 24, 2019 at 3:14 PM Ralph Böhme <slow@xxxxxxxxx> wrote:
> > >
> > > On Thu, Jan 24, 2019 at 12:24:53PM -0500, Jacob Shivers wrote:
> > > >On Thu, Jan 24, 2019 at 12:11 PM Ralph Böhme via samba-technical
> > > ><samba-technical@xxxxxxxxxxxxxxx> wrote:
> > > >>
> > > >> On Thu, Jan 24, 2019 at 09:03:41AM -0800, Jeremy Allison via samba-technical wrote:
> > > >> >Maybe. Changing meta-data semantics on write is fraught with danger,
> > > >> >and we don't even do that for SMB1 unix extensions. So let's not
> > > >> >add contraints we don't understand yet please.
> > > >> >
> > > >> >My money is on a client bug, as always :-).
> > > >>
> > > >> fwiw, just in case you were not aware of this one:
> > > >>
> > > >> https://bugzilla.samba.org/show_bug.cgi?id=13594
> > > >>
> > > >> We also seem to have a bug that a set-eof on a handle with
> > > >> set-eof-size=existing-size doesn't flush a pending write time update. At least
> > > >> newer Windows server seem to do that.
> > > >
> > > >This seems like what the issue is.
> > > >The SMB server is uptime mtime after the server actually flushes to
> > > >stable storage.
> > >
> > > not quite, but still a client bug. :) The client uses a second handle to set the
> > > mtime, it should use the first handle. Or open the second handle after closing
> > > the first one where it did the write.
> >
> > Ahh.
> >
> > Thank you very much for your help and for narrowing down the problem
> > to a client side bug :)
>
> Bingo ! I claim my 5 euro :-) :-).
