Test: add msdms milestone logging field validation autest#12899
Merged
bryancall merged 8 commits intoapache:masterfrom Mar 23, 2026
Merged
Test: add msdms milestone logging field validation autest#12899bryancall merged 8 commits intoapache:masterfrom
bryancall merged 8 commits intoapache:masterfrom
Conversation
difference_msec() only checked whether ms_end was zero (unset). When ms_start was unset (zero) but ms_end was set, the subtraction produced a large epoch-relative value instead of returning the missing sentinel. Check both milestones before computing the delta.
Mark TS_MILESTONE_UA_BEGIN_WRITE in the SERVER_READ and SERVE_FROM_CACHE paths of handle_api_return(). Previously this milestone was only set in the API_SEND_RESPONSE_HDR hook path, which requires a plugin to hook TS_HTTP_SEND_RESPONSE_HDR_HOOK. Without plugins the milestone stayed at zero, causing msdms log fields that reference UA_BEGIN_WRITE (c_ttfb, o_proc, o_body, hit_proc, hit_xfer) to report -1.
New end-to-end test that sends a cacheable request twice (miss then hit) and validates all Phase 1 msdms timing fields in the resulting log: - All 16 key=value fields present on every line - Values are integers with no epoch-length garbage - Cache miss: origin-phase chain sums to c_ttfb within 2ms - Cache hit: hit_proc and hit_xfer are non-negative Includes a reusable verify_milestone_fields.py validation script. Depends on apache#12897 (difference_msec fix) and apache#12898 (UA_BEGIN_WRITE fix).
3 tasks
Contributor
There was a problem hiding this comment.
Pull request overview
This PR adds a comprehensive end-to-end test for the msdms milestone timing fields in ATS logging. The test validates that milestone timing calculations produce correct values for both cache miss and cache hit paths, catching issues like the epoch leak bug that was fixed in PR #12897.
Changes:
- Adds a new autest (
log-milestone-fields.test.py) that exercises both cache miss and cache hit paths with milestone logging - Includes a Python validation script (
verify_milestone_fields.py) that parses log output and verifies timing field correctness - Includes fixes from PRs #12897 and #12898 for the
difference_msecepoch leak and unconditionalUA_BEGIN_WRITEmilestone marking (to be rebased once those PRs merge)
Reviewed changes
Copilot reviewed 4 out of 4 changed files in this pull request and generated 1 comment.
| File | Description |
|---|---|
| tests/gold_tests/logging/log-milestone-fields.test.py | New autest that sends cache miss and hit requests, configures milestone logging, and validates the output |
| tests/gold_tests/logging/verify_milestone_fields.py | Python script that validates log output: checks field presence, integer values, no epoch leaks, and timing chain correctness |
| src/proxy/http/HttpSM.cc | Marks UA_BEGIN_WRITE milestone unconditionally in SERVER_READ and SERVE_FROM_CACHE cases (from PR #12898) |
| include/proxy/Milestones.h | Fixes epoch leak by checking both start and end milestones are non-zero in difference_msec (from PR #12897) |
These lists were development artifacts not referenced by the test. The validation logic lives in verify_milestone_fields.py which has its own field definitions.
Contributor
Author
|
/retest |
Contributor
Author
|
[approve ci ubuntu] |
The dns field (SERVER_FIRST_CONNECT - CACHE_OPEN_READ_END) can have small negative values due to millisecond-granularity timing overlap. Allow up to -10ms jitter instead of rejecting anything below -1.
Contributor
Author
|
[approve ci autest 1] |
Contributor
Author
|
[approve ci clang-analyzer] |
Contributor
Author
|
[approve ci freebsd] |
Contributor
Author
|
[approve ci] |
bneradt
requested changes
Mar 12, 2026
bneradt
approved these changes
Mar 23, 2026
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Problem
The
msdmsmilestone timing log fields had no end-to-end test coverage.Bugs like the epoch leak in #12897 and the missing
UA_BEGIN_WRITEmilestone in #12898 went undetected until manual inspection.
Changes
log-milestone-fields-- sends a cacheable requesttwice (cache miss then cache hit) and validates all Phase 1
msdmstiming fields in the resulting log output.
verify_milestone_fields.py-- reusable Pythonscript that parses key=value log lines and checks: all 16 fields
present, values are integers with no epoch-length garbage, miss-path
chain sums to
c_ttfbwithin 2 ms, and hit-path fields arenon-negative.
dnsfieldto handle millisecond-granularity overlap between
SERVER_FIRST_CONNECTandCACHE_OPEN_READ_END.Testing
cache-hit paths