trafficserver icon indicating copy to clipboard operation
trafficserver copied to clipboard
verified publisher icon apache

Negative revalidating lifetime not fully respected, appears only valid on first stale request

Open ezelkow1 opened this issue 5 years ago • 6 comments

Doing some testing here something seems not quite right with the negative revalidating. I ran with these settings:

CONFIG proxy.config.http.cache.max_stale_age INT 200 CONFIG proxy.config.http.negative_revalidating_enabled INT 1 CONFIG proxy.config.http.negative_revalidating_lifetime INT 40 CONFIG proxy.config.http.cache.guaranteed_max_lifetime INT 30 CONFIG proxy.config.http.cache.heuristic_min_lifetime INT 20 CONFIG proxy.config.http.cache.heuristic_max_lifetime INT 200 CONFIG proxy.config.http.cache.heuristic_lm_factor FLOAT 0.10

Client response: url http://localhost:8080/test2 -Lvsk -o /dev/null

GET /test2 HTTP/1.1 < Last-Modified: Mon, 13 Apr 2020 16:15:13 GMT < Date: Mon, 13 Apr 2020 16:15:13 GMT < Age: 18

< Last-Modified: Mon, 13 Apr 2020 16:15:13 GMT < Date: Mon, 13 Apr 2020 16:15:13 GMT < Expires: Mon, 13 Apr 2020 16:16:19 GMT < Age: 26

< HTTP/1.1 502 Bad Gateway < Date: Mon, 13 Apr 2020 16:15:42 GMT < Content-Length: 0 < Age: 0

After the first request I had the origin respond with 502's. The second request is being served stale and then has the expires header properly generated for revalidating_lifetime in to the future. However the last request is still within the expiration time but is coming back as the actual origin error.

