Slow PUSH transaction

diags.log

Long pause in state machine code it appears:

+++++++++ Incoming Request +++++++++
-- State Machine Id: 0
PUSH http://httpbin.org/ip HTTP/1.1
Host: httpbin.org
User-Agent: curl/7.59.0
Accept: */*
Proxy-Connection: Keep-Alive
Content-Length: 0

[Aug  8 16:56:56.058] {0x2b436febe700} DEBUG: <HttpTransact.cc:1819 (DecideCacheLookup)> (http_trans) [0] [DecideCacheLookup] Will do cache lookup.
[Aug  8 16:56:56.058] {0x2b436febe700} DEBUG: <HttpTransact.cc:1820 (DecideCacheLookup)> (http_seq) [0] [DecideCacheLookup] Will do cache lookup
[Aug  8 16:56:56.058] {0x2b436febe700} DEBUG: <HttpTransact.cc:1863 (DecideCacheLookup)> (http_trans) Next action SM_ACTION_CACHE_LOOKUP; nullptr
[Aug  8 16:56:56.059] {0x2b436febe700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_POST_REMAP -> SM_ACTION_CACHE_LOOKUP
[Aug  8 16:56:56.060] {0x2b436febe700} DEBUG: <HttpSM.cc:4524 (do_cache_lookup_and_read)> (http_seq) [HttpSM::do_cache_lookup_and_read] [0] Issuing cache lookup for URL http://httpbin.org/ip
[Aug  8 16:56:56.060] {0x2b436febe700} DEBUG: <HttpCacheSM.cc:116 (state_cache_open_read)> (http_cache) [0] [&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED]
[Aug  8 16:56:56.061] {0x2b436febe700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [0] [HttpSM::main_handler, CACHE_EVENT_OPEN_READ_FAILED]
[Aug  8 16:56:56.061] {0x2b436febe700} DEBUG: <HttpSM.cc:2504 (state_cache_open_read)> (http) [0] [&HttpSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED]
[Aug  8 16:56:56.061] {0x2b436febe700} DEBUG: <HttpSM.cc:2538 (state_cache_open_read)> (http) [0] cache_open_read - CACHE_EVENT_OPEN_READ_FAILED with ECACHE_NO_DOC (-20400)
[Aug  8 16:56:56.061] {0x2b436febe700} DEBUG: <HttpSM.cc:2540 (state_cache_open_read)> (http) [state_cache_open_read] open read failed.
[Aug  8 16:56:56.062] {0x2b436febe700} DEBUG: <HttpTransact.cc:2074 (HandleCacheOpenRead)> (http_trans) [0] [HttpTransact::HandleCacheOpenRead]
[Aug  8 16:56:56.062] {0x2b436febe700} DEBUG: <HttpTransact.cc:1941 (HandleCacheOpenReadPush)> (http_trans) Next action SM_ACTION_READ_PUSH_HDR; HandlePushResponseHdr
[Aug  8 16:56:56.062] {0x2b436febe700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_CACHE_LOOKUP -> SM_ACTION_READ_PUSH_HDR
[Aug  8 16:57:26.472] {0x2b436febe700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT]
[Aug  8 16:57:26.473] {0x2b436febe700} DEBUG: <HttpSM.cc:986 (state_read_push_response_header)> (http) [0] [&HttpSM::state_read_push_response_header, VC_EVENT_INACTIVITY_TIMEOUT]
[Aug  8 16:57:26.474] {0x2b436febe700} DEBUG: <HttpTransactHeaders.cc:638 (generate_and_set_squid_codes)> (http_trans) [Squid code generation] Hit/Miss: b, Log: v, Hier: 1
[Aug  8 16:57:26.474] {0x2b436febe700} DEBUG: <HttpTransactHeaders.cc:1220 (add_server_header_to_response)> (http_trans) Adding Server: ATS/9.0.0
+++++++++ Proxy's Response 2 +++++++++
-- State Machine Id: 0
HTTP/1.1 400 Malformed Pushed Response Header
Date: Wed, 08 Aug 2018 16:56:56 GMT
Proxy-Connection: close
Server: ATS/9.0.0

[Aug  8 16:57:26.476] {0x2b436febe700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_READ_PUSH_HDR -> SM_ACTION_SEND_ERROR_CACHE_NOOP
[Aug  8 16:57:26.478] {0x2b436febe700} DEBUG: <HttpTunnel.cc:655 (add_producer)> (http_tunnel) [0] adding producer 'internal msg'
[Aug  8 16:57:26.479] {0x2b436febe700} DEBUG: <HttpTunnel.cc:710 (add_consumer)> (http_tunnel) [0] adding consumer 'user agent'
[Aug  8 16:57:26.479] {0x2b436febe700} DEBUG: <HttpTunnel.cc:757 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Aug  8 16:57:26.479] {0x2b436febe700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Aug  8 16:57:26.481] {0x2b436febe700} DEBUG: <HttpTunnel.cc:1350 (consumer_handler)> (http_tunnel) [0] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Aug  8 16:57:26.482] {0x2b436febe700} DEBUG: <HttpSM.cc:3179 (tunnel_handler_ua)> (http) [0] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Aug  8 16:57:26.482] {0x2b436febe700} DEBUG: <Http1ClientSession.cc:290 (do_io_close)> (http_cs) [0] session half close
[Aug  8 16:57:26.483] {0x2b436febe700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [0] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Aug  8 16:57:26.483] {0x2b436febe700} DEBUG: <HttpSM.cc:2862 (tunnel_handler)> (http) [0] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Aug  8 16:57:26.483] {0x2b436febe700} DEBUG: <HttpSM.cc:8059 (clear)> (http_redirect) [PostDataBuffers::clear]
[Aug  8 16:57:26.484] {0x2b436febe700} DEBUG: <HttpSM.cc:6866 (kill_this)> (http_seq) [HttpSM::update_stats] Logging transaction
[Aug  8 16:57:26.484] {0x2b436febe700} DEBUG: <HttpSM.cc:6892 (kill_this)> (http) [0] deallocating sm
[Aug  8 16:57:26.484] {0x2b436febe700} DEBUG: <Http1ClientSession.cc:333 (state_wait_for_close)> (http_cs) [0] [&Http1ClientSession::state_wait_for_close, VC_EVENT_EOS]
[Aug  8 16:57:26.484] {0x2b436febe700} DEBUG: <Http1ClientSession.cc:316 (do_io_close)> (http_cs) [0] session closed
[Aug  8 16:57:26.485] {0x2b436febe700} DEBUG: <Http1ClientSession.cc:93 (destroy)> (http_cs) [0] session destroy
[Aug  8 16:57:26.485] {0x2b436febe700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 1

PUSH.cap

wkaras ~/TSX/TS/bin
C$ date ; curl --verbose http://127.0.0.1:8080/ip -X PUSH -H 'Content-Length: 0' -H 'Host: httpbin.org' 2>&1 | fgrep '< HTTP/' ; date
Wed Aug  8 16:47:16 UTC 2018
  0     0    0     0    0     0      0      0 --:--:--  0:00:29 --:--:--     0< HTTP/1.1 400 Malformed Pushed Response Header
Wed Aug  8 16:47:46 UTC 2018
wkaras ~/TSX/TS/bin
C$ date ; curl --verbose http://httpbin.org/ip -X PUSH -H 'Content-Length: 0' 2>&1 | fgrep '< HTTP/' ; date
Wed Aug  8 16:48:26 UTC 2018
< HTTP/1.1 405 METHOD NOT ALLOWED
Wed Aug  8 16:48:26 UTC 2018
wkaras ~/TSX/TS/bin
C$