Test: add msdms milestone logging field validation autest#12899
Open
bryancall wants to merge 7 commits intoapache:masterfrom
Open
Test: add msdms milestone logging field validation autest#12899bryancall wants to merge 7 commits intoapache:masterfrom
bryancall wants to merge 7 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) |
Comment on lines
60
to
88
| MISS_FIELDS = [ | ||
| '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', | ||
| ] | ||
|
|
||
| HIT_FIELDS = [ | ||
| 'ms', | ||
| 'c_ttfb', | ||
| 'c_tls', | ||
| 'c_hdr', | ||
| 'c_proc', | ||
| 'cache', | ||
| 'hit_proc', | ||
| 'hit_xfer', | ||
| ] | ||
|
|
There was a problem hiding this comment.
The constants MISS_FIELDS and HIT_FIELDS are defined but never used in the test. They appear to be leftover from development and should be removed to keep the code clean.
Suggested change
| MISS_FIELDS = [ | |
| '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', | |
| ] | |
| HIT_FIELDS = [ | |
| 'ms', | |
| 'c_ttfb', | |
| 'c_tls', | |
| 'c_hdr', | |
| 'c_proc', | |
| 'cache', | |
| 'hit_proc', | |
| 'hit_xfer', | |
| ] |
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 ubuntu] |
Contributor
Author
|
[approve ci autest 1] |
Contributor
Author
|
[approve ci clang-analyzer] |
Contributor
Author
|
[approve ci freebsd] |
Contributor
Author
|
[approve ci] |
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.
msdmsmilestone timing fields -- sends a cacheable request twice (miss then hit) and validates all Phase 1 timing fields in the log output. The validation script (verify_milestone_fields.py) checks:c_hdr + c_proc + cache + dns + o_tcp + o_wait + o_hdr + o_proc) sums toc_ttfbwithin 2ms tolerancehit_procandhit_xferare non-negativeThis test exercises the full msdms unmarshal path end-to-end and will catch regressions like the epoch leak fixed in #12897.
Note: This PR also includes the fixes from #12897 (
difference_msecepoch leak) and #12898 (UA_BEGIN_WRITEunconditional) which are required for the test to pass. Once those PRs merge, this branch can be rebased to drop the duplicate commits.Testing: The test itself is the test.