Re: 8.14.1: Test 1542 racy?

From: Stefan Eissing via curl-library <curl-library_at_lists.haxx.se>
Date: Tue, 10 Jun 2025 10:18:30 +0200

Thanks! Curl's check for a connection being "too old" were rounding things in the wrong direction. This led to a connection being reused up to 999ms longer than intended.

This triggered on OpenBSD since the "sleep(2)" in the test case returned after 1996ms (on the clock used).

Proposed fix in https://github.com/curl/curl/pull/17571

Kind regards,
Stefan

> Am 09.06.2025 um 23:14 schrieb Christian Weisgerber via curl-library <curl-library_at_lists.haxx.se>:
>
> Stefan Eissing:
>
>> Not reproducible on macOS. If you apply the attached patch on a debug build, we should learn more. The log in tests/log/stderr1542 should then show when connections are reused with that life times and when they are closed instead.
>>
>> The close that is missing in your failed runs would be missing the line:
>> == Info: Too old connection (20xx ms since creation), disconnect it
>
> Here's the run output...
>
> ------------------->
> test 1542...[connection reuse with CURLOPT_MAXLIFETIME_CONN]
> --p---oe--- OK (1 out of 10 , remaining: 00:27, took 3.063s, duration: 00:03)
> test 1542...[connection reuse with CURLOPT_MAXLIFETIME_CONN]
> --p---oe--- OK (2 out of 10 , remaining: 00:20, took 2.075s, duration: 00:05)
> test 1542...[connection reuse with CURLOPT_MAXLIFETIME_CONN]
>
> 1542: output (log/stderr1542) FAILED:
> --- log/check-expected Mon Jun 9 23:10:22 2025
> +++ log/check-generated Mon Jun 9 23:10:22 2025
> _at__at_ -1,5 +1,4 _at__at_
> == Info: Connection #0 to host 127.0.0.1 left intact[CR][LF]
> == Info: Connection #0 to host 127.0.0.1 left intact[CR][LF]
> == Info: Connection #0 to host 127.0.0.1 left intact[CR][LF]
> -== Info: shutting down connection #0[CR][LF]
> -== Info: Connection #1 to host 127.0.0.1 left intact[CR][LF]
> +== Info: Connection #0 to host 127.0.0.1 left intact[CR][LF]
>
> - abort tests
> TESTDONE: 3 tests were considered during 7 seconds.
> TESTDONE: 2 tests out of 3 reported OK: 66%
> <-------------------
>
> ... and here's log/stderr1542:
>
> ------------------->
> URL: http://127.0.0.1:46884/1542
> == Info: !!! WARNING !!!
> == Info: This is a debug build of libcurl, do not use in production.
> == Info: Trying 127.0.0.1:46884...
> == Info: Connected to 127.0.0.1 (127.0.0.1) port 46884
> == Info: using HTTP/1.x
> == Info: sending last upload chunk of 58 bytes
> == Info: Curl_xfer_send(len=58, eos=1) -> 0, 58
> => Send header, 58 bytes (0x3a)
> 0000: GET /1542 HTTP/1.1
> 0014: Host: 127.0.0.1:46884
> 002b: Accept: */*
> 0038:
> <= Recv header, 17 bytes (0x11)
> 0000: HTTP/1.1 200 OK
> <= Recv header, 19 bytes (0x13)
> 0000: Content-Length: 0
> <= Recv header, 2 bytes (0x2)
> 0000:
> == Info: Connection #0 to host 127.0.0.1 left intact
> == Info: connection has been idle for 0 ms (max idle 118 sec)
> == Info: Re-using existing http: connection with host 127.0.0.1
> == Info: sending last upload chunk of 58 bytes
> == Info: Curl_xfer_send(len=58, eos=1) -> 0, 58
> => Send header, 58 bytes (0x3a)
> 0000: GET /1542 HTTP/1.1
> 0014: Host: 127.0.0.1:46884
> 002b: Accept: */*
> 0038:
> <= Recv header, 17 bytes (0x11)
> 0000: HTTP/1.1 200 OK
> <= Recv header, 19 bytes (0x13)
> 0000: Content-Length: 0
> <= Recv header, 2 bytes (0x2)
> 0000:
> == Info: Connection #0 to host 127.0.0.1 left intact
> == Info: connection has been idle for 1993 ms (max idle 118 sec)
> == Info: connection has been idle for 1993 ms (max idle 118 sec)
> == Info: Re-using existing http: connection with host 127.0.0.1
> == Info: sending last upload chunk of 58 bytes
> == Info: Curl_xfer_send(len=58, eos=1) -> 0, 58
> => Send header, 58 bytes (0x3a)
> 0000: GET /1542 HTTP/1.1
> 0014: Host: 127.0.0.1:46884
> 002b: Accept: */*
> 0038:
> <= Recv header, 17 bytes (0x11)
> 0000: HTTP/1.1 200 OK
> <= Recv header, 19 bytes (0x13)
> 0000: Content-Length: 0
> <= Recv header, 2 bytes (0x2)
> 0000:
> == Info: Connection #0 to host 127.0.0.1 left intact
> == Info: connection has been idle for 0 ms (max idle 118 sec)
> == Info: connection age is 1996 ms (max 1 sec)
> == Info: Re-using existing http: connection with host 127.0.0.1
> == Info: sending last upload chunk of 58 bytes
> == Info: Curl_xfer_send(len=58, eos=1) -> 0, 58
> => Send header, 58 bytes (0x3a)
> 0000: GET /1542 HTTP/1.1
> 0014: Host: 127.0.0.1:46884
> 002b: Accept: */*
> 0038:
> <= Recv header, 17 bytes (0x11)
> 0000: HTTP/1.1 200 OK
> <= Recv header, 19 bytes (0x13)
> 0000: Content-Length: 0
> <= Recv header, 2 bytes (0x2)
> 0000:
> == Info: Connection #0 to host 127.0.0.1 left intact
> Test ended with result 0
> ------------------->
>
> --
> Christian "naddy" Weisgerber naddy_at_mips.inka.de
> --
> Unsubscribe: https://lists.haxx.se/mailman/listinfo/curl-library
> Etiquette: https://curl.se/mail/etiquette.html

-- 
Unsubscribe: https://lists.haxx.se/mailman/listinfo/curl-library
Etiquette:   https://curl.se/mail/etiquette.html

Received on 2025-06-10