Logging: add cache freshness fields - #13417
Conversation
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: apache#13127 Co-authored-by: sheikh-saifi <p240592@pwr.nu.edu.pk>
ab8b85a to
fed4605
Compare
|
Thanks for fixing this! the reset in DecideCacheLookup and splitting the write vs hit call sites was exactly what my version was missing. Went through the code and the three test cases (write/hit/uncacheable) and it all makes sense. |
Sounds good. Thanks for the comments. I definitely plan to attribute your work with the commit, in addition to the PR here. |
| 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); |
There was a problem hiding this comment.
These should use s->request_sent_time and s->response_received_time rather than the object's raw timestamps.
what_is_document_freshness() uses the transaction timestamps, which are capped against s->client_request_time. The Age header sent to the client uses those values as well. Using the object's raw timestamps here can therefore make cca differ from both the freshness decision and the response's Age header.
There is also a problem on the api_update_cached_object == CONTINUE path. There, obj is &s->cache_info.object_store, whose timestamps can still be zero after a plugin creates it with TSHttpTxnCachedRespModifiableGet(). Passing those values to calculate_document_age() makes cca roughly the current Unix timestamp.
Passing s->request_sent_time and s->response_received_time fixes both cases.
| // 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); |
There was a problem hiding this comment.
This call is skipped by the negative revalidation path earlier in the function. That branch sets action = SERVE_AND_UPDATE and returns before reaching here.
Those transactions serve the stale cached object and extend its stored Expires, but leave both freshness fields at -1. Negative revalidation is enabled by default for 500, 502, 503, and 504 responses. There is a reproducer in the review summary.
|
|
||
| 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 |
There was a problem hiding this comment.
"the effective cache configuration" is broader than what calculate_document_freshness_limit() currently includes.
The calculation uses the response headers plus guaranteed_min/max_lifetime and heuristic_min/max_lifetime, but not s->cache_control. That excludes cache.config directives such as ttl-in-cache and revalidate-after.
For example, with ttl-in-cache=300 and an origin response containing max-age=1, a hit at age 3 logs cfl=1 cca=3.
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 p240592@pwr.nu.edu.pk