Log test details at the end when the test times out. by sarthakaggarwal97 · Pull Request #2276 · valkey-io/valkey

sarthakaggarwal97 · 2025-06-26T06:23:19Z

Resolves #2267

Verified that the name of the test now prints in the bottom during test time out.

[TIMEOUT]: clients state report follows.
sock15b01d810 => (IN PROGRESS) WAIT should not acknowledge 2 additional copies of the data
sock15b01dd10 => (IN PROGRESS) WAIT should not acknowledge 2 additional copies of the data
sock15b01d110 => (IN PROGRESS) WAIT should not acknowledge 2 additional copies of the data
sock15b01e490 => (IN PROGRESS) WAIT should not acknowledge 2 additional copies of the data
sock15b01e710 => (IN PROGRESS) WAIT should not acknowledge 2 additional copies of the data
Killing still running Valkey server 26294
Killing still running Valkey server 26299
Killing still running Valkey server 26302
Killing still running Valkey server 26304
Killing still running Valkey server 26306
Killing still running Valkey server 26342
Killing still running Valkey server 26349
Killing still running Valkey server 26357
Killing still running Valkey server 26358
Killing still running Valkey server 26359

                   The End

Execution time of different units:

!!! WARNING The following tests failed:

*** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl
*** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl
*** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl
*** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl
*** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl
Cleanup: may take some time... OK

------- 

[TIMEOUT]: clients state report follows.
sock146070790 => (IN PROGRESS) Check for memory leaks (pid 26494)
Killing still running Valkey server 26480
Killing still running Valkey server 26494

                   The End

Execution time of different units:

!!! WARNING The following tests failed:

*** [TIMEOUT]: Check for memory leaks in tests/unit/introspection.tcl
Cleanup: may take some time... OK

Signed-off-by: Sarthak Aggarwal <[email protected]>

codecov · 2025-06-26T06:39:02Z

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 71.43%. Comparing base (57459f7) to head (23f107a).
Report is 16 commits behind head on unstable.

Additional details and impacted files

@@             Coverage Diff              @@
##           unstable    #2276      +/-   ##
============================================
- Coverage     71.50%   71.43%   -0.08%     
============================================
  Files           123      123              
  Lines         66926    67030     +104     
============================================
+ Hits          47856    47880      +24     
- Misses        19070    19150      +80

see 21 files with indirect coverage changes

🚀 New features to boost your workflow:

❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.
📦 JS Bundle Analysis: Save yourself from yourself by tracking and limiting bundle sizes in JS merges.

hpatro · 2025-06-26T20:53:16Z

Could you add the output for multiple test failures? Want to see how it looks like before merging it in.

sarthakaggarwal97 · 2025-06-26T21:26:48Z

@hpatro check if this looks good!

(base) ~/workspace/valkey git:[fix-bug-2267]
./runtest --single unit/wait --clients 5 --timeout 0 --loop
Cleanup: may take some time... OK
Starting test server at port 21079
[ready]: 72691
Testing unit/wait
[ready]: 72692
Testing unit/wait
[ready]: 72693
Testing unit/wait
[ready]: 72695
Testing unit/wait
[ready]: 72694
Testing unit/wait
[ok]: Setup slave (106 ms)
[ok]: WAIT out of range timeout (milliseconds) (1 ms)
[ok]: WAIT should acknowledge 1 additional copy of the data (1 ms)
[ok]: Setup slave (103 ms)
[ok]: WAIT out of range timeout (milliseconds) (1 ms)
[ok]: WAIT should acknowledge 1 additional copy of the data (1 ms)
[ok]: Setup slave (106 ms)
[ok]: Setup slave (104 ms)
[ok]: WAIT out of range timeout (milliseconds) (1 ms)
[ok]: WAIT out of range timeout (milliseconds) (1 ms)
[ok]: WAIT should acknowledge 1 additional copy of the data (1 ms)
[ok]: WAIT should acknowledge 1 additional copy of the data (2 ms)
[ok]: Setup slave (107 ms)
[ok]: WAIT out of range timeout (milliseconds) (1 ms)
[ok]: WAIT should acknowledge 1 additional copy of the data (1 ms)
[TIMEOUT]: clients state report follows.
sock13e032390 => (IN PROGRESS) WAIT should not acknowledge 2 additional copies of the data
sock13e032890 => (IN PROGRESS) WAIT should not acknowledge 2 additional copies of the data
sock13e031d90 => (IN PROGRESS) WAIT should not acknowledge 2 additional copies of the data
sock13e032e90 => (IN PROGRESS) WAIT should not acknowledge 2 additional copies of the data
sock13e033090 => (IN PROGRESS) WAIT should not acknowledge 2 additional copies of the data
Killing still running Valkey server 72709
Killing still running Valkey server 72710
Killing still running Valkey server 72712
Killing still running Valkey server 72717
Killing still running Valkey server 72719
Killing still running Valkey server 72760
Killing still running Valkey server 72763
Killing still running Valkey server 72770
Killing still running Valkey server 72772
Killing still running Valkey server 72773

                   The End

