ATS 10: uncacheable redirect is cached when number_of_redirections > 0 (most of the time)
- Dominant language
- C++
- Stars
- 2k
- Forks
- 874
- Avg merge
- 6d 15h
- Merged PRs (30d)
- 46
Description
On ATS 10.0.0 and 10.0.1-rc0, it seems that when a remap rule has `number_of_redirections` set to a non-zero value, the redirect itself is _sometimes_ cached even though it is not cacheable. The "sometimes" seems to be deterministic for a given set of configuration files, but after changing something unrelated (including comments in config files), the server may flip to a state where things work as expected (redirect is not cached).
`redirect_use_orig_cache_key` is unset and traffic_ctl shows that it is the default (0).
Steps to reproduce:
1. Add a remap rule such as `map http://localhost/ http://localhost/ @plugin=conf_remap.so @pparam=proxy.config.http.number_of_redirections=2`
2. Have a webserver generate a redirect to somewhere, for example with Apache: `Redirect /aaa1 http://example.com/whatever`
3. Request the URL: `curl -x http://localhost:8000 http://localhost/aaa1`, note in HTTP server log that ATS fetches the redirect.
4. Repeat the request, note that ATS (probably) doesn't fetch the redirect again. Though sometimes it will work correctly.
5. (Bonus step: Try to fetch the redirect target manually through the cache, note that it gets a MISS.)
Complete debug log is included from the non-working state, I was not able to capture one from a working state. Some interesting parts:
Initial request (step 3) with the redirect fetched from origin:
```
[Oct 7 16:58:35.939] [ET_NET 0] DIAG: (http) [0] State Transition: SM_ACTION_API_
OS_DNS -> SM_ACTION_CACHE_ISSUE_WRITE
[Oct 7 16:58:35.939] [ET_NET 0] DIAG: (http_cache_write) [0] writing to cache with URL htt
p://localhost/aaa1
[Oct 7 16:58:35.939] [ET_NET 0] DIAG: (http_cache) [0] [&HttpCacheSM::state_cache_open_
write, CACHE_EVENT_OPEN_WRITE/TS_EVENT_CACHE_OPEN_WRITE]
[Oct 7 16:58:35.939] [ET_NET 0] DIAG: (http) [0] CACHE_EVENT_OPEN_WRITE/TS_EVENT_CACHE_OPEN_WRITE, 11
08
[Oct 7 16:58:35.939] [ET_NET 0] DIAG: (http) [0] [&HttpSM : state_cache_open_write, CACHE_E
VENT_OPEN_WRITE/TS_EVENT_CACHE_OPEN_WRITE]
[Oct 7 16:58:35.940] [ET_NET 0] DIAG: (http_trans) Next action next; nullptr
[Oct 7 16:58:35.940] [ET_NET 0] DIAG: (http) [0] State Transition: SM_ACTION_CACH
E_ISSUE_WRITE -> SM_ACTION_ORIGIN_SERVER_OPEN
[Oct 7 16:58:35.940] [ET_NET 0] DIAG: (http) Setting upstream connection failure 0 to 5
[Oct 7 16:58:35.940] [ET_NET 0] DIAG: (http_track) [0] entered inside do_http_server_open ][ip
v4]
[Oct 7 16:58:35.940] [ET_NET 0] DIAG: (http) [0] open connection to localhost: 127.0.0.1:80
[Oct 7 16:58:35.940] [ET_NET 0] DIAG: (http_seq) [0] Sending request to server
…
[Oct 7 16:58:35.942] [ET_NET 0] DIAG: (http_trans) [0] [hfsco] cache a
ction: CACHE_DO_WRITE
[Oct 7 16:58:35.942] [ET_NET 0] DIAG: (http_trans) [0] (hc
oofsr)
[Oct 7 16:58:35.942] [ET_NET 0] DIAG: (http_seq) [0] Enter
ing handle_cache_operation_on_forward_server_response
[Oct 7 16:58:35.942] [ET_NET 0] DIAG: (http_trans) [0] client permits storing
[Oct 7 16:58:35.942] [ET_NET 0] DIAG: (http_trans) [0] cache-control or expires header is required for 302
[Oct 7 16:58:35.942] [ET_NET 0] DIAG: (http_trans) [0] [hcoofsr] response is not cacheable
[Oct 7 16:58:35.942] [ET_NET 0] DIAG: (http_trans) [0] [hcoofsr] response code: 302
```
Redirect is followed and the target is written:
```
Oct 7 16:58:35.942] [ET_NET 0] DIAG: (http) [0] State Transition: SM_ACTION_ORIG
IN_SERVER_OPEN -> SM_ACTION_SERVER_READ
[Oct 7 16:58:35.942] [ET_NET 0] DIAG: (http_redirect) [0] redirect_required: 1
[Oct 7 16:58:35.942] [ET_NET 0] DIAG: (http_redirect) [0] enable_redirection 1
[Oct 7 16:58:35.942] [ET_NET 0] DIAG: (http_redirect) [0] redirect_required: 1
[Oct 7 16:58:35.942] [ET_NET 0] DIAG: (http_redirect) [0] redirect url: http://XXX.s3.amazonaws.c
om/aaa-assets/71321fb9c8ddca4edd3f3a7a3ac55c08eac6d0a201efae369d1eb3fa0fe96fe7/assets/XXX_assets/customer_benefits_page.html
…
[Oct 7 16:58:35.974] [ET_NET 0] DIAG: (http) [0] State Transition: SM_ACTION_API_
OS_DNS -> SM_ACTION_CACHE_ISSUE_WRITE
[Oct 7 16:58:35.974] [ET_NET 0] DIAG: (http_cache_write) [0] writing to cache with URL htt
p://XXX.s3.amazonaws.com/aaa-assets/71321fb9c8ddca4edd3f3a7a3ac55c08eac6d0a201efae369d1eb3fa0fe96fe7/assets/XXX_assets/customer_benefi
ts_page.html
[Oct 7 16:58:35.974] [ET_NET 0] DIAG: (http) [0] CACHE_EVENT_OPEN_WRITE_FAILED/TS_EVENT_CACHE_OPEN_WR
ITE_FAILED, 1109
[Oct 7 16:58:35.974] [ET_NET 0] DIAG: (http) [0] [&HttpSM : state_cache_open_write, CACHE_E
VENT_OPEN_WRITE_FAILED/TS_EVENT_CACHE_OPEN_WRITE_FAILED]
[Oct 7 16:58:35.974] [ET_NET 0] DIAG: (http_redirect) [0] CACHE_EVENT_OPEN_WRITE_FAILED dur
ing redirect follow
[Oct 7 16:58:35.974] [ET_NET 0] DIAG: (http_trans) Next action next; nullptr
[Oct 7 16:58:35.974] [ET_NET 0] DIAG: (http) [0] State Transition: SM_ACTION_CACH
E_ISSUE_WRITE -> SM_ACTION_ORIGIN_SERVER_OPEN
…
[Oct 7 16:58:36.013] [ET_NET 0] DIAG: (http) [0] server info = 52.95.170.56:80
[Oct 7 16:58:36.013] [ET_NET 0] DIAG: (http_trans) [0] [hfsco] redirect in progress, non-3xx response, setting cache_do_write
[Oct 7 16:58:36.013] [ET_NET 0] DIAG: (http_trans) [0] [hfsco] cache action: CACHE_DO_WRITE
[Oct 7 16:58:36.013] [ET_NET 0] DIAG: (http_trans) [0] (hcoofsr)
[Oct 7 16:58:36.013] [ET_NET 0] DIAG: (http_seq) [0] Entering handle_cache_operation_on_forward_server_response
[Oct 7 16:58:36.013] [ET_NET 0] DIAG: (http_trans) [0] client permits storing
[Oct 7 16:58:36.013] [ET_NET 0] DIAG: (http_trans) [0] YES by response cache control
[Oct 7 16:58:36.013] [ET_NET 0] DIAG: (http_trans) [0] [hcoofsr] response is cacheable
[Oct 7 16:58:36.013] [ET_NET 0] DIAG: (http_trans) [0] [hcoofsr] response code: 200
[Oct 7 16:58:36.013] [ET_NET 0] DIAG: (http_trans) [0] [hcoofsr] cache write
+++++++++ Cached Request Hdr +++++++++
-- State Machine Id: 0
GET http://XXX.s3.amazonaws.com/aaa-assets/71321fb9c8ddca4edd3f3a7a3ac55c08eac6d0a201efae369d1eb3fa0fe96fe7/assets/XXX_assets/customer_benefits_page.html HTTP/1.1
```
Second request (step 4):
```
[Oct 7 16:58:38.364] [ET_NET 1] DIAG: (http) [1] State Transition: SM_ACTION_API_POST_REMAP -> SM_ACTION_CACHE_LOOKUP
[Oct 7 16:58:38.364] [ET_NET 1] DIAG: (http_seq) [1] Issuing cache lookup for URL http://localhost/aaa1
[Oct 7 16:58:38.364] [ET_NET 1] DIAG: (http_match) [SelectFromAlternates] # alternates = 1
[Oct 7 16:58:38.364] [ET_NET 1] DIAG: (http_seq) [SelectFromAlternates] 1 alternates for this cached doc
[alts] There are 1 alternates for this request header.
…
[alts] ---- alternate #1 (Q = 1) has these request/response hdrs:
GET http://XXX.s3.amazonaws.com/aaa-assets/71321fb9c8ddca4edd3f3a7a3ac55c08eac6d0a201efae369d1eb3fa0fe96fe7/assets/XXX_assets/customer_benefits_page.html HTTP/1.1
…
[Oct 7 16:58:38.364] [ET_NET 1] DIAG: (http_trans) [1] CacheOpenRead -- hit
[Oct 7 16:58:38.364] [ET_NET 1] DIAG: (http_trans) Next action SM_ACTION_API_READ_CACHE_HDR; HandleCacheOpenReadHitFreshness
[Oct 7 16:58:38.364] [ET_NET 1] DIAG: (http) [1] State Transition: SM_ACTION_CACHE_LOOKUP -> SM_ACTION_API_READ_CACHE_HDR
```
So somehow the redirect target got cached at the location of the redirect. The target has a `Cache-Control` that allows caching, nothing relevant to this target is set in `cache.config`. The same thing happens regardless of whether any global plugins are enabled. This 10.0.0 was built with cmake defaults on Ubuntu 22.04, though the same thing happens when 10.0.1-rc0 is built on Debian Bookworm.
Any suggestions? I looked at the relevant code, but I'm not familiar with the internals of the HTTP state machine and couldn't see anything obviously wrong.
[log.txt](https://github.com/user-attachments/files/17280297/log.txt)
Contributor guide
Assessment
This issue has not been assessed yet.