ATS 9.2.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