ATS 9.2.x | 10.0.x and origin 301/302 chase redirections

[mkrug1981]

We are running Trafficserver 9.2.3 and observed an issue where trafficserver seems not to work as expected by following 302 redirects.

Following the redirect from Origin, ATS now serves the content on the first attempt. Unfortunately, re-querying the same object always results in a timeout.
After some debugging, it appears that the second and subsequent requests never get the content and always hit a timeout.
The debug logs show 'cache open read failure' in a retry loop.

[Dec 22 09:13:55.428] [ET_NET 19] DEBUG: <HttpTransact.cc:1499 (HandleRequest)> (http_seq) [453] request valid.
[Dec 22 09:13:55.429] [ET_NET 19] DEBUG: <HttpTransact.cc:2148 (DecideCacheLookup)> (http_trans) [453] Will do cache lookup.
[Dec 22 09:13:55.429] [ET_NET 19] DEBUG: <HttpTransact.cc:2149 (DecideCacheLookup)> (http_seq) [453] Will do cache lookup
[Dec 22 09:13:55.429] [ET_NET 19] DEBUG: <HttpSM.cc:7636 (call_transact_and_set_next_state)> (http) [453] State Transition: SM_ACTION_API_POST_REMAP -> SM_ACTION_CACHE_LOOKUP
[Dec 22 09:13:55.429] [ET_NET 19] DEBUG: <HttpSM.cc:4860 (do_cache_lookup_and_read)> (http_seq) [453] Issuing cache lookup for URL http://ida-mkrug-cdn.check.com/aaa/test100MB.nff
[Dec 22 09:13:56.440] [ET_NET 19] DEBUG: <HttpCacheSM.cc:100 (state_cache_open_read)> (http_cache) [453] [&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED/TS_EVENT_CACHE_OPEN_READ_FAILED]
[Dec 22 09:13:56.451] [ET_NET 19] DEBUG: <HttpCacheSM.cc:100 (state_cache_open_read)> (http_cache) [453] [&HttpCacheSM::state_cache_open_read, EVENT_INTERVAL]
[Dec 22 09:13:56.451] [ET_NET 19] DEBUG: <HttpCacheSM.cc:142 (state_cache_open_read)> (http_cache) [453] [state_cache_open_read] cache open read failure 1. retrying cache open read...
[Dec 22 09:13:57.426] [ET_NET 19] DEBUG: <HttpCacheSM.cc:100 (state_cache_open_read)> (http_cache) [453] [&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED/TS_EVENT_CACHE_OPEN_READ_FAILED]
[Dec 22 09:13:57.436] [ET_NET 19] DEBUG: <HttpCacheSM.cc:100 (state_cache_open_read)> (http_cache) [453] [&HttpCacheSM::state_cache_open_read, EVENT_INTERVAL]
[Dec 22 09:13:57.436] [ET_NET 19] DEBUG: <HttpCacheSM.cc:142 (state_cache_open_read)> (http_cache) [453] [state_cache_open_read] cache open read failure 2. retrying cache open read...
[Dec 22 09:13:58.388] [ET_NET 19] DEBUG: <HttpCacheSM.cc:100 (state_cache_open_read)> (http_cache) [453] [&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED/TS_EVENT_CACHE_OPEN_READ_FAILED]
[Dec 22 09:13:58.398] [ET_NET 19] DEBUG: <HttpCacheSM.cc:100 (state_cache_open_read)> (http_cache) [453] [&HttpCacheSM::state_cache_open_read, EVENT_INTERVAL]
[Dec 22 09:13:58.398] [ET_NET 19] DEBUG: <HttpCacheSM.cc:142 (state_cache_open_read)> (http_cache) [453] [state_cache_open_read] cache open read failure 3. retrying cache open read...
[Dec 22 09:13:59.355] [ET_NET 19] DEBUG: <HttpCacheSM.cc:100 (state_cache_open_read)> (http_cache) [453] [&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED/TS_EVENT_CACHE_OPEN_READ_FAILED]
[Dec 22 09:13:59.365] [ET_NET 19] DEBUG: <HttpCacheSM.cc:100 (state_cache_open_read)> (http_cache) [453] [&HttpCacheSM::state_cache_open_read, EVENT_INTERVAL]
[Dec 22 09:13:59.365] [ET_NET 19] DEBUG: <HttpCacheSM.cc:142 (state_cache_open_read)> (http_cache) [453] [state_cache_open_read] cache open read failure 4. retrying cache open read...
[Dec 22 09:14:00.368] [ET_NET 19] DEBUG: <HttpCacheSM.cc:100 (state_cache_open_read)> (http_cache) [453] [&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED/TS_EVENT_CACHE_OPEN_READ_FAILED]
[Dec 22 09:14:00.378] [ET_NET 19] DEBUG: <HttpCacheSM.cc:100 (state_cache_open_read)> (http_cache) [453] [&HttpCacheSM::state_cache_open_read, EVENT_INTERVAL]
[Dec 22 09:14:00.378] [ET_NET 19] DEBUG: <HttpCacheSM.cc:142 (state_cache_open_read)> (http_cache) [453] [state_cache_open_read] cache open read failure 5. retrying cache open read...
[Dec 22 09:14:01.367] [ET_NET 19] DEBUG: <HttpCacheSM.cc:100 (state_cache_open_read)> (http_cache) [453] [&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED/TS_EVENT_CACHE_OPEN_READ_FAILED]
[Dec 22 09:14:01.367] [ET_NET 19] DEBUG: <HttpSM.cc:2741 (main_handler)> (http) [453] CACHE_EVENT_OPEN_READ_FAILED/TS_EVENT_CACHE_OPEN_READ_FAILED, 1103
[Dec 22 09:14:01.367] [ET_NET 19] DEBUG: <HttpSM.cc:2671 (state_cache_open_read)> (http) [453] [&HttpSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED/TS_EVENT_CACHE_OPEN_READ_FAILED]
[Dec 22 09:14:01.367] [ET_NET 19] DEBUG: <HttpSM.cc:2703 (state_cache_open_read)> (http) [453] [453] cache_open_read - CACHE_EVENT_OPEN_READ_FAILED with ECACHE_DOC_BUSY (-20401)
[Dec 22 09:14:01.367] [ET_NET 19] DEBUG: <HttpSM.cc:2706 (state_cache_open_read)> (http) [453] open read failed.

