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..80c5840acea --- /dev/null +++ b/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: '% % %' + 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') 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..f31fc2fe8c1 --- /dev/null +++ b/tests/gold_tests/timeout/tunnel_timeout_client.py @@ -0,0 +1,95 @@ +#!/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]) + + # 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()