Execution time of different units:

!!! WARNING The following tests failed:

*** WAIT should not acknowledge 2 additional copies of the data
*** WAIT should not acknowledge 2 additional copies of the data
*** WAIT should not acknowledge 2 additional copies of the data
*** WAIT should not acknowledge 2 additional copies of the data
*** WAIT should not acknowledge 2 additional copies of the data
Cleanup: may take some time... OK

Signed-off-by: Sarthak Aggarwal <[email protected]>

sarthakaggarwal97 · 2025-06-26T21:53:49Z

@hpatro added a change to handle Check for memory leaks tests as well

hpatro · 2025-06-26T22:34:35Z

Should we prefix the failed test with the file name? WDYT @sarthakaggarwal97 ?

sarthakaggarwal97 · 2025-06-30T15:02:59Z

@hpatro only thing is the Checking for memory leaks test is a common across the test suite. Otherwise the test names will be mostly unique enough to identify. I can spend some time to add the file name if you think that's more descriptive. We can take it incrementally as well if it's not a major requirement.

hpatro · 2025-06-30T20:16:15Z

@hpatro only thing is the Checking for memory leaks test is a common across the test suite. Otherwise the test names will be mostly unique enough to identify. I can spend some time to add the file name if you think that's more descriptive. We can take it incrementally as well if it's not a major requirement.

Not in a rush here. Have a look if it's feasible to add it in an easy way. I generally jump to a file and then to the test. So, I feel it's logical to prepend the test file name.

Signed-off-by: Sarthak Aggarwal <[email protected]>

sarthakaggarwal97 · 2025-07-02T00:46:35Z

@hpatro prefixed the tests with the test file name as well.

(base) ~/workspace/valkey git:[fix-bug-2267]
./runtest --single unit/wait --clients 5 --timeout 0 --loop
Cleanup: may take some time... OK
Starting test server at port 21079
[ready]: 397
Testing unit/wait
[ready]: 404
Testing unit/wait
[ready]: 405
Testing unit/wait
[ready]: 408
Testing unit/wait
[ready]: 410
Testing unit/wait
[ok]: Setup slave (106 ms)
-------
[ok]: WAIT should acknowledge 1 additional copy of the data (1 ms)
[TIMEOUT]: clients state report follows.
sock11f87fa90 => (IN PROGRESS) WAIT should not acknowledge 2 additional copies of the data
sock11f880410 => (IN PROGRESS) WAIT should not acknowledge 2 additional copies of the data
sock11f880610 => (IN PROGRESS) WAIT should not acknowledge 2 additional copies of the data
sock11f880890 => (IN PROGRESS) WAIT should not acknowledge 2 additional copies of the data
sock11f880990 => (IN PROGRESS) WAIT should not acknowledge 2 additional copies of the data
Killing still running Valkey server 438
Killing still running Valkey server 442
Killing still running Valkey server 444
Killing still running Valkey server 448
Killing still running Valkey server 452
Killing still running Valkey server 494
Killing still running Valkey server 508
Killing still running Valkey server 512
Killing still running Valkey server 517
Killing still running Valkey server 525

                   The End

