qa: Intermittent failure in `wallet_encryption.py --descriptors` #25482

https://cirrus-ci.com/task/4615142003441664

<details><summary>log excerpt</summary> <p>

177/244 - wallet_encryption.py --descriptors failed, Duration: 6 s

stdout:
2022-06-27T07:50:03.095000Z TestFramework (INFO): Initializing test directory C:\Users\ContainerAdministrator\AppData\Local\Temp\test_runner_₿_🏃_20220627_071202\wallet_encryption_65

2022-06-27T07:50:08.820000Z TestFramework (INFO): Check a timeout less than the limit

2022-06-27T07:50:09.007000Z TestFramework (ERROR): Assertion failed

Traceback (most recent call last):

  File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\test_framework\test_framework.py", line 133, in main

    self.run_test()

  File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\wallet_encryption.py", line 85, in run_test

    assert_greater_than(expected_time_with_buffer, actual_time)

  File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\test_framework\util.py", line 56, in assert_greater_than

    raise AssertionError("%s <= %s" % (str(thing1), str(thing2)))

AssertionError: 1756315608.992383 <= 1756315609

2022-06-27T07:50:09.070000Z TestFramework (INFO): Stopping nodes

2022-06-27T07:50:09.211000Z TestFramework (WARNING): Not cleaning up dir C:\Users\ContainerAdministrator\AppData\Local\Temp\test_runner_₿_🏃_20220627_071202\wallet_encryption_65

2022-06-27T07:50:09.211000Z TestFramework (ERROR): Test failed. Test logging available at C:\Users\ContainerAdministrator\AppData\Local\Temp\test_runner_₿_🏃_20220627_071202\wallet_encryption_65/test_framework.log

2022-06-27T07:50:09.211000Z TestFramework (ERROR): 

2022-06-27T07:50:09.211000Z TestFramework (ERROR): Hint: Call C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\combine_logs.py 'C:\Users\ContainerAdministrator\AppData\Local\Temp\test_runner_₿_🏃_20220627_071202\wallet_encryption_65' to consolidate all logs

2022-06-27T07:50:09.211000Z TestFramework (ERROR): 

2022-06-27T07:50:09.211000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.

2022-06-27T07:50:09.211000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues

2022-06-27T07:50:09.211000Z TestFramework (ERROR): 

</p> </details>

See #25021

Couldn't reproduce locally, ran just fine on Mac OS M1

I could reproduce this locally on my laptop: Windows 10, V21H2, built with MS Visual Studio Community 2022 V17.2.6, Python 3.10.5. The test failed for me 6 times over 1000 runs. I'll try to investigate further.

Nice, can you try if this was caused by 0000a63689036dc4368d04c0648a55fdf507932f (switch from time() -> std::chrono)?

Also, you might be able to reproduce more often if you determine the duration of the rpc and try to delay the test so that it more often ends in the "bug range" of ".99":

while time.time() % 1 < 0.98 - rpc_dur : pass

Also, you might be able to reproduce more often if you determine the duration of the rpc and try to delay the test so that it more often ends in the "bug range" of ".99":

Great idea, that worked to make it fail more often.

Nice, can you try if this was caused by 0000a63 (switch from time() -> std::chrono)?

I did this by reintroducing the old code as int64_t GetTimeLegacy() on top of master and when I use it in encrypt.cpp instead of the new GetTime() the test didn't fail anymore. Then I logged both GetTime() and GetTimeLegacy() at this spot, and confirmed that GetTime(), although executed first, is bigger by 1 in runs where the test fails.

So it does seem that on msvc, the std::chrono time deviates slightly from time() (by ~0.005s) - and the python clock, which seems to coincide with time().

So it does seem that on msvc, the std::chrono time deviates slightly from time() (by ~0.005s) - and the python clock, which seems to coincide with time().

That's both shocking and funny. :smiling_face_with_tear:

cc @sipsorcery

To clarify, the following code would print a negative value?

#include <chrono>
#include <iostream>

using SecondsDouble =
    std::chrono::duration<double, std::chrono::seconds::period>;

int main() {
    const int64_t start{time(nullptr)};
    int64_t run{start};
    while (start == run) {
        run = time(nullptr);
    }
    const SecondsDouble start_dbl{
        std::chrono::system_clock::now().time_since_epoch()};
    std::cout << start_dbl.count() - run << std::endl;
}

To clarify, the following code would print a negative value?

No, it prints a (small) positive value. Since the std::chrono time is larger than time(), this is expected?

I guess I got it backward. So the following would print -1s, instead of a small negative value, or 0?

(Edit: Needs C++20)

#include <chrono>
#include <iostream>

auto Now() { return std::chrono::system_clock::now().time_since_epoch(); }

auto FloorS(auto dur) {
    return std::chrono::duration_cast<std::chrono::seconds>(dur);
}

int main() {
    const auto start{Now()};
    auto run{start};
    while (FloorS(start) == FloorS(run)) {
        run = Now();
    }
    const int64_t end{time(nullptr)};
    std::cout << (std::chrono::seconds(end) - run) << std::endl;
}

It prints -10000000[1/10000000]s I'd assume that's equivalent to -1s, if I instead use std::chrono::seconds(end) - FloorS(run) in the cout statement, it actually prints -1s.

I was thinking that this could be fixed by translating the time_t time to std::chrono time with from_time_t, but no success. Funnily, on godbolt msvc is "fine", but gcc and clang "fail": https://godbolt.org/z/dT8r3n911 .

Locally on my Linux the clocks are off by 1 millisecond.

For the functional tests on Linux, it doesn't matter that there is an offset between time_t and std::chrono, because (at least on my machine) both Python time.time(), as well as std::chrono use clock_gettime, see https://github.com/python/cpython/blame/621b33ce258f3eaf154322c1edf0ead1e4892e36/Python/pytime.c#L896

On Windows, Python time.time() uses GetSystemTimeAsFileTime, see https://github.com/python/cpython/blame/621b33ce258f3eaf154322c1edf0ead1e4892e36/Python/pytime.c#L856 . Does anyone know what std::chrono on Windows uses?

Probably using the same as python:

• https://github.com/microsoft/STL/blob/fdcafc0dfd8789565a2d8481a6b64d1771faa31a/stl/inc/__msvc_chrono.hpp#L634
• https://github.com/llvm/llvm-project/blob/ce167c6fb2ae67cffa6702b869762fb80b62d3bc/libcxx/src/chrono.cpp#L107

Cleared milestone for now. While this is a regression for 24.0, I don't think anyone has figured out why or how to fix it. The underlying bug shouldn't lead to consensus failure or other user facing bugs, so it seems fine to ship 24.0 with this "bug".