I have tried as well to set proxy.config.http.redirect_use_orig_cache_key 1 but after doing that, I get the timeout right at the first try. The 302 response itself seems to be a success based on the logs but neither a 301 or 302 itself is cached. I suppose because the inflight transaction never finishes.

System details:

• OS - Rocky Linux release 8.8 (Green Obsidian)
• ATS - 9.2.3-24

ATS settings:

Initial settings:
##### /opt/trafficserver/bin/traffic_ctl config match proxy.config.http.redirect_use_orig_cache_key proxy.config.http.number_of_redirections
proxy.config.http.redirect_use_orig_cache_key: 0 
proxy.config.http.number_of_redirections: 1

##### /opt/trafficserver/bin/traffic_ctl config match open_read_retries open_write_retries
proxy.config.http.cache.max_open_read_retries: 150
proxy.config.http.cache.max_open_write_retries: 150
proxy.config.http.cache.open_read_retry_time: 10
proxy.config.http.cache.open_write_fail_action: 0

##### /opt/trafficserver/etc/trafficserver/remap.config /opt/trafficserver/etc/trafficserver/parent.config
/opt/trafficserver/etc/trafficserver/remap.config:map http://ida-mkrug-cdn.check.com/ http://ida-mkrug-cdn.check.com/
/opt/trafficserver/etc/trafficserver/parent.config:dest_domain=ida-mkrug-cdn.check.com port=80 parent="y.y.y.y80|0.999" round_robin=consistent_hash go_direct=true qstring=ignore parent_is_proxy=false

Following settings seems to make it better (content is served with huge 6 second delay because each of the 5 open_read_retries seems to take 1 second) but the issue still persists with CACHE_EVENT_OPEN_READ_FAILED/TS_EVENT_CACHE_OPEN_READ_FAILED which seem to cause the slowness.

##### /opt/trafficserver/bin/traffic_ctl config match open_read_retries open_write_retries
proxy.config.http.cache.max_open_read_retries: 5
proxy.config.http.cache.max_open_write_retries: 5

I have used initial another origin but for troubleshooting, I have setting a simple nginx instance with following configuration
traffic.out-clean-2nd-sanitized.txt
traffic.out-clean-1st-sanitized.txt

