Add ERR_TUN_ACTIVE_TIMEOUT squid code for tunnel timeouts (#12786)

* Add ERR_TUN_ACTIVE_TIMEOUT squid code ('T') so CONNECT
  tunnel timeouts are visible in access logs via the crc
  field instead of only in DEBUG output.
* Set the code in tunnel_handler_ssl_producer() and
  tunnel_handler_ssl_consumer() on VC_EVENT_ACTIVE_TIMEOUT.
* Add the code to traffic_logstats switch statements so
  tunnel timeouts count in the errors bucket.
* Add autest with Python CONNECT client that triggers a
  tunnel timeout and verifies the log entry.

Author: bryancall

include/proxy/hdrs/HTTP.h

@@ -162,6 +162,7 @@ enum class SquidLogCode {
   ERR_FUTURE_1              = 'I',
   ERR_CLIENT_READ_ERROR     = 'J', // Client side abort logging
   ERR_LOOP_DETECTED         = 'K', // Loop or cycle detected, request came back to this server
+  ERR_TUN_ACTIVE_TIMEOUT    = 'T', // Tunnel (CONNECT) active timeout
   ERR_UNKNOWN               = 'Z'
 };
 

src/proxy/http/HttpSM.cc

@@ -4162,6 +4162,10 @@ HttpSM::tunnel_handler_ssl_producer(int event, HttpTunnelProducer *p)
   case VC_EVENT_ERROR:
   case VC_EVENT_INACTIVITY_TIMEOUT:
   case VC_EVENT_ACTIVE_TIMEOUT:
+    // Set squid code for tunnel active timeout
+    if (event == VC_EVENT_ACTIVE_TIMEOUT) {
+      t_state.squid_codes.log_code = SquidLogCode::ERR_TUN_ACTIVE_TIMEOUT;
+    }
     // The other side of the connection is either already dead
     //   or rendered inoperative by the error on the connection
     //   Note: use tunnel close vc so the tunnel knows we are
@@ -4216,6 +4220,10 @@ HttpSM::tunnel_handler_ssl_consumer(int event, HttpTunnelConsumer *c)
   case VC_EVENT_EOS:
   case VC_EVENT_INACTIVITY_TIMEOUT:
   case VC_EVENT_ACTIVE_TIMEOUT:
+    // Set squid code for tunnel active timeout
+    if (event == VC_EVENT_ACTIVE_TIMEOUT) {
+      t_state.squid_codes.log_code = SquidLogCode::ERR_TUN_ACTIVE_TIMEOUT;
+    }
     // we need to mark the producer dead
     // otherwise it can stay alive forever.
     if (c->producer->alive) {

src/proxy/logging/Log.cc

@@ -665,7 +665,7 @@ Log::init_fields()
 
   Ptr<LogFieldAliasTable> cache_code_map = make_ptr(new LogFieldAliasTable);
   cache_code_map->init(
-    53, SquidLogCode::EMPTY, "UNDEFINED", SquidLogCode::TCP_HIT, "TCP_HIT", SquidLogCode::TCP_DISK_HIT, "TCP_DISK_HIT",
+    54, SquidLogCode::EMPTY, "UNDEFINED", SquidLogCode::TCP_HIT, "TCP_HIT", SquidLogCode::TCP_DISK_HIT, "TCP_DISK_HIT",
     SquidLogCode::TCP_MEM_HIT, "TCP_MEM_HIT", SquidLogCode::TCP_MISS, "TCP_MISS", SquidLogCode::TCP_EXPIRED_MISS,
     "TCP_EXPIRED_MISS", SquidLogCode::TCP_REFRESH_HIT, "TCP_REFRESH_HIT", SquidLogCode::TCP_REF_FAIL_HIT, "TCP_REFRESH_FAIL_HIT",
     SquidLogCode::TCP_REFRESH_MISS, "TCP_REFRESH_MISS", SquidLogCode::TCP_CLIENT_REFRESH, "TCP_CLIENT_REFRESH_MISS",
@@ -686,7 +686,8 @@ Log::init_fields()
     SquidLogCode::ERR_NO_RELAY, "ERR_NO_RELAY", SquidLogCode::ERR_DISK_IO, "ERR_DISK_IO", SquidLogCode::ERR_ZERO_SIZE_OBJECT,
     "ERR_ZERO_SIZE_OBJECT", SquidLogCode::ERR_PROXY_DENIED, "ERR_PROXY_DENIED", SquidLogCode::ERR_WEBFETCH_DETECTED,
     "ERR_WEBFETCH_DETECTED", SquidLogCode::ERR_FUTURE_1, "ERR_FUTURE_1", SquidLogCode::ERR_LOOP_DETECTED, "ERR_LOOP_DETECTED",
-    SquidLogCode::ERR_UNKNOWN, "ERR_UNKNOWN", SquidLogCode::TCP_CF_HIT, "TCP_CF_HIT");
+    SquidLogCode::ERR_TUN_ACTIVE_TIMEOUT, "ERR_TUN_ACTIVE_TIMEOUT", SquidLogCode::ERR_UNKNOWN, "ERR_UNKNOWN",
+    SquidLogCode::TCP_CF_HIT, "TCP_CF_HIT");
 
   Ptr<LogFieldAliasTable> cache_subcode_map = make_ptr(new LogFieldAliasTable);
   cache_subcode_map->init(2, SquidSubcode::EMPTY, "NONE", SquidSubcode::NUM_REDIRECTIONS_EXCEEDED, "NUM_REDIRECTIONS_EXCEEDED");

src/traffic_logstats/logstats.cc

@@ -450,6 +450,7 @@ class UrlLru
       case SquidLogCode::ERR_INVALID_REQ:
       case SquidLogCode::ERR_UNKNOWN:
       case SquidLogCode::ERR_READ_TIMEOUT:
+      case SquidLogCode::ERR_TUN_ACTIVE_TIMEOUT:
         ++(l->errors);
         break;
       default:
@@ -527,6 +528,7 @@ class UrlLru
       case SquidLogCode::ERR_INVALID_REQ:
       case SquidLogCode::ERR_UNKNOWN:
       case SquidLogCode::ERR_READ_TIMEOUT:
+      case SquidLogCode::ERR_TUN_ACTIVE_TIMEOUT:
         l->errors = 1;
         break;
       default:

tests/gold_tests/timeout/tunnel_active_timeout.test.py

@@ -0,0 +1,93 @@
+'''
+Verify that tunnel active timeout produces ERR_TUN_ACTIVE_TIMEOUT squid code.
+'''
+#  Licensed to the Apache Software Foundation (ASF) under one
+#  or more contributor license agreements.  See the NOTICE file
+#  distributed with this work for additional information
+#  regarding copyright ownership.  The ASF licenses this file
+#  to you under the Apache License, Version 2.0 (the
+#  "License"); you may not use this file except in compliance
+#  with the License.  You may obtain a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+#  Unless required by applicable law or agreed to in writing, software
+#  distributed under the License is distributed on an "AS IS" BASIS,
+#  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+#  See the License for the specific language governing permissions and
+#  limitations under the License.
+
+import os
+import sys
+
+Test.Summary = '''
+Verify that tunnel active timeout produces ERR_TUN_ACTIVE_TIMEOUT squid code.
+'''
+
+ts = Test.MakeATSProcess("ts", enable_tls=True)
+server = Test.MakeOriginServer("server", ssl=True)
+
+# Simple response from origin
+request_header = {"headers": "GET / HTTP/1.1\r\nHost: server\r\n\r\n", "timestamp": "1234", "body": ""}
+response_header = {"headers": "HTTP/1.1 200 OK\r\nConnection: close\r\n\r\n", "timestamp": "1234", "body": "hello"}
+server.addResponse("sessionlog.json", request_header, response_header)
+
+ts.addDefaultSSLFiles()
+
+ts.Disk.ssl_multicert_config.AddLine('dest_ip=* ssl_cert_name=server.pem ssl_key_name=server.key')
+
+ts.Disk.records_config.update(
+    {
+        'proxy.config.diags.debug.enabled': 1,
+        'proxy.config.diags.debug.tags': 'http|ssl|tunnel',
+        'proxy.config.ssl.server.cert.path': ts.Variables.SSLDir,
+        'proxy.config.ssl.server.private_key.path': ts.Variables.SSLDir,
+        'proxy.config.ssl.client.verify.server.policy': 'PERMISSIVE',
+        'proxy.config.http.connect_ports': f'{server.Variables.SSL_Port}',
+        # Set a short active timeout for tunnels (2 seconds)
+        'proxy.config.http.transaction_active_timeout_in': 2,
+        # Force log flush every second for test reliability
+        'proxy.config.log.max_secs_per_buffer': 1,
+    })
+
+ts.Disk.remap_config.AddLine(f'map / https://127.0.0.1:{server.Variables.SSL_Port}')
+
+# Configure custom log format to capture squid code
+ts.Disk.logging_yaml.AddLines(
+    '''
+logging:
+  formats:
+    - name: custom
+      format: '%<crc> %<pssc> %<cqhm>'
+  logs:
+    - filename: squid.log
+      format: custom
+'''.split("\n"))
+
+# Test: Perform a CONNECT request that will time out
+tr = Test.AddTestRun("Tunnel active timeout test")
+tr.Processes.Default.StartBefore(server)
+tr.Processes.Default.StartBefore(ts)
+
+# Use the tunnel_timeout_client.py script to establish a CONNECT tunnel and then
+# just hold the connection until ATS times it out
+tr.Setup.Copy('tunnel_timeout_client.py')
+
+# Connect, establish tunnel, then sleep to trigger active timeout
+tr.Processes.Default.Command = (
+    f'{sys.executable} tunnel_timeout_client.py 127.0.0.1 {ts.Variables.port} '
+    f'127.0.0.1 {server.Variables.SSL_Port} 5')
+# The connection will be closed by ATS due to timeout
+tr.Processes.Default.ReturnCode = 0
+tr.StillRunningAfter = ts
+
+# Wait for the access log to be written
+tr = Test.AddTestRun("Wait for the access log to write out")
+tr.DelayStart = 3
+tr.StillRunningAfter = ts
+tr.Processes.Default.Command = 'echo "waiting for log flush"'
+tr.Processes.Default.ReturnCode = 0
+
+# Verify the squid code in the access log
+ts.Disk.File(os.path.join(ts.Variables.LOGDIR, 'squid.log')).Content = Testers.ContainsExpression(
+    'ERR_TUN_ACTIVE_TIMEOUT.*CONNECT', 'Verify the tunnel timeout squid code is logged')

tests/gold_tests/timeout/tunnel_timeout_client.py

@@ -0,0 +1,86 @@
+#!/usr/bin/env python3
+'''
+A simple client that establishes a CONNECT tunnel and then holds the connection
+idle to trigger an active timeout.
+'''
+#  Licensed to the Apache Software Foundation (ASF) under one
+#  or more contributor license agreements.  See the NOTICE file
+#  distributed with this work for additional information
+#  regarding copyright ownership.  The ASF licenses this file
+#  to you under the Apache License, Version 2.0 (the
+#  "License"); you may not use this file except in compliance
+#  with the License.  You may obtain a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+#  Unless required by applicable law or agreed to in writing, software
+#  distributed under the License is distributed on an "AS IS" BASIS,
+#  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+#  See the License for the specific language governing permissions and
+#  limitations under the License.
+
+import socket
+import sys
+
+
+def main():
+    if len(sys.argv) < 6:
+        print(f"Usage: {sys.argv[0]} proxy_host proxy_port target_host target_port sleep_seconds")
+        sys.exit(1)
+
+    proxy_host = sys.argv[1]
+    proxy_port = int(sys.argv[2])
+    target_host = sys.argv[3]
+    target_port = int(sys.argv[4])
+    sleep_seconds = int(sys.argv[5])
+
+    with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as sock:
+        sock.settimeout(10)
+
+        try:
+            sock.connect((proxy_host, proxy_port))
+            print(f"Connected to proxy {proxy_host}:{proxy_port}")
+
+            connect_request = f"CONNECT {target_host}:{target_port} HTTP/1.1\r\nHost: {target_host}:{target_port}\r\n\r\n"
+            sock.sendall(connect_request.encode())
+            print(f"Sent CONNECT request for {target_host}:{target_port}")
+
+            response = b""
+            while b"\r\n\r\n" not in response:
+                data = sock.recv(1024)
+                if not data:
+                    break
+                response += data
+
+            response_str = response.decode()
+            print(f"Received response: {response_str.strip()}")
+
+            if "200" not in response_str:
+                print(f"CONNECT failed: {response_str}")
+                sys.exit(1)
+
+            print(f"Tunnel established, sleeping for {sleep_seconds} seconds to trigger active timeout...")
+
+            sock.settimeout(sleep_seconds + 5)
+
+            try:
+                data = sock.recv(1024)
+                if not data:
+                    print("Connection closed by server (timeout)")
+                else:
+                    print(f"Received data: {data}")
+            except socket.timeout:
+                print("Socket timeout waiting for server")
+            except Exception as e:
+                print(f"Exception: {e}")
+
+        except socket.timeout:
+            print("Socket timeout during connect/handshake")
+        except Exception as e:
+            print(f"Error: {e}")
+
+    print("Done")
+
+
+if __name__ == "__main__":
+    main()