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

[ezelkow1]

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]

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]

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]

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

[github-actions]

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.

[bneradt]

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.

[github-actions]

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.