From 461e4afc944a901e74c90f6ba11597172160eb7d Mon Sep 17 00:00:00 2001 From: Masaori Koshiba Date: Thu, 22 Jan 2026 14:21:19 +0900 Subject: [PATCH 1/3] Add % logging verification to the negative revalidating AuTest --- tests/gold_tests/autest-site/ats_replay.test.ext | 10 ++++++++++ .../negative-revalidating-enabled-access.gold | 12 ++++++++++++ .../negative-revalidating-enabled.replay.yaml | 16 ++++++++++++++++ 3 files changed, 38 insertions(+) create mode 100644 tests/gold_tests/cache/gold/negative-revalidating-enabled-access.gold diff --git a/tests/gold_tests/autest-site/ats_replay.test.ext b/tests/gold_tests/autest-site/ats_replay.test.ext index 63ee6c217f5..75bd1306d54 100644 --- a/tests/gold_tests/autest-site/ats_replay.test.ext +++ b/tests/gold_tests/autest-site/ats_replay.test.ext @@ -47,6 +47,11 @@ def configure_ats(obj: 'TestRun', server: 'Process', ats_config: dict, dns: Opti for parent_line in parent_config: ts.Disk.parent_config.AddLine(parent_line) + # Configure logging.yaml if specified. + logging_yaml = ats_config.get('logging_yaml') + if logging_yaml != None: + ts.Disk.logging_yaml.AddLines(yaml.dump(logging_yaml).split('\n')) + remap_config = ats_config.get('remap_config', []) for remap_entry in remap_config: if isinstance(remap_entry, str): @@ -113,6 +118,11 @@ def configure_ats(obj: 'TestRun', server: 'Process', ats_config: dict, dns: Opti gold_file = diags_log['gold_file'] ts.Disk.diags_log.Content += gold_file + # access_log validation. + access_log = log_validation.get('access_log', {}) + if 'gold_file' in access_log: + obj.Disk.File(os.path.join(ts.Variables.LOGDIR, access_log['filename']), exists=True, content=access_log['gold_file']) + return ts diff --git a/tests/gold_tests/cache/gold/negative-revalidating-enabled-access.gold b/tests/gold_tests/cache/gold/negative-revalidating-enabled-access.gold new file mode 100644 index 00000000000..46f852bded5 --- /dev/null +++ b/tests/gold_tests/cache/gold/negative-revalidating-enabled-access.gold @@ -0,0 +1,12 @@ +TCP_MISS +TCP_MISS +TCP_MEM_HIT +TCP_MEM_HIT +TCP_REFRESH_MISS +TCP_REFRESH_MISS +TCP_REFRESH_MISS +TCP_REFRESH_MISS +TCP_REFRESH_MISS +TCP_MISS +TCP_MEM_HIT +TCP_REFRESH_MISS diff --git a/tests/gold_tests/cache/replay/negative-revalidating-enabled.replay.yaml b/tests/gold_tests/cache/replay/negative-revalidating-enabled.replay.yaml index 607c3816d34..ec22198698f 100644 --- a/tests/gold_tests/cache/replay/negative-revalidating-enabled.replay.yaml +++ b/tests/gold_tests/cache/replay/negative-revalidating-enabled.replay.yaml @@ -53,6 +53,22 @@ autest: - from: "http://example.com/" to: "http://backend.example.com:{SERVER_HTTP_PORT}/" + logging_yaml: + logging: + formats: + - name: access + format: '%' + + logs: + - filename: access + format: access + mode: ascii + + log_validation: + access_log: + filename: access.log + gold_file: gold/negative-revalidating-enabled-access.gold + sessions: - transactions: From ace1b728effe0fb8327e23328fa62c6e114cdf1e Mon Sep 17 00:00:00 2001 From: Masaori Koshiba Date: Fri, 23 Jan 2026 13:06:49 +0900 Subject: [PATCH 2/3] Fix crc for stale-if-error --- src/proxy/http/HttpTransact.cc | 3 +++ src/proxy/http/HttpTransactHeaders.cc | 3 +++ .../negative-revalidating-enabled-access.gold | 24 +++++++++---------- .../negative-revalidating-enabled.replay.yaml | 2 +- 4 files changed, 19 insertions(+), 13 deletions(-) diff --git a/src/proxy/http/HttpTransact.cc b/src/proxy/http/HttpTransact.cc index aba3e30b7e5..8eb181da214 100644 --- a/src/proxy/http/HttpTransact.cc +++ b/src/proxy/http/HttpTransact.cc @@ -4349,6 +4349,9 @@ HttpTransact::handle_cache_operation_on_forward_server_response(State *s) base_response->set_expires(exp_time); SET_VIA_STRING(VIA_CACHE_FILL_ACTION, VIA_CACHE_UPDATED); + SET_VIA_STRING(VIA_CACHE_RESULT, VIA_IN_CACHE_STALE); + // change VIA_SERVER_RESULT to ERROR because this status hit the negative_revalidating_list + SET_VIA_STRING(VIA_SERVER_RESULT, VIA_SERVER_ERROR); Metrics::Counter::increment(http_rsb.cache_updates); // unset Cache-control: "need-revalidate-once" (if it's set) diff --git a/src/proxy/http/HttpTransactHeaders.cc b/src/proxy/http/HttpTransactHeaders.cc index a7ecee2eb32..328c0fce735 100644 --- a/src/proxy/http/HttpTransactHeaders.cc +++ b/src/proxy/http/HttpTransactHeaders.cc @@ -39,6 +39,7 @@ #include "proxy/hdrs/HTTP.h" #include "iocore/utils/Machine.h" +#include "tsutil/DbgCtl.h" using namespace std::literals; @@ -423,6 +424,8 @@ HttpTransactHeaders::downgrade_request(bool *origin_server_keep_alive, HTTPHdr * void HttpTransactHeaders::generate_and_set_squid_codes(HTTPHdr *header, char *via_string, HttpTransact::SquidLogInfo *squid_codes) { + Dbg(dbg_ctl_http_transact_headers, "via_string=%s", via_string); + SquidLogCode log_code = SquidLogCode::EMPTY; SquidHierarchyCode hier_code = SquidHierarchyCode::EMPTY; SquidHitMissCode hit_miss_code = SQUID_HIT_RESERVED; diff --git a/tests/gold_tests/cache/gold/negative-revalidating-enabled-access.gold b/tests/gold_tests/cache/gold/negative-revalidating-enabled-access.gold index 46f852bded5..058b0df9009 100644 --- a/tests/gold_tests/cache/gold/negative-revalidating-enabled-access.gold +++ b/tests/gold_tests/cache/gold/negative-revalidating-enabled-access.gold @@ -1,12 +1,12 @@ -TCP_MISS -TCP_MISS -TCP_MEM_HIT -TCP_MEM_HIT -TCP_REFRESH_MISS -TCP_REFRESH_MISS -TCP_REFRESH_MISS -TCP_REFRESH_MISS -TCP_REFRESH_MISS -TCP_MISS -TCP_MEM_HIT -TCP_REFRESH_MISS +11 TCP_MISS 200 200 +31 TCP_MISS 200 200 +12 TCP_MEM_HIT 200 000 +32 TCP_MEM_HIT 200 000 +13 TCP_REFRESH_FAIL_HIT 200 503 +33 TCP_REFRESH_FAIL_HIT 200 503 +34 TCP_REFRESH_FAIL_HIT 200 503 +14 TCP_REFRESH_MISS 503 503 +35 TCP_REFRESH_MISS 503 503 +21 TCP_MISS 200 200 +22 TCP_MEM_HIT 200 000 +23 TCP_REFRESH_FAIL_HIT 200 503 diff --git a/tests/gold_tests/cache/replay/negative-revalidating-enabled.replay.yaml b/tests/gold_tests/cache/replay/negative-revalidating-enabled.replay.yaml index ec22198698f..b39ff1e8e6d 100644 --- a/tests/gold_tests/cache/replay/negative-revalidating-enabled.replay.yaml +++ b/tests/gold_tests/cache/replay/negative-revalidating-enabled.replay.yaml @@ -57,7 +57,7 @@ autest: logging: formats: - name: access - format: '%' + format: '%<{uuid}cqh> % % %' logs: - filename: access From f749735cef2bd74a3615f7ada801fe6a75c42508 Mon Sep 17 00:00:00 2001 From: Masaori Koshiba Date: Fri, 23 Jan 2026 14:19:46 +0900 Subject: [PATCH 3/3] Fix for conditional request --- src/proxy/http/HttpTransactHeaders.cc | 2 + .../negative-revalidating-enabled-access.gold | 3 ++ .../negative-revalidating-enabled.replay.yaml | 49 +++++++++++++++++++ 3 files changed, 54 insertions(+) diff --git a/src/proxy/http/HttpTransactHeaders.cc b/src/proxy/http/HttpTransactHeaders.cc index 328c0fce735..11e00c1bc18 100644 --- a/src/proxy/http/HttpTransactHeaders.cc +++ b/src/proxy/http/HttpTransactHeaders.cc @@ -482,6 +482,8 @@ HttpTransactHeaders::generate_and_set_squid_codes(HTTPHdr *header, char *via_str } else { if (via_string[VIA_CACHE_RESULT] == VIA_IN_CACHE_STALE && via_string[VIA_SERVER_RESULT] == VIA_SERVER_NOT_MODIFIED) { log_code = SquidLogCode::TCP_REFRESH_HIT; + } else if (via_string[VIA_CACHE_RESULT] == VIA_IN_CACHE_STALE && via_string[VIA_SERVER_RESULT] == VIA_SERVER_ERROR) { + log_code = SquidLogCode::TCP_REF_FAIL_HIT; } else { log_code = SquidLogCode::TCP_IMS_MISS; } diff --git a/tests/gold_tests/cache/gold/negative-revalidating-enabled-access.gold b/tests/gold_tests/cache/gold/negative-revalidating-enabled-access.gold index 058b0df9009..b7b5e08abce 100644 --- a/tests/gold_tests/cache/gold/negative-revalidating-enabled-access.gold +++ b/tests/gold_tests/cache/gold/negative-revalidating-enabled-access.gold @@ -1,8 +1,10 @@ 11 TCP_MISS 200 200 31 TCP_MISS 200 200 12 TCP_MEM_HIT 200 000 +42 TCP_IMS_HIT 304 000 32 TCP_MEM_HIT 200 000 13 TCP_REFRESH_FAIL_HIT 200 503 +43 TCP_REFRESH_FAIL_HIT 304 503 33 TCP_REFRESH_FAIL_HIT 200 503 34 TCP_REFRESH_FAIL_HIT 200 503 14 TCP_REFRESH_MISS 503 503 @@ -10,3 +12,4 @@ 21 TCP_MISS 200 200 22 TCP_MEM_HIT 200 000 23 TCP_REFRESH_FAIL_HIT 200 503 +`` diff --git a/tests/gold_tests/cache/replay/negative-revalidating-enabled.replay.yaml b/tests/gold_tests/cache/replay/negative-revalidating-enabled.replay.yaml index b39ff1e8e6d..fdf7fca6fc6 100644 --- a/tests/gold_tests/cache/replay/negative-revalidating-enabled.replay.yaml +++ b/tests/gold_tests/cache/replay/negative-revalidating-enabled.replay.yaml @@ -93,6 +93,7 @@ sessions: fields: - [ Content-Length, 32 ] - [ Cache-Control, max-age=2 ] + - [ ETag, C0FFEE ] proxy-response: status: 200 @@ -146,6 +147,30 @@ sessions: proxy-response: status: 200 + # Verify we serve the 304 Not Modified out of the cache with INM request + - client-request: + method: "GET" + version: "1.1" + scheme: "http" + url: /path/reques_item + headers: + fields: + - [ Host, example.com ] + - [ uuid, 42 ] + - [ If-None-Match, C0FFEE ] + + # This should not reach the origin server. + server-response: + status: 503 + reason: "Service Unavailable" + headers: + fields: + - [ Content-Length, 32 ] + + # Again, we should serve this out of the cache. + proxy-response: + status: 304 + # Verify zero-length is also served from cache when fresh. - client-request: method: "GET" @@ -196,6 +221,30 @@ sessions: proxy-response: status: 200 + # Verify that we serve the 304 Not Modified out of the cache with INM request + - client-request: + method: "GET" + version: "1.1" + scheme: "http" + url: /path/reques_item + headers: + fields: + - [ Host, example.com ] + - [ uuid, 43 ] + - [ If-None-Match, C0FFEE ] + + # This should not reach the origin server. + server-response: + status: 503 + reason: "Service Unavailable" + headers: + fields: + - [ Content-Length, 32 ] + + # Again, we should serve this out of the cache. + proxy-response: + status: 304 + # Test zero-length while stale - first request (regression test for issue #6649). - client-request: method: "GET"