Checking the logs I can see that last request is an actual cache miss [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransactHeaders.cc:404 (calculate_document_age)> (http_age) [calculate_document_age] now: 1586794531 [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransactHeaders.cc:405 (calculate_document_age)> (http_age) [calculate_document_age] now (fixed): 1586794531 [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransactHeaders.cc:406 (calculate_document_age)> (http_age) [calculate_document_age] apparent_age: 0 [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransactHeaders.cc:407 (calculate_document_age)> (http_age) [calculate_document_age] corrected_received_age: 0 [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransactHeaders.cc:408 (calculate_document_age)> (http_age) [calculate_document_age] response_delay: 0 [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransactHeaders.cc:409 (calculate_document_age)> (http_age) [calculate_document_age] corrected_initial_age: 0 [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransactHeaders.cc:410 (calculate_document_age)> (http_age) [calculate_document_age] resident_time: 18 [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransactHeaders.cc:411 (calculate_document_age)> (http_age) [calculate_document_age] current_age: 18 [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransact.cc:7350 (what_is_document_freshness)> (http_match) [9] [what_is_document_freshness] fresh_limit: 20 current_age: 18 [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransact.cc:7397 (what_is_document_freshness)> (http_match) [9] [..._document_freshness] initial age limit: 20 [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransact.cc:7453 (what_is_document_freshness)> (http_match) [9] document_freshness --- current_age = 18 [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransact.cc:7454 (what_is_document_freshness)> (http_match) [9] document_freshness --- age_limit = 20 [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransact.cc:7455 (what_is_document_freshness)> (http_match) [9] document_freshness --- fresh_limit = 20 [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransact.cc:7456 (what_is_document_freshness)> (http_seq) [9] document_freshness --- current_age = 18 [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransact.cc:7457 (what_is_document_freshness)> (http_seq) [9] document_freshness --- age_limit = 20 [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransact.cc:7458 (what_is_document_freshness)> (http_seq) [9] document_freshness --- fresh_limit = 20 [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransact.cc:7477 (what_is_document_freshness)> (http_match) [9] [..._document_freshness] document is fresh; returning FRESHNESS_FRESH [Apr 13 16:15:31.892] [ET_NET 22] DEBUG: <HttpTransact.cc:2529 (HandleCacheOpenReadHitFreshness)> (http_seq) [9] [HttpTransact::HandleCacheOpenReadHitFreshness] Fresh copy

[Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:406 (calculate_document_age)> (http_age) [calculate_document_age] apparent_age: 0 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:407 (calculate_document_age)> (http_age) [calculate_document_age] corrected_received_age: 0 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:408 (calculate_document_age)> (http_age) [calculate_document_age] response_delay: 0 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:409 (calculate_document_age)> (http_age) [calculate_document_age] corrected_initial_age: 0 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:410 (calculate_document_age)> (http_age) [calculate_document_age] resident_time: 26 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:411 (calculate_document_age)> (http_age) [calculate_document_age] current_age: 26 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:7350 (what_is_document_freshness)> (http_match) [10] [what_is_document_freshness] fresh_limit: 20 current_age: 26 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:7397 (what_is_document_freshness)> (http_match) [10] [..._document_freshness] initial age limit: 20 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:7453 (what_is_document_freshness)> (http_match) [10] document_freshness --- current_age = 26 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:7454 (what_is_document_freshness)> (http_match) [10] document_freshness --- age_limit = 20 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:7455 (what_is_document_freshness)> (http_match) [10] document_freshness --- fresh_limit = 20 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:7456 (what_is_document_freshness)> (http_seq) [10] document_freshness --- current_age = 26 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:7457 (what_is_document_freshness)> (http_seq) [10] document_freshness --- age_limit = 20 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:7458 (what_is_document_freshness)> (http_seq) [10] document_freshness --- fresh_limit = 20 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:7465 (what_is_document_freshness)> (http_match) [10] [..._document_freshness] document needs revalidate/too old; returning FRESHNESS_STALE [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:2539 (HandleCacheOpenReadHitFreshness)> (http_seq) [10] [HttpTransact::HandleCacheOpenReadHitFreshness] Stale in cache [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:2625 (need_to_revalidate)> (http_seq) [10] [HttpTransact::HandleCacheOpenReadHit] Authentication not needed [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:2558 (HandleCacheOpenReadHitFreshness)> (http_trans) Next action SM_ACTION_API_CACHE_LOOKUP_COMPLETE; CallOSDNSLookup [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpSM.cc:7247 (call_transact_and_set_next_state)> (http) [10] State Transition: SM_ACTION_API_READ_CACHE_HDR -> SM_ACTION_API_CACHE_LOOKUP_COMPLETE [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:2576 (CallOSDNSLookup)> (http) [10] [HttpTransact::callos] 127.0.0.1 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:2590 (CallOSDNSLookup)> (http_trans) Next action SM_ACTION_DNS_LOOKUP; OSDNSLookup [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpSM.cc:7247 (call_transact_and_set_next_state)> (http) [10] State Transition: SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_DNS_LOOKUP [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:1788 (OSDNSLookup)> (http_trans) [10] [HttpTransact::OSDNSLookup] This was attempt 0 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:1858 (OSDNSLookup)> (http_seq) [10] [HttpTransact::OSDNSLookup] DNS Lookup successful [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:1898 (OSDNSLookup)> (http_trans) [10] [OSDNSLookup] DNS lookup for O.S. successful IP: 127.0.0.1 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:1995 (OSDNSLookup)> (http_trans) Next action SM_ACTION_API_OS_DNS; HandleCacheOpenReadHit [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpSM.cc:7247 (call_transact_and_set_next_state)> (http) [10] State Transition: SM_ACTION_DNS_LOOKUP -> SM_ACTION_API_OS_DNS [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:2722 (HandleCacheOpenReadHit)> (http_seq) [10] [HttpTransact::HandleCacheOpenReadHit] Authentication not needed [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:2791 (HandleCacheOpenReadHit)> (http_trans) [10] CacheOpenRead --- needs_auth = 0 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:2792 (HandleCacheOpenReadHit)> (http_trans) [10] CacheOpenRead --- needs_revalidate = 1 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:2793 (HandleCacheOpenReadHit)> (http_trans) [10] CacheOpenRead --- response_returnable = 1 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:2794 (HandleCacheOpenReadHit)> (http_trans) [10] CacheOpenRead --- needs_cache_auth = 0 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:2795 (HandleCacheOpenReadHit)> (http_trans) [10] CacheOpenRead --- send_revalidate = 1 [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:2798 (HandleCacheOpenReadHit)> (http_trans) [10] CacheOpenRead --- HIT-STALE [Apr 13 16:15:39.629] [ET_NET 23] DEBUG: <HttpTransact.cc:2802 (HandleCacheOpenReadHit)> (http_seq) [10] [HttpTransact::HandleCacheOpenReadHit] Revalidate document with server .... [Apr 13 16:15:39.630] [ET_NET 23] DEBUG: <HttpTransact.cc:4053 (handle_forward_server_connection_open)> (http_trans) [10] [hfsco] cache action: CACHE_DO_UPDATE [Apr 13 16:15:39.630] [ET_NET 23] DEBUG: <HttpTransact.cc:4182 (handle_cache_operation_on_forward_server_response)> (http_trans) [10] [handle_cache_operation_on_forward_server_response] (hcoofsr) [Apr 13 16:15:39.630] [ET_NET 23] DEBUG: <HttpTransact.cc:4183 (handle_cache_operation_on_forward_server_response)> (http_seq) [10] [handle_cache_operation_on_forward_server_response] [Apr 13 16:15:39.630] [ET_NET 23] DEBUG: <HttpTransact.cc:6229 (is_response_cacheable)> (http_trans) [10] [is_response_cacheable] client permits storing [Apr 13 16:15:39.630] [ET_NET 23] DEBUG: <HttpTransact.cc:6333 (is_response_cacheable)> (http_trans) [10] [is_response_cacheable] NO by default [Apr 13 16:15:39.630] [ET_NET 23] DEBUG: <HttpTransact.cc:4192 (handle_cache_operation_on_forward_server_response)> (http_trans) [10] [hcoofsr] response is not cacheable [Apr 13 16:15:39.630] [ET_NET 23] DEBUG: <HttpTransact.cc:4339 (handle_cache_operation_on_forward_server_response)> (http_trans) [10] [hcoofsr] response code: 502 [Apr 13 16:15:39.630] [ET_NET 23] DEBUG: <HttpTransact.cc:4350 (handle_cache_operation_on_forward_server_response)> (http_trans) [10] neg reval check: server_resp: 502, action: 8, neg_reval: 1, is_stale_returnable: [Apr 13 16:15:39.630] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:401 (calculate_document_age)> (http_age) [calculate_document_age] age_value: 0 [Apr 13 16:15:39.630] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:402 (calculate_document_age)> (http_age) [calculate_document_age] date_value: 1586794513 [Apr 13 16:15:39.630] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:403 (calculate_document_age)> (http_age) [calculate_document_age] response_time: 1586794513 [Apr 13 16:15:39.630] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:404 (calculate_document_age)> (http_age) [calculate_document_age] now: 1586794539 [Apr 13 16:15:39.630] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:405 (calculate_document_age)> (http_age) [calculate_document_age] now (fixed): 1586794539 [Apr 13 16:15:39.630] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:406 (calculate_document_age)> (http_age) [calculate_document_age] apparent_age: 0 [Apr 13 16:15:39.630] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:407 (calculate_document_age)> (http_age) [calculate_document_age] corrected_received_age: 0 [Apr 13 16:15:39.631] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:408 (calculate_document_age)> (http_age) [calculate_document_age] response_delay: 0 [Apr 13 16:15:39.631] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:409 (calculate_document_age)> (http_age) [calculate_document_age] corrected_initial_age: 0 [Apr 13 16:15:39.631] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:410 (calculate_document_age)> (http_age) [calculate_document_age] resident_time: 26 [Apr 13 16:15:39.631] [ET_NET 23] DEBUG: <HttpTransactHeaders.cc:411 (calculate_document_age)> (http_age) [calculate_document_age] current_age: 26 [Apr 13 16:15:39.631] [ET_NET 23] DEBUG: <HttpTransact.cc:5967 (is_stale_cache_response_returnable)> (http_trans) [10] [is_stale_cache_response_returnable] can serve stale [Apr 13 16:15:39.631] [ET_NET 23] DEBUG: <HttpTransact.cc:4356 (handle_cache_operation_on_forward_server_response)> (http_trans) [10] [hcoofsr] negative revalidating: revalidate stale object and serve from cache [Apr 13 16:15:39.631] [ET_NET 23] DEBUG: <HttpTransact.cc:4364 (handle_cache_operation_on_forward_server_response)> (http_Trans) [10] [hcoofsr] negative reval, lifetime: 40, curtime: 1586794539, exp: 1586794579

[Apr 13 16:15:42.061] [ET_NET 24] DEBUG: <HttpTransact.cc:2334 (HandleCacheOpenRead)> (http_trans) [11] CacheOpenRead -- miss [Apr 13 16:15:42.061] [ET_NET 24] DEBUG: <HttpTransact.cc:3213 (HandleCacheOpenReadMiss)> (http_trans) [11] [HandleCacheOpenReadMiss] --- MISS [Apr 13 16:15:42.061] [ET_NET 24] DEBUG: <HttpTransact.cc:3215 (HandleCacheOpenReadMiss)> (http_seq) [11] [HttpTransact::HandleCacheOpenReadMiss] Miss in cache ..... [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransact.cc:4053 (handle_forward_server_connection_open)> (http_trans) [11] [hfsco] cache action: CACHE_DO_WRITE [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransact.cc:4182 (handle_cache_operation_on_forward_server_response)> (http_trans) [11] [handle_cache_operation_on_forward_server_response] (hcoofsr) [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransact.cc:4183 (handle_cache_operation_on_forward_server_response)> (http_seq) [11] [handle_cache_operation_on_forward_server_response] [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransact.cc:6229 (is_response_cacheable)> (http_trans) [11] [is_response_cacheable] client permits storing [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransact.cc:6333 (is_response_cacheable)> (http_trans) [11] [is_response_cacheable] NO by default [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransact.cc:4192 (handle_cache_operation_on_forward_server_response)> (http_trans) [11] [hcoofsr] response is not cacheable [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransact.cc:4339 (handle_cache_operation_on_forward_server_response)> (http_trans) [11] [hcoofsr] response code: 502 [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransact.cc:4350 (handle_cache_operation_on_forward_server_response)> (http_trans) [11] neg reval check: server_resp: 502, action: 9, neg_reval: 1, is_stale_returnable: [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransactHeaders.cc:401 (calculate_document_age)> (http_age) [calculate_document_age] age_value: 0 [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransactHeaders.cc:402 (calculate_document_age)> (http_age) [calculate_document_age] date_value: 1586794542 [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransactHeaders.cc:403 (calculate_document_age)> (http_age) [calculate_document_age] response_time: 1586794542 [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransactHeaders.cc:404 (calculate_document_age)> (http_age) [calculate_document_age] now: 1586794542 [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransactHeaders.cc:405 (calculate_document_age)> (http_age) [calculate_document_age] now (fixed): 1586794542 [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransactHeaders.cc:406 (calculate_document_age)> (http_age) [calculate_document_age] apparent_age: 0 [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransactHeaders.cc:407 (calculate_document_age)> (http_age) [calculate_document_age] corrected_received_age: 0 [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransactHeaders.cc:408 (calculate_document_age)> (http_age) [calculate_document_age] response_delay: 0 [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransactHeaders.cc:409 (calculate_document_age)> (http_age) [calculate_document_age] corrected_initial_age: 0 [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransactHeaders.cc:410 (calculate_document_age)> (http_age) [calculate_document_age] resident_time: 0 [Apr 13 16:15:42.062] [ET_NET 24] DEBUG: <HttpTransactHeaders.cc:411 (calculate_document_age)> (http_age) [calculate_document_age] current_age: 0

So there seems like there might be an issue that after a negative revalidating is done to hand back a stale copy, the object is being marked as expired and the newly added expires header is being ignore

ezelkow1 avatar Apr 13 '20 16:04 ezelkow1

Also to add to this, on the transaction where the object was considered a miss, it was initially found in cache and with the expires header: [Apr 13 16:15:42.061] [ET_NET 24] DEBUG: <HttpTransactCache.cc:180 (SelectFromAlternates)> (http_match) [SelectFromAlternates] # alternates = 1 [Apr 13 16:15:42.061] [ET_NET 24] DEBUG: <HttpTransactCache.cc:181 (SelectFromAlternates)> (http_seq) [SelectFromAlternates] 1 alternates for this cached doc [alts] ---- alternate #1 (Q = 1) has these request/response hdrs: GET http://127.0.0.1/test2 HTTP/1.1 Host: 127.0.0.1 User-Agent: curl/7.69.1 Accept: /

HTTP/1.1 200 OK Accept-Ranges: bytes Content-Length: 0 Content-Type: text/plain Last-Modified: Mon, 13 Apr 2020 16:15:13 GMT Date: Mon, 13 Apr 2020 16:15:13 GMT Expires: Mon, 13 Apr 2020 16:16:19 GMT

[Apr 13 16:15:42.061] [ET_NET 24] DEBUG: <HttpTransactCache.cc:252 (SelectFromAlternates)> (http_seq) [SelectFromAlternates] Chosen alternate # 0 [alts] and the winner is alternate number 0 [Apr 13 16:15:42.061] [ET_NET 24] DEBUG: <HttpCacheSM.cc:100 (state_cache_open_read)> (http_cache) [11] [&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED/TS_EVENT_CACHE_OPEN_READ_FAILED] [Apr 13 16:15:42.061] [ET_NET 24] DEBUG: <HttpSM.cc:2632 (main_handler)> (http) [11] [HttpSM::main_handler, CACHE_EVENT_OPEN_READ_FAILED/TS_EVENT_CACHE_OPEN_READ_FAILED] [Apr 13 16:15:42.061] [ET_NET 24] DEBUG: <HttpSM.cc:2563 (state_cache_open_read)> (http) [11] [&HttpSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED/TS_EVENT_CACHE_OPEN_READ_FAILED] [Apr 13 16:15:42.061] [ET_NET 24] DEBUG: <HttpSM.cc:2597 (state_cache_open_read)> (http) [11] cache_open_read - CACHE_EVENT_OPEN_READ_FAILED with ECACHE_NO_DOC (-20400) [Apr 13 16:15:42.061] [ET_NET 24] DEBUG: <HttpSM.cc:2599 (state_cache_open_read)> (http) [state_cache_open_read] open read failed. [Apr 13 16:15:42.061] [ET_NET 24] DEBUG: <HttpTransact.cc:2304 (HandleCacheOpenRead)> (http_trans) [11] [HttpTransact::HandleCacheOpenRead] [Apr 13 16:15:42.061] [ET_NET 24] DEBUG: <HttpTransact.cc:2334 (HandleCacheOpenRead)> (http_trans) [11] CacheOpenRead -- miss

However it was considered a cache miss anyway

ezelkow1 avatar Apr 13 '20 17:04 ezelkow1

Doing more testing here this appears to be an oddity of using 0 length requests

I see this issue, where only the first get on a 0 length cached object comes back as stale and the second succeeds, when using only 0 length objects.

When using objects of any size then it appears negative revalidating does work, though the docs description could be updated to give a better idea of what its doing. It looks like if the server returns a 5xx then the expires header is set for negreval-lifetime in to the future. Then subsequent requests are returned as fresh up until that new expiration time is hit. Then the expires header is updated again if the requests still fails or it is fetched from the origin.

This will continue until max-stale-age is hit

ezelkow1 avatar Apr 14 '20 16:04 ezelkow1

@SolidWallOfCode since we talked a bit about this :), was just going through and closing my open issues and was reminded of this one

ezelkow1 avatar May 14 '20 18:05 ezelkow1

This issue has been automatically marked as stale because it has not had recent activity. Marking it stale to flag it for further consideration by the community.

github-actions[bot] avatar Jun 18 '21 18:06 github-actions[bot]

This is interesting. I've written a test around the negative revalidating feature before. I'll assign this to myself and see whether I can add a test for this.

bneradt avatar Jun 18 '21 20:06 bneradt

This issue has been automatically marked as stale because it has not had recent activity. Marking it stale to flag it for further consideration by the community.

github-actions[bot] avatar Jun 19 '22 02:06 github-actions[bot]