Re: Test 1061 flaky when run without valgrind

From: Fabian Keil via curl-library <curl-library_at_cool.haxx.se>
Date: Sat, 9 Jan 2021 14:04:45 +0100

Fabian Keil via curl-library <curl-library_at_cool.haxx.se> wrote on 2021-01-08:

> using a curl binary built from git master 060658f634, test 1061
> works reliably for me when valgrind is being used but is flaky
> without it:
>
> fk_at_t520 ~/git/curl/tests $./runtests.pl -n 1061 1061 1061 1061 1061 1061 1061 1061 1061 1061
> ********* System characteristics ********
> * curl 7.75.0-DEV (amd64-unknown-freebsd11.4)
> * libcurl/7.75.0-DEV OpenSSL/1.1.1i zlib/1.2.11 brotli/1.0.9 zstd/1.4.5 libidn2/2.3.0 libpsl/0.21.1 (+libidn2/2.3.0) nghttp2/1.42.0
> * Features: alt-svc AsynchDNS brotli Debug HTTP2 HTTPS-proxy IDN IPv6 Largefile libz NTLM NTLM_WB PSL SSL TLS-SRP TrackMemory UnixSockets zstd
> * Disabled:
> * Host: t520.local
> * System: ElectroBSD t520.local 11.4-STABLE ElectroBSD 11.4-STABLE #2 r368530+b956f65cb108(electrobsd): Sat Dec 12 08:37:23 UTC 2020 fk_at_t520.local:/usr/obj/usr/src/sys/ELECTRO_BEER amd64
> * OS: freebsd
> *
> *** DISABLES memory tracking when using threaded resolver
> *
> * Servers: HTTP-IPv6 HTTP-unix FTP-IPv6
> * Env:
> * Seed: 265959
> *****************************************
> test 1061...[HTTP proxy CONNECT auth Digest, large headers and chunked data]
> --pd---e--- OK (1 out of 10 , remaining: 00:13, took 1.471s, duration: 00:01)
> test 1061...[HTTP proxy CONNECT auth Digest, large headers and chunked data]
> --pd---e--- OK (2 out of 10 , remaining: 00:06, took 0.229s, duration: 00:01)
> test 1061...[HTTP proxy CONNECT auth Digest, large headers and chunked data]
> --pd---e--- OK (3 out of 10 , remaining: 00:04, took 0.193s, duration: 00:01)
> test 1061...[HTTP proxy CONNECT auth Digest, large headers and chunked data]
> --pd---e--- OK (4 out of 10 , remaining: 00:03, took 0.192s, duration: 00:02)
> test 1061...[HTTP proxy CONNECT auth Digest, large headers and chunked data]
>
> 1061: protocol FAILED:
> --- log/check-expected 2021-01-08 20:25:33.229181000 +0100
> +++ log/check-generated 2021-01-08 20:25:33.229096000 +0100
> _at__at_ -3,12 +3,6 _at__at_
> User-Agent: curl/7.75.0-DEV[CR][LF]
> Proxy-Connection: Keep-Alive[CR][LF]
> [CR][LF]
> -CONNECT test.remote.haxx.se.1061:8990 HTTP/1.1[CR][LF]
> -Host: test.remote.haxx.se.1061:8990[CR][LF]
> -Proxy-Authorization: Digest username="silly", realm="weirdorealm", nonce="12345", uri="test.remote.haxx.se.1061:8990", response="4e23449fa93224834299e7282a70472c"[CR][LF]
> -User-Agent: curl/7.75.0-DEV[CR][LF]
> -Proxy-Connection: Keep-Alive[CR][LF]
> -[CR][LF]
> GET /path/10610002 HTTP/1.1[CR][LF]
> Host: test.remote.haxx.se.1061:8990[CR][LF]
> User-Agent: curl/7.75.0-DEV[CR][LF]
>
> - abort tests
> TESTDONE: 4 tests out of 5 reported OK: 80%
>
> TESTFAIL: These test cases failed: 1061
>
> TESTDONE: 5 tests were considered during 2 seconds.
>
> When it fails, it's always because of the missing CONNECT request.

The problem seems to be that curl is ignoring the authentication
request.

With valgrind the trace contains:

    3e40: aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
    3e80: aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
    3ec0: aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
    13:49:27.034809 <= Recv header, 2 bytes (0x2)
    0000:
    13:49:27.035505 == Info: Ignore chunked response-body
    13:49:28.941985 == Info: chunk reading DONE
    13:49:28.945615 == Info: Establish HTTP proxy tunnel to test.remote.haxx.se.1061:8990
    13:49:28.973582 == Info: Proxy auth using Digest with user 'silly'
    13:49:28.974488 => Send header, 310 bytes (0x136)
    0000: CONNECT test.remote.haxx.se.1061:8990 HTTP/1.1
    0030: Host: test.remote.haxx.se.1061:8990
    0055: Proxy-Authorization: Digest username="silly", realm="weirdorealm
    0095: ", nonce="12345", uri="test.remote.haxx.se.1061:8990", response=
    00d5: "4e23449fa93224834299e7282a70472c"
    00f9: User-Agent: curl/7.75.0-DEV
    0116: Proxy-Connection: Keep-Alive
    0134:

Without valgrind I get no "chunk reading DONE" message:

    3e40: aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
    3e80: aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
    3ec0: aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
    13:55:12.014360 <= Recv header, 2 bytes (0x2)
    0000:
    13:55:12.014374 == Info: Ignore chunked response-body
    13:55:12.047597 == Info: CONNECT phase completed!
    13:55:12.047607 == Info: STATE: WAITPROXYCONNECT => SENDPROTOCONNECT handle 0x8030d3c08; line 1819 (connection #0)
    13:55:12.047613 == Info: CONNECT phase completed!
    13:55:12.047617 == Info: CONNECT phase completed!
    13:55:12.047621 == Info: STATE: SENDPROTOCONNECT => DO handle 0x8030d3c08; line 1869 (connection #0)
    13:55:12.047668 => Send header, 110 bytes (0x6e)
    0000: GET /path/10610002 HTTP/1.1
    001d: Host: test.remote.haxx.se.1061:8990
    0042: User-Agent: curl/7.75.0-DEV
    005f: Accept: */*
    006c:

> I haven't executed the tests in a while so I'm not sure
> if this is a new issue.

This does not appear to be a new issue. I tried a couple of
past releases stopping in 2019 and the problem was present
there as well. Finally with curl-7_65_0 the test hangs instead
of failing.
 
Fabian


-------------------------------------------------------------------
Unsubscribe: https://cool.haxx.se/list/listinfo/curl-library
Etiquette: https://curl.se/mail/etiquette.html
Received on 2021-01-09