test 1399 failing

[eworm-de]

I did this

I am building the downstream package for Arch Linux. The build succeeds, but check fails in test 1399:

 URL: -
 is 2496891 us same as 2 seconds? Yes
 is 2497277 us same as 2 seconds? Yes
 is 2497481 us same as 2 seconds? Yes
 is 2497690 us same as 2 seconds? Yes
 is 2497885 us same as 2 seconds? Yes
 is 4001244 us same as 3 seconds? No
 /usr/src/debug/curl/curl/tests/unit/unit1399.c:77 Assertion 'usec_matches_seconds(p->total.nslookup_us, seconds)' FAILED: about 3 seconds should have passed
 is 4001776 us same as 3 seconds? No
 /usr/src/debug/curl/curl/tests/unit/unit1399.c:78 Assertion 'usec_matches_seconds(p->total.connect_us, seconds)' FAILED: about 3 seconds should have passed
 is 4002122 us same as 3 seconds? No
 /usr/src/debug/curl/curl/tests/unit/unit1399.c:79 Assertion 'usec_matches_seconds(p->total.appconnect_us, seconds)' FAILED: about 3 seconds should have passed
 is 4002481 us same as 3 seconds? No
 /usr/src/debug/curl/curl/tests/unit/unit1399.c:80 Assertion 'usec_matches_seconds(p->total.pretransfer_us, seconds)' FAILED: about 3 seconds should have passed
 is 4002810 us same as 3 seconds? No
 /usr/src/debug/curl/curl/tests/unit/unit1399.c:81 Assertion 'usec_matches_seconds(p->total.starttransfer_us, seconds)' FAILED: about 3 seconds should have passed
 Test ended with result 5

There are recent changes to the test in fbcf10a & 35843dd by @icing .

I expected the following

All tests should succeed.

curl/libcurl version

curl 8.22.0

operating system

Arch Linux

[icing]

Hmm, test1399 unfortunately uses the real clock to check progress values. When the runner does not get enought CPU, this test may overrun the expected values, unfortunately.

We should improve the test to become independant of that.

[eworm-de]

What looks suspicious to me... Three seconds are expected, but in case of failure it is always four seconds and about 2 milliseconds. Are we just one second off here?

[icing]

"It works on my machine" and in CI. If you get always one second off, that's indeed weird.

[eworm-de]

Tried on my notebook, but in our clean build environment. Similar results:

 URL: -
 is 2817908 us same as 2 seconds? Yes
 is 2818611 us same as 2 seconds? Yes
 is 2818982 us same as 2 seconds? Yes
 is 2819355 us same as 2 seconds? Yes
 is 2819720 us same as 2 seconds? Yes
 is 4647431 us same as 3 seconds? No
 /usr/src/debug/curl/curl/tests/unit/unit1399.c:77 Assertion 'usec_matches_seconds(p->total.nslookup_us, seconds)' FAILED: about 3 seconds should have passed
 is 4648408 us same as 3 seconds? No
 /usr/src/debug/curl/curl/tests/unit/unit1399.c:78 Assertion 'usec_matches_seconds(p->total.connect_us, seconds)' FAILED: about 3 seconds should have passed
 is 4649054 us same as 3 seconds? No
 /usr/src/debug/curl/curl/tests/unit/unit1399.c:79 Assertion 'usec_matches_seconds(p->total.appconnect_us, seconds)' FAILED: about 3 seconds should have passed
 is 4649708 us same as 3 seconds? No
 /usr/src/debug/curl/curl/tests/unit/unit1399.c:80 Assertion 'usec_matches_seconds(p->total.pretransfer_us, seconds)' FAILED: about 3 seconds should have passed
 is 4650340 us same as 3 seconds? No
 /usr/src/debug/curl/curl/tests/unit/unit1399.c:81 Assertion 'usec_matches_seconds(p->total.starttransfer_us, seconds)' FAILED: about 3 seconds should have passed
 Test ended with result 5

Every request takes half a second longer, but we are still in the range of one-second-off. Possibly a side effect with name lookups?

How to manually run a single test from my local checkout?

[icing]

I run individual tests during development via

>  make -j20 && (cd tests && make -j20 && ./runtests.pl -v 1399)

[eworm-de]

Succeeds then...

URL: -
is 2312162 us same as 2 seconds? Yes
is 2312373 us same as 2 seconds? Yes
is 2312472 us same as 2 seconds? Yes
is 2312538 us same as 2 seconds? Yes
is 2312599 us same as 2 seconds? Yes
is 3627945 us same as 3 seconds? Yes
is 3628187 us same as 3 seconds? Yes
is 3628312 us same as 3 seconds? Yes
is 3628404 us same as 3 seconds? Yes
is 3628490 us same as 3 seconds? Yes
Test ended with result 0

So where does that extra second add up?

[icing]

Good question. Probably not Arch's doing, but something makes runtimes strange there.

In the meantime, I made an improved version of the test that is disconnected from the real clock: #22800

[eworm-de]

Applying f9933d9 from #22800 makes the tests succeed. Thanks!