H2 stream is closed by sending 100 Continue response

[masaori335]

When the POST request on HTTP/2 connection has Expect: 100-continue header, the stream is closed right after the sending 100 Continue response.
The stream should not be closed until complete sending a final status code.

This is obviously violation of rfc7231 5.1.1. Expect

A server that sends a 100 (Continue) response MUST ultimately send a final status code, once the message body is received and processed, unless the connection is closed prematurely.

Affected version: 8.0.x, 9.0.x, master.

Below is debug log with head of 8.0.x branch

[Nov 19 12:00:12.773] [ET_NET 2] DEBUG: <HttpTransactHeaders.cc:1220 (add_server_header_to_response)> (http_trans) Adding Server: ATS/8.0.6
+++++++++ Proxy's Response +++++++++
-- State Machine Id: 2
HTTP/1.1 100 Continue
Date: Tue, 19 Nov 2019 03:00:12 GMT
Server: ATS/8.0.6

[Nov 19 12:00:12.773] [ET_NET 2] DEBUG: <HttpTransact.cc:3869 (handle_100_continue_response)> (http_trans) Next action SM_ACTION_INTERNAL_100_RESPONSE; HandleResponse
[Nov 19 12:00:12.773] [ET_NET 2] DEBUG: <HttpSM.cc:7142 (call_transact_and_set_next_state)> (http) [2] State Transition: SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_INTERNAL_100_RESPONSE
[Nov 19 12:00:12.773] [ET_NET 2] DEBUG: <HttpTunnel.cc:655 (add_producer)> (http_tunnel) [2] adding producer 'internal msg - 100 continue'
[Nov 19 12:00:12.773] [ET_NET 2] DEBUG: <HttpTunnel.cc:710 (add_consumer)> (http_tunnel) [2] adding consumer 'user agent'
[Nov 19 12:00:12.773] [ET_NET 2] DEBUG: <HttpTunnel.cc:757 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Nov 19 12:00:12.773] [ET_NET 2] DEBUG: <Http2Stream.cc:571 (update_write_request)> (http2_stream) [2] [1] write_vio.nbytes=81, write_vio.ndone=0, write_vio.write_avail=4015, reader.read_avail=81
[Nov 19 12:00:12.773] [ET_NET 2] DEBUG: <Http2ConnectionState.cc:1537 (send_headers_frame)> (http2_con) [2] [1] Send HEADERS frame
[Nov 19 12:00:12.773] [ET_NET 2] DEBUG: <Http2ConnectionState.cc:1469 (send_a_data_frame)> (http2_con) [2] [1] Send a DATA frame - client window con: 1073741824 stream: 1073741824 payload:     0
[Nov 19 12:00:12.773] [ET_NET 2] DEBUG: <Http2ConnectionState.cc:1484 (send_a_data_frame)> (http2_con) [2] [1] End of DATA frame
[Nov 19 12:00:12.773] [ET_NET 2] DEBUG: <Http2Stream.cc:268 (change_state)> (http2_stream) [2] [1] Http2StreamState::HTTP2_STREAM_STATE_CLOSED
[Nov 19 12:00:12.774] [ET_NET 2] DEBUG: <Http2ConnectionState.cc:1517 (send_data_frames)> (http2_con) [2] [1] Shutdown stream
[Nov 19 12:00:12.774] [ET_NET 2] DEBUG: <Http2ConnectionState.cc:1259 (delete_stream)> (http2_con) [2] [1] Delete stream
[Nov 19 12:00:12.774] [ET_NET 2] DEBUG: <Http2Stream.cc:389 (initiating_close)> (http2_stream) [2] [1] initiating_close

[shinrich]

I'm not seeing this problem with master. I've been testing with http-replay with the http2 client. At the moment I'm testing with master plugin PR #6199.

+++++++++ Incoming O.S. Response +++++++++
-- State Machine Id: 4
HTTP/1.1 100 continue