Origin nginx settings

    server {
        listen       80;
        listen       [::]:80;
        server_name  _;
        root         /usr/share/nginx/html;

        error_page 404 /404.html;
    error_page 301 302 @30x; # keep original HTTP status code w/o `=`
    location @30x {
        default_type ""; # will remove Content-Type completely
        # `300` is a filler: client will get the original HTTP status code
        return 300;
        add_header Cache-Control "public, max-age=3600";
    }
    add_header X-Cache-Server $server_addr;
    location /aaa/test100MB.nff {
        add_header Cache-Control "public, max-age=3600";
        return 301 /redirect/test100MB.nff;
        keepalive_timeout 0;
    }
    location ^~ /redirect/ {
    root  /usr/share/nginx/html/;
    add_header Cache-Control "public, max-age=3600";
    index  index.html;
    }

[mkrug1981]

I did a bit further testing and looks like as soon as following proxy.config.http.cache.max_open_write_retries is set to something > INT 1 - it gets into the state of doing on the 2nd, 3rd request for the object, the Cache open read failure

[Jan 11 08:35:11.292] [ET_NET 19] DEBUG: <HttpCacheSM.cc:142 (state_cache_open_read)> (http_cache) [3] [state_cache_open_read] cache open read failure 1. retrying cache open read...
[Jan 11 08:35:12.258] [ET_NET 19] DEBUG: <HttpCacheSM.cc:142 (state_cache_open_read)> (http_cache) [3] [state_cache_open_read] cache open read failure 2. retrying cache open read...
[Jan 11 08:35:13.251] [ET_NET 19] DEBUG: <HttpCacheSM.cc:142 (state_cache_open_read)> (http_cache) [3] [state_cache_open_read] cache open read failure 3. retrying cache open read...
[Jan 11 08:35:14.241] [ET_NET 19] DEBUG: <HttpCacheSM.cc:142 (state_cache_open_read)> (http_cache) [3] [state_cache_open_read] cache open read failure 4. retrying cache open read...
[Jan 11 08:35:15.208] [ET_NET 19] DEBUG: <HttpCacheSM.cc:142 (state_cache_open_read)> (http_cache) [3] [state_cache_open_read] cache open read failure 5. retrying cache open read...
[Jan 11 08:35:16.175] [ET_NET 19] DEBUG: <HttpCacheSM.cc:142 (state_cache_open_read)> (http_cache) [3] [state_cache_open_read] cache open read failure 6. retrying cache open read...
[Jan 11 08:35:17.174] [ET_NET 19] DEBUG: <HttpCacheSM.cc:142 (state_cache_open_read)> (http_cache) [3] [state_cache_open_read] cache open read failure 7. retrying cache open read...
[Jan 11 08:35:18.173] [ET_NET 19] DEBUG: <HttpCacheSM.cc:142 (state_cache_open_read)> (http_cache) [3] [state_cache_open_read] cache open read failure 8. retrying cache open read...
[Jan 11 08:35:19.173] [ET_NET 19] DEBUG: <HttpCacheSM.cc:142 (state_cache_open_read)> (http_cache) [3] [state_cache_open_read] cache open read failure 9. retrying cache open read...
[Jan 11 08:35:20.172] [ET_NET 19] DEBUG: <HttpCacheSM.cc:142 (state_cache_open_read)> (http_cache) [3] [state_cache_open_read] cache open read failure 10. retrying cache open read...

it is doing as many read retries based on following settings: Example proxy.config.http.cache.max_open_read_retries 10 , the retry itself is 1 every 1 second

If I set "proxy.config.http.cache.max_open_write_retries" to INT 1, everything seems working fine

[mingzym]

@mkrug1981 have you review the #10981 change ? after that change, what is the status of your problem here?

[JosiahWI]

Could this be the same issue as or directly related to #9275?

Your description of ATS failing to fetch the resource on subsequent requests, and the lock retry settings impacting the issue, makes me think of that issue, where the cache lock wasn't handled correctly. Also, in my testing a few months ago, there were still cases where the read locking seemed broken, depending on the cache configuration, even after #11542 fixed the particular write lock issue.

[mkrug1981]

@mingzym Hi. We were doing regression testing for our configuration with ATS10 and noticed that the 302/301 behaviour still does not seem to be working as expected for range requests. If the origin returns a 302 for a partial request object, ATS is following the 302 on the first attempt, but unfortunately, re-querying the same object always results in a timeout or, worse, returns a 200 response for a partial object. The current issue looks similar to #11542

Configuration:

**** header_rewrite: 
@plugin=header_rewrite.so @pparam=test.config

**** cache_range_requests:
@plugin=cache_range_requests.so @pparam=--consider-ims @pparam=--no-modify-cachekey 


cond %{REMAP_PSEUDO_HOOK}
set-config proxy.config.http.number_of_redirections 1
set-config proxy.config.http.redirect_use_orig_cache_key 0
set-config proxy.config.http.cache.max_open_read_retries 150
set-config proxy.config.http.cache.max_open_write_retries 1
set-config proxy.config.http.cache.max_open_write_retry_timeout 0
set-config proxy.config.http.cache.open_write_fail_action 0
set-config proxy.config.http.negative_caching_lifetime 5
set-config proxy.config.http.negative_caching_enabled 1

**** remap.config:

map http://cdn.example.com http://cdn.example.com  @plugin=header_rewrite.so @pparam=test.config  @plugin=cachekey.so @pparam=--include-headers=Range @pparam=--include-params=test-rand @plugin=cache_range_requests.so @pparam=--consider-ims @pparam=--no-modify-cachekey @plugin=fq_pacing.so @pparam=--rate=15000000 

**** Example curl:

# curl -v -o /dev/null -x x.x.x:80 --range 15728640-31457279 "http://cdn.example.com/60441/test-file.nff?test-rand=value501"

> GET http://cdn.example.com/60441/test-file.nff?test-rand=value501HTTP/1.1
> Host: cdn.example.com
> Range: bytes=15728640-31457279
> User-Agent: curl/7.61.1
> Accept: */*
> Proxy-Connection: Keep-Alive
> 
< HTTP/1.1 206 Partial Content
< Accept-Ranges: bytes
< Server: SkyCDN
< Last-Modified: Sun, 21 Sep 2025 23:44:08 GMT
< ETag: "c1f39d7e0245f6d44a6c44253e043e97:1758498219.186501"
< Date: Tue, 23 Sep 2025 07:02:23 GMT
< Content-Range: bytes 15728640-31457279/1804937164
< Content-Length: 15728640
< Content-Type: application/octet-stream
< Cache-Control: max-age=604800
< Age: 0
< Proxy-Connection: keep-alive
< Via: http/1.1 cache1 (ATS10 [cMsSfW])
< 
{ [14018 bytes data]


--- same request again, took 3 minutes for a response based on read while write settings "proxy.config.http.cache.max_open_read_retries 150" and returned a 200 respones

> GET http://cdn.example.com/60441/test-file.nff?test-rand=value501HTTP/1.1
> Host: cdn.example.com
> Range: bytes=15728640-31457279
> User-Agent: curl/7.61.1
> Accept: */*
> Proxy-Connection: Keep-Alive
> 
  0     0    0     0    0     0      0      0 --:--:--  0:02:28 --:--:--     0
< HTTP/1.1 200 Partial Content
< Accept-Ranges: bytes
< Server: SkyCDN
< Last-Modified: Sun, 21 Sep 2025 23:44:08 GMT
< ETag: "c1f39d7e0245f6d44a6c44253e043e97:1758498219.186501"
< Date: Tue, 23 Sep 2025 07:02:23 GMT
< Content-Range: bytes 15728640-31457279/1804937164
< Content-Length: 15728640
< Content-Type: application/octet-stream
< Cache-Control: max-age=604800
< Age: 151
< Proxy-Connection: keep-alive
< Via: http/1.1 cache1 (ATS10 [cHs f ])
< 
{ [14016 bytes data]

And now for every request even a different range or no range at all I get the cached 15MB object after waiting the 150 cache read retries.

[mkrug1981]

See as well the traffic.out debug log file

traffic.out-clean-sanitized-2209.txt

[ezelkow1]

@mkrug1981 I have merged the 10.0.x fixes (#11542 and #12215) for this into the 9.2.x branch if you would like to try them out. Or if you believe that will fix this issue you can close this

[mkrug1981]

I think we can close this issue. Validation confirmed it is fixed with (#11542 and #12215)