Skip to content

curl 7.87.0 test 0313 [CRL test] failing on EL-9 #10135

@pghmcfc

Description

@pghmcfc

I did this

Updated my curl packaging from 7.86.0 to 7.87.0 and built for current Fedora and RHEL releases (RHEL builds on Rocky Linux, an RHEL clone).

I expected the following

All builds completing successfully. And they did, except for the build on Rocky Linux 9.

curl/libcurl version

7.87.0

[curl -V output]
Don't get as far as a built curl package but here are the system characteristics from the start of the test run:

 ********* System characteristics ******** 
* curl 7.87.0 (x86_64-redhat-linux-gnu)
* libcurl/7.87.0 OpenSSL/3.0.1 zlib/1.2.11 libidn2/2.3.0 nghttp2/1.43.0 
* Features: alt-svc AsynchDNS GSS-API HSTS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile libz SPNEGO SSL threadsafe UnixSockets
* Disabled: 
* Host: 329c6f4b6550494fa67371c7360baef3 
* System: Linux 329c6f4b6550494fa67371c7360baef3 6.0.12-300.fc37.x86_64 #1 SMP PREEMPT_DYNAMIC Thu Dec 8 16:58:47 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
* OS: linux
* Servers: SSL HTTP-IPv6 HTTP-unix FTP-IPv6  
* Env: 
* Seed: 264484 
* Unix socket paths:
*   HTTP-Unix:http71383.sock
*   Socks-Unix:/builddir/build/BUILD/curl-7.87.0/build-minimal/tests/socks71383.sock
*****************************************

operating system

I am building on a Fedora 37 (x86_64) host using a chroot-based build system targeting Rocky Linux 9 (x86_64).

Here is the build output from the failing test:

-------e--- OK (312 out of 1544, remaining: 09:00, took 7.351s, duration: 02:16)
RUN: Process with pid 75961 signalled to die
RUN: Process with pid 75977 signalled to die
RUN: Process with pid 75981 signalled to die
RUN: Process with pid 75981 gracefully died
RUN: Process with pid 75961 forced to die with SIGKILL
RUN: Process with pid 75977 forced to die with SIGKILL 
startnew: perl -I../../tests ../../tests/httpserver.pl --pidfile ".http_server.pid" --logfile "log/http_server.log" --portfile .http_server.port --ipv4 --port 0 --srcdir "../../tests/data/.." 
RUN: ../src/curl --max-time 13 --output log/http_verify.out --silent --verbose --globoff "http://127.0.0.1:35713/verifiedserver" 2>log/http_verify.log
CMD (0): ../src/curl --max-time 13 --output log/http_verify.out --silent --verbose --globoff "http://127.0.0.1:35713/verifiedserver" 2>log/http_verify.log
RUN: HTTP server is on PID 76002 port 35713
* pid http => 76002 76002
startnew: perl -I../../tests ../../tests/secureserver.pl --pidfile ".https_server.pid" --logfile "log/https_stunnel.log" --ipv4 --proto https --certfile "Server-localhost-sv.pem" --stunnel "/usr/bin/stunnel" --srcdir "../../tests" --connect 35713 --accept 25073
RUN: HTTPS server is PID 76018 port 25073
* pid https => 76018 76022
prechecked /usr/bin/perl -e "print 'Test requires default test server host' if ( '127.0.0.1' ne '127.0.0.1' );"
test 0313...[CRL test]
../src/curl --output log/curl313.out  --include --trace-ascii log/trace313 --trace-time --cacert ../../tests/certs/EdelCurlRoot-ca.crt --crlfile ../../tests/certs/Server-localhost-sv.crl https://localhost:25073/313 >log/stdout313 2>log/stderr313
CMD (8960): ../src/curl --output log/curl313.out  --include --trace-ascii log/trace313 --trace-time --cacert ../../tests/certs/EdelCurlRoot-ca.crt --crlfile ../../tests/certs/Server-localhost-sv.crl https://localhost:25073/313 >log/stdout313 2>log/stderr313
curl returned 35, when expecting 60
 exit FAILED 
== Contents of files in the log/ dir after test 313
=== Start of file commands.log
 ../src/curl --output log/curl313.out  --include --trace-ascii log/trace313 --trace-time --cacert ../../tests/certs/EdelCurlRoot-ca.crt --crlfile ../../tests/certs/Server-localhost-sv.crl https://localhost:25073/313 >log/stdout313 2>log/stderr313
=== End of file commands.log 
=== Start of file ftpserver.cmd
 Testnum 313
=== End of file ftpserver.cmd
=== Start of file http_server.log
 22:21:17.184802 exit_signal_handler: 15
 22:21:17.185144 signalled to die
 22:21:17.185232 ========> IPv4 sws (port 37921 pid: 75961) exits with signal (15)
 22:21:22.245861 Running HTTP IPv4 version on port 35713
 22:21:22.245946 Wrote pid 76002 to .http_server.pid
 22:21:22.245973 Wrote port 35713 to .http_server.port
 22:21:23.244589 ====> Client connect
 22:21:23.244675 accept_connection 3 returned 4
 22:21:23.244725 accept_connection 3 returned 0
 22:21:23.244766 Read 93 bytes
 22:21:23.244797 Process 93 bytes request
 22:21:23.244845 Got request: GET /verifiedserver HTTP/1.1
 22:21:23.244872 Are-we-friendly question received
 22:21:23.244922 Wrote request (93 bytes) input to log/server.input
 22:21:23.244981 Identifying ourselves as friends
 22:21:23.245205 Response sent (56 bytes) and written to log/server.response
 22:21:23.245244 special request received, no persistency
 22:21:23.245266 ====> Client disconnect 0
