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.
Created attachment 14455 [details] Work in progress patch Patch from metze from bug #13541
Marking all comments private that are moved to the bug #14157.
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
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.
I think I agree, it is file system dependent so we can just return what we have when requested.
Created attachment 18608 [details] Historic Notes
This bug was referenced in samba master: 560c7359cedc0286f75d4946e755f7925b9c4e45 907f17dda9984dd70af9fd23ab02c21b7c50fbe8 e2ed11e0f7aa9ca73e40483a24c1556df78ce32e 24ae9d6a720656ddbc7d8181069cd3179bab0679 43ed3456d9ba4b90efe07dbaefcf85fff9b538d7 1a02a9ebabe67dc48f96bc9ad3575ef85eabfe3a e60596f48d7d00ca5c7da479d5332de15cb57f06 5bf3a516cab91b91df146095a733686f4861cef7 d75abdc3049e0754d49e71a44e6b8f7e4e0b2a63 344ec3971aedf301b355fcf6ea77ca34196cbbbd 44446d7c556b5c2929485ae3e0c7b1a9c7362735 f64c25c1a9bcc225878825c889b863fa3bb3c473 1e7d56338a30d31565e2500e7723ed825cd9a605 83dba3cabc25a7b058177a79ebeddd8ccbac86f6 141b2ef2769acb92127812a4fc98ec2471b36dea 86cb56eda688934029d4c1fee415c7987a9c18a4 f54b9330e134b40fc6096a5f810540c515b99287 165e9670280c7073b8d94a4feb2b3d98efdf0fda f5faa524a05f91c13dbfbb5dc54d54277f400743 6bc1ffe8d57927eb9ff2a0b95caf973866b6bbae e118fe5e8b228d0e2fdb945d18d0e0570b8d3476 47075041d85500dee7315d12d8d5a034414f2f16 28804006da477c6ce30a8cd839ad6ec5ecf49a35 76899e3c0c0dd5e73219bf3d1ff1f0eec67af052 bed764ac8059823b9a0d6f19e3e4990594f86017 b78202327fad0b9e2fb23d1aa383e6954757db81 0635966c325efd751ef9dbe12186998e1e28a28d b6c8d5d82917b2601b566039dbfc6cad045c917a
Fixed in 4.23.