Bug 13594 - smbd write time handling differs compared to recent Windows releases
Summary: smbd write time handling differs compared to recent Windows releases
Status: ASSIGNED
Alias: None
Product: Samba 4.1 and newer
Classification: Unclassified
Component: File services (show other bugs)
Version: unspecified
Hardware: All All
: P5 normal (vote)
Target Milestone: ---
Assignee: Ralph Böhme
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-08-30 21:35 UTC by Ralph Böhme
Modified: 2020-02-10 01:28 UTC (History)
9 users (show)

See Also:


Attachments
Work in progress patch (645.45 KB, patch)
2018-08-30 21:39 UTC, Ralph Böhme
no flags Details
win2k16 strace+pcap data (22.17 KB, application/gzip)
2019-06-12 16:08 UTC, Jacob Shivers
no flags Details
samba strace+pcap data (57.79 KB, application/gzip)
2019-06-12 16:08 UTC, Jacob Shivers
no flags Details
notes (4.75 KB, application/gzip)
2019-06-12 16:08 UTC, Jacob Shivers
no flags Details
win2k19 strace and pcap data (19.07 KB, application/gzip)
2019-06-25 04:35 UTC, Jacob Shivers
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Ralph Böhme 2018-08-30 21:35:08 UTC
From metze from bug #13541:

It turns out that our write time update handling differs compared to
recent Windows releases.

We basically implement the behavior of Windows 2000:

- The only write time update happens ~2 seconds after
  the first write.
- If the handle was written the close will trigger
  a 2nd write time update.

Both updates use the current timestamp.

Windows >= 2008R2 behaves differently:
(Actually I don't know when the behavior changed,
I guess with 2008, as SMB2 was introduced):

Behavior without SMB1 Query Path Info:
- Write time updates are deferred up to 4 seconds
  after a write. Once the time is updated, the timer
  will be re-scheduled by the next write.
- Close only updates the write time if a pending
  update is still pending.
All updates use the current timestamp.

Additional behavior with SMB1 Query Path Info:
- If an SMB1 Query Path Info is processed
  Any pending timer on all open handles
  are removed. And no new timers are every scheduled
  on these handles.
- The only write time update will happen on close (to the current time).

I think we better implement the new behavior, as this is what all
Windows SMB2 enabled servers provide, even over SMB1.
First I was confused by the difference between the protocol,
but once I removed the SMB1 query path info calls from
the tests, SMB1 and SMB2 behaved in the same way for pure
handle based access.
Comment 1 Ralph Böhme 2018-08-30 21:39:28 UTC
Created attachment 14455 [details]
Work in progress patch

Patch from metze from bug #13541
Comment 9 Ralph Böhme 2019-10-10 13:50:04 UTC
Marking all comments private that are moved to the bug #14157.
Comment 10 Ralph Böhme 2019-10-10 14:56:02 UTC
It's worse. Windows 2019 mtime update behaviour is bizarre.

Setup
=====

Testcode: <https://git.samba.org/?p=slow/samba.git;a=shortlog;h=refs/heads/write-time>
SMB1 test: "base.delaywrite.delayed update of write time loop" (hardcoded delay of 0)
SMB2 test: smb2.delaywrite.delayed-write2 --option=torture:delay_ms=X

Servers:
* Windows 2003 R2:	172.18.103.94
* Windows 7:   		172.18.103.129
* Windows 2008 R1:	172.18.103.81
* Windows 2016:		172.18.103.204
* Windows 2019:		192.168.122.99

SMB1
====

Windows 2003 R2
---------------

* one delayed mtime update
* no subsequent updates
* update on close when delayed update pending

Initial write time Wed Oct  9 13:31:37 2019 CEST
Server updated write_time after 4.65 seconds (correct)

Windows 7
---------

* delayed update every 2 s on avg, can be only 0.8 s and up to 3 s
* update on close when delayed update pending

Initial write time Wed Oct  9 13:35:31 2019 CEST
Server updated write_time after 2.97 seconds (correct)
Server updated write_time after 1.57 seconds (correct)
Server updated write_time after 2.01 seconds (correct)
Server updated write_time after 2.00 seconds (correct)
Server updated write_time after 2.00 seconds (correct)
Server updated write_time after 1.85 seconds (correct)
Server updated write_time after 1.99 seconds (correct)
Server updated write_time after 2.00 seconds (correct)
Server updated write_time after 0.88 seconds (correct)
Server updated write_time after 2.00 seconds (correct)

Windows 2016
------------

* delayed update every 1.3 s on avg
* update on close when delayed update pending