=== End of file http_server.log
=== Start of file http_verify.log
 *   Trying 127.0.0.1:35713...
 * Connected to 127.0.0.1 (127.0.0.1) port 35713 (#0)
 > GET /verifiedserver HTTP/1.1
 > Host: 127.0.0.1:35713
 > User-Agent: curl/7.87.0
 > Accept: */*
 >
 * Mark bundle as not supporting multiuse
 < HTTP/1.1 200 OK
 < Content-Length: 17
 <
 { [1 bytes data]
 * Connection #0 to host 127.0.0.1 left intact
=== End of file http_verify.log
=== Start of file http_verify.out
 WE ROOLZ: 76002
=== End of file http_verify.out
=== Start of file https_stunnel.log
 2022.12.21 22:21:23 LOG5[ui]: stunnel 5.62 on x86_64-redhat-linux-gnu platform
 2022.12.21 22:21:23 LOG5[ui]: Compiled/running with OpenSSL 3.0.1 14 Dec 2021
 2022.12.21 22:21:23 LOG5[ui]: Threading:PTHREAD Sockets:POLL,IPv6 TLS:ENGINE,FIPS,OCSP,PSK,SNI
 2022.12.21 22:21:23 LOG5[ui]: Reading configuration from file /builddir/build/BUILD/curl-7.87.0/build-minimal/tests/https_stunnel.conf
 2022.12.21 22:21:23 LOG5[ui]: UTF-8 byte order mark not detected
 2022.12.21 22:21:23 LOG5[ui]: FIPS mode disabled
 2022.12.21 22:21:23 LOG5[ui]: Configuration successful
 2022.12.21 22:21:23 LOG5[ui]: Binding service [curltest] to :::25073: Address already in use (98)
 2022.12.21 22:21:23 LOG5[cron]: Updating DH parameters
 2022.12.21 22:21:24 LOG5[0]: Service [curltest] accepted connection from 127.0.0.1:47430
 2022.12.21 22:21:24 LOG3[0]: SSL_accept: ssl/record/rec_layer_s3.c:1584: error:0A00041B:SSL routines::tlsv1 alert decrypt error
 2022.12.21 22:21:24 LOG5[0]: Connection reset: 0 byte(s) sent to TLS, 0 byte(s) sent to socket
=== End of file https_stunnel.log
=== Start of file server.response
 HTTP/1.1 200 OK
 Content-Length: 17
 WE ROOLZ: 76002
=== End of file server.response
=== Start of file stderr313
   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                  Dload  Upload   Total   Spent    Left  Speed
 
   0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
   0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
 curl: (35) OpenSSL/3.0.1: error:03000098:digital envelope routines::invalid digest
=== End of file stderr313
=== Start of file trace313
 22:21:24.309341 == Info:   Trying 127.0.0.1:25073...
 22:21:24.508941 == Info: Connected to localhost (127.0.0.1) port 25073 (#0)
 22:21:24.514959 == Info: ALPN: offers h2
 22:21:24.514984 == Info: ALPN: offers http/1.1
 22:21:24.517003 == Info:  CAfile: ../../tests/certs/EdelCurlRoot-ca.crt
 22:21:24.517026 == Info:  CApath: none
 22:21:24.517228 == Info: successfully loaded CRL file:
 22:21:24.517245 == Info:   CRLfile: ../../tests/certs/Server-localhost-sv.crl
 22:21:24.517786 == Info: [CONN-0-0][CF-SSL] TLSv1.0 (OUT), TLS header, Certificate Status (22):
 22:21:24.517804 => Send SSL data, 5 bytes (0x5)
 0000: .....
 22:21:24.517847 == Info: [CONN-0-0][CF-SSL] TLSv1.3 (OUT), TLS handshake, Client hello (1):
 22:21:24.517858 => Send SSL data, 512 bytes (0x200)
 0000: ............F.......J..y............[9 .H=s.#.1p.U.;.c..p..-..5.
 0040: ..OR....>.......,.0.........+./...$.(.k.#.'.g.....9.....3.....=.
 0080: <.5./.....u.........localhost...................................
 00c0: ......h2.http/1.1.........1.....*.(.............................
 0100: ............+............-.....3.&.$... X.3...#..2A.....7.,0....
 0140: :H..d.\q........................................................
 0180: ................................................................
 01c0: ................................................................
 22:21:24.524820 == Info: [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Certificate Status (22):
22:21:24.524852 <= Recv SSL data, 5 bytes (0x5)
 0000: ....z
 22:21:24.524893 == Info: [CONN-0-0][CF-SSL] TLSv1.3 (IN), TLS handshake, Server hello (2):
 22:21:24.524905 <= Recv SSL data, 122 bytes (0x7a)
 0000: ...v..sVH..C...is.m30..i"......!....6= .H=s.#.1p.U.;.c..p..-..5.
 0040: ..OR.........+.....3.$... W~..c.kzw70..........Uz..@v.X`SH
 22:21:24.525642 == Info: [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Finished (20):
 22:21:24.525661 <= Recv SSL data, 5 bytes (0x5)
 0000: .....
 22:21:24.525688 == Info: [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
 22:21:24.525699 <= Recv SSL data, 5 bytes (0x5)
 0000: .....
 22:21:24.525724 <= Recv SSL data, 1 bytes (0x1)
 0000: .
 22:21:24.525766 == Info: [CONN-0-0][CF-SSL] TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
 22:21:24.525777 <= Recv SSL data, 10 bytes (0xa)
 0000: ..........
 22:21:24.525804 == Info: [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
 22:21:24.525814 <= Recv SSL data, 5 bytes (0x5)
 0000: ....f
 22:21:24.525845 <= Recv SSL data, 1 bytes (0x1)
 0000: .
 22:21:24.525872 == Info: [CONN-0-0][CF-SSL] TLSv1.3 (IN), TLS handshake, Certificate (11):
 22:21:24.525881 <= Recv SSL data, 1109 bytes (0x455)
 0000: ...Q...M..H0..D0..,............f0...*.H........0h1.0...U....NN11
 0040: 0/..U...(Edel Curl Arctic Illudium Research Cloud1&0$..U....Nort
 0080: hern Nowhere Trust Anchor0...221125123246Z..310211123246Z0T1.0..
 00c0: .U....NN110/..U...(Edel Curl Arctic Illudium Research Cloud1.0..
 0100: .U....localhost0.."0...*.H.............0.........h2O..O}2.......
 0140: d|-...+.T..r]..9..u.......G.......(&& ,|*...)x-.>o.........v..Xj
 0180: 9.....=.GYQ_....B..B..O[V../.c{......>..N...D..N...bj6cP....".#.
 01c0: ...\...c.....F...R..{.[......9..P.....`..&Y."..W.1....jZ......q.
 0200: ..*..z.....s..r.....7s..^.....fK..\....k.................0...0..
 0240: .U....0...localhost0...U........0...U.%..0...+.......0...U......
 0280: dg......A.b.v...).2A0...U.#..0...R@..O.X)..g.........0...U....0.
 02c0: 0C..+........70503..+.....0..'http://test.curl.se/ca/EdelCurlRoo
 0300: t.cer08..U...10/0-.+.).'http://test.curl.se/ca/EdelCurlRoot.crl0
 0340: ...*.H.............1.c.../.Z.....I...........3v.....T..M.S....Q.
 0380: l82..V..."E......,6A..X..~TA..`..T.g..+......(..=...O3....4...3X
 03c0: .#..9."..1.GqM.&kP.M._.m<..-..=...>.[...1.......g.4.z..W...>....
 0400: 0VM1.e}j:o&...;...Z...j.,....l.._v......7.....t.ST..B.@..H.../|.
 0440: .......q....Ps*"..V..
 22:21:24.527991 == Info: [CONN-0-0][CF-SSL] TLSv1.2 (OUT), TLS header, Unknown (21):
 22:21:24.528013 => Send SSL data, 5 bytes (0x5)
 0000: .....
 22:21:24.528106 == Info: [CONN-0-0][CF-SSL] TLSv1.3 (OUT), TLS alert, decrypt error (563):
 22:21:24.528120 => Send SSL data, 2 bytes (0x2)
 0000: .3
 22:21:24.528164 == Info: OpenSSL/3.0.1: error:03000098:digital envelope routines::invalid digest
 22:21:24.528309 == Info: Closing connection 0
=== End of file trace313

The equivalent test in 7.86.0 still passes in the same build environment. At first I suspected that this would be related to the more strict crypto policies in RHEL9 that disallow SHA1 signatures etc., but the certificates in this test look to be using SHA256, which should be fine. Then, whilst pasting in the build log above I noticed this inhttps_stunnel.log:

 2022.12.21 22:21:23 LOG5[ui]: Binding service [curltest] to :::25073: Address already in use (98)

This is a type of error I've seen many times before, usually when running a second iteration of the test suite for a differently-configured curl build in the same environment, where a test server from the original test run was still running. That's not the case here though, because this is the first test run. Also, I don't see any mention of the use of port 25073 earlier in the build log. That would usually lead me to suspect a service running on that port on the build host but I can't see anything there either.

I suspect that if I could persuade the test to run stunnel on a different port that it might work, but since the port numbers seem to be selected at random and based on the build environment somehow, I don't know how to do that. Any suggestions?

Ideally, the test suite could be made a bit more robust about this sort of thing if it could check that the ports needed for a test were not already in use, and pick different ports if necessary. Clearly that would be racy but better than nothing.

Metadata

Metadata

Assignees

No one assigned

    Labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions