fix: intermittent failure in feature_llmq_simplepose.py #5859

knst · 2024-02-02T19:17:38Z

Issue being fixed or feature implemented

kudos to kwvg to report issue: he pointed out that functional tests randomly fail lately.
Bisect pointed out an exact commit: bitcoin#20027 - mockable time everywhere

What was done?

Added call mn.node.mockscheduler as it is done in 20027 for other functional tests

How Has This Been Tested?

Run 20 times. Without this patch 20% failures; with this patch - zero failures.

test/functional/test_runner.py -j20 feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py feature_llmq_simplepose.py

Breaking Changes

N/a

Checklist:

I have performed a self-review of my own code
I have commented my code, particularly in hard-to-understand areas
I have added or updated relevant unit/integration/functional/e2e tests
I have made corresponding changes to the documentation
I have assigned this pull request to a milestone

knst · 2024-02-03T12:08:03Z

@kwvg claims that with this patch it still fails randomly on his machine, but only 1/3 of failures compare to without patch.

<with patch>
feature_llmq_simplepose.py | � Passed  | 376 s
feature_llmq_simplepose.py | � Passed  | 379 s
feature_llmq_simplepose.py | � Passed  | 382 s
feature_llmq_simplepose.py | � Passed  | 383 s
feature_llmq_simplepose.py | � Passed  | 384 s
feature_llmq_simplepose.py | � Passed  | 384 s
feature_llmq_simplepose.py | � Passed  | 386 s
feature_llmq_simplepose.py | � Passed  | 387 s
feature_llmq_simplepose.py | � Passed  | 387 s
feature_llmq_simplepose.py | � Passed  | 388 s
feature_llmq_simplepose.py | � Passed  | 388 s
feature_llmq_simplepose.py | � Passed  | 389 s
feature_llmq_simplepose.py | � Passed  | 389 s
feature_llmq_simplepose.py | � Passed  | 390 s
feature_llmq_simplepose.py | � Passed  | 390 s
feature_llmq_simplepose.py | � Passed  | 391 s
feature_llmq_simplepose.py | � Passed  | 391 s
feature_llmq_simplepose.py | � Failed  | 69 s
feature_llmq_simplepose.py | � Failed  | 69 s
feature_llmq_simplepose.py | � Failed  | 71 s

vs

<without patch>
feature_llmq_simplepose.py | � Passed  | 353 s
feature_llmq_simplepose.py | � Passed  | 356 s
feature_llmq_simplepose.py | � Passed  | 351 s
feature_llmq_simplepose.py | � Passed  | 352 s
feature_llmq_simplepose.py | � Passed  | 354 s
feature_llmq_simplepose.py | � Passed  | 350 s
feature_llmq_simplepose.py | � Passed  | 353 s
feature_llmq_simplepose.py | � Passed  | 357 s
feature_llmq_simplepose.py | � Passed  | 346 s
feature_llmq_simplepose.py | � Passed  | 356 s
feature_llmq_simplepose.py | � Passed  | 346 s
feature_llmq_simplepose.py | � Failed  | 62 s
feature_llmq_simplepose.py | � Failed  | 63 s
feature_llmq_simplepose.py | � Failed  | 59 s
feature_llmq_simplepose.py | � Failed  | 61 s
feature_llmq_simplepose.py | � Failed  | 63 s
feature_llmq_simplepose.py | � Failed  | 59 s
feature_llmq_simplepose.py | � Failed  | 61 s
feature_llmq_simplepose.py | � Failed  | 60 s
feature_llmq_simplepose.py | � Failed  | 60 s

any ideas how we can improve this simplepose test futhermore?

UdjinM6

I don't see any improvement on my machine using this PR. Nodes drop connections on develop for no clear reason (no errors in logs). Simply waiting for connections did not help so I tried moving block generation out of the loop and suddenly d89f41c fixed the issue for me. But I don't understand how/why exactly... 🤷‍♂️ It would be nice if someone could explain why it worked 😄 Anyway, pls try this patch instead and share your thoughts.

test/functional/feature_llmq_simplepose.py

knst · 2024-02-03T16:58:00Z

Simply waiting for connections did not help so I tried moving block generation out of the loop and suddenly d89f41c fixed the issue for me

almost fixed for me, still one failure out of 20 which is pretty good

@kwvg , can you test it, please?

