From d3fae8341d1f9cc58275c5d60e76fcc3d1d90182 Mon Sep 17 00:00:00 2001 From: Bryan Call Date: Tue, 6 Jan 2026 15:04:21 -0800 Subject: [PATCH 1/2] Add ERR_TUN_ACTIVE_TIMEOUT squid code for tunnel timeouts Add new SquidLogCode to identify when CONNECT tunnels time out due to active timeout. This makes tunnel timeouts visible in access logs via the crc (cache result code) field. Previously, tunnel timeouts were not distinguishable in logs - users could only see them in DEBUG logs. Now the access log will show crc=ERR_TUN_ACTIVE_TIMEOUT for timed-out tunnels. Includes autotest to verify the squid code is logged correctly. --- include/proxy/hdrs/HTTP.h | 1 + src/proxy/http/HttpSM.cc | 8 ++ src/proxy/logging/Log.cc | 5 +- .../timeout/tunnel_active_timeout.test.py | 85 ++++++++++++++++ .../timeout/tunnel_timeout_client.py | 96 +++++++++++++++++++ 5 files changed, 193 insertions(+), 2 deletions(-) create mode 100644 tests/gold_tests/timeout/tunnel_active_timeout.test.py create mode 100644 tests/gold_tests/timeout/tunnel_timeout_client.py diff --git a/include/proxy/hdrs/HTTP.h b/include/proxy/hdrs/HTTP.h index 8759fcc09ab..835bc18a4c3 100644 --- a/include/proxy/hdrs/HTTP.h +++ b/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' }; diff --git a/src/proxy/http/HttpSM.cc b/src/proxy/http/HttpSM.cc index 87e8c859456..303842ddfcc 100644 --- a/src/proxy/http/HttpSM.cc +++ b/src/proxy/http/HttpSM.cc @@ -4064,6 +4064,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 @@ -4118,6 +4122,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) { diff --git a/src/proxy/logging/Log.cc b/src/proxy/logging/Log.cc index ca56f27c5ac..6855ba53b60 100644 --- a/src/proxy/logging/Log.cc +++ b/src/proxy/logging/Log.cc @@ -655,7 +655,7 @@ Log::init_fields() Ptr 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", @@ -676,7 +676,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 cache_subcode_map = make_ptr(new LogFieldAliasTable); cache_subcode_map->init(2, SquidSubcode::EMPTY, "NONE", SquidSubcode::NUM_REDIRECTIONS_EXCEEDED, "NUM_REDIRECTIONS_EXCEEDED"); diff --git a/tests/gold_tests/timeout/tunnel_active_timeout.test.py b/tests/gold_tests/timeout/tunnel_active_timeout.test.py new file mode 100644 index 00000000000..80827cd394e --- /dev/null +++ b/tests/gold_tests/timeout/tunnel_active_timeout.test.py @@ -0,0 +1,85 @@ +''' +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, + }) + +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: '% % %' + 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 + +# Verify the squid code in the access log +squid_log_path = ts.Disk.File(os.path.join(ts.Variables.LOGDIR, 'squid.log')) +squid_log_path.Content = Testers.ContainsExpression( + 'ERR_TUN_ACTIVE_TIMEOUT.*CONNECT', 'Verify the tunnel timeout squid code is logged') diff --git a/tests/gold_tests/timeout/tunnel_timeout_client.py b/tests/gold_tests/timeout/tunnel_timeout_client.py new file mode 100644 index 00000000000..e9f6202ae31 --- /dev/null +++ b/tests/gold_tests/timeout/tunnel_timeout_client.py @@ -0,0 +1,96 @@ +#!/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 +import time + + +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]) + + # Connect to the proxy + sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) + sock.settimeout(10) + + try: + sock.connect((proxy_host, proxy_port)) + print(f"Connected to proxy {proxy_host}:{proxy_port}") + + # Send CONNECT request + 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}") + + # Read the response + 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}") + sock.close() + sys.exit(1) + + print(f"Tunnel established, sleeping for {sleep_seconds} seconds to trigger active timeout...") + + # Now hold the connection idle until the active timeout fires + # Use a longer socket timeout so we can detect when ATS closes the connection + sock.settimeout(sleep_seconds + 5) + + try: + # Wait for data or connection close + 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}") + finally: + sock.close() + + print("Done") + + +if __name__ == "__main__": + main() From c71d9166f72e02e452f430e9d80c150760ab058e Mon Sep 17 00:00:00 2001 From: Bryan Call Date: Thu, 8 Jan 2026 09:54:39 -0800 Subject: [PATCH 2/2] Fix autest for tunnel active timeout logging - Add proxy.config.log.max_secs_per_buffer=1 to force log flush - Add delay test run to wait for log file to be written - Remove unused 'import time' from client script --- .../gold_tests/timeout/tunnel_active_timeout.test.py | 12 ++++++++++-- tests/gold_tests/timeout/tunnel_timeout_client.py | 1 - 2 files changed, 10 insertions(+), 3 deletions(-) diff --git a/tests/gold_tests/timeout/tunnel_active_timeout.test.py b/tests/gold_tests/timeout/tunnel_active_timeout.test.py index 80827cd394e..80c5840acea 100644 --- a/tests/gold_tests/timeout/tunnel_active_timeout.test.py +++ b/tests/gold_tests/timeout/tunnel_active_timeout.test.py @@ -46,6 +46,8 @@ '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}') @@ -79,7 +81,13 @@ 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 -squid_log_path = ts.Disk.File(os.path.join(ts.Variables.LOGDIR, 'squid.log')) -squid_log_path.Content = Testers.ContainsExpression( +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') diff --git a/tests/gold_tests/timeout/tunnel_timeout_client.py b/tests/gold_tests/timeout/tunnel_timeout_client.py index e9f6202ae31..f31fc2fe8c1 100644 --- a/tests/gold_tests/timeout/tunnel_timeout_client.py +++ b/tests/gold_tests/timeout/tunnel_timeout_client.py @@ -21,7 +21,6 @@ import socket import sys -import time def main():