apache / trafficserver

Apache Traffic Server™ is a fast, scalable and extensible HTTP/1.1 and HTTP/2 compliant caching proxy server.
https://trafficserver.apache.org/
Apache License 2.0
1.82k stars 804 forks source link

H2 POST request causes crash #9857

Closed maskit closed 4 months ago

maskit commented 1 year ago

ATS master crashes while handling this request below.

$ curl -kv -d @~/tmp/8k --http2 -H "Expect: 100-Continue" https://127.0.0.1:8443/httpbin/post

Removing these 2 lines works for the crash, but I'm not sure if we can really remove those. The lines were added by the PR for H2-to-Origin. https://github.com/apache/trafficserver/blob/9909da8b5621ac85f0a474527cf7fd58a03b1ff0/proxy/http/HttpTunnel.cc#L995-L996

* thread #3, name = '[ET_NET 0]', stop reason = EXC_BAD_ACCESS (code=2, address=0x10a3a3d50)
  * frame #0: 0x00000001835f42e8 libsystem_c.dylib`getenv + 8
    frame #1: 0x00000001835f9d24 libsystem_c.dylib`_st_tzset_basic + 60
    frame #2: 0x00000001835f9cb8 libsystem_c.dylib`localtime_r + 52
    frame #3: 0x00000001836116dc libsystem_c.dylib`ctime_r + 48
    frame #4: 0x0000000104fee444 libclang_rt.asan_osx_dynamic.dylib`wrap_ctime_r + 112
    frame #5: 0x0000000103e33558 libtscore.10.dylib`(anonymous namespace)::BWF_Timestamp(w=0x000000010a3a4f00, spec=0x000000010a3a4e80) at BufferWriterFormat.cc:950:3
    frame #6: 0x0000000100fcded4 traffic_server`ts::BufferWriter& ts::BufferWriter::printv<>(this=0x000000010a3a5400, fmt=(std::__1::string_view = "] "), args=size=0) at BufferWriter.h:660:11
    frame #7: 0x0000000103e5ae54 libtscore.10.dylib`ts::FixedBufferWriter& ts::FixedBufferWriter::print<>(this=0x000000010a3a5400, fmt=(std::__1::string_view = "[{timestamp}] ")) at BufferWriter.h:887:53
    frame #8: 0x0000000103e59c5c libtscore.10.dylib`Diags::print_va(this=0x0000000108502d40, debug_tag="http_trans", diags_level=DL_Debug, loc=0x0000000101833000, format_string="Adding Server: %s", ap="pu`\a\U00000001") const at Diags.cc:254:17
    frame #9: 0x0000000103f72ef8 libtscore.10.dylib`LogMessage::message_print_helper(this=0x000000010cbb7828, fmt="Adding Server: %s", args="pu`\a\U00000001")::$_2::operator()(char const*, char*) const at LogMessage.cc:103:66
    frame #10: 0x0000000103f72dc4 libtscore.10.dylib`decltype(__f=0x000000010cbb7828, __args=0x000000010a3a6840, __args=<no value available>)::$_2&>()(std::declval<char const*>(), std::declval<char*>())) std::__1::__invoke[abi:v15006]<LogMessage::message_print_helper(char const*, DiagsLevel, SourceLocation const&, char const*, char*)::$_2&, char const*, char*>(LogMessage::message_print_helper(char const*, DiagsLevel, SourceLocation const&, char const*, char*)::$_2&, char const*&&, char*&&) at invoke.h:394:23
    frame #11: 0x0000000103f72ce0 libtscore.10.dylib`void std::__1::__invoke_void_return_wrapper<void, true>::__call<LogMessage::message_print_helper(__args=0x000000010cbb7828, __args=0x000000010a3a6840, __args=<no value available>)::$_2&, char const*, char*>(LogMessage::message_print_helper(char const*, DiagsLevel, SourceLocation const&, char const*, char*)::$_2&, char const*&&, char*&&) at invoke.h:479:9
    frame #12: 0x0000000103f72cac libtscore.10.dylib`std::__1::__function::__alloc_func<LogMessage::message_print_helper(char const*, DiagsLevel, SourceLocation const&, char const*, char*)::$_2, std::__1::allocator<LogMessage::message_print_helper(char const*, DiagsLevel, SourceLocation const&, char const*, char*)::$_2>, void (char const*, char*)>::operator(this=0x000000010cbb7828, __arg=0x000000010a3a6840, __arg=<no value available>)[abi:v15006](char const*&&, char*&&) at function.h:185:16
    frame #13: 0x0000000103f6ee54 libtscore.10.dylib`std::__1::__function::__func<LogMessage::message_print_helper(char const*, DiagsLevel, SourceLocation const&, char const*, char*)::$_2, std::__1::allocator<LogMessage::message_print_helper(char const*, DiagsLevel, SourceLocation const&, char const*, char*)::$_2>, void (char const*, char*)>::operator(this=0x000000010cbb7820, __arg=0x000000010a3a6840, __arg=<no value available>)(char const*&&, char*&&) at function.h:359:12
    frame #14: 0x0000000103f62108 libtscore.10.dylib`std::__1::__function::__value_func<void (char const*, char*)>::operator(this=0x000000010a3a6d80, __args=0x000000010a3a6840, __args=<no value available>)[abi:v15006](char const*&&, char*&&) const at function.h:512:16
    frame #15: 0x0000000103f5d26c libtscore.10.dylib`std::__1::function<void (char const*, char*)>::operator(this=0x000000010a3a6d80, __arg="Adding Server: %s", __arg="pu`\a\U00000001")(char const*, char*) const at function.h:1197:12
    frame #16: 0x0000000103f5c9bc libtscore.10.dylib`LogMessage::message_helper(this=0x0000000101833060, current_configured_interval=(__rep_ = 0), log_function=0x000000010a3a6d80, fmt="Adding Server: %s", args="pu`\a\U00000001")> const&, char const*, char*) at LogMessage.cc:59:5
    frame #17: 0x0000000103f5e584 libtscore.10.dylib`LogMessage::message_print_helper(this=0x0000000101833060, tag="http_trans", level=DL_Debug, loc=0x0000000101833000, fmt="Adding Server: %s", args="pu`\a\U00000001") at LogMessage.cc:101:3
    frame #18: 0x0000000103f60b68 libtscore.10.dylib`LogMessage::print(this=0x0000000101833060, tag="http_trans", level=DL_Debug, loc=0x0000000101833000, fmt="Adding Server: %s") at LogMessage.cc:204:3
    frame #19: 0x00000001004dcd20 traffic_server`HttpTransactHeaders::add_server_header_to_response(http_txn_conf=0x0000000113bbdce0, header=0x0000000113bbd848) at HttpTransactHeaders.cc:1177:7
    frame #20: 0x000000010042e8ac traffic_server`HttpTransact::build_response_copy(s=0x0000000113bbd108, base_response=0x0000000113bbd8c8, outgoing_response=0x0000000113bbd848, outgoing_version=(vmajor = '\x01', vminor = '\x01')) at HttpTransact.cc:4107:3
    frame #21: 0x0000000100472a74 traffic_server`HttpTransact::handle_100_continue_response(s=0x0000000113bbd108) at HttpTransact.cc:4091:5
    frame #22: 0x000000010046eb6c traffic_server`HttpTransact::handle_forward_server_connection_open(s=0x0000000113bbd108) at HttpTransact.cc:3992:5
    frame #23: 0x000000010046a1c0 traffic_server`HttpTransact::handle_response_from_server(s=0x0000000113bbd108) at HttpTransact.cc:3742:5
    frame #24: 0x0000000100430dc4 traffic_server`HttpTransact::HandleResponse(s=0x0000000113bbd108) at HttpTransact.cc:3447:5
    frame #25: 0x00000001002fa0a0 traffic_server`HttpSM::call_transact_and_set_next_state(this=0x0000000113bbd000, f=0x0000000000000000)(HttpTransact::State*)) at HttpSM.cc:7826:5
    frame #26: 0x000000010030cb68 traffic_server`HttpSM::handle_api_return(this=0x0000000113bbd000) at HttpSM.cc:1701:5
    frame #27: 0x000000010030a804 traffic_server`HttpSM::state_api_callout(this=0x0000000113bbd000, event=0, data=0x0000000000000000) at HttpSM.cc:1633:5
    frame #28: 0x0000000100372ec8 traffic_server`HttpSM::do_api_callout_internal(this=0x0000000113bbd000) at HttpSM.cc:5781:10
    frame #29: 0x00000001002ec9bc traffic_server`HttpSM::do_api_callout(this=0x0000000113bbd000) at HttpSM.cc:411:12
    frame #30: 0x00000001002fe3fc traffic_server`HttpSM::tunnel_handler_post(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at HttpSM.cc:2964:7
    frame #31: 0x00000001002eb700 traffic_server`HttpSM::main_handler(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at HttpSM.cc:2802:5
    frame #32: 0x000000010000d588 traffic_server`Continuation::handleEvent(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at I_Continuation.h:228:12
    frame #33: 0x00000001004ef5f4 traffic_server`HttpTunnel::tunnel_run(this=0x0000000113bbe948, p_arg=0x0000000113bbeb58) at HttpTunnel.cc:752:9
    frame #34: 0x0000000100334890 traffic_server`HttpSM::do_setup_post_tunnel(this=0x0000000113bbd000, to_vc_type=HTTP_SERVER_VC) at HttpSM.cc:6386:10
    frame #35: 0x000000010034db2c traffic_server`HttpSM::tunnel_handler_100_continue(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at HttpSM.cc:3090:7
    frame #36: 0x00000001002eb700 traffic_server`HttpSM::main_handler(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at HttpSM.cc:2802:5
    frame #37: 0x000000010000d588 traffic_server`Continuation::handleEvent(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at I_Continuation.h:228:12
    frame #38: 0x00000001004ef5f4 traffic_server`HttpTunnel::tunnel_run(this=0x0000000113bbe948, p_arg=0x0000000113bbeb58) at HttpTunnel.cc:752:9
    frame #39: 0x00000001003782a4 traffic_server`HttpSM::setup_100_continue_transfer(this=0x0000000113bbd000) at HttpSM.cc:6869:10
    frame #40: 0x0000000100381864 traffic_server`HttpSM::set_next_state(this=0x0000000113bbd000) at HttpSM.cc:8022:5
    frame #41: 0x00000001002fa584 traffic_server`HttpSM::call_transact_and_set_next_state(this=0x0000000113bbd000, f=0x0000000000000000)(HttpTransact::State*)) at HttpSM.cc:7834:3
    frame #42: 0x000000010030cb68 traffic_server`HttpSM::handle_api_return(this=0x0000000113bbd000) at HttpSM.cc:1701:5
    frame #43: 0x000000010030a804 traffic_server`HttpSM::state_api_callout(this=0x0000000113bbd000, event=0, data=0x0000000000000000) at HttpSM.cc:1633:5
    frame #44: 0x0000000100372ec8 traffic_server`HttpSM::do_api_callout_internal(this=0x0000000113bbd000) at HttpSM.cc:5781:10
    frame #45: 0x00000001002ec9bc traffic_server`HttpSM::do_api_callout(this=0x0000000113bbd000) at HttpSM.cc:411:12
    frame #46: 0x00000001002fe3fc traffic_server`HttpSM::tunnel_handler_post(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at HttpSM.cc:2964:7
    frame #47: 0x00000001002eb700 traffic_server`HttpSM::main_handler(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at HttpSM.cc:2802:5
    frame #48: 0x000000010000d588 traffic_server`Continuation::handleEvent(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at I_Continuation.h:228:12
    frame #49: 0x00000001004ef5f4 traffic_server`HttpTunnel::tunnel_run(this=0x0000000113bbe948, p_arg=0x0000000113bbeb58) at HttpTunnel.cc:752:9
    frame #50: 0x0000000100334890 traffic_server`HttpSM::do_setup_post_tunnel(this=0x0000000113bbd000, to_vc_type=HTTP_SERVER_VC) at HttpSM.cc:6386:10
    frame #51: 0x000000010034db2c traffic_server`HttpSM::tunnel_handler_100_continue(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at HttpSM.cc:3090:7
    frame #52: 0x00000001002eb700 traffic_server`HttpSM::main_handler(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at HttpSM.cc:2802:5
    frame #53: 0x000000010000d588 traffic_server`Continuation::handleEvent(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at I_Continuation.h:228:12
    frame #54: 0x00000001004ef5f4 traffic_server`HttpTunnel::tunnel_run(this=0x0000000113bbe948, p_arg=0x0000000113bbeb58) at HttpTunnel.cc:752:9
    frame #55: 0x00000001003782a4 traffic_server`HttpSM::setup_100_continue_transfer(this=0x0000000113bbd000) at HttpSM.cc:6869:10
    frame #56: 0x0000000100381864 traffic_server`HttpSM::set_next_state(this=0x0000000113bbd000) at HttpSM.cc:8022:5
    frame #57: 0x00000001002fa584 traffic_server`HttpSM::call_transact_and_set_next_state(this=0x0000000113bbd000, f=0x0000000000000000)(HttpTransact::State*)) at HttpSM.cc:7834:3
    frame #58: 0x000000010030cb68 traffic_server`HttpSM::handle_api_return(this=0x0000000113bbd000) at HttpSM.cc:1701:5
    frame #59: 0x000000010030a804 traffic_server`HttpSM::state_api_callout(this=0x0000000113bbd000, event=0, data=0x0000000000000000) at HttpSM.cc:1633:5
    frame #60: 0x0000000100372ec8 traffic_server`HttpSM::do_api_callout_internal(this=0x0000000113bbd000) at HttpSM.cc:5781:10
    frame #61: 0x00000001002ec9bc traffic_server`HttpSM::do_api_callout(this=0x0000000113bbd000) at HttpSM.cc:411:12
    frame #62: 0x00000001002fe3fc traffic_server`HttpSM::tunnel_handler_post(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at HttpSM.cc:2964:7
    frame #63: 0x00000001002eb700 traffic_server`HttpSM::main_handler(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at HttpSM.cc:2802:5
    frame #64: 0x000000010000d588 traffic_server`Continuation::handleEvent(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at I_Continuation.h:228:12
    frame #65: 0x00000001004ef5f4 traffic_server`HttpTunnel::tunnel_run(this=0x0000000113bbe948, p_arg=0x0000000113bbeb58) at HttpTunnel.cc:752:9
    frame #66: 0x0000000100334890 traffic_server`HttpSM::do_setup_post_tunnel(this=0x0000000113bbd000, to_vc_type=HTTP_SERVER_VC) at HttpSM.cc:6386:10
    frame #67: 0x000000010034db2c traffic_server`HttpSM::tunnel_handler_100_continue(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at HttpSM.cc:3090:7
    frame #68: 0x00000001002eb700 traffic_server`HttpSM::main_handler(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at HttpSM.cc:2802:5
    frame #69: 0x000000010000d588 traffic_server`Continuation::handleEvent(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at I_Continuation.h:228:12
    frame #70: 0x00000001004ef5f4 traffic_server`HttpTunnel::tunnel_run(this=0x0000000113bbe948, p_arg=0x0000000113bbeb58) at HttpTunnel.cc:752:9
    frame #71: 0x00000001003782a4 traffic_server`HttpSM::setup_100_continue_transfer(this=0x0000000113bbd000) at HttpSM.cc:6869:10
    frame #72: 0x0000000100381864 traffic_server`HttpSM::set_next_state(this=0x0000000113bbd000) at HttpSM.cc:8022:5
    frame #73: 0x00000001002fa584 traffic_server`HttpSM::call_transact_and_set_next_state(this=0x0000000113bbd000, f=0x0000000000000000)(HttpTransact::State*)) at HttpSM.cc:7834:3
{{snip}}
    frame #1145: 0x00000001002fa584 traffic_server`HttpSM::call_transact_and_set_next_state(this=0x0000000113bbd000, f=0x0000000000000000)(HttpTransact::State*)) at HttpSM.cc:7834:3
    frame #1146: 0x000000010030cb68 traffic_server`HttpSM::handle_api_return(this=0x0000000113bbd000) at HttpSM.cc:1701:5
    frame #1147: 0x000000010030a804 traffic_server`HttpSM::state_api_callout(this=0x0000000113bbd000, event=0, data=0x0000000000000000) at HttpSM.cc:1633:5
    frame #1148: 0x0000000100372ec8 traffic_server`HttpSM::do_api_callout_internal(this=0x0000000113bbd000) at HttpSM.cc:5781:10
    frame #1149: 0x00000001002ec9bc traffic_server`HttpSM::do_api_callout(this=0x0000000113bbd000) at HttpSM.cc:411:12
    frame #1150: 0x00000001002fe3fc traffic_server`HttpSM::tunnel_handler_post(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at HttpSM.cc:2964:7
    frame #1151: 0x00000001002eb700 traffic_server`HttpSM::main_handler(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at HttpSM.cc:2802:5
    frame #1152: 0x000000010000d588 traffic_server`Continuation::handleEvent(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at I_Continuation.h:228:12
    frame #1153: 0x00000001004ef5f4 traffic_server`HttpTunnel::tunnel_run(this=0x0000000113bbe948, p_arg=0x0000000113bbeb58) at HttpTunnel.cc:752:9
    frame #1154: 0x0000000100334890 traffic_server`HttpSM::do_setup_post_tunnel(this=0x0000000113bbd000, to_vc_type=HTTP_SERVER_VC) at HttpSM.cc:6386:10
    frame #1155: 0x000000010034db2c traffic_server`HttpSM::tunnel_handler_100_continue(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at HttpSM.cc:3090:7
    frame #1156: 0x00000001002eb700 traffic_server`HttpSM::main_handler(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at HttpSM.cc:2802:5
    frame #1157: 0x000000010000d588 traffic_server`Continuation::handleEvent(this=0x0000000113bbd000, event=2301, data=0x0000000113bbe948) at I_Continuation.h:228:12
    frame #1158: 0x00000001004ef5f4 traffic_server`HttpTunnel::tunnel_run(this=0x0000000113bbe948, p_arg=0x0000000113bbeb58) at HttpTunnel.cc:752:9
    frame #1159: 0x00000001003782a4 traffic_server`HttpSM::setup_100_continue_transfer(this=0x0000000113bbd000) at HttpSM.cc:6869:10
    frame #1160: 0x0000000100381864 traffic_server`HttpSM::set_next_state(this=0x0000000113bbd000) at HttpSM.cc:8022:5
    frame #1161: 0x00000001002fa584 traffic_server`HttpSM::call_transact_and_set_next_state(this=0x0000000113bbd000, f=0x0000000000000000)(HttpTransact::State*)) at HttpSM.cc:7834:3
    frame #1162: 0x000000010030cb68 traffic_server`HttpSM::handle_api_return(this=0x0000000113bbd000) at HttpSM.cc:1701:5
    frame #1163: 0x000000010030a804 traffic_server`HttpSM::state_api_callout(this=0x0000000113bbd000, event=0, data=0x0000000000000000) at HttpSM.cc:1633:5
    frame #1164: 0x0000000100372ec8 traffic_server`HttpSM::do_api_callout_internal(this=0x0000000113bbd000) at HttpSM.cc:5781:10
    frame #1165: 0x00000001002ec9bc traffic_server`HttpSM::do_api_callout(this=0x0000000113bbd000) at HttpSM.cc:411:12
    frame #1166: 0x000000010032dc20 traffic_server`HttpSM::state_read_server_response_header(this=0x0000000113bbd000, event=100, data=0x0000000113ca3e08) at HttpSM.cc:2165:7
    frame #1167: 0x00000001002eb594 traffic_server`HttpSM::main_handler(this=0x0000000113bbd000, event=100, data=0x0000000113ca3e08) at HttpSM.cc:2799:5
    frame #1168: 0x000000010000d588 traffic_server`Continuation::handleEvent(this=0x0000000113bbd000, event=100, data=0x0000000113ca3e08) at I_Continuation.h:228:12
    frame #1169: 0x0000000100ec12f8 traffic_server`read_signal_and_update(event=100, vc=0x0000000113ca3bf0) at UnixNetVConnection.cc:82:24
    frame #1170: 0x0000000100ebf854 traffic_server`read_from_net(nh=0x0000000109b08c00, vc=0x0000000113ca3bf0, thread=0x0000000109b04800) at UnixNetVConnection.cc:322:11
    frame #1171: 0x0000000100ebe00c traffic_server`UnixNetVConnection::net_read_io(this=0x0000000113ca3bf0, nh=0x0000000109b08c00, lthread=0x0000000109b04800) at UnixNetVConnection.cc:854:3
    frame #1172: 0x0000000100e84dac traffic_server`NetHandler::process_ready_list(this=0x0000000109b08c00) at UnixNet.cc:405:11
    frame #1173: 0x0000000100e865c0 traffic_server`NetHandler::waitForActivity(this=0x0000000109b08c00, timeout=10000000) at UnixNet.cc:540:3
    frame #1174: 0x000000010116cdf4 traffic_server`EThread::execute_regular(this=0x0000000109b04800) at UnixEThread.cc:285:14
    frame #1175: 0x000000010116e078 traffic_server`EThread::execute(this=0x0000000109b04800) at UnixEThread.cc:334:11
    frame #1176: 0x00000001011688b8 traffic_server`spawn_thread_internal(a=0x0000000107432780) at Thread.cc:79:12