[Nov 19 21:46:38.769] [ET_NET 1] DEBUG: <HttpTransact.cc:6280 (is_response_valid)> (http_trans) [4] [is_response_valid] No errors in response
[Nov 19 21:46:38.769] [ET_NET 1] DEBUG: <HttpTransact.cc:3175 (HandleResponse)> (http_seq) [4] [HttpTransact::HandleResponse] Response valid
[Nov 19 21:46:38.769] [ET_NET 1] DEBUG: <HttpTransact.cc:5550 (initialize_state_variables_from_response)> (http_hdrs) [4] [initialize_state_variables_from_response]Server is keep-alive.
[Nov 19 21:46:38.769] [ET_NET 1] DEBUG: <HttpTransact.cc:3466 (handle_response_from_server)> (http_trans) [4] [handle_response_from_server] (hrfs)
[Nov 19 21:46:38.769] [ET_NET 1] DEBUG: <HttpTransact.cc:3478 (handle_response_from_server)> (http_trans) [4] [hrfs] connection alive
[Nov 19 21:46:38.770] [ET_NET 1] DEBUG: <HttpTransact.cc:3745 (handle_forward_server_connection_open)> (http_trans) [4] [handle_forward_server_connection_open] (hfsco)
[Nov 19 21:46:38.770] [ET_NET 1] DEBUG: <HttpTransact.cc:3746 (handle_forward_server_connection_open)> (http_seq) [4] [HttpTransact::handle_server_connection_open] 
[Nov 19 21:46:38.770] [ET_NET 1] DEBUG: <HttpTransactHeaders.cc:1137 (add_server_header_to_response)> (http_trans) Adding Server: ATS/10.0.0
+++++++++ Proxy's Response +++++++++
-- State Machine Id: 4
HTTP/1.1 100 continue
Date: Tue, 19 Nov 2019 21:46:38 GMT
Server: ATS/10.0.0

[Nov 19 21:46:38.770] [ET_NET 1] DEBUG: <HttpTransact.cc:3887 (handle_100_continue_response)> (http_trans) Next action SM_ACTION_INTERNAL_100_RESPONSE; HandleResponse
[Nov 19 21:46:38.770] [ET_NET 1] DEBUG: <HttpSM.cc:7164 (call_transact_and_set_next_state)> (http) [4] State Transition: SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_INTERNAL_100_RESPONSE
[Nov 19 21:46:38.770] [ET_NET 1] DEBUG: <HttpTunnel.cc:595 (add_producer)> (http_tunnel) [4] adding producer 'internal msg - 100 continue'
[Nov 19 21:46:38.770] [ET_NET 1] DEBUG: <HttpTunnel.cc:650 (add_consumer)> (http_tunnel) [4] adding consumer 'user agent'
[Nov 19 21:46:38.770] [ET_NET 1] DEBUG: <HttpTunnel.cc:697 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Nov 19 21:46:38.770] [ET_NET 1] DEBUG: <Http2Stream.cc:605 (update_write_request)> (http2_stream) [1] [1] write_vio.nbytes=82, write_vio.ndone=0, write_vio.write_avail=4014, reader.read_avail=82
[Nov 19 21:46:38.770] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1562 (send_headers_frame)> (http2_con) [1] [1] Send HEADERS frame
[Nov 19 21:46:38.770] [ET_NET 1] DEBUG: <HttpTunnel.cc:1290 (consumer_handler)> (http_tunnel) [4] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Nov 19 21:46:38.770] [ET_NET 1] DEBUG: <HttpSM.cc:3125 (tunnel_handler_100_continue_ua)> (http) [4] [&HttpSM::tunnel_handler_100_continue_ua, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Nov 19 21:46:38.770] [ET_NET 1] DEBUG: <HttpSM.cc:2600 (main_handler)> (http) [4] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Nov 19 21:46:38.770] [ET_NET 1] DEBUG: <HttpSM.cc:2807 (tunnel_handler_100_continue)> (http) [4] [&HttpSM::tunnel_handler_100_continue, HTTP_TUNNEL_EVENT_DONE]
[Nov 19 21:46:38.770] [ET_NET 1] DEBUG: <HttpSM.cc:8095 (clear)> (http_redirect) [PostDataBuffers::clear]
[Nov 19 21:46:38.771] [ET_NET 1] DEBUG: <HttpSM.cc:1866 (state_read_server_response_header)> (http) [4] [&HttpSM::state_read_server_response_header, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Nov 19 21:46:38.771] [ET_NET 1] DEBUG: <HttpSM.cc:2600 (main_handler)> (http) [4] [HttpSM::main_handler, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Nov 19 21:46:38.771] [ET_NET 1] DEBUG: <HttpSM.cc:1866 (state_read_server_response_header)> (http) [4] [&HttpSM::state_read_server_response_header, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Nov 19 21:46:38.771] [ET_NET 1] DEBUG: <HttpSM.cc:1967 (state_read_server_response_header)> (http_seq) Done parsing server response header
[Nov 19 21:46:38.771] [ET_NET 1] DEBUG: <HttpSM.cc:8095 (clear)> (http_redirect) [PostDataBuffers::clear]
[Nov 19 21:46:38.771] [ET_NET 1] DEBUG: <HttpTransact.cc:3150 (HandleResponse)> (http_trans) [4] [HttpTransact::HandleResponse]
[Nov 19 21:46:38.771] [ET_NET 1] DEBUG: <HttpTransact.cc:3151 (HandleResponse)> (http_seq) [4] [HttpTransact::HandleResponse] Response received
[Nov 19 21:46:38.771] [ET_NET 1] DEBUG: <HttpTransact.cc:3158 (HandleResponse)> (http_trans) [4] [HandleResponse] response_received_time: 1574199998
+++++++++ Incoming O.S. Response +++++++++
-- State Machine Id: 4
HTTP/1.1 204 no content
via: http/1.1 kubenode22.prod1.ensemble.ne1.yahoo.com (ApacheTrafficServer [c s f ])
server: ATS
age: 0
date: Sat, 16 Mar 2019 01:43:40 GMT
x-frame-options: DENY
x-xss-protection: 1; mode=block
connection: keep-alive
x-content-type-options: nosniff
pragma: no-cache
x-omg-env: norrin-green--production-ne1-66d977bf65-mwf8d
content-security-policy: child-src blob:;connect-src 'self' https://*.yimg.com https://*.yahoo.com https://s.yimg.com/nq/ads/mb/native/* wss://prod.iris.yahoo.com https://www.hipmunk.com/ https://service.cmp.oath.com;default-src 'self';font-src https: data:;frame-src https://*.yahoo.com https://*.yimg.com https://*.ymail.com https://6518610.fls.doubleclick.net/ https://6589630.fls.doubleclick.net/ https://8478561.fls.doubleclick.net/ https://8523621.fls.doubleclick.net/ https://delivery.vidible.tv/ https://secure.bannerfarm.ace.advertising.com https://cmp.advertising.com https://www.fbsbx.com/ads/audience_network/integrations/yahoo-iframe/;img-src data: blob: http: https:;media-src blob: https://*.yahoo.com https://*.yimg.com;report-uri https://csp.yahoo.com/beacon/csp?src=mail-norrin;script-src 'self' https://iris.corp.yahoo.com:8900 https://s.yimg.com/jd/ https://pr.comet.yahoo.com https://s.yimg.com/nq/nr/ https://s.yimg.com/os/yaft/ https://s.yimg.com/ss/ https://s.yimg.com/aaq/yc/ https://s.yimg.com/rq/darla/ https://fc.yahoo.com/sdarla/ https://s.yimg.com/gu/static/ https://www.yahoo.com/polyfill.min.js https://yep.video.yahoo.com/js/ https://s.yimg.com/rx/ https://www.gstatic.com/cv/js/sender/v1/cast_sender.js https://cdn-ssl.vidible.tv/prod/player/js/ https://yep.video.yahoo.com/oath/js/1/ https://assets.video.yahoo.net/playerassets/ https://jsapi.login.yahoo.com/w/ https://consent.cmp.oath.com/ 'sha256-lRMQ2lQozgbWLOqNJOrnclJXX6G77pQVIlF8SAI3++I=' 'unsafe-inline' 'unsafe-eval' 'nonce-0l57lPA8vA0eEZH8tZOFaeX3BbIx1tG1szTGr/58UZhOZXuh' ;style-src 'self' https://s.yimg.com/nq/nr/ https://s.yimg.com/rx/ https://assets.video.yahoo.net/playerassets/ 'unsafe-inline';worker-src 'self';manifest-src https://s.yimg.com/nq/nr/json/
strict-transport-security: max-age=2592000
cache-control: no-store, no-cache, must-revalidate, private
public-key-pins-report-only: max-age=2592000; pin-sha256="2oALgLKofTmeZvoZ1y/fSZg7R9jPMix8eVA6DH4o/q8="; pin-sha256="cAajgxHlj7GTSEIzIYIQxmEloOSoJq7VOaxWHfv72QM="; pin-sha256="SVqWumuteCQHvVIaALrOZXuzVVVeS7f4FGxxu6V+es4="; pin-sha256="UZJDjsNp1+4M5x9cbbdflB779y5YRBcV6Z6rBMLIrO4="; pin-sha256="JbQbUG5JMJUoI6brnx0x3vZF6jilxsapbXGVfjhN8Fg="; pin-sha256="lnsM2T/O9/J84sJFdnrpsFp3awZJ+ZZbYpCWhGloaHI="; pin-sha256="h6801m+z8v3zbgkRHpq6L29Esgfzhj89C1SyUCOQmqU="; pin-sha256="SQVGZiOrQXi+kqxcvWWE96HhfydlLVqFr4lQTqI5qqo="; pin-sha256="q5hJUnat8eyv8o81xTBIeB5cFxjaucjmelBPT2pRMo8="; pin-sha256="vPtEqrmtAhAVcGtBIep2HIHJ6IlnWQ9vlK50TciLePs="; pin-sha256="lpkiXF3lLlbN0y3y6W0c/qWqPKC7Us2JM8I7XCdEOCA="; pin-sha256="r/mIkG3eEpVdm+u/ko/cwxzOMo1bk4TyHIlByibiA5E="; pin-sha256="WoiWRyIOVNa9ihaBciRSC7XHjliYS9VwUGOIud4PB18="; pin-sha256="2fRAUXyxl4A1/XHrKNBmc8bTkzA7y4FB/GLJuNAzCqY="; pin-sha256="dolnbtzEBnELx/9lOEQ22e6OZO/QNb6VSSX2XHA3E7A="; report-uri="http://csp.yahoo.com/beacon/csp?src=yahoocom-hpkp-report-only"
referrer-policy: origin-when-cross-origin
expires: 0

[Nov 19 21:46:38.771] [ET_NET 1] DEBUG: <HttpTransact.cc:6280 (is_response_valid)> (http_trans) [4] [is_response_valid] No errors in response
[Nov 19 21:46:38.771] [ET_NET 1] DEBUG: <HttpTransact.cc:3175 (HandleResponse)> (http_seq) [4] [HttpTransact::HandleResponse] Response valid
[Nov 19 21:46:38.771] [ET_NET 1] DEBUG: <HttpTransact.cc:5550 (initialize_state_variables_from_response)> (http_hdrs) [4] [initialize_state_variables_from_response]Server is keep-alive.

[shinrich]

I would assume it is the addition of the is_status_1xx() in the PR #6199 that fixed it.

And confirmed that. Backed out PR #6199 and just ran master, and my H2 100-continue test gets stuck. Looks like the H2 logic gives up after the first 100 response.

[masaori335]

Span out the fix for this from #6199. Diffs from #6199 are

• Add a test case to cover this
• Rename & tweak logic of is_status_1xx() for exclude "101 switching protocol"