h2_sm_acquire_stream fails at Arch Linux

[anatol]

I am trying to build aws-c-http project at Arch Linux.

The project compiles fine. But 2 tests are failing with the following cryptic error. Could anyone explain what is going on here?

645/647 Test #645: random_access_set_exist_test .....................................................   Passed    0.01 sec
        Start 646: random_access_set_remove_test
646/647 Test #646: random_access_set_remove_test ....................................................   Passed    0.01 sec
        Start 647: random_access_set_owns_element_test
647/647 Test #647: random_access_set_owns_element_test ..............................................   Passed    0.01 sec

99% tests passed, 2 tests failed out of 647

Total Test time (real) =  54.32 sec

The following tests FAILED:
	638 - h2_sm_acquire_stream (Failed)
	639 - h2_sm_acquire_stream_multiple_connections (Failed)
Errors while running CTest
Output from these tests are in: /mnt/nvme/sources/arch/community/aws-c-http/trunk/src/aws-c-http-0.6.22/build/Testing/Temporary/LastTest.log
Use "--rerun-failed --output-on-failure" to re-run the failed cases verbosely.
make: *** [Makefile:71: test] Error 8

[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [socket] - id=0x7f8484001140 fd=14: read of 175
[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [socket-handler] - id=0x7f8484012d00: read 175 from socket
[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [channel] - id=0x7f8484001da0: sending read message of size 175, from slot 0x7f8484006330 to slot 0x7f84840062e0 with handler 0x7f8484012f40.
[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [tls-handler] - id=0x7f8484012f40: Downstream window 18446744073709551615
[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [channel] - id=0x7f8484001da0: acquired message 0x7f848400e580 of capacity 16384 from pool 0x7f8484001b60. Requested size was 18446744073709551615
[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [tls-handler] - id=0x7f8484012f40: Bytes read 13
[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [channel] - id=0x7f8484001da0: sending read message of size 13, from slot 0x7f84840062e0 to slot 0x7f8484028c60 with handler 0x7f8484016398.
[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [http-connection] - id=0x7f8484016390: Begin processing message of size 13.
[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [http-decoder] - id=0x7f8484016390 Running state 'prefix' with 13 bytes available
[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [http-decoder] - id=0x7f8484016390 Done decoding frame prefix (type=RST_STREAM stream-id=1 payload-len=4), moving on to payload
[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [http-decoder] - id=0x7f8484016390 Moving from state 'prefix' to 'frame_rst_stream'
[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [http-decoder] - id=0x7f8484016390 Running state 'frame_rst_stream' with 4 bytes available
[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [http-decoder] - id=0x7f8484016390 Invoking callback on_rst_stream
[ERROR] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [http-stream] - id=1 connection=0x7f8484016390 state=HALF_CLOSED_LOCAL: Peer terminated stream with HTTP/2 RST_STREAM frame, error-code=0x1(PROTOCOL_ERROR)
[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [http-stream] - id=1 connection=0x7f8484016390 state=CLOSED: Received RST_STREAM code=0x1(PROTOCOL_ERROR). State -> CLOSED
[ERROR] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [http-stream] - id=1 connection=0x7f8484016390 state=CLOSED: Stream completed with error 2077 (AWS_ERROR_HTTP_RST_STREAM_RECEIVED).
[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [http2-stream-manager] - id=0x55c542674590: Stream manager internal counts status: connection acquiring=0, streams opening=4, pending make request count=0, pending acquisition count=0, holding connections count=1
[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [http-stream] - id=0x7f848401a110: Stream refcount released, 1 remaining.
[TRACE] [2022-10-18T17:13:30Z] [00007f84977fe6c0] [http-decoder] - id=0x7f8484016390 RST_STREAM frame complete


......

id=9 payload-len=4), moving on to payload
[TRACE] [2022-10-18T17:13:30Z] [00007f77a55fa6c0] [http-decoder] - id=0x7f7788015c50 Moving from state 'prefix' to 'frame_rst_stream'
[TRACE] [2022-10-18T17:13:30Z] [00007f77a55fa6c0] [http-decoder] - id=0x7f7788015c50 Running state 'frame_rst_stream' with 4 bytes available
[TRACE] [2022-10-18T17:13:30Z] [00007f77a55fa6c0] [http-decoder] - id=0x7f7788015c50 Invoking callback on_rst_stream
[ERROR] [2022-10-18T17:13:30Z] [00007f77a55fa6c0] [http-stream] - id=9 connection=0x7f7788015c50 state=HALF_CLOSED_LOCAL: Peer terminated stream with HTTP/2 RST_STREAM frame, error-code=0x1(PROTOCOL_ERROR)
[TRACE] [2022-10-18T17:13:30Z] [00007f77a55fa6c0] [http-stream] - id=9 connection=0x7f7788015c50 state=CLOSED: Received RST_STREAM code=0x1(PROTOCOL_ERROR). State -> CLOSED
[ERROR] [2022-10-18T17:13:30Z] [00007f77a55fa6c0] [http-stream] - id=9 connection=0x7f7788015c50 state=CLOSED: Stream completed with error 2077 (AWS_ERROR_HTTP_RST_STREAM_RECEIVED).
[TRACE] [2022-10-18T17:13:30Z] [00007f77a55fa6c0] [http2-stream-manager] - id=0x560194654650: Stream manager internal counts status: connection acquiring=0, streams opening=0, pending make request count=0, pending acquisition count=0, holding connections count=1
[DEBUG] [2022-10-18T17:13:30Z] [00007f77a55fa6c0] [http2-stream-manager] - id=0x560194654650: Release connection:0x7f7788015c50 back to connection manager as no outstanding streams
[DEBUG] [2022-10-18T17:13:30Z] [00007f77a55fa6c0] [connection-manager] - id=0x560194679b70: User releasing connection (id=0x7f7788015c50)
***FAILURE*** 20 != 0: ***FAILURE*** [DEBUG] [2022-10-18T17:13:30Z] [00007f77a55fa6c0] [connection-manager] - id=0x560194679b70: snapshot - state=1, idle_connection_count=2, pending_acquire_count=0, pending_settings_count=1, pending_connect_count=0, vended_connection_count=0, open_connection_count=3, ref_count=1
[TRACE] [2022-10-18T17:13:30Z] [00007f77a55fa6c0] [http-stream] - id=0x7f778803be70: Stream refcount released, 1 remaining.
[TRACE] [2022-10-18T17:13:30Z] [00007f77a55fa6c0] [http-decoder] - id=0x7f7788015c50 RST_STREAM frame complete
[TRACE] [2022-10-18T17:13:30Z] [00007f77a55fa6c0] [http-decoder] - id=0x7f7788015c50 State 'prefix' requires 9 bytes, but only 0 available, trying again later
num_to_acquire != s_tester.stream_200_count [s_test_h2_sm_acquire_stream_multiple_connections():/mnt/nvme/sources/arch/community/aws-c-http/trunk/src/aws-c-http-0.6.22/tests/test_stream_manager.c@#1217]
[TRACE] [2022-10-18T17:13:30Z] [00007f77a55fa6c0] [channel] - id=0x7f7788001b00: acquired message 0x7f778800a1c0 of capacity 16384 from pool 0x7f7788001700. Requested size was 18446744073709551550
No call stack information available
***FAILURE*** h2_sm_acquire_stream_multiple_connections [ FAILED ] [s_aws_run_test_case():/usr/include/aws/testing/aws_test_harness.h@#456]
<end of output>
Test time =   0.30 sec
----------------------------------------------------------
Test Failed.
"h2_sm_acquire_stream_multiple_connections" end time: Oct 18 10:13 PDT
"h2_sm_acquire_stream_multiple_connections" time elapsed: 00:00:00
----------------------------------------------------------

[h-vetinari]

We observe the same failure on windows in conda-forge when compiled against aws-c-io 0.3.15 resp. 0.3.16; other architectures are fine though.

[h-vetinari]

@graebm @JonathanHenson @sbSteveK @TingDaoK
Sorry for the direct ping out of the blue, but could you have a look here please? This is blocking some pretty intertwined upgrade paths in conda-forge, which we depend on to keep supporting aws-bindings in pyarrow

Background: it's been ~one year waiting for a fix for aws/aws-sdk-cpp#1809; now that a fix apparently landed in aws-c-io 0.3.15, that very version seems to break something in aws-c-http; since aws-sdk-cpp 1.8 (pinned in arrow to avoid the above-mentioned bug) is now not compatible with newer aws-c-* packages anymore, we're pretty stuck.

This repo doesn't seem to have a lot of activity (hence the ping, apologies), but if we cannot figure this out, it's likely we'll have to fall back to disabling the aws-bindings in pyarrow, unfortunately.

Any help would be appreciated.

[waahm7]

Thank you for reporting the issue. It is fixed in aws-c-http v0.6.24. Please reopen the issue if required.

[h-vetinari]

Tested in conda-forge/aws-c-http-feedstock#84 & it worked - thanks a lot! :)