Execution time of different units:

!!! WARNING The following tests failed:

*** tests/unit/wait.tcl: WAIT should not acknowledge 2 additional copies of the data
*** tests/unit/wait.tcl: WAIT should not acknowledge 2 additional copies of the data
*** tests/unit/wait.tcl: WAIT should not acknowledge 2 additional copies of the data
*** tests/unit/wait.tcl: WAIT should not acknowledge 2 additional copies of the data
*** tests/unit/wait.tcl: WAIT should not acknowledge 2 additional copies of the data
Cleanup: may take some time... OK


(base) ~/workspace/valkey git:[fix-bug-2267]
./runtest --single unit/introspection --timeout 1
Cleanup: may take some time... OK
Starting test server at port 21079
[ready]: 742
Testing unit/introspection
[ready]: 744
[ready]: 753
[ready]: 745
[ready]: 750
[ready]: 743
[ready]: 752
[ready]: 749
[ready]: 757
[ready]: 755
[ready]: 748
[ready]: 746
[ready]: 756
[ready]: 751
[ready]: 754
[ready]: 747
[ok]: PING (0 ms)
------
[ok]: CONFIG sanity (23 ms)
[TIMEOUT]: clients state report follows.
sock14106e690 => (IN PROGRESS) Check for memory leaks (pid 761)
Killing still running Valkey server 761

                   The End

Execution time of different units:

!!! WARNING The following tests failed:

*** tests/unit/introspection.tcl: Check for memory leaks
Cleanup: may take some time... OK

hpatro

LGTM. Discussed with @sarthakaggarwal97, we will follow the same format as regular test failure but add timeout as prefix.

*** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl

tests/test_helper.tcl

Signed-off-by: Sarthak Aggarwal <[email protected]>

sarthakaggarwal97 · 2025-07-02T20:34:51Z

@hpatro sharing the format with the latest changes. Updating PR desc too.

[TIMEOUT]: clients state report follows.
sock146070790 => (IN PROGRESS) Check for memory leaks (pid 26494)
Killing still running Valkey server 26480
Killing still running Valkey server 26494

                   The End

Execution time of different units:

!!! WARNING The following tests failed:

*** [TIMEOUT]: Check for memory leaks in tests/unit/introspection.tcl
Cleanup: may take some time... OK

Execution time of different units:

!!! WARNING The following tests failed:

*** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl
*** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl
*** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl
*** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl
*** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl
Cleanup: may take some time... OK

tests/test_helper.tcl

Signed-off-by: Sarthak Aggarwal <[email protected]>

sarthakaggarwal97 · 2025-07-02T23:43:56Z

@hpatro good to merge?

With the change #2276, there are some cases where the the active_clients_file is not set. ``` can't unset "::active_clients_file(sock11d811610)": no such element in array while executing "unset ::active_clients_file($fd)" (procedure "read_from_test_client" line 22) invoked from within "read_from_test_client sock11d811610" ``` It is because when the test is done, we were unsetting the active_clients_file after the new task was assigned. Ideally we should unset it before that since the first task is assigned via `ready` state. `make test` is consistently passing now. Signed-off-by: Sarthak Aggarwal <[email protected]>

We used to did print the context but after valkey-io#2276, we lost the context. unstable: ``` *** Extract version and sha1 details from info command and print in tests/unit/info-command.tcl ``` now: ``` *** [err]: Extract version and sha1 details from info command and print in tests/unit/info-command.tcl Expected '0' to be equal to '1' (context: type source line 7 file /xxx/info-command.tcl cmd {assert_equal 0 1} proc ::test) ``` We can see the different, we have provided enough context when asserting fail. Otherwise we need to scroll back (which is usually a lot of server logs) to see the context. Signed-off-by: Binbin <[email protected]>

