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

hebasto commented at 8:19 am on June 27, 2022: member

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

 0177/244 - wallet_encryption.py --descriptors failed, Duration: 6 s
 1
 2stdout:
 32022-06-27T07:50:03.095000Z TestFramework (INFO): Initializing test directory C:\Users\ContainerAdministrator\AppData\Local\Temp\test_runner_₿_🏃_20220627_071202\wallet_encryption_65
 4
 52022-06-27T07:50:08.820000Z TestFramework (INFO): Check a timeout less than the limit
 6
 72022-06-27T07:50:09.007000Z TestFramework (ERROR): Assertion failed
 8
 9Traceback (most recent call last):
10
11  File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\test_framework\test_framework.py", line 133, in main
12
13    self.run_test()
14
15  File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\wallet_encryption.py", line 85, in run_test
16
17    assert_greater_than(expected_time_with_buffer, actual_time)
18
19  File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\test_framework\util.py", line 56, in assert_greater_than
20
21    raise AssertionError("%s <= %s" % (str(thing1), str(thing2)))
22
23AssertionError: 1756315608.992383 <= 1756315609
24
252022-06-27T07:50:09.070000Z TestFramework (INFO): Stopping nodes
26
272022-06-27T07:50:09.211000Z TestFramework (WARNING): Not cleaning up dir C:\Users\ContainerAdministrator\AppData\Local\Temp\test_runner_₿_🏃_20220627_071202\wallet_encryption_65
28
292022-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
30
312022-06-27T07:50:09.211000Z TestFramework (ERROR): 
32
332022-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
34
352022-06-27T07:50:09.211000Z TestFramework (ERROR): 
36
372022-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.
38
392022-06-27T07:50:09.211000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
40
412022-06-27T07:50:09.211000Z TestFramework (ERROR):

hebasto added the label Bug on Jun 27, 2022

hebasto added the label Wallet on Jun 27, 2022

hebasto added the label Tests on Jun 27, 2022

bitcoin deleted a comment on Jun 29, 2022

MarcoFalke commented at 10:43 am on July 4, 2022: member

See #25021

saranshisatgit commented at 6:23 am on July 7, 2022: none

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

MarcoFalke added this to the milestone 24.0 on Jul 31, 2022

mzumsande commented at 5:22 pm on August 1, 2022: contributor

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.

MarcoFalke commented at 7:14 am on August 2, 2022: member

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

MarcoFalke commented at 7:20 am on August 2, 2022: member

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

mzumsande commented at 6:24 pm on August 2, 2022: contributor

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().

MarcoFalke commented at 11:42 am on August 3, 2022: member

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?

 0#include <chrono>
 1#include <iostream>
 2
 3using SecondsDouble =
 4    std::chrono::duration<double, std::chrono::seconds::period>;
 5
 6int main() {
 7    const int64_t start{time(nullptr)};
 8    int64_t run{start};
 9    while (start == run) {
10        run = time(nullptr);
11    }
12    const SecondsDouble start_dbl{
13        std::chrono::system_clock::now().time_since_epoch()};
14    std::cout << start_dbl.count() - run << std::endl;
15}

mzumsande commented at 4:00 pm on August 3, 2022: contributor

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?

MarcoFalke commented at 5:20 pm on August 3, 2022: member

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

(Edit: Needs C++20)

 0#include <chrono>
 1#include <iostream>
 2
 3auto Now() { return std::chrono::system_clock::now().time_since_epoch(); }
 4
 5auto FloorS(auto dur) {
 6    return std::chrono::duration_cast<std::chrono::seconds>(dur);
 7}
 8
 9int main() {
10    const auto start{Now()};
11    auto run{start};
12    while (FloorS(start) == FloorS(run)) {
13        run = Now();
14    }
15    const int64_t end{time(nullptr)};
16    std::cout << (std::chrono::seconds(end) - run) << std::endl;
17}

mzumsande commented at 6:41 pm on August 3, 2022: contributor

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.

MarcoFalke commented at 7:31 pm on August 3, 2022: member

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.

MarcoFalke commented at 8:27 am on August 4, 2022: member

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?

MarcoFalke commented at 12:24 pm on August 4, 2022: member

Probably using the same as python:

MarcoFalke removed this from the milestone 24.0 on Aug 19, 2022

MarcoFalke commented at 2:38 pm on August 19, 2022: member

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”.

MarcoFalke referenced this in commit c73c8d53fe on Aug 20, 2022

MarcoFalke closed this on Aug 20, 2022

sidhujag referenced this in commit 7031380243 on Aug 20, 2022

bitcoin locked this on Aug 20, 2023

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

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