Re: Test 1452 failing on ElectroBSD when executed with valgrind

From: Timothe Litt <litt_at_acm.org>
Date: Sun, 25 Sep 2022 08:07:19 -0400

The 56 exit code is the "Recv failure: Connection reset by peer" from curl.

valgrind might affect timing.

If you expect anyone to look into this, you probably should post the
valgrind log (log/valgrind1452) to see what it is doing, and
log/telnet_server.log to see why the telnet server is closing the
connection...

Also consider replacing the --quiet with --verbose to see more of
valgrind is doing.


Timothe Litt
ACM Distinguished Engineer
--------------------------
This communication may not represent the ACM or my employer's views,
if any, on the matters discussed.

On 25-Sep-22 07:46, Fabian Keil via curl-library wrote:
> I recently noticed that test 1452 is failing on my
> ElectroBSD system when run with valgrind:
>
> fk_at_t520 ~/git/curl/tests $./runtests.pl -v 1452
> CMD (256): valgrind >/dev/null 2>&1
> CMD (0): valgrind --help 2>&1 | grep -- --tool > /dev/null 2>&1
> CMD (0): ../src/curl --version 1>log/curlverout.log 2>log/curlvererr.log
> ********* System characteristics ********
> * curl 7.86.0-DEV (amd64-unknown-freebsd13.1)
> * libcurl/7.86.0-DEV OpenSSL/1.1.1q zlib/1.2.12 libidn2/2.3.2 libpsl/0.21.1 (+libidn2/2.3.2) nghttp2/1.48.0
> * Features: alt-svc AsynchDNS Debug HSTS HTTP2 HTTPS-proxy IDN IPv6 Largefile libz NTLM NTLM_WB PSL SSL threadsafe TLS-SRP TrackMemory UnixSockets
> * Disabled:
> * Host: t520.local
> * System: ElectroBSD t520.local 13.1-STABLE ElectroBSD 13.1-STABLE #28 electrobsd-n252821-8ff5d83a0f97: Sat Sep 24 14:45:58 UTC 2022fk_at_t520.local:/usr/obj/usr/src/amd64.amd64/sys/ELECTRO_BEER amd64
> * OS: freebsd
> *
> *** DISABLES memory tracking when using threaded resolver
> *
> * Servers: SSL HTTP-IPv6 HTTP-unix FTP-IPv6
> * Env: Valgrind
> * Seed: 257280
> * Unix socket paths:
> * HTTP-Unix:http8380.sock
> * Socks-Unix:/home/fk/git/curl/tests/socks8380.sock
> *****************************************
> DISABLED: test 323
> DISABLED: test 594
> DISABLED: test 836
> DISABLED: test 882
> DISABLED: test 938
> DISABLED: test 1182
> DISABLED: test 1184
> DISABLED: test 1209
> DISABLED: test 1211
> DISABLED: test 1307
> DISABLED: test 1316
> DISABLED: test 1510
> DISABLED: test 1512
> DISABLED: test 1801
> DISABLED: test 2086
> DISABLED: test 2043
> startnew: ./negtelnetserver.py --port 32151 --pidfile ".telnet_server.pid" --logfile "log/telnet_server.log" --srcdir "."
> RUN: TELNET server PID 87063 port 32151
> * pid neg TELNET => 87063 87063
> test 1452...[Basic TELNET negotiation]
> /usr/local/bin/valgrind --tool=memcheck --quiet --leak-check=yes --suppressions=./valgrind.supp --num-callers=16 --log-file=log/valgrind1452 ../src/curl --include --trace-ascii log/trace1452 --trace-timetelnet://127.0.0.1:32151 --upload-file - <log/stdin-for-1452 >log/stdout1452 2>log/stderr1452
> CMD (14336): /usr/local/bin/valgrind --tool=memcheck --quiet --leak-check=yes --suppressions=./valgrind.supp --num-callers=16 --log-file=log/valgrind1452 ../src/curl --include --trace-ascii log/trace1452 --trace-timetelnet://127.0.0.1:32151 --upload-file - <log/stdin-for-1452 >log/stdout1452 2>log/stderr1452
>
> curl returned 56, when expecting 0
> exit FAILED
>
> - abort tests
> * kill pid for telnet => 87063
> RUN: Process with pid 87063 signalled to die
> RUN: Process with pid 87063 forced to die with SIGKILL
> TESTDONE: 1 tests were considered during 3 seconds.
> TESTDONE: 0 tests out of 1 reported OK: 0%
>
> TESTFAIL: These test cases failed: 1452
>
> fk_at_t520 ~/git/curl/tests $cat log/trace1452
> 13:43:19.609877 == Info: STATE: INIT => CONNECT handle 0x5b7d5e8; line 1880 (connection #-5000)
> 13:43:19.703006 == Info: Added connection 0. The cache now contains 1 members
> 13:43:19.721972 == Info: family0 == v4, family1 == v6
> 13:43:19.729215 == Info: Trying 127.0.0.1:32151...
> 13:43:19.737885 == Info: STATE: CONNECT => CONNECTING handle 0x5b7d5e8; line 1941 (connection #0)
> 13:43:19.759007 == Info: Connected to 127.0.0.1 (127.0.0.1) port 32151 (#0)
> 13:43:19.760004 == Info: STATE: CONNECTING => PROTOCONNECT handle 0x5b7d5e8; line 2075 (connection #0)
> 13:43:19.762026 == Info: STATE: PROTOCONNECT => DO handle 0x5b7d5e8; line 2096 (connection #0)
> 13:43:19.769679 == Info: RCVD DO NEW-ENVIRON
> 13:43:19.772434 == Info: SENT WONT NEW-ENVIRON
> 13:43:19.774137 == Info: SENT WILL BINARY
> 13:43:19.775047 == Info: SENT DO BINARY
> 13:43:19.775508 == Info: SENT WILL SUPPRESS GO AHEAD
> 13:43:19.775739 == Info: SENT DO SUPPRESS GO AHEAD
> 13:43:19.781168 == Info: RCVD WILL NEW-ENVIRON
> 13:43:19.782089 == Info: SENT DONT NEW-ENVIRON
> 13:43:19.782580 == Info: RCVD DONT NAWS
> 13:43:19.783326 == Info: RCVD WONT NAWS
> 13:43:19.792238 == Info: Recv failure: Connection reset by peer
> 13:43:19.795258 == Info: multi_done: status: 56 prem: 0 done: 0
> 13:43:19.810885 == Info: The cache now contains 0 members
> 13:43:19.813519 == Info: Closing connection 0
> 13:43:19.824535 == Info: Expire cleared (transfer 0x5b7d5e8)
>
> I usually run the tests without valgrind so I'm not sure if
> this is a recent regression.
>
> Is anyone else seeing this?
>
> Fabian
>

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

Received on 2022-09-25