bneradt commented 1 year ago

I took a stab at reproducing this via an autest with the following patch:

Click to expand ``` diff --git a/tests/gold_tests/h2/h2origin.test.py b/tests/gold_tests/h2/h2origin.test.py index cedbc7d00..e3db7b971 100644 --- a/tests/gold_tests/h2/h2origin.test.py +++ b/tests/gold_tests/h2/h2origin.test.py @@ -17,6 +17,8 @@ Test communication to origin with H2 # See the License for the specific language governing permissions and # limitations under the License. +import os + Test.Summary = ''' Test communication to origin with H2 ''' @@ -32,6 +34,7 @@ ts = Test.MakeATSProcess("ts", enable_tls="true") ts.addDefaultSSLFiles() replay_file = "replay_h2origin/" server = Test.MakeVerifierServerProcess("h2-origin", replay_file) +httpbin = Test.MakeHttpBinServer("httpbin") ts.Disk.records_config.update({ 'proxy.config.ssl.server.cert.path': '{0}'.format(ts.Variables.SSLDir), 'proxy.config.ssl.server.private_key.path': '{0}'.format(ts.Variables.SSLDir), @@ -47,9 +50,10 @@ ts.Disk.records_config.update({ 'proxy.config.ssl.client.verify.server.policy': 'PERMISSIVE', }) -ts.Disk.remap_config.AddLine( - 'map / https://127.0.0.1:{0}'.format(server.Variables.https_port) -) +ts.Disk.remap_config.AddLines([ + f'map /httpbin http://127.0.0.1:{httpbin.Variables.Port}', + f'map / https://127.0.0.1:{server.Variables.https_port}' +]) ts.Disk.ssl_multicert_config.AddLine( 'dest_ip=* ssl_cert_name=server.pem ssl_key_name=server.key' ) @@ -74,14 +78,22 @@ tr.AddVerifierClientProcess("client", replay_file, http_ports=[ts.Variables.port tr.StillRunningAfter = ts tr.TimeOut = 60 -# Just a check to flush out the traffic log until we have a clean shutdown for traffic_server -tr = Test.AddTestRun("Wait for the access log to write out") -tr.DelayStart = 10 -tr.StillRunningAfter = ts -tr.StillRunningAfter = server -tr.Processes.Default.Command = 'ls' +tr = Test.AddTestRun("Test a POST request with an Expect: 100-continue header") +content_file = os.path.join(Test.RunDirectory, '8k') +with open(content_file, 'wb') as f: + f.write(os.urandom(8192)) +tr.Processes.Default.StartBefore(httpbin) +tr.Processes.Default.Command = ( + f'curl -kv -d @{content_file} --http2 -H "Expect: 100-Continue" ' + f'https://127.0.0.1:{ts.Variables.ssl_port}/httpbin/post') tr.Processes.Default.ReturnCode = 0 +# Wait until the transaction log is written. +tr = Test.AddTestRun("Wait for the access log to write out") +cond_wait_path = os.path.join(Test.Variables.AtsTestToolsDir, 'condwait') +squid_log_path = os.path.join(ts.Variables.LOGDIR, 'squid.log') +tr.Processes.Default.Command = f'{cond_wait_path} 60 1 -f {squid_log_path}' + # UUIDs 1-4 should be http/1.1 clients and H2 origin # UUIDs 5-9 should be http/2 clients and H2 origins ts.Disk.squid_log.Content = Testers.ContainsExpression(" [1-4] http/1.1 http/2", "cases 1-4 request http/1.1") ```