feature_llmq_simplepose.py | ✓ Passed  | 355 s
feature_llmq_simplepose.py | ✓ Passed  | 355 s
feature_llmq_simplepose.py | ✓ Passed  | 358 s
feature_llmq_simplepose.py | ✓ Passed  | 359 s
feature_llmq_simplepose.py | ✓ Passed  | 360 s
feature_llmq_simplepose.py | ✓ Passed  | 360 s
feature_llmq_simplepose.py | ✓ Passed  | 361 s
feature_llmq_simplepose.py | ✓ Passed  | 361 s
feature_llmq_simplepose.py | ✓ Passed  | 362 s
feature_llmq_simplepose.py | ✓ Passed  | 366 s
feature_llmq_simplepose.py | ✓ Passed  | 366 s
feature_llmq_simplepose.py | ✓ Passed  | 367 s
feature_llmq_simplepose.py | ✓ Passed  | 367 s
feature_llmq_simplepose.py | ✓ Passed  | 368 s
feature_llmq_simplepose.py | ✓ Passed  | 369 s
feature_llmq_simplepose.py | ✓ Passed  | 369 s
feature_llmq_simplepose.py | ✓ Passed  | 370 s
feature_llmq_simplepose.py | ✓ Passed  | 370 s
feature_llmq_simplepose.py | ✓ Passed  | 371 s
feature_llmq_simplepose.py | ✖ Failed  | 126 s

kwvg · 2024-02-03T17:30:37Z

dash@228219c1225b:/src/dash$ ./test/functional/test_runner.py -j20 feature_llmq_simplepose.py [...]
[...]
TEST                       | STATUS    | DURATION

feature_llmq_simplepose.py | � Passed  | 381 s
feature_llmq_simplepose.py | � Passed  | 385 s
feature_llmq_simplepose.py | � Passed  | 386 s
feature_llmq_simplepose.py | � Passed  | 386 s
feature_llmq_simplepose.py | � Passed  | 387 s
feature_llmq_simplepose.py | � Passed  | 387 s
feature_llmq_simplepose.py | � Passed  | 388 s
feature_llmq_simplepose.py | � Passed  | 389 s
feature_llmq_simplepose.py | � Passed  | 390 s
feature_llmq_simplepose.py | � Passed  | 392 s
feature_llmq_simplepose.py | � Passed  | 392 s
feature_llmq_simplepose.py | � Passed  | 393 s
feature_llmq_simplepose.py | � Passed  | 393 s
feature_llmq_simplepose.py | � Passed  | 394 s
feature_llmq_simplepose.py | � Passed  | 394 s
feature_llmq_simplepose.py | � Passed  | 395 s
feature_llmq_simplepose.py | � Passed  | 395 s
feature_llmq_simplepose.py | � Passed  | 396 s
feature_llmq_simplepose.py | � Passed  | 396 s
feature_llmq_simplepose.py | � Passed  | 397 s

ALL                        | � Passed  | 7816 s (accumulated)
Runtime: 397 s
dash@228219c1225b:/src/dash$ git rev-parse HEAD
d89f41caeec33b9a4957c95b1a747e26e2e915b9

UdjinM6 · 2024-02-03T20:31:04Z

I think I figured it out. Previously isolated nodes are trying to fetch blocks they missed as soon as they have a new connection open. When we bump mocktime 10+ minutes in the middle of that we trigger Timeout downloading block event https://github.com/dashpay/dash/blob/develop/src/net_processing.cpp#L5171. So these nodes drop "slow" peers (node0, the only connection they have) and everything falls apart. Bumping mocktime only when nodes are synced already should solve the issue. Pls check f8581d8.

kwvg · 2024-02-03T21:18:51Z

dash@228219c1225b:/src/dash$ ./test/functional/test_runner.py -j20 feature_llmq_simplepose.py [...]
[...]
TEST                       | STATUS    | DURATION

feature_llmq_simplepose.py | � Passed  | 374 s
feature_llmq_simplepose.py | � Passed  | 379 s
feature_llmq_simplepose.py | � Passed  | 384 s
feature_llmq_simplepose.py | � Passed  | 385 s
feature_llmq_simplepose.py | � Passed  | 386 s
feature_llmq_simplepose.py | � Passed  | 387 s
feature_llmq_simplepose.py | � Passed  | 389 s
feature_llmq_simplepose.py | � Passed  | 389 s
feature_llmq_simplepose.py | � Passed  | 390 s
feature_llmq_simplepose.py | � Passed  | 390 s
feature_llmq_simplepose.py | � Passed  | 391 s
feature_llmq_simplepose.py | � Passed  | 393 s
feature_llmq_simplepose.py | � Passed  | 394 s
feature_llmq_simplepose.py | � Passed  | 394 s
feature_llmq_simplepose.py | � Passed  | 395 s
feature_llmq_simplepose.py | � Passed  | 396 s
feature_llmq_simplepose.py | � Passed  | 396 s
feature_llmq_simplepose.py | � Passed  | 397 s
feature_llmq_simplepose.py | � Passed  | 397 s
feature_llmq_simplepose.py | � Passed  | 398 s

