From b4cdadaca3d1eb2b151f1618f5230389f5f6864f Mon Sep 17 00:00:00 2001 From: bneradt Date: Tue, 24 Mar 2026 10:30:24 -0500 Subject: [PATCH] log-milestone-fields: stabilize across ms truncation Update the log-milestone-fields validator script to use a tolerance that matches per-field millisecond truncation. Also wait for the content of the expectred log lines, not just the existence of the log itself, before validating to ensure that the log entries are present when the validator runs. --- .../gold_tests/logging/log-milestone-fields.test.py | 11 +++++++---- tests/gold_tests/logging/verify_milestone_fields.py | 12 +++++++----- 2 files changed, 14 insertions(+), 9 deletions(-) diff --git a/tests/gold_tests/logging/log-milestone-fields.test.py b/tests/gold_tests/logging/log-milestone-fields.test.py index 60fc69f4536..e2a47ccb346 100644 --- a/tests/gold_tests/logging/log-milestone-fields.test.py +++ b/tests/gold_tests/logging/log-milestone-fields.test.py @@ -33,7 +33,7 @@ class MilestoneFieldsTest: 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) + - All values are integers, with "-" 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) @@ -155,9 +155,12 @@ def _sendCacheHit(self): 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 = Test.AddAwaitFileContainsTestRun( + 'Wait for milestone log lines to be written', + self._log_path, + r'^crc=.* hit_xfer=', + desired_count=2, + ) tr.StillRunningAfter = self._server tr.StillRunningAfter = self._ts diff --git a/tests/gold_tests/logging/verify_milestone_fields.py b/tests/gold_tests/logging/verify_milestone_fields.py index dd161cfccdd..419b8ccc9a3 100644 --- a/tests/gold_tests/logging/verify_milestone_fields.py +++ b/tests/gold_tests/logging/verify_milestone_fields.py @@ -54,6 +54,9 @@ MISS_CHAIN = ['c_hdr', 'c_proc', 'cache', 'dns', 'o_tcp', 'o_wait', 'o_hdr', 'o_proc'] EPOCH_THRESHOLD = 1_000_000_000 +# Each msdms field is truncated independently to integer milliseconds. +# Allow one truncated millisecond per component in the miss chain. +CHAIN_TOLERANCE = len(MISS_CHAIN) def parse_line(line: str) -> dict[str, str]: @@ -116,7 +119,8 @@ def validate_line(fields: dict[str, str], line_num: int) -> list[str]: 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). + # Verify the signed chain sum approximates c_ttfb within a tolerance + # for per-field millisecond truncation. chain_vals = [] for name in MISS_CHAIN: val_str = fields.get(name) @@ -124,8 +128,7 @@ def validate_line(fields: dict[str, str], line_num: int) -> list[str]: chain_vals.append(0) continue try: - v = int(val_str) - chain_vals.append(v if v >= 0 else 0) + chain_vals.append(int(val_str)) except ValueError: chain_vals.append(0) @@ -134,8 +137,7 @@ def validate_line(fields: dict[str, str], line_num: int) -> list[str]: 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: + if c_ttfb_val >= 0 and abs(chain_sum - c_ttfb_val) > CHAIN_TOLERANCE: errors.append( f'line {line_num}: chain sum ({chain_sum}) != c_ttfb ({c_ttfb_val}), ' f'diff={abs(chain_sum - c_ttfb_val)}ms')