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 b7db7b8190 Test: add msdms milestone logging field validation autest
(#12899)
b7db7b8190 is described below
commit b7db7b8190ad90ae11a2200bebc025270c2a3736
Author: Bryan Call <[email protected]>
AuthorDate: Mon Mar 23 14:07:23 2026 -0700
Test: add msdms milestone logging field validation autest (#12899)
Add end-to-end autest for msdms milestone timing log fields.
* New test sends a cacheable request twice (miss then hit) and
validates all Phase 1 msdms fields in the log output.
* Reusable verify_milestone_fields.py checks: all 16 fields
present, values are integers with no epoch-length garbage,
miss-path chain sums to c_ttfb within 2ms tolerance, and
hit-path fields (hit_proc, hit_xfer) are non-negative.
* Allow up to -10ms jitter on the dns field to handle
millisecond-granularity overlap between SERVER_FIRST_CONNECT
and CACHE_OPEN_READ_END.
---
.../logging/log-milestone-fields.test.py | 173 +++++++++++++++++
.../gold_tests/logging/verify_milestone_fields.py | 211 +++++++++++++++++++++
2 files changed, 384 insertions(+)
diff --git a/tests/gold_tests/logging/log-milestone-fields.test.py
b/tests/gold_tests/logging/log-milestone-fields.test.py
new file mode 100644
index 0000000000..60fc69f453
--- /dev/null
+++ b/tests/gold_tests/logging/log-milestone-fields.test.py
@@ -0,0 +1,173 @@
+'''
+Verify that msdms milestone difference fields produce valid output for both
+cache-miss and cache-hit transactions. This exercises the Phase 1 timing
+fields proposed for the squid.log local_disk format.
+'''
+# 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
+
+Test.Summary = 'Verify msdms milestone logging fields for cache miss and cache
hit paths'
+Test.ContinueOnFail = True
+
+
+class MilestoneFieldsTest:
+ """
+ Sends two requests for the same cacheable URL: the first is a cache miss
+ that populates the cache, the second is a cache hit served from RAM cache.
+ A custom log format records all Phase 1 milestone timing fields plus the
+ cache result code. A validation script then parses the log and checks:
+
+ - Every expected key=value pair is present on each line
+ - All values are integers (>= 0 or -1 for unset milestones)
+ - Cache miss line: ms > 0, origin-phase fields present
+ - Cache hit line: hit_proc >= 0 and hit_xfer >= 0
+ - No epoch-length garbage values (> 1_000_000_000)
+ """
+
+ # All Phase 1 msdms fields plus ms and cache result code for
identification.
+ LOG_FORMAT = (
+ 'crc=%<crc> ms=%<ttms>'
+ ' c_ttfb=%<{TS_MILESTONE_UA_BEGIN_WRITE-TS_MILESTONE_SM_START}msdms>'
+ '
c_tls=%<{TS_MILESTONE_TLS_HANDSHAKE_END-TS_MILESTONE_TLS_HANDSHAKE_START}msdms>'
+ '
c_hdr=%<{TS_MILESTONE_UA_READ_HEADER_DONE-TS_MILESTONE_SM_START}msdms>'
+ '
c_proc=%<{TS_MILESTONE_CACHE_OPEN_READ_BEGIN-TS_MILESTONE_UA_READ_HEADER_DONE}msdms>'
+ '
cache=%<{TS_MILESTONE_CACHE_OPEN_READ_END-TS_MILESTONE_CACHE_OPEN_READ_BEGIN}msdms>'
+ '
dns=%<{TS_MILESTONE_SERVER_FIRST_CONNECT-TS_MILESTONE_CACHE_OPEN_READ_END}msdms>'
+ '
o_tcp=%<{TS_MILESTONE_SERVER_CONNECT_END-TS_MILESTONE_SERVER_FIRST_CONNECT}msdms>'
+ '
o_wait=%<{TS_MILESTONE_SERVER_FIRST_READ-TS_MILESTONE_SERVER_CONNECT_END}msdms>'
+ '
o_hdr=%<{TS_MILESTONE_SERVER_READ_HEADER_DONE-TS_MILESTONE_SERVER_FIRST_READ}msdms>'
+ '
o_proc=%<{TS_MILESTONE_UA_BEGIN_WRITE-TS_MILESTONE_SERVER_READ_HEADER_DONE}msdms>'
+ '
o_body=%<{TS_MILESTONE_SERVER_CLOSE-TS_MILESTONE_UA_BEGIN_WRITE}msdms>'
+ ' c_xfer=%<{TS_MILESTONE_SM_FINISH-TS_MILESTONE_SERVER_CLOSE}msdms>'
+ '
hit_proc=%<{TS_MILESTONE_UA_BEGIN_WRITE-TS_MILESTONE_CACHE_OPEN_READ_END}msdms>'
+ '
hit_xfer=%<{TS_MILESTONE_SM_FINISH-TS_MILESTONE_UA_BEGIN_WRITE}msdms>')
+
+ def __init__(self):
+ self._server = Test.MakeOriginServer("server")
+ self._nameserver = Test.MakeDNServer("dns", default='127.0.0.1')
+ self._setupOriginServer()
+ self._setupTS()
+
+ def _setupOriginServer(self):
+ self._server.addResponse(
+ "sessionlog.json",
+ {
+ 'timestamp': 100,
+ "headers": "GET /cacheable HTTP/1.1\r\nHost:
example.com\r\n\r\n",
+ "body": "",
+ },
+ {
+ 'timestamp': 100,
+ "headers":
+ (
+ "HTTP/1.1 200 OK\r\n"
+ "Content-Type: text/plain\r\n"
+ "Cache-Control: max-age=300\r\n"
+ "Connection: close\r\n"
+ "\r\n"),
+ "body": "This is a cacheable response body for milestone
testing.",
+ },
+ )
+
+ def _setupTS(self):
+ self._ts = Test.MakeATSProcess("ts", enable_cache=True)
+
+ self._ts.Disk.records_config.update(
+ {
+ 'proxy.config.diags.debug.enabled': 1,
+ 'proxy.config.diags.debug.tags': 'http|log',
+ 'proxy.config.dns.nameservers':
f'127.0.0.1:{self._nameserver.Variables.Port}',
+ 'proxy.config.dns.resolv_conf': 'NULL',
+ 'proxy.config.http.cache.http': 1,
+ 'proxy.config.log.max_secs_per_buffer': 1,
+ })
+
+ self._ts.Disk.remap_config.AddLine(f'map /
http://127.0.0.1:{self._server.Variables.Port}/')
+
+ self._ts.Disk.logging_yaml.AddLines(
+ f'''
+logging:
+ formats:
+ - name: milestone_test
+ format: '{self.LOG_FORMAT}'
+ logs:
+ - filename: milestone_fields
+ format: milestone_test
+ mode: ascii
+'''.split("\n"))
+
+ @property
+ def _log_path(self) -> str:
+ return os.path.join(self._ts.Variables.LOGDIR, 'milestone_fields.log')
+
+ @property
+ def _validate_script(self) -> str:
+ return os.path.join(Test.TestDirectory, 'verify_milestone_fields.py')
+
+ def run(self):
+ self._sendCacheMiss()
+ self._waitForCacheIO()
+ self._sendCacheHit()
+ self._waitForLog()
+ self._validateLog()
+
+ def _sendCacheMiss(self):
+ tr = Test.AddTestRun('Cache miss request')
+ tr.Processes.Default.StartBefore(self._server)
+ tr.Processes.Default.StartBefore(self._nameserver)
+ tr.Processes.Default.StartBefore(self._ts)
+ tr.MakeCurlCommand(
+ f'--verbose --header "Host: example.com" '
+ f'http://127.0.0.1:{self._ts.Variables.port}/cacheable',
ts=self._ts)
+ tr.Processes.Default.ReturnCode = 0
+ tr.StillRunningAfter = self._server
+ tr.StillRunningAfter = self._ts
+
+ def _waitForCacheIO(self):
+ tr = Test.AddTestRun('Wait for cache write to complete')
+ tr.Processes.Default.Command = 'sleep 1'
+ tr.Processes.Default.ReturnCode = 0
+ tr.StillRunningAfter = self._server
+ tr.StillRunningAfter = self._ts
+
+ def _sendCacheHit(self):
+ tr = Test.AddTestRun('Cache hit request')
+ tr.MakeCurlCommand(
+ f'--verbose --header "Host: example.com" '
+ f'http://127.0.0.1:{self._ts.Variables.port}/cacheable',
ts=self._ts)
+ tr.Processes.Default.ReturnCode = 0
+ tr.StillRunningAfter = self._server
+ tr.StillRunningAfter = self._ts
+
+ def _waitForLog(self):
+ tr = Test.AddTestRun('Wait for log file to be written')
+ tr.Processes.Default.Command =
(os.path.join(Test.Variables.AtsTestToolsDir, 'condwait') + f' 60 1 -f
{self._log_path}')
+ tr.Processes.Default.ReturnCode = 0
+ tr.StillRunningAfter = self._server
+ tr.StillRunningAfter = self._ts
+
+ def _validateLog(self):
+ tr = Test.AddTestRun('Validate milestone fields in log')
+ tr.Processes.Default.Command = f'python3 {self._validate_script}
{self._log_path}'
+ tr.Processes.Default.ReturnCode = 0
+ tr.Processes.Default.TimeOut = 10
+ tr.Processes.Default.Streams.stdout +=
Testers.ContainsExpression('PASS', 'Validation script should report PASS')
+ tr.Processes.Default.Streams.stdout +=
Testers.ExcludesExpression('FAIL', 'Validation script should not report FAIL')
+
+
+MilestoneFieldsTest().run()
diff --git a/tests/gold_tests/logging/verify_milestone_fields.py
b/tests/gold_tests/logging/verify_milestone_fields.py
new file mode 100644
index 0000000000..dd161cfccd
--- /dev/null
+++ b/tests/gold_tests/logging/verify_milestone_fields.py
@@ -0,0 +1,211 @@
+#!/usr/bin/env python3
+'''
+Validate milestone timing fields in an ATS log file.
+
+Parses key=value log lines and checks:
+ - All expected fields are present
+ - All values are integers
+ - No epoch-length garbage (> 1 billion) from the difference_msec bug
+ - Cache miss lines have ms > 0 and origin-phase fields populated
+ - Cache hit lines have hit_proc and hit_xfer populated
+ - The miss-path chain sums to approximately c_ttfb
+'''
+# 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 sys
+
+ALL_FIELDS = [
+ 'crc',
+ 'ms',
+ 'c_ttfb',
+ 'c_tls',
+ 'c_hdr',
+ 'c_proc',
+ 'cache',
+ 'dns',
+ 'o_tcp',
+ 'o_wait',
+ 'o_hdr',
+ 'o_proc',
+ 'o_body',
+ 'c_xfer',
+ 'hit_proc',
+ 'hit_xfer',
+]
+
+TIMING_FIELDS = [f for f in ALL_FIELDS if f != 'crc']
+
+# Fields that form the contiguous miss-path chain to c_ttfb:
+# c_ttfb = c_hdr + c_proc + cache + dns + o_conn + o_wait + o_hdr + o_proc
+MISS_CHAIN = ['c_hdr', 'c_proc', 'cache', 'dns', 'o_tcp', 'o_wait', 'o_hdr',
'o_proc']
+
+EPOCH_THRESHOLD = 1_000_000_000
+
+
+def parse_line(line: str) -> dict[str, str]:
+ """Parse a space-separated key=value log line into a dict."""
+ fields = {}
+ for token in line.strip().split():
+ if '=' in token:
+ key, val = token.split('=', 1)
+ fields[key] = val
+ return fields
+
+
+def validate_line(fields: dict[str, str], line_num: int) -> list[str]:
+ """Return a list of error strings (empty = pass)."""
+ errors = []
+
+ for name in ALL_FIELDS:
+ if name not in fields:
+ errors.append(f'line {line_num}: missing field "{name}"')
+
+ for name in TIMING_FIELDS:
+ val_str = fields.get(name)
+ if val_str is None:
+ continue
+ # Accept '-' as a valid sentinel for unset milestones.
+ if val_str == '-':
+ continue
+ try:
+ val = int(val_str)
+ except ValueError:
+ errors.append(f'line {line_num}: field "{name}" is not an integer:
{val_str!r}')
+ continue
+
+ if val > EPOCH_THRESHOLD:
+ errors.append(f'line {line_num}: field "{name}" looks like an
epoch leak: {val} '
+ f'(> {EPOCH_THRESHOLD})')
+
+ crc = fields.get('crc', '')
+ is_miss = 'MISS' in crc or 'NONE' in crc
+ is_hit = 'HIT' in crc and 'MISS' not in crc
+
+ ms_str = fields.get('ms', '0')
+ try:
+ ms_val = int(ms_str)
+ except ValueError:
+ ms_val = -1
+
+ if ms_val < 0 and ms_str != '-':
+ errors.append(f'line {line_num}: ms should be >= 0, got {ms_val}')
+
+ if is_miss:
+ for name in MISS_CHAIN:
+ val_str = fields.get(name)
+ if val_str is None or val_str == '-':
+ continue
+ try:
+ val = int(val_str)
+ except ValueError:
+ continue
+ if val < -10:
+ errors.append(f'line {line_num}: miss field "{name}" has
unexpected value: {val}')
+
+ # Verify chain sum approximates c_ttfb (within tolerance for rounding).
+ chain_vals = []
+ for name in MISS_CHAIN:
+ val_str = fields.get(name)
+ if val_str is None or val_str == '-':
+ chain_vals.append(0)
+ continue
+ try:
+ v = int(val_str)
+ chain_vals.append(v if v >= 0 else 0)
+ except ValueError:
+ chain_vals.append(0)
+
+ chain_sum = sum(chain_vals)
+ c_ttfb_str = fields.get('c_ttfb')
+ if c_ttfb_str and c_ttfb_str != '-':
+ try:
+ c_ttfb_val = int(c_ttfb_str)
+ # Allow 2ms tolerance for rounding across multiple
sub-millisecond fields.
+ if c_ttfb_val >= 0 and abs(chain_sum - c_ttfb_val) > 2:
+ errors.append(
+ f'line {line_num}: chain sum ({chain_sum}) != c_ttfb
({c_ttfb_val}), '
+ f'diff={abs(chain_sum - c_ttfb_val)}ms')
+ except ValueError:
+ pass
+
+ if is_hit:
+ for name in ['hit_proc', 'hit_xfer']:
+ val_str = fields.get(name)
+ if val_str is None:
+ errors.append(f'line {line_num}: cache hit missing field
"{name}"')
+ continue
+ if val_str == '-':
+ errors.append(f'line {line_num}: cache hit field "{name}"
should not be "-"')
+ continue
+ try:
+ val = int(val_str)
+ if val < 0:
+ errors.append(f'line {line_num}: cache hit field "{name}"
should be >= 0, got {val}')
+ except ValueError:
+ errors.append(f'line {line_num}: cache hit field "{name}" is
not an integer: {val_str!r}')
+
+ return errors
+
+
+def main():
+ if len(sys.argv) != 2:
+ print(f'Usage: {sys.argv[0]} <log_file>', file=sys.stderr)
+ sys.exit(1)
+
+ log_path = sys.argv[1]
+ try:
+ with open(log_path) as f:
+ lines = [l for l in f.readlines() if l.strip()]
+ except FileNotFoundError:
+ print(f'FAIL: log file not found: {log_path}')
+ sys.exit(1)
+
+ if len(lines) < 2:
+ print(f'FAIL: expected at least 2 log lines (miss + hit), got
{len(lines)}')
+ sys.exit(1)
+
+ all_errors = []
+ miss_found = False
+ hit_found = False
+
+ for i, line in enumerate(lines, start=1):
+ fields = parse_line(line)
+ crc = fields.get('crc', '')
+ if 'MISS' in crc:
+ miss_found = True
+ if 'HIT' in crc and 'MISS' not in crc:
+ hit_found = True
+ errors = validate_line(fields, i)
+ all_errors.extend(errors)
+
+ if not miss_found:
+ all_errors.append('No cache miss line found in log')
+ if not hit_found:
+ all_errors.append('No cache hit line found in log')
+
+ if all_errors:
+ for err in all_errors:
+ print(f'FAIL: {err}')
+ sys.exit(1)
+ else:
+ print(f'PASS: validated {len(lines)} log lines '
+ f'(miss={miss_found}, hit={hit_found}), all fields correct')
+ sys.exit(0)
+
+
+if __name__ == '__main__':
+ main()