Initial write time Wed Oct  9 14:18:58 2019 CEST
Server updated write_time after 0.21 seconds (correct)
Server updated write_time after 1.48 seconds (correct)
Server updated write_time after 1.32 seconds (correct)
Server updated write_time after 1.32 seconds (correct)
Server updated write_time after 1.30 seconds (correct)
Server updated write_time after 1.30 seconds (correct)
Server updated write_time after 1.30 seconds (correct)
Server updated write_time after 1.32 seconds (correct)
Server updated write_time after 1.32 seconds (correct)
Server updated write_time after 1.30 seconds (correct)

SMB2
====

Windows 7
---------

--option=torture:delay_ms=1000

Using delay of 0 ms
Server updated write_time after 0.605584 s
Server updated write_time after 1.967016 s
Server updated write_time after 2.118526 s
Server updated write_time after 1.966535 s
Server updated write_time after 1.966680 s
Server updated write_time after 1.967038 s
Server updated write_time after 1.966066 s
Server updated write_time after 2.117810 s
Server updated write_time after 1.966421 s
Server updated write_time after 1.966136 s

Windows 2008 R1
---------------

--option=torture:delay_ms=0

Using delay of 0 ms
Server updated write_time after 0.908788 s
Server updated write_time after 1.815782 s
Server updated write_time after 1.967364 s
Server updated write_time after 2.119486 s
Server updated write_time after 1.967551 s
Server updated write_time after 1.967161 s
Server updated write_time after 1.967556 s
Server updated write_time after 1.072425 s
Server updated write_time after 1.968118 s
Server updated write_time after 1.966277 s

Windows 2016
------------

* strange behaviour, depends on time between create/IO and getinfo
  threshold is between 900-1000ms for the delay

* below the threshold the mtime isn't updated when queried with SMB2 GETINFO,
  only the final close updates mtime

* above the threshold write IO always triggers an delayed update. The first
  mtime query after the write IO is done after 900 ms, but the mtime gets
  updated a bit later, ~1.3 s after the write IO

--option=torture:delay_ms=900

Using delay of 900 ms
No update within 10 s
No update within 10 s
No update within 10 s
No update within 10 s
No update within 10 s
No update within 10 s
No update within 10 s
No update within 10 s
No update within 10 s
No update within 10 s

--option=torture:delay_ms=1000

Using delay of 1000 ms
Server updated write_time after 2.060728 s
Server updated write_time after 1.304737 s
Server updated write_time after 1.304404 s
Server updated write_time after 1.304762 s
Server updated write_time after 1.456069 s
Server updated write_time after 1.455422 s
Server updated write_time after 1.304588 s
Server updated write_time after 1.455730 s
Server updated write_time after 1.304448 s
Server updated write_time after 1.455462 s

Windows 2019
------------

* strange behaviour: depends on time between write IO and querying mtime.
  Threshold is between 0 ms and 15 ms for the time between write IO and querying mtime

* below the threshold the mtime is updated immediately after every second write IO

* if the last IO didn't trigger an mtime update, then also the close doesn't
  update it (!)

* above the threshold every write IO triggers immediate mtime update

* bottom line: querying mtime too early after write IO prevents mtime
  updates. This applies to every second write IO.

--option=torture:delay_ms=0

Using delay of 0 ms
No update within 10 s
Server updated write_time after 0.000638 s
No update within 10 s
Server updated write_time after 0.000496 s
No update within 10 s
Server updated write_time after 0.000559 s
No update within 10 s
Server updated write_time after 0.000627 s
No update within 10 s
Server updated write_time after 0.000782 s
No update within 10 s

--option=torture:delay_ms=15

Using delay of 15 ms
Server updated write_time after 0.015542 s
Server updated write_time after 0.016005 s
Server updated write_time after 0.015416 s
Server updated write_time after 0.016130 s
Server updated write_time after 0.015710 s
Server updated write_time after 0.016943 s
Server updated write_time after 0.015579 s
Server updated write_time after 0.016992 s
Server updated write_time after 0.015489 s
Server updated write_time after 0.016931 s

Samba SMB 1+2
=============

* one delayed mtime update
* no subsequent updates
* update on close when delayed update pending
* same as Windows 2003 R2 behaviour
Comment 11 Ralph Böhme 2019-12-19 10:00:44 UTC
Dochelp:

https://lists.samba.org/archive/cifs-protocol/2019-November/003341.html
https://lists.samba.org/archive/cifs-protocol/2019-November/003340.html

In the light of that, I guess we can simply remove the whole "delayed" magic and simply expose the timestamp from the fs.