The interesting portion of the patch being the following new TestRun:

tr = Test.AddTestRun("Test a POST request with an Expect: 100-continue header")
content_file = os.path.join(Test.RunDirectory, '8k')
with open(content_file, 'wb') as f:
    f.write(os.urandom(8192))
tr.Processes.Default.StartBefore(httpbin)
tr.Processes.Default.Command = (
    f'curl -kv -d @{content_file} --http2 -H "Expect: 100-Continue" '
    f'https://127.0.0.1:{ts.Variables.ssl_port}/httpbin/post')
tr.Processes.Default.ReturnCode = 0

Our local autests use go-httpbin because httpbin is deprecated and no longer supported. Masakazu confirmed that when he switched his remap from map /httpbin/ http://httpbin.org/ to map /httpbin/ http://httpbingo.org/, the crash no longer reproduced. So it seems the crash relies upon some behavior in httpbin that go-httpbin does not quite replicate.

I'm going to try to reproduce the crash using Proxy Verifier. I think I saw a crash with that in an earlier attempt, but Proxy Verifier could use some Expect: 100-continue updates.

github-actions[bot] commented 5 months ago

This issue has been automatically marked as stale because it has not had recent activity. Marking it stale to flag it for further consideration by the community.

maskit commented 5 months ago

This is still a valid issue. The crash is reproducible.