ALL                        | � Passed  | 7804 s (accumulated)
Runtime: 398 s
dash@228219c1225b:/src/dash$ git rev-parse HEAD
f8581d89975f78ebde1a66de2bd98788c4422e18

UdjinM6 · 2024-02-06T12:57:23Z

Pls check f8581d8

ping @knst

knst

Pls check f8581d8

this one works perfectly for me.

UdjinM6

ACK :)

PastaPastaPasta

utACK for squash merge

kwvg

post-merge utACK

knst added this to the 20.1 milestone Feb 2, 2024

knst marked this pull request as draft February 2, 2024 19:21

knst force-pushed the fix-llmq-simplepose branch from 878bd28 to 9b6eb25 Compare February 2, 2024 19:38

knst requested review from kwvg, UdjinM6 and PastaPastaPasta February 2, 2024 20:48

knst marked this pull request as ready for review February 2, 2024 20:48

UdjinM6 requested changes Feb 3, 2024

View reviewed changes

test/functional/feature_llmq_simplepose.py Outdated Show resolved Hide resolved

knst force-pushed the fix-llmq-simplepose branch from 9b6eb25 to ea0d064 Compare February 3, 2024 17:03

knst requested a review from UdjinM6 February 3, 2024 17:03

knst mentioned this pull request Feb 6, 2024

backport: Merge bitcoin#19370, 19562, 19538, 19272, 19214, 19429, 18990, 20927, 20507 #5770

Merged

UdjinM6 added 2 commits February 7, 2024 16:56

fix feature_llmq_simplepose.py

89d5ac7

fix: sync before bumping mocktime

623c30d

knst force-pushed the fix-llmq-simplepose branch from ea0d064 to 623c30d Compare February 7, 2024 12:03

knst commented Feb 7, 2024

View reviewed changes

UdjinM6 approved these changes Feb 7, 2024

View reviewed changes

PastaPastaPasta approved these changes Feb 7, 2024

View reviewed changes

PastaPastaPasta merged commit 83ec7f2 into dashpay:develop Feb 7, 2024
9 checks passed

kwvg reviewed Feb 8, 2024

View reviewed changes

knst mentioned this pull request Nov 22, 2024

feat: start DIP0024 from block 1 - fire up test chains by first block - 7/n #6325

Merged

5 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: intermittent failure in feature_llmq_simplepose.py #5859

fix: intermittent failure in feature_llmq_simplepose.py #5859

knst commented Feb 2, 2024

knst commented Feb 3, 2024

UdjinM6 left a comment

knst commented Feb 3, 2024 •

edited

Loading

kwvg commented Feb 3, 2024

UdjinM6 commented Feb 3, 2024

kwvg commented Feb 3, 2024 •

edited

Loading

UdjinM6 commented Feb 6, 2024

knst left a comment

UdjinM6 left a comment

PastaPastaPasta left a comment

kwvg left a comment

fix: intermittent failure in feature_llmq_simplepose.py #5859

fix: intermittent failure in feature_llmq_simplepose.py #5859

Conversation

knst commented Feb 2, 2024

Issue being fixed or feature implemented

What was done?

How Has This Been Tested?

Breaking Changes

Checklist:

knst commented Feb 3, 2024

UdjinM6 left a comment

Choose a reason for hiding this comment

knst commented Feb 3, 2024 • edited Loading

kwvg commented Feb 3, 2024

UdjinM6 commented Feb 3, 2024

kwvg commented Feb 3, 2024 • edited Loading

UdjinM6 commented Feb 6, 2024

knst left a comment

Choose a reason for hiding this comment

UdjinM6 left a comment

Choose a reason for hiding this comment

PastaPastaPasta left a comment

Choose a reason for hiding this comment

kwvg left a comment

Choose a reason for hiding this comment

knst commented Feb 3, 2024 •

edited

Loading

kwvg commented Feb 3, 2024 •

edited

Loading