microsoft / WSL

Issues found on WSL
https://docs.microsoft.com/windows/wsl
MIT License
17.23k stars 808 forks source link

clock skew in `wsl2` #11790

Open surfacepatterns opened 1 month ago

surfacepatterns commented 1 month ago

Windows Version

Microsoft Windows [Version 10.0.22631.3737]

WSL Version

2.2.4.0

Are you using WSL 1 or WSL 2?

Kernel Version

5.15.153.1-2

Distro Version

CBL-Mariner 2.0.20240628

Other Software

No response

Repro Steps

  1. Start the Linux instance.
  2. Do various things in the wsl instance.
  3. Observe that, occasionally, you get error messages regarding timestamps in the future, and detection of clock skew. Sometimes, depending on the task, clock skew occurs often enough that you can't complete the task (e.g. building RPMs wherein the tests rely on file modification times that end up appearing to be in the future).

Expected Behavior

I expect to observe clock skew quite rarely, and to have it impact my work on a much less frequent basis.

Actual Behavior

Here are a couple examples.

dmesg output

[danderson: /tmp/tmpawdfb76t]
> dmesg | tail -n 40
[404082.973889] systemd-journald[84]: Time jumped backwards, rotating.
[404111.348115] systemd-journald[84]: Time jumped backwards, rotating.
[404139.703269] systemd-journald[84]: Time jumped backwards, rotating.
[404168.096403] systemd-journald[84]: Time jumped backwards, rotating.
[404196.480773] systemd-journald[84]: Time jumped backwards, rotating.
[404224.872429] systemd-journald[84]: Time jumped backwards, rotating.
[404253.223833] systemd-journald[84]: Time jumped backwards, rotating.
[404281.594155] systemd-journald[84]: Time jumped backwards, rotating.
[404309.968480] systemd-journald[84]: Time jumped backwards, rotating.
[404338.363311] systemd-journald[84]: Time jumped backwards, rotating.
[404366.732147] systemd-journald[84]: Time jumped backwards, rotating.
[404395.108002] systemd-journald[84]: Time jumped backwards, rotating.
[404423.480880] systemd-journald[84]: Time jumped backwards, rotating.
[404451.831353] systemd-journald[84]: Time jumped backwards, rotating.
[404480.194392] systemd-journald[84]: Time jumped backwards, rotating.
[404508.549149] systemd-journald[84]: Time jumped backwards, rotating.
[404536.920285] systemd-journald[84]: Time jumped backwards, rotating.
[404565.283479] systemd-journald[84]: Time jumped backwards, rotating.
[404593.654135] systemd-journald[84]: Time jumped backwards, rotating.
[404622.024996] systemd-journald[84]: Time jumped backwards, rotating.
[404650.397592] systemd-journald[84]: Time jumped backwards, rotating.
[404678.775581] systemd-journald[84]: Time jumped backwards, rotating.
[404707.127293] systemd-journald[84]: Time jumped backwards, rotating.
[404735.490979] systemd-journald[84]: Time jumped backwards, rotating.
[404763.840208] systemd-journald[84]: Time jumped backwards, rotating.
[404792.189098] systemd-journald[84]: Time jumped backwards, rotating.
[404820.536595] systemd-journald[84]: Time jumped backwards, rotating.
[404848.904155] systemd-journald[84]: Time jumped backwards, rotating.
[404877.268762] systemd-journald[84]: Time jumped backwards, rotating.
[404905.630039] systemd-journald[84]: Time jumped backwards, rotating.
[404933.999577] systemd-journald[84]: Time jumped backwards, rotating.
[404962.374937] systemd-journald[84]: Time jumped backwards, rotating.
[404990.729142] systemd-journald[84]: Time jumped backwards, rotating.
[405019.091547] systemd-journald[84]: Time jumped backwards, rotating.
[405047.445148] systemd-journald[84]: Time jumped backwards, rotating.
[405075.793623] systemd-journald[84]: Time jumped backwards, rotating.
[405104.138690] systemd-journald[84]: Time jumped backwards, rotating.
[405132.488783] systemd-journald[84]: Time jumped backwards, rotating.
[405160.846706] systemd-journald[84]: Time jumped backwards, rotating.
[405189.185044] systemd-journald[84]: Time jumped backwards, rotating.

Partial (relevant) output when meson tests fail, which are run as part of building binary RPMs:

Traceback (most recent call last):
  File "/builddir/build/BUILD/meson-1.3.1/meson.py", line 40, in <module>
    sys.exit(mesonmain.main())
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/mesonmain.py", line 294, in main
    return run(sys.argv[1:], launcher)
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/mesonmain.py", line 280, in run
    return errorhandler(e, 'setup')
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/mesonmain.py", line 40, in errorhandler
    raise e
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/mesonmain.py", line 278, in run
    return msetup.run(['--reconfigure'] + args[2:])
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/msetup.py", line 358, in run
    app.generate()
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/msetup.py", line 181, in generate
    return self._generate(env, capture, vslite_ctx)
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/msetup.py", line 251, in _generate
    captured_compile_args = intr.backend.generate(capture, vslite_ctx)
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/backend/ninjabackend.py", line 657, in generate
    self.generate_ending()
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/backend/ninjabackend.py", line 3679, in generate_ending
    deps = self.get_regen_filelist()
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/backend/backends.py", line 1353, in get_regen_filelist
    self.check_clock_skew(deps)
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/backend/backends.py", line 1380, in check_clock_skew
    raise MesonException(f'Clock skew detected. File {absf} has a time stamp {delta:.4f}s in the future.')
mesonbuild.utils.core.MesonException: Clock skew detected. File /builddir/build/BUILD/meson-1.3.1/b 41766a13e6/../test cases/common/22 object extraction/meson.build has a time stamp 0.2633s in the future.
ninja: error: rebuilding 'build.ninja': subcommand failed

(In the build log this excerpt is from, there were 32 such clock skew failures. I've tried building this package five times today, and each instance results in a similar amount of failures.)

Note that I've seen the issues about clock skew after sleeping. A few things make me think this is different:

  1. I'm running a version of WSL that should have the fix for that issue.
  2. I observe these issues right after restarting my computer, prior to the computer sleeping.
  3. Running sudo hwclock -s doesn't seem to change anything.

Diagnostic Logs

No response

github-actions[bot] commented 1 month ago

Logs are required for review from WSL team

If this a feature request, please reply with '/feature'. If this is a question, reply with '/question'. Otherwise please attach logs by following the instructions below, your issue will not be reviewed unless they are added. These logs will help us understand what is going on in your machine.

How to collect WSL logs Download and execute [collect-wsl-logs.ps1](https://github.com/Microsoft/WSL/blob/master/diagnostics/collect-wsl-logs.ps1) in an **administrative powershell prompt**: ``` Invoke-WebRequest -UseBasicParsing "https://raw.githubusercontent.com/microsoft/WSL/master/diagnostics/collect-wsl-logs.ps1" -OutFile collect-wsl-logs.ps1 Set-ExecutionPolicy Bypass -Scope Process -Force .\collect-wsl-logs.ps1 ``` The scipt will output the path of the log file once done. Once completed please upload the output files to this Github issue. [Click here for more info on logging](https://github.com/microsoft/WSL/blob/master/CONTRIBUTING.md#8-collect-wsl-logs-recommended-method) If you choose to email these logs instead of attaching to the bug, please send them to wsl-gh-logs@microsoft.com with the number of the github issue in the subject, and in the message a link to your comment in the github issue and reply with '/emailed-logs'.

View similar issues

Please view the issues below to see if they solve your problem, and if the issue describes your problem please consider closing this one and thumbs upping the other issue to help us prioritize it!

Closed similar issues:

Note: You can give me feedback by thumbs upping or thumbs downing this comment.

surfacepatterns commented 1 month ago

WslLogs-2024-07-17_16-35-07.zip

github-actions[bot] commented 1 month ago
Diagnostic information ``` Detected appx version: 2.2.4.0 ```
surfacepatterns commented 1 month ago

So, it seems like wsl, or something wsl is dependent upon, get's in a bad state sometimes. Right now, after waking up from sleep, the issue isn't happening:

[danderson: /tmp/tmpawdfb76t]
> dmesg | tail -n 5
[456589.205091] hv_utils: TimeSync IC version 4.0
[456665.948959] mini_init (176): drop_caches: 1
[459550.465849] mini_init (176): drop_caches: 1
[459640.326553] mini_init (176): drop_caches: 1
[459910.870860] mini_init (176): drop_caches: 1

I'm going to continue monitoring the system, and try to identify what happens around the time that the issue starts.