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())