This is an automated email from the ASF dual-hosted git repository.
bcall pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/trafficserver.git
The following commit(s) were added to refs/heads/master by this push:
new 2baa396b90 Add ERR_TUN_ACTIVE_TIMEOUT squid code for tunnel timeouts
(#12786)
2baa396b90 is described below
commit 2baa396b90b2550101c5acc2273123afcc1fcb14
Author: Bryan Call <[email protected]>
AuthorDate: Mon Apr 13 13:51:20 2026 -0700
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.
---
include/proxy/hdrs/HTTP.h | 1 +
src/proxy/http/HttpSM.cc | 8 ++
src/proxy/logging/Log.cc | 5 +-
src/traffic_logstats/logstats.cc | 2 +
.../timeout/tunnel_active_timeout.test.py | 93 ++++++++++++++++++++++
tests/gold_tests/timeout/tunnel_timeout_client.py | 86 ++++++++++++++++++++
6 files changed, 193 insertions(+), 2 deletions(-)
diff --git a/include/proxy/hdrs/HTTP.h b/include/proxy/hdrs/HTTP.h
index dd69181120..104743e593 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 85d1b4caf4..fcdf912e75 100644
--- a/src/proxy/http/HttpSM.cc
+++ b/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) {
diff --git a/src/proxy/logging/Log.cc b/src/proxy/logging/Log.cc
index 3462bfaefb..49a21978b7 100644
--- a/src/proxy/logging/Log.cc
+++ b/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");
diff --git a/src/traffic_logstats/logstats.cc b/src/traffic_logstats/logstats.cc
index f9099b8c9c..8904ded0a8 100644
--- a/src/traffic_logstats/logstats.cc
+++ b/src/traffic_logstats/logstats.cc
@@ -450,6 +450,7 @@ public:
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 @@ public:
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:
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 0000000000..80c5840ace
--- /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: '%<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')
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 0000000000..d96da1c974
--- /dev/null
+++ b/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()
