[Bug 53171] New: advapi32:registry - test_performance_keys() sometimes fails due to time going backwards!
https://bugs.winehq.org/show_bug.cgi?id=53171
Bug ID: 53171 Summary: advapi32:registry - test_performance_keys() sometimes fails due to time going backwards! Product: Wine Version: unspecified Hardware: x86-64 OS: Windows Status: NEW Severity: normal Priority: P2 Component: advapi32 Assignee: wine-bugs@winehq.org Reporter: fgouget@codeweavers.com
advapi32:registry - test_performance_keys() sometimes fails due to time going backwards:
registry.c:3757: Test failed: key FFFFFFFF80000004: value (null): got times 132999520626290092, 132999520626290092, 132967560392269933 registry.c:3763: Test failed: key FFFFFFFF80000004: value (null): got times 132999520626290092, 132999520626290000, 132967560392269933
https://test.winehq.org/data/patterns.html#advapi32:registry
This failure is pretty rate: I only found 4 cases (~0.9%): win2009_newtb-w1064-tsign, win21H1_newtb-w10pro64-mx-MX, 2x win21H2_fgtb-w10pro64.
The failure lines above happened on w10pro64-mx-MX on 2022-06-17. Here are the corresponding timestamps:
systime1 = 132999520626290092 = 2022-06-17 15:07:42.629009 file_time = 132999520626290000 = 2022-06-17 15:07:42.629000 systime2 = 132967560392269933 = 2022-05-11 15:20:39.226993
file_time is a little lower than systime1 which is normal due to its granularity.
What is totally wrong however is that systime2 is way lower than systime1. The interesting part is that the live snapshot was created on 2022-05-11 which matches systime2. This scenario is confirmed it two of the other instances; the snapshot creation time for the last case is unknown but a match with systime2 is plausible.
After restoring the VM from the live snapshot LibvirtTool sets the VM time through TestAgent::SetTime(): https://gitlab.winehq.org/winehq/tools/-/blob/master/testbot/bin/LibvirtTool... https://gitlab.winehq.org/winehq/tools/-/blob/master/testbot/src/testagentd/...
So it looks like in rare cases the system time gets reset backwards precisely between this test's two NtQuerySystemTime() calls, which is really unlucky... or lucky: maybe it happens in other cases causing less obvious failures.
I don't know if TestAgentd sets the time wrong, if there's something wrong with Windows, or if this is an artifact of the QEmu clocks:
<clock offset='localtime'> <timer name='rtc' tickpolicy='delay'/> <timer name='pit' tickpolicy='delay'/> <timer name='hpet' present='yes'/> <timer name='hypervclock' present='yes'/> </clock>
https://bugs.winehq.org/show_bug.cgi?id=53171
François Gouget fgouget@codeweavers.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Keywords| |source, testcase
https://bugs.winehq.org/show_bug.cgi?id=53171
--- Comment #1 from François Gouget fgouget@codeweavers.com --- The failure can also happen when querying HKEY_PERFORMANCE_TEXT (0x80000050) instead of HKEY_PERFORMANCE_DATA (0x80000004).
https://bugs.winehq.org/show_bug.cgi?id=53171
François Gouget fgouget@codeweavers.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Resolution|--- |FIXED Status|NEW |RESOLVED
--- Comment #2 from François Gouget fgouget@codeweavers.com --- I suspect this was caused by Windows' Secure Time Seeding: https://arstechnica.com/security/2023/08/windows-feature-that-resets-system-...
To summarize the article, w32time tries to defend against dead CMOS clock batteries and bad BIOSes messing the clock by using the time from the ServerUnixTime field of various SSL connections to compute a 'high probability' time interval and reset the computer's time if it is not in that interval. However w32time sometimes guesses wrong, thus setting the time back or forward by hours or days. This may be compounded by OpenSSL putting random data in that field since 2014 so w32time is getting less reliable data from it.
One can check Windows' guess as to the plausible time range in the following registry key: [HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\W32Time\SecureTimeLimits] See SecureTimeEstimated, SecureTimeHigh, SecureTimeLow, RunTime\SecureTimeConfidence
It's not clear if w32time initiates SSL connections itself, to which hosts, or somehow gets information some other way. In any case building the range may take a bit of time which could explain why this happens during a test rather than immediately on startup.
In any case, if this is the issue, a workaround would be to set the following registry value:
[HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\w32time\Config] UtilizeSslTimeData = 0
But then the TestBot has been disabling w32time entirely since December 2022 (the VMs were updated over a couple of weeks) which should also avoid this issue entirely. Indeed this issue does not seem to have happened in the past 8 months (so going back to 2022-12-16).
So I think this can be considered to be fixed.
https://bugs.winehq.org/show_bug.cgi?id=53171
Alexandre Julliard julliard@winehq.org changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|RESOLVED |CLOSED
--- Comment #3 from Alexandre Julliard julliard@winehq.org --- Closing bugs fixed in 8.14.
-
WineHQ Bugzilla