We used to did print the context but after #2276, we lost the context. unstable: ``` *** Extract version and sha1 details from info command and print in tests/unit/info-command.tcl ``` now: ``` *** [err]: Extract version and sha1 details from info command and print in tests/unit/info-command.tcl Expected '0' to be equal to '1' (context: type source line 7 file /xxx/info-command.tcl cmd {assert_equal 0 1} proc ::test) ``` We can see the different, we have provided enough context when asserting fail. Otherwise we need to scroll back (which is usually a lot of server logs) to see the context. Signed-off-by: Binbin <[email protected]>

We used to did print the context but after valkey-io#2276, we lost the context. unstable: ``` *** Extract version and sha1 details from info command and print in tests/unit/info-command.tcl ``` now: ``` *** [err]: Extract version and sha1 details from info command and print in tests/unit/info-command.tcl Expected '0' to be equal to '1' (context: type source line 7 file /xxx/info-command.tcl cmd {assert_equal 0 1} proc ::test) ``` We can see the different, we have provided enough context when asserting fail. Otherwise we need to scroll back (which is usually a lot of server logs) to see the context. Signed-off-by: Binbin <[email protected]>

Resolves valkey-io#2267 Timed out test gets logged at the end of the test run. ``` !!! WARNING The following tests failed: *** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl Cleanup: may take some time... OK ``` Signed-off-by: Sarthak Aggarwal <[email protected]>

Resolves #2267 Timed out test gets logged at the end of the test run. ``` !!! WARNING The following tests failed: *** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl Cleanup: may take some time... OK ``` Signed-off-by: Sarthak Aggarwal <[email protected]>

Resolves valkey-io#2267 Timed out test gets logged at the end of the test run. ``` !!! WARNING The following tests failed: *** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl Cleanup: may take some time... OK ``` Signed-off-by: Sarthak Aggarwal <[email protected]>

Resolves valkey-io#2267 Timed out test gets logged at the end of the test run. ``` !!! WARNING The following tests failed: *** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl Cleanup: may take some time... OK ``` Signed-off-by: Sarthak Aggarwal <[email protected]> Signed-off-by: Roshan Khatri <[email protected]>

Resolves valkey-io#2267 Timed out test gets logged at the end of the test run. ``` !!! WARNING The following tests failed: *** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl Cleanup: may take some time... OK ``` Signed-off-by: Sarthak Aggarwal <[email protected]>

Resolves valkey-io#2267 Timed out test gets logged at the end of the test run. ``` !!! WARNING The following tests failed: *** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl Cleanup: may take some time... OK ``` Signed-off-by: Sarthak Aggarwal <[email protected]> Signed-off-by: Roshan Khatri <[email protected]>

Resolves valkey-io#2267 Timed out test gets logged at the end of the test run. ``` !!! WARNING The following tests failed: *** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl Cleanup: may take some time... OK ``` Signed-off-by: Sarthak Aggarwal <[email protected]>

Resolves #2267 Timed out test gets logged at the end of the test run. ``` !!! WARNING The following tests failed: *** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl Cleanup: may take some time... OK ``` Signed-off-by: Sarthak Aggarwal <[email protected]>

Resolves #2267 Timed out test gets logged at the end of the test run. ``` !!! WARNING The following tests failed: *** [TIMEOUT]: WAIT should not acknowledge 2 additional copies of the data in tests/unit/wait.tcl Cleanup: may take some time... OK ``` Signed-off-by: Sarthak Aggarwal <[email protected]> Signed-off-by: Roshan Khatri <[email protected]>

get test name when test timeout occurs

64b3ef1

Signed-off-by: Sarthak Aggarwal <[email protected]>

Nikhil-Manglore approved these changes Jun 26, 2025

View reviewed changes

sarthakaggarwal97 requested a review from hpatro June 26, 2025 19:49

handles cases for Check for memory leaks test

32357a9

Signed-off-by: Sarthak Aggarwal <[email protected]>

prefix with test file name

6ab14d6

Signed-off-by: Sarthak Aggarwal <[email protected]>

hpatro reviewed Jul 2, 2025

