From fed4605f1de952e152c6cef0bf1350da27c6da12 Mon Sep 17 00:00:00 2001 From: bneradt Date: Tue, 21 Jul 2026 15:11:48 -0500 Subject: [PATCH] Logging: add cache freshness fields MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Cache modeling cannot currently observe an object’s effective freshness limit or its age when ATS serves it, leaving access logs unable to describe cache lifetime and churn. This adds cfl and cca log fields and records their values when ATS prepares cache metadata or serves a cached response. It resets the values for each lookup and adds replay coverage for writes, hits, and non-cacheable responses. Fixes: #13127 Co-authored-by: sheikh-saifi --- doc/admin-guide/logging/formatting.en.rst | 13 ++ include/proxy/http/HttpTransact.h | 4 + include/proxy/logging/LogAccess.h | 2 + include/proxy/logging/TransactionLogData.h | 12 +- src/proxy/http/HttpTransact.cc | 21 +++ src/proxy/logging/Log.cc | 10 ++ src/proxy/logging/LogAccess.cc | 18 +++ src/proxy/logging/TransactionLogData.cc | 18 +++ .../logging/cache-freshness-fields.test.py | 38 +++++ .../replay/cache-freshness-fields.replay.yaml | 135 ++++++++++++++++++ .../logging/verify_cache_freshness_fields.py | 60 ++++++++ 11 files changed, 326 insertions(+), 5 deletions(-) create mode 100644 tests/gold_tests/logging/cache-freshness-fields.test.py create mode 100644 tests/gold_tests/logging/replay/cache-freshness-fields.replay.yaml create mode 100644 tests/gold_tests/logging/verify_cache_freshness_fields.py diff --git a/doc/admin-guide/logging/formatting.en.rst b/doc/admin-guide/logging/formatting.en.rst index 420df43090b..92d8a70228f 100644 --- a/doc/admin-guide/logging/formatting.en.rst +++ b/doc/admin-guide/logging/formatting.en.rst @@ -157,6 +157,8 @@ Cache Details .. _crra: .. _cwra: .. _cccs: +.. _cfl: +.. _cca: These log fields reveal details of the |TS| proxy interaction with its own cache while attempting to service incoming client requests. @@ -191,6 +193,17 @@ cccs Proxy Cache Cache collapsed connection success; -1: collapsing was attempted but failed, request went upstream 0: collapsing was unnecessary 1: attempted to collapse and got a cache hit on subsequent read attempts + +cfl Proxy Cache Freshness limit, in seconds, for an object served from or + written to cache. The limit reflects parsed cache response + metadata and the effective cache configuration. The value + is ``-1`` when not applicable. + +cca Proxy Cache Current age, in seconds, of the cached object when served. + The age is calculated from the cached response metadata + and cache timing state. The value is ``-1`` when not + applicable. + ===== ============== ========================================================== .. _admin-logging-fields-txn: diff --git a/include/proxy/http/HttpTransact.h b/include/proxy/http/HttpTransact.h index b918fa0c27e..adf115f3938 100644 --- a/include/proxy/http/HttpTransact.h +++ b/include/proxy/http/HttpTransact.h @@ -490,6 +490,8 @@ class HttpTransact HTTPInfo transform_store; CacheDirectives directives; HTTPInfo *object_read = nullptr; + int freshness_limit = -1; + ink_time_t current_age = -1; HTTPInfo *stale_fallback = nullptr; // Saved stale object for action 6 fallback during retry CacheWriteLock_t write_lock_state = CacheWriteLock_t::INIT; int lookup_count = 0; @@ -1114,6 +1116,8 @@ class HttpTransact static void handle_response_keep_alive_headers(State *s, HTTPVersion ver, HTTPHdr *heads); static int get_max_age(HTTPHdr *response); static int calculate_document_freshness_limit(State *s, HTTPHdr *response, time_t response_date, bool *heuristic); + static void set_cache_freshness_info(State *s, HTTPHdr *response, ink_time_t request_time, ink_time_t response_time, + bool include_current_age); static Freshness_t what_is_document_freshness(State *s, HTTPHdr *client_request, HTTPHdr *cached_obj_response, bool evaluate_actual_freshness = false); static Authentication_t AuthenticationNeeded(const OverridableHttpConfigParams *p, HTTPHdr *client_request, diff --git a/include/proxy/logging/LogAccess.h b/include/proxy/logging/LogAccess.h index 35f14ea55c5..7c981d58c6b 100644 --- a/include/proxy/logging/LogAccess.h +++ b/include/proxy/logging/LogAccess.h @@ -196,6 +196,8 @@ class LogAccess int marshal_cache_result_subcode(char *); // INT int marshal_proxy_host_port(char *); // INT int marshal_cache_hit_miss(char *); // INT + int marshal_cache_freshness_limit(char *); // INT + int marshal_cache_current_age(char *); // INT int marshal_proxy_resp_all_header_fields(char *); // STR // diff --git a/include/proxy/logging/TransactionLogData.h b/include/proxy/logging/TransactionLogData.h index 908e036e389..4092a555b1a 100644 --- a/include/proxy/logging/TransactionLogData.h +++ b/include/proxy/logging/TransactionLogData.h @@ -166,11 +166,13 @@ class TransactionLogData int64_t get_congestion_control_crat() const; // ===== Cache state ===== - int get_cache_write_code() const; - int get_cache_transform_write_code() const; - int get_cache_open_read_tries() const; - int get_cache_open_write_tries() const; - int get_max_cache_open_write_retries() const; + int get_cache_write_code() const; + int get_cache_transform_write_code() const; + int get_cache_open_read_tries() const; + int get_cache_open_write_tries() const; + int get_cache_freshness_limit() const; + int64_t get_cache_current_age() const; + int get_max_cache_open_write_retries() const; // ===== Retry attempts ===== int64_t get_simple_retry_attempts() const; diff --git a/src/proxy/http/HttpTransact.cc b/src/proxy/http/HttpTransact.cc index cea93328fb0..09fdf90cdb4 100644 --- a/src/proxy/http/HttpTransact.cc +++ b/src/proxy/http/HttpTransact.cc @@ -2139,6 +2139,9 @@ HttpTransact::HandleRequestAuthorized(State *s) void HttpTransact::DecideCacheLookup(State *s) { + s->cache_info.freshness_limit = -1; + s->cache_info.current_age = -1; + // Check if a client request is lookupable. if (s->redirect_info.redirect_in_process) { // for redirect, we want to skip cache lookup and write into @@ -3059,6 +3062,7 @@ HttpTransact::build_response_from_cache(State *s, HTTPWarningCode warning_code) obj = s->cache_info.object_read; } cached_response = obj->response_get(); + set_cache_freshness_info(s, cached_response, obj->request_sent_time_get(), obj->response_received_time_get(), true); // If the client request is conditional, and the cached copy meets // the conditions, do not need to send back the full document, @@ -4835,6 +4839,7 @@ HttpTransact::handle_cache_operation_on_forward_server_response(State *s) // unset warning revalidation failed header if it set // (potentially added by negative revalidating) delete_warning_value(base_response, HTTPWarningCode::REVALIDATION_FAILED); + set_cache_freshness_info(s, base_response, s->request_sent_time, s->response_received_time, true); } ink_assert(base_response->valid()); @@ -5223,6 +5228,8 @@ HttpTransact::set_headers_for_cache_write(State *s, HTTPInfo *cache_info, HTTPHd cache_info->response_get()->field_delete(static_cast(MIME_FIELD_WWW_AUTHENTICATE)); } + set_cache_freshness_info(s, cache_info->response_get(), s->request_sent_time, s->response_received_time, false); + dump_header(dbg_ctl_http_hdrs, cache_info->request_get(), s->state_machine_id(), "Cached Request Hdr"); } @@ -7510,6 +7517,20 @@ HttpTransact::calculate_document_freshness_limit(State *s, HTTPHdr *response, ti return (freshness_limit); } +void +HttpTransact::set_cache_freshness_info(State *s, HTTPHdr *response, ink_time_t request_time, ink_time_t response_time, + bool include_current_age) +{ + bool heuristic = false; + ink_time_t response_date = response->get_date(); + + s->cache_info.freshness_limit = calculate_document_freshness_limit(s, response, response_date, &heuristic); + if (include_current_age) { + s->cache_info.current_age = + HttpTransactCache::calculate_document_age(request_time, response_time, response, response_date, s->current.now); + } +} + ////////////////////////////////////////////////////////////////////////////// // // diff --git a/src/proxy/logging/Log.cc b/src/proxy/logging/Log.cc index 96b7a56798e..51cd5d31590 100644 --- a/src/proxy/logging/Log.cc +++ b/src/proxy/logging/Log.cc @@ -767,6 +767,16 @@ Log::init_fields() global_field_list.add(field, false); field_symbol_hash.emplace("chm", field); + field = new LogField("cache_freshness_limit", "cfl", LogField::Type::sINT, &LogAccess::marshal_cache_freshness_limit, + &LogAccess::unmarshal_int_to_str); + global_field_list.add(field, false); + field_symbol_hash.emplace("cfl", field); + + field = new LogField("cache_current_age", "cca", LogField::Type::sINT, &LogAccess::marshal_cache_current_age, + &LogAccess::unmarshal_int_to_str); + global_field_list.add(field, false); + field_symbol_hash.emplace("cca", field); + field = new LogField("proxy_response_all_header_fields", "psah", LogField::Type::STRING, &LogAccess::marshal_proxy_resp_all_header_fields, &LogUtils::unmarshalMimeHdr); global_field_list.add(field, false); diff --git a/src/proxy/logging/LogAccess.cc b/src/proxy/logging/LogAccess.cc index 6d0d2fe6641..073942d79c3 100644 --- a/src/proxy/logging/LogAccess.cc +++ b/src/proxy/logging/LogAccess.cc @@ -2695,6 +2695,24 @@ LogAccess::marshal_cache_hit_miss(char *buf) return INK_MIN_ALIGN; } +int +LogAccess::marshal_cache_freshness_limit(char *buf) +{ + if (buf) { + marshal_int(buf, static_cast(m_data->get_cache_freshness_limit())); + } + return INK_MIN_ALIGN; +} + +int +LogAccess::marshal_cache_current_age(char *buf) +{ + if (buf) { + marshal_int(buf, m_data->get_cache_current_age()); + } + return INK_MIN_ALIGN; +} + /*------------------------------------------------------------------------- -------------------------------------------------------------------------*/ diff --git a/src/proxy/logging/TransactionLogData.cc b/src/proxy/logging/TransactionLogData.cc index b226fc8349f..c7f8e788559 100644 --- a/src/proxy/logging/TransactionLogData.cc +++ b/src/proxy/logging/TransactionLogData.cc @@ -992,6 +992,24 @@ TransactionLogData::get_max_cache_open_write_retries() const return -1; } +int +TransactionLogData::get_cache_freshness_limit() const +{ + if (likely(m_http_sm != nullptr)) { + return m_http_sm->t_state.cache_info.freshness_limit; + } + return -1; +} + +int64_t +TransactionLogData::get_cache_current_age() const +{ + if (likely(m_http_sm != nullptr)) { + return static_cast(m_http_sm->t_state.cache_info.current_age); + } + return -1; +} + // ===== Retry attempts ===== int64_t diff --git a/tests/gold_tests/logging/cache-freshness-fields.test.py b/tests/gold_tests/logging/cache-freshness-fields.test.py new file mode 100644 index 00000000000..80673b3f6f7 --- /dev/null +++ b/tests/gold_tests/logging/cache-freshness-fields.test.py @@ -0,0 +1,38 @@ +''' +Verify the cache freshness limit and current age log fields. +''' +# 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 +import sys + +Test.Summary = 'Verify cache freshness limit and current age log fields' + +traffic_run = Test.ATSReplayTest(replay_file='replay/cache-freshness-fields.replay.yaml') +ts = traffic_run.Processes.ts +log_path = os.path.join(ts.Variables.LOGDIR, 'cache_freshness_fields.log') + +Test.AddAwaitFileContainsTestRun( + 'Wait for cache freshness log output', + log_path, + r'^uncacheable ', +) + +validation_run = Test.AddTestRun('Validate cache freshness log fields') +validation_script = os.path.join(Test.TestDirectory, 'verify_cache_freshness_fields.py') +validation_run.Processes.Default.Command = f'{sys.executable} {validation_script} {log_path}' +validation_run.Processes.Default.ReturnCode = 0 diff --git a/tests/gold_tests/logging/replay/cache-freshness-fields.replay.yaml b/tests/gold_tests/logging/replay/cache-freshness-fields.replay.yaml new file mode 100644 index 00000000000..17576bc5171 --- /dev/null +++ b/tests/gold_tests/logging/replay/cache-freshness-fields.replay.yaml @@ -0,0 +1,135 @@ +# 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. + +meta: + version: "1.0" + +autest: + description: 'Exercise cache freshness logging for writes, hits, and non-cacheable responses' + + dns: + name: dns + + server: + name: server + + client: + name: client + + ats: + name: ts + process_config: + enable_cache: true + + records_config: + proxy.config.http.cache.http: 1 + proxy.config.http.insert_age_in_response: 0 + proxy.config.log.max_secs_per_buffer: 1 + + remap_config: + - from: "http://example.com/" + to: "http://backend.example.com:{SERVER_HTTP_PORT}/" + + logging_yaml: + logging: + formats: + - name: cache_freshness_fields + format: '%<{uuid}cqh> % % %' + logs: + - filename: cache_freshness_fields + format: cache_freshness_fields + mode: ascii + +sessions: + - transactions: + - client-request: + method: GET + url: /cacheable + version: '1.1' + headers: + fields: + - [Host, example.com] + - [uuid, cache-write] + + server-response: + status: 200 + reason: OK + headers: + fields: + - [Content-Length, 4] + - [Cache-Control, "max-age=60"] + - [Age, 7] + content: + encoding: plain + data: body + + proxy-response: + status: 200 + content: + encoding: plain + data: body + verify: {as: equal} + + - client-request: + delay: 100ms + method: GET + url: /cacheable + version: '1.1' + headers: + fields: + - [Host, example.com] + - [uuid, cache-hit] + + proxy-request: + expect: absent + + server-response: + status: 500 + reason: Not Used + + proxy-response: + status: 200 + content: + encoding: plain + data: body + verify: {as: equal} + + - client-request: + method: GET + url: /uncacheable + version: '1.1' + headers: + fields: + - [Host, example.com] + - [uuid, uncacheable] + + server-response: + status: 200 + reason: OK + headers: + fields: + - [Content-Length, 4] + - [Cache-Control, no-store] + content: + encoding: plain + data: body + + proxy-response: + status: 200 + content: + encoding: plain + data: body + verify: {as: equal} diff --git a/tests/gold_tests/logging/verify_cache_freshness_fields.py b/tests/gold_tests/logging/verify_cache_freshness_fields.py new file mode 100644 index 00000000000..eaf71980117 --- /dev/null +++ b/tests/gold_tests/logging/verify_cache_freshness_fields.py @@ -0,0 +1,60 @@ +''' +Validate the cache freshness fields produced by cache-freshness-fields.test.py. +''' +# 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 pathlib +import sys + + +def load_log_entries(log_path: pathlib.Path) -> dict[str, tuple[int, int, str]]: + entries: dict[str, tuple[int, int, str]] = {} + + for line in log_path.read_text(encoding='utf-8').splitlines(): + uuid, freshness_limit, current_age, cache_result = line.split() + entries[uuid] = (int(freshness_limit), int(current_age), cache_result) + + return entries + + +def main() -> int: + entries = load_log_entries(pathlib.Path(sys.argv[1])) + expected_uuids = {'cache-write', 'cache-hit', 'uncacheable'} + + if entries.keys() != expected_uuids: + print(f'Expected entries for {sorted(expected_uuids)}, got {sorted(entries)}', file=sys.stderr) + return 1 + + write_freshness, write_age, write_result = entries['cache-write'] + if write_freshness != 60 or write_age != -1 or 'MISS' not in write_result: + print(f'Unexpected cache-write entry: {entries["cache-write"]}', file=sys.stderr) + return 1 + + hit_freshness, hit_age, hit_result = entries['cache-hit'] + if hit_freshness != 60 or hit_age < 7 or 'HIT' not in hit_result or 'MISS' in hit_result: + print(f'Unexpected cache-hit entry: {entries["cache-hit"]}', file=sys.stderr) + return 1 + + if entries['uncacheable'][:2] != (-1, -1): + print(f'Unexpected uncacheable entry: {entries["uncacheable"]}', file=sys.stderr) + return 1 + + return 0 + + +if __name__ == '__main__': + sys.exit(main())