Rustls: test_09_02_h2_push frequent SIGSEGV in CI

[vszakats]

I did this

Started seeing this on Linux in the Rustls job's pytests:

=================================== FAILURES ===================================
_________________________ TestPush.test_09_02_h2_push __________________________

self = <test_09_push.TestPush object at 0x7f2f1c44e330>
env = <testenv.env.Env object at 0x7f2f1c479d60>
httpd = <testenv.httpd.Httpd object at 0x7f2f1c479e20>

    def test_09_02_h2_push(self, env: Env, httpd):
        # use localhost as we do not have resolve support in local client
        url = f'https://localhost:{env.https_port}/push/data1'
        client = LocalClient(name='h2-serverpush', env=env)
        if not client.exists():
            pytest.skip(f'example client not built: {client.name}')
        r = client.run(args=[url])
>       r.check_exit_code(0)

../../tests/http/test_09_push.py:82: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = ExecResult[code=-11, exception=None, args=['/home/runner/work/curl/curl/bld/tests/../tests/http/clients/h2-serverpush'...tes (0x2f)\n', '0000: server: Apache/2.4.58 (Ubuntu) OpenSSL/3.0.13\n', '<= Recv header, 2 bytes (0x2)\n', '0000: \n']]
code = 0

    def check_exit_code(self, code: Union[int, bool]):
        if code is True:
            assert self.exit_code == 0, f'expected exit code {code}, '\
                                        f'got {self.exit_code}\n{self.dump_logs()}'
        elif code is False:
            assert self.exit_code != 0, f'expected exit code {code}, '\
                                                f'got {self.exit_code}\n{self.dump_logs()}'
        else:
>           assert self.exit_code == code, f'expected exit code {code}, '\
                                           f'got {self.exit_code}\n{self.dump_logs()}'
E           AssertionError: expected exit code 0, got -11
E             >>--stdout ----------------------------------------------
E             >>--stderr ----------------------------------------------
E             == Info: !!! WARNING !!!
E             == Info: This is a debug build of libcurl, do not use in production.
E             == Info: Host localhost:44991 was resolved.
E             == Info: IPv6: ::1
E             == Info: IPv4: 127.0.0.1
E             == Info:   Trying [::1]:44991...
E             == Info: ALPN: curl offers h2,http/1.1
E             == Info: ALPN: server accepted h2
E             == Info: rustls: handshake complete, TLSv1.3, cipher: TLS_AES_256_GCM_SHA384
E             == Info: Connected to localhost (::1) port 44991
E             == Info: using HTTP/2
E             == Info: sending last upload chunk of 62 bytes
E             == Info: [HTTP/2] [1] OPENED stream for https://localhost:44991/push/data1
E             == Info: [HTTP/2] [1] [:method: GET]
E             == Info: [HTTP/2] [1] [:scheme: https]
E             == Info: [HTTP/2] [1] [:authority: localhost:44991]
E             == Info: [HTTP/2] [1] [:path: /push/data1]
E             == Info: [HTTP/2] [1] [accept: */*]
E             == Info: Curl_xfer_send(len=62, eos=1) -> 0, 62
E             => Send header, 62 bytes (0x3e)
E             0000: GET /push/data1 HTTP/2
E             0018: Host: localhost:44991
E             002f: Accept: */*
E             003c: 
E             == Info: Request completely sent off
E             **** push callback approves stream 1, got 6 headers!
E             **** header 0: :scheme:https
E             **** header 1: :authority:localhost:44991
E             **** header 2: :path:/push/data2
E             **** header 3: :method:GET
E             **** header 4: accept:*/*
E             **** header 5: host:localhost:44991
E             **** The PATH is /push/data2
E             == Info: HTTP/2 found, allow multiplexing
E             <= Recv header, 13 bytes (0xd)
E             0000: HTTP/2 103 
E             <= Recv header, 34 bytes (0x22)
E             0000: link: </push/data2>; rel=preload
E             <= Recv header, 22 bytes (0x16)
E             0000: push-policy: default
E             <= Recv header, 2 bytes (0x2)
E             0000: 
E             == Info: http/2 recv on a transfer never opened or already cleared, mid=1
E             == Info: sendrecv_dl() -> 16
E             == Info: Curl_sendrecv() -> 16
E             == Info: HTTP/2 found, allow multiplexing
E             <= Recv header, 13 bytes (0xd)
E             0000: HTTP/2 200 
E             <= Recv header, 46 bytes (0x2e)
E             0000: last-modified: Sun, 30 Mar 2025 21:35:23 GMT
E             <= Recv header, 29 bytes (0x1d)
E             0000: etag: W/"400-6319614c9dd17"
E             <= Recv header, 22 bytes (0x16)
E             0000: accept-ranges: bytes
E             <= Recv header, 22 bytes (0x16)
E             0000: content-length: 1024
E             <= Recv header, 37 bytes (0x25)
E             0000: date: Sun, 30 Mar 2025 21:35:23 GMT
E             <= Recv header, 47 bytes (0x2f)
E             0000: server: Apache/2.4.58 (Ubuntu) OpenSSL/3.0.13
E             <= Recv header, 2 bytes (0x2)
E             0000: 
E             <<-------------------------------------------------------
E             
E           assert -11 == 0
E            +  where -11 = ExecResult[code=-11, exception=None, args=['/home/runner/work/curl/curl/bld/tests/../tests/http/clients/h2-serverpush', 'https://localhost:44991/push/data1'], stdout=[], stderr=['== Info: !!! WARNING !!!\n', '== Info: This is a debug build of libcurl, do not use in production.\n', '== Info: Host localhost:44991 was resolved.\n', '== Info: IPv6: ::1\n', '== Info: IPv4: 127.0.0.1\n', '== Info:   Trying [::1]:44991...\n', '== Info: ALPN: curl offers h2,http/1.1\n', '== Info: ALPN: server accepted h2\n', '== Info: rustls: handshake complete, TLSv1.3, cipher: TLS_AES_256_GCM_SHA384\n', '== Info: Connected to localhost (::1) port 44991\n', '== Info: using HTTP/2\n', '== Info: sending last upload chunk of 62 bytes\n', '== Info: [HTTP/2] [1] OPENED stream for https://localhost:44991/push/data1\n', '== Info: [HTTP/2] [1] [:method: GET]\n', '== Info: [HTTP/2] [1] [:scheme: https]\n', '== Info: [HTTP/2] [1] [:authority: localhost:44991]\n', '== Info: [HTTP/2] [1] [:path: /push/data1]\n', '== Info: [HTTP/2] [1] [accept: */*]\n', '== Info: Curl_xfer_send(len=62, eos=1) -> 0, 62\n', '=> Send header, 62 bytes (0x3e)\n', '0000: GET /push/data1 HTTP/2\n', '0018: Host: localhost:44991\n', '002f: A...', '**** header 4: accept:*/*\n', '**** header 5: host:localhost:44991\n', '**** The PATH is /push/data2\n', '== Info: HTTP/2 found, allow multiplexing\n', '<= Recv header, 13 bytes (0xd)\n', '0000: HTTP/2 103 \n', '<= Recv header, 34 bytes (0x22)\n', '0000: link: </push/data2>; rel=preload\n', '<= Recv header, 22 bytes (0x16)\n', '0000: push-policy: default\n', '<= Recv header, 2 bytes (0x2)\n', '0000: \n', '== Info: http/2 recv on a transfer never opened or already cleared, mid=1\n', '== Info: sendrecv_dl() -> 16\n', '== Info: Curl_sendrecv() -> 16\n', '== Info: HTTP/2 found, allow multiplexing\n', '<= Recv header, 13 bytes (0xd)\n', '0000: HTTP/2 200 \n', '<= Recv header, 46 bytes (0x2e)\n', '0000: last-modified: Sun, 30 Mar 2025 21:35:23 GMT\n', '<= Recv header, 29 bytes (0x1d)\n', '0000: etag: W/"400-6319614c9dd17"\n', '<= Recv header, 22 bytes (0x16)\n', '0000: accept-ranges: bytes\n', '<= Recv header, 22 bytes (0x16)\n', '0000: content-length: 1024\n', '<= Recv header, 37 bytes (0x25)\n', '0000: date: Sun, 30 Mar 2025 21:35:23 GMT\n', '<= Recv header, 47 bytes (0x2f)\n', '0000: server: Apache/2.4.58 (Ubuntu) OpenSSL/3.0.13\n', '<= Recv header, 2 bytes (0x2)\n', '0000: \n']].exit_code

../../tests/http/testenv/curl.py:326: AssertionError
=========================== short test summary info ============================
FAILED ../../tests/http/test_09_push.py::TestPush::test_09_02_h2_push - AssertionError: expected exit code 0, got -11
  >>--stdout ----------------------------------------------
  >>--stderr ----------------------------------------------
  == Info: !!! WARNING !!!
  == Info: This is a debug build of libcurl, do not use in production.
  == Info: Host localhost:44991 was resolved.
  == Info: IPv6: ::1
  == Info: IPv4: 127.0.0.1
  == Info:   Trying [::1]:44991...
  == Info: ALPN: curl offers h2,http/1.1
  == Info: ALPN: server accepted h2
  == Info: rustls: handshake complete, TLSv1.3, cipher: TLS_AES_256_GCM_SHA384
  == Info: Connected to localhost (::1) port 44991
  == Info: using HTTP/2
  == Info: sending last upload chunk of 62 bytes
  == Info: [HTTP/2] [1] OPENED stream for https://localhost:44991/push/data1
  == Info: [HTTP/2] [1] [:method: GET]
  == Info: [HTTP/2] [1] [:scheme: https]
  == Info: [HTTP/2] [1] [:authority: localhost:44991]
  == Info: [HTTP/2] [1] [:path: /push/data1]
  == Info: [HTTP/2] [1] [accept: */*]
  == Info: Curl_xfer_send(len=62, eos=1) -> 0, 62
  => Send header, 62 bytes (0x3e)
  0000: GET /push/data1 HTTP/2
  0018: Host: localhost:44991
  002f: Accept: */*
  003c: 
  == Info: Request completely sent off
  **** push callback approves stream 1, got 6 headers!
  **** header 0: :scheme:https
  **** header 1: :authority:localhost:44991
  **** header 2: :path:/push/data2
  **** header 3: :method:GET
  **** header 4: accept:*/*
  **** header 5: host:localhost:44991
  **** The PATH is /push/data2
  == Info: HTTP/2 found, allow multiplexing
  <= Recv header, 13 bytes (0xd)
  0000: HTTP/2 103 
  <= Recv header, 34 bytes (0x22)
  0000: link: </push/data2>; rel=preload
  <= Recv header, 22 bytes (0x16)
  0000: push-policy: default
  <= Recv header, 2 bytes (0x2)
  0000: 
  == Info: http/2 recv on a transfer never opened or already cleared, mid=1
  == Info: sendrecv_dl() -> 16
  == Info: Curl_sendrecv() -> 16
  == Info: HTTP/2 found, allow multiplexing
  <= Recv header, 13 bytes (0xd)
  0000: HTTP/2 200 
  <= Recv header, 46 bytes (0x2e)
  0000: last-modified: Sun, 30 Mar 2025 21:35:23 GMT
  <= Recv header, 29 bytes (0x1d)
  0000: etag: W/"400-6319614c9dd17"
  <= Recv header, 22 bytes (0x16)
  0000: accept-ranges: bytes
  <= Recv header, 22 bytes (0x16)
  0000: content-length: 1024
  <= Recv header, 37 bytes (0x25)
  0000: date: Sun, 30 Mar 2025 21:35:23 GMT
  <= Recv header, 47 bytes (0x2f)
  0000: server: Apache/2.4.58 (Ubuntu) OpenSSL/3.0.13
  <= Recv header, 2 bytes (0x2)
  0000: 
  <<-------------------------------------------------------
  
assert -11 == 0
 +  where -11 = ExecResult[code=-11, exception=None, args=['/home/runner/work/curl/curl/bld/tests/../tests/http/clients/h2-serverpush', 'https://localhost:44991/push/data1'], stdout=[], stderr=['== Info: !!! WARNING !!!\n', '== Info: This is a debug build of libcurl, do not use in production.\n', '== Info: Host localhost:44991 was resolved.\n', '== Info: IPv6: ::1\n', '== Info: IPv4: 127.0.0.1\n', '== Info:   Trying [::1]:44991...\n', '== Info: ALPN: curl offers h2,http/1.1\n', '== Info: ALPN: server accepted h2\n', '== Info: rustls: handshake complete, TLSv1.3, cipher: TLS_AES_256_GCM_SHA384\n', '== Info: Connected to localhost (::1) port 44991\n', '== Info: using HTTP/2\n', '== Info: sending last upload chunk of 62 bytes\n', '== Info: [HTTP/2] [1] OPENED stream for https://localhost:44991/push/data1\n', '== Info: [HTTP/2] [1] [:method: GET]\n', '== Info: [HTTP/2] [1] [:scheme: https]\n', '== Info: [HTTP/2] [1] [:authority: localhost:44991]\n', '== Info: [HTTP/2] [1] [:path: /push/data1]\n', '== Info: [HTTP/2] [1] [accept: */*]\n', '== Info: Curl_xfer_send(len=62, eos=1) -> 0, 62\n', '=> Send header, 62 bytes (0x3e)\n', '0000: GET /push/data1 HTTP/2\n', '0018: Host: localhost:44991\n', '002f: A...', '**** header 4: accept:*/*\n', '**** header 5: host:localhost:44991\n', '**** The PATH is /push/data2\n', '== Info: HTTP/2 found, allow multiplexing\n', '<= Recv header, 13 bytes (0xd)\n', '0000: HTTP/2 103 \n', '<= Recv header, 34 bytes (0x22)\n', '0000: link: </push/data2>; rel=preload\n', '<= Recv header, 22 bytes (0x16)\n', '0000: push-policy: default\n', '<= Recv header, 2 bytes (0x2)\n', '0000: \n', '== Info: http/2 recv on a transfer never opened or already cleared, mid=1\n', '== Info: sendrecv_dl() -> 16\n', '== Info: Curl_sendrecv() -> 16\n', '== Info: HTTP/2 found, allow multiplexing\n', '<= Recv header, 13 bytes (0xd)\n', '0000: HTTP/2 200 \n', '<= Recv header, 46 bytes (0x2e)\n', '0000: last-modified: Sun, 30 Mar 2025 21:35:23 GMT\n', '<= Recv header, 29 bytes (0x1d)\n', '0000: etag: W/"400-6319614c9dd17"\n', '<= Recv header, 22 bytes (0x16)\n', '0000: accept-ranges: bytes\n', '<= Recv header, 22 bytes (0x16)\n', '0000: content-length: 1024\n', '<= Recv header, 37 bytes (0x25)\n', '0000: date: Sun, 30 Mar 2025 21:35:23 GMT\n', '<= Recv header, 47 bytes (0x2f)\n', '0000: server: Apache/2.4.58 (Ubuntu) OpenSSL/3.0.13\n', '<= Recv header, 2 bytes (0x2)\n', '0000: \n']].exit_code
============ 1 failed, 500 passed, 226 skipped in 96.49s (0:01:36) =============
FAILED: tests/CMakeFiles/curl-pytest-ci /home/runner/work/curl/curl/bld/tests/CMakeFiles/curl-pytest-ci 
cd /home/runner/work/curl/curl/bld/tests && pytest -v /home/runner/work/curl/curl/tests/http
ninja: build stopped: subcommand failed.

Error: Process completed with exit code 1.

https://github.com/curl/curl/actions/runs/14160172286/job/39664557285#step:43:803
https://github.com/curl/curl/actions/runs/14149632958/job/39641190739
https://github.com/curl/curl/actions/runs/14145043858/job/39631366961
https://github.com/curl/curl/actions/runs/14145958822/job/39633296953
https://github.com/curl/curl/actions/runs/14162991213/job/39671406439#step:43:1

I expected the following

Clean pytest run.

curl/libcurl version

master

operating system

Linux

[vszakats]

-11 means SIGSEGV.

https://docs.python.org/3/library/subprocess.html

[cpu]

👋 This is an odd one. I have somewhat limited availability today (power outages from an ice storm) but I took a quick initial peek.

Unfortunately I don't have any immediate theories. The test itself doesn't appear related to any of my recent changes (e.g. isn't using ECH, mTLS, etc) 🤔. It's possible it's shaking out a bug from the rustls-ffi update itself and not the vTLS changes. That might be an interesting avenue to try and hone in on.

I had to run the test locally ~149 times before I finally caught a failure. I loaded the core, but the backtrace doesn't give me any strong theories:

Core was generated by `/home/daniel/Code/C/curl/cmake-build-debug-rustls-ech/tests/../tests/http/clients/h2-serverpush https://localhost:39687/push/data1'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x000055555557cc65 in ?? ()
(gdb) bt
#0  0x000055555557cc65 in ?? ()
#1  0x00007ffff7ed4d08 in trc_write (data=0x55555557c9f8, type=CURLINFO_TEXT, ptr=0x7fffffff2810 "Internal NULL stream\n", size=21) at /home/daniel/Code/C/curl/lib/curl_trc.c:62
#2  0x00007ffff7ed4c6d in Curl_failf (data=0x55555557c9f8, fmt=0x7ffff7f9164a "Internal NULL stream") at /home/daniel/Code/C/curl/lib/curl_trc.c:198
#3  0x00007ffff7f0c8b2 in on_header (session=0x555555569aa0, frame=0x555555569d78, name=0x7ffff7911a9e ":status", namelen=7, value=0x55555557c918 "103", valuelen=3, flags=0 '\000',
    userp=0x555555569258) at /home/daniel/Code/C/curl/lib/http2.c:1591
#4  0x00007ffff79077d2 in nghttp2_session_mem_recv2 () from /nix/store/j17zmzz6z8fi8rd2yqk36n5jy8whzfhy-nghttp2-1.61.0-lib/lib/libnghttp2.so.14
#5  0x00007ffff7f0f7f6 in h2_process_pending_input (cf=0x555555569258, data=0x55555555be28, err=0x7fffffff2c4c) at /home/daniel/Code/C/curl/lib/http2.c:649
#6  0x00007ffff7f0abe6 in h2_progress_ingress (cf=0x555555569258, data=0x55555555be28, data_max_bytes=14104) at /home/daniel/Code/C/curl/lib/http2.c:2093
#7  0x00007ffff7f08a40 in cf_h2_recv (cf=0x555555569258, data=0x55555555be28, buf=0x555555573d48 "", len=16384, err=0x7fffffff2e24) at /home/daniel/Code/C/curl/lib/http2.c:2134
#8  0x00007ffff7ec0154 in Curl_cf_def_recv (cf=0x55555555e8f8, data=0x55555555be28, buf=0x555555573d48 "", len=16384, err=0x7fffffff2e24) at /home/daniel/Code/C/curl/lib/cfilters.c:113
#9  0x00007ffff7ec0a13 in Curl_cf_recv (data=0x55555555be28, num=0, buf=0x555555573d48 "", len=16384, code=0x7fffffff2e24) at /home/daniel/Code/C/curl/lib/cfilters.c:250
#10 0x00007ffff7ec302e in Curl_conn_recv (data=0x55555555be28, sockindex=0, buf=0x555555573d48 "", blen=16384, n=0x7fffffff2eb8) at /home/daniel/Code/C/curl/lib/cfilters.c:917
#11 0x00007ffff7f5e4f0 in Curl_xfer_recv (data=0x55555555be28, buf=0x555555573d48 "", blen=16384, pnrcvd=0x7fffffff2eb8) at /home/daniel/Code/C/curl/lib/transfer.c:963
#12 0x00007ffff7f5e72c in xfer_recv_resp (data=0x55555555be28, buf=0x555555573d48 "", blen=16384, eos_reliable=true, err=0x7fffffff2f4c) at /home/daniel/Code/C/curl/lib/transfer.c:236
#13 0x00007ffff7f5c8d3 in sendrecv_dl (data=0x55555555be28, k=0x55555555bf10, didwhat=0x7fffffff2f90) at /home/daniel/Code/C/curl/lib/transfer.c:306
#14 0x00007ffff7f5c434 in Curl_sendrecv (data=0x55555555be28, nowp=0x7fffffff3128) at /home/daniel/Code/C/curl/lib/transfer.c:441
#15 0x00007ffff7f31b8d in state_performing (data=0x55555555be28, nowp=0x7fffffff3128, stream_errorp=0x7fffffff3097, resultp=0x7fffffff309c) at /home/daniel/Code/C/curl/lib/multi.c:1749
#16 0x00007ffff7f2da94 in multi_runsingle (multi=0x5555555592a8, nowp=0x7fffffff3128, data=0x55555555be28) at /home/daniel/Code/C/curl/lib/multi.c:2441
#17 0x00007ffff7f2cf72 in curl_multi_perform (m=0x5555555592a8, running_handles=0x7fffffff3184) at /home/daniel/Code/C/curl/lib/multi.c:2617
#18 0x000055555555534d in main (argc=2, argv=0x7fffffff32d8) at /home/daniel/Code/C/curl/tests/http/clients/h2-serverpush.c:235

[cpu]

With some more luck + iteration locally I was able to get an ASAN trace: https://gist.github.com/cpu/cbbe93520999f81ef422b66af977072d but I'm still unclear on the root cause

[dfandrich]

They're both failing in Curl_failf(). In the ASAN trace there is only call to Curl_failf() in cf_h2_on_invalid_frame_recv(), which has two string pointers. One points to a stack-allocated array which can't be the problem, whereas the other gets the pointer from nghttp2_strerror(). I'm guessing something fishy is going on in that function. Does the problem go away with a different version of nghttp2?

In the first backtrace, the Curl_failf() call on line 1591 is failf(data_s, "Internal NULL stream"); which has a static string argument so that can't be it. The data_s parameter comes from nghttp2_session_get_stream_user_data() so it looks like that's where the bad pointer comes from. Adding a DEBUGASSERT(data->magic == CURLEASY_MAGIC_NUMBER); in Curl_failf() would help pinpoint a bad pointer being passed in.

[icing]

Running this normally, did not reproduce in several 100 iterations, but I get it pretty fast via

> make -j20 && (cd tests && make -j20 && CURL_DBG_SOCK_RBLOCK=50 pytest -v -k "test_09_02" --count=100 --maxfail=1)

which makes the socket receive return EAGAIN 50% of the times. Using the same command line with a GnuTLS build does not trigger the crash. I do not really think rustls does anything wrong, but that it exhibits just different timings and plain data chunks. I suspect the bug to be in the http2 push code.

Investigating further...

[icing]

Fix in #16905. Nothing to do with rustls, other than different call sequences resulted, exposing the bug.

[vszakats]

Thanks @icing, @cpu!

[cpu]

thanks for flagging the flake 🤝