POST requests get INACTIVITY_TIMEOUT immediately

[masaori335]

@elsloo found that inactive timeout is odd on POST request cases on our 9.0.3 deployment.

When this issue happens, debug logs are below. It looks like the HttpSM starts TLS handshake with origin server and read op of inbound side connection is disabled. But the inactive_cop closed the inbound connection immediately.

 [Aug 24 02:05:31.976] [ET_NET 19] DEBUG: <HttpSM.cc:5272 (do_http_server_open)> (http) calling sslNetProcessor.connect_re
 ...
[Aug 24 02:05:31.976] [ET_NET 19] DEBUG: <HttpSM.cc:1817 (state_http_server_open)> (http) [10713971] setting handler for TCP handshake
[Aug 24 02:05:31.976] [ET_NET 19] DEBUG: <P_UnixNet.h:554 (read_disable)> (socket) read_disable updating inactivity_at 0, NetEvent=0x7fbf7811dc30
...
[Aug 24 02:05:32.552] [ET_NET 19] DEBUG: <UnixNet.cc:56 (check_inactivity)> (inactivity_cop_check) Checking inactivity on Thread-ID #19
[Aug 24 02:05:32.552] [ET_NET 19] DEBUG: <UnixNet.cc:574 (manage_active_queue)> (v_net_queue) max_connections_per_thread_in: 4687 max_requests_per_thread_in: 937 total_connections_in: 12 active_queue_size: 10 keep_alive_queue_size: 2
[Aug 24 02:05:32.552] [ET_NET 19] DEBUG: <UnixNet.cc:683 (_close_ne)> (net_queue) closing connection NetEvent=0x7fbf7811dc30 idle: 2 now: 1629770732 at: 0 in: 70 diff: 1629770802
[Aug 24 02:05:32.552] [ET_NET 19] DEBUG: <HttpSM.cc:2632 (main_handler)> (http) [10713971] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT]

I think #7134 introduced this behavior. The issue is gone by reverting the commit.

To fix this issue with #7134, we need to check the ne->next_inactivity_timeout_at before closing the connection by the inactive_cop. A caveat is connection throttling is using the same function (NetHandler::manage_keep_alive_queue()).

[masaori335]

We found 2 things. I'm working on writing up an AuTest and fixing it.

1. this happens only if proxy.config.net.max_requests_in is set (default value is 0)
   

   trafficserver/iocore/net/UnixNet.cc

   Lines 581 to 584 in 2d49a40

   	if (!max_requests_per_thread_in) {
   	// active queue has no max
   	return true;
   	}

2. the reason why # 7304 introduced the problem is the below condition.
   

   trafficserver/iocore/net/UnixNet.cc

   Lines 606 to 609 in 2d49a40

   	if ((ne->inactivity_timeout_in && ne->next_inactivity_timeout_at <= now) ||
   	(ne->active_timeout_in && ne->next_activity_timeout_at <= now)) {
   	_close_ne(ne, now, handle_event, closed, total_idle_time, total_idle_count);
   	}

[shinrich]

Ah, that makes sense why we have not run into this. We are running with max_requests_in set to the default of 0.