Logging: add cache freshness fields

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:

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,

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
 
   //

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;

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<std::string_view>(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);
+  }
+}
+
 //////////////////////////////////////////////////////////////////////////////
 //
 //

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

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<int64_t>(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;
+}
+
 /*-------------------------------------------------------------------------
   -------------------------------------------------------------------------*/
 

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<int64_t>(m_http_sm->t_state.cache_info.current_age);
+  }
+  return -1;
+}
+
 // ===== Retry attempts =====
 
 int64_t

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

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> %<cfl> %<cca> %<crc>'
+        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}