View reviewed changes

tests/test_helper.tcl Outdated Show resolved Hide resolved

sarthakaggarwal97 added 2 commits July 2, 2025 13:29

update test print format

b0ceeb1

Signed-off-by: Sarthak Aggarwal <[email protected]>

remove dead condition

ba65bb3

Signed-off-by: Sarthak Aggarwal <[email protected]>

hpatro changed the title ~~Add test details when the run times out.~~ Log test details at the end when the test times out. Jul 2, 2025

hpatro approved these changes Jul 2, 2025

View reviewed changes

tests/test_helper.tcl Outdated Show resolved Hide resolved

uncatch

23f107a

Signed-off-by: Sarthak Aggarwal <[email protected]>

hpatro merged commit 2f3e363 into valkey-io:unstable Jul 3, 2025
51 checks passed

sarthakaggarwal97 mentioned this pull request Jul 10, 2025

Unset the active_clients_file before new test is assigned #2339

Merged

enjoy-binbin mentioned this pull request Aug 6, 2025

Print error context when test fails #2437

Merged

sarthakaggarwal97 added this to Valkey 8.0 and Valkey 8.1 Nov 6, 2025

sarthakaggarwal97 moved this to To be backported in Valkey 8.0 Nov 6, 2025

sarthakaggarwal97 moved this to To be backported in Valkey 8.1 Nov 6, 2025

zuiderkwast mentioned this pull request Dec 3, 2025

Backport fixes to prepare for 8.1.5 #2902

Merged

zuiderkwast moved this from To be backported to 8.1.5 (not yet released) in Valkey 8.1 Dec 3, 2025

roshkhatri moved this from To be backported to 8.0.7 in Valkey 8.0 Jan 30, 2026

sarthakaggarwal97 mentioned this pull request Feb 5, 2026

Backport bugfixes for 7.2.12 #3139

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Log test details at the end when the test times out.#2276

Log test details at the end when the test times out.#2276
hpatro merged 6 commits intovalkey-io:unstablefrom
sarthakaggarwal97:fix-bug-2267

sarthakaggarwal97 commented Jun 26, 2025 •

edited

Loading

Uh oh!

codecov bot commented Jun 26, 2025 •

edited

Loading

Uh oh!

hpatro commented Jun 26, 2025

Uh oh!

sarthakaggarwal97 commented Jun 26, 2025 •

edited

Loading

Uh oh!

sarthakaggarwal97 commented Jun 26, 2025

Uh oh!

hpatro commented Jun 26, 2025

Uh oh!

sarthakaggarwal97 commented Jun 30, 2025

Uh oh!

hpatro commented Jun 30, 2025

Uh oh!

sarthakaggarwal97 commented Jul 2, 2025 •

edited

Loading

Uh oh!

hpatro left a comment

Uh oh!

Uh oh!

sarthakaggarwal97 commented Jul 2, 2025

Uh oh!

Uh oh!

sarthakaggarwal97 commented Jul 2, 2025

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Conversation

sarthakaggarwal97 commented Jun 26, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

codecov bot commented Jun 26, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

hpatro commented Jun 26, 2025

Uh oh!

sarthakaggarwal97 commented Jun 26, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

sarthakaggarwal97 commented Jun 26, 2025

Uh oh!

hpatro commented Jun 26, 2025

Uh oh!

sarthakaggarwal97 commented Jun 30, 2025

Uh oh!

hpatro commented Jun 30, 2025

Uh oh!

sarthakaggarwal97 commented Jul 2, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

hpatro left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

sarthakaggarwal97 commented Jul 2, 2025

Uh oh!

Uh oh!

sarthakaggarwal97 commented Jul 2, 2025

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

sarthakaggarwal97 commented Jun 26, 2025 •

edited

Loading

codecov bot commented Jun 26, 2025 •

edited

Loading

sarthakaggarwal97 commented Jun 26, 2025 •

edited

Loading

sarthakaggarwal97 commented Jul 2, 2025 •

edited

Loading