Successful PUSH Fails to Cache on Wrap

[slipthebit]

On ATS 10.0.2, when pushing content to cache with a full volume, wrap event(s) occur allowing the write to succeed while the content fails to cache. On PUSH, ATS returns Status Code 201, but HEAD request for object returns 504. ATS metrics indicate write success and wrap count is incremented. diags.logs indicate wrap has occurred. Behavior is observed with pinned objects where one would expect write to fail, but also where previous objects have PURGED from cache.

Expected Result: PUSH should fail (non-20X status code) if content is not cached.

Testing was performed with pinned cached objects.

Replication Steps:

1. configure pinning in cache.config
   url_regex=.* src_ip=<CLIENT_IP> pin-in-cache=30d
2. Observe 0 bytes used and 256MB for "bytes_total" to start test

$ traffic_ctl metric match volume_0 | grep -e wrap -e remove -e evacuate -e "bytes_total" -e "bytes_used" -e write
proxy.process.cache.volume_0.write.active 0
proxy.process.cache.volume_0.write.success 0
proxy.process.cache.volume_0.write.failure 0
proxy.process.cache.volume_0.remove.active 0
proxy.process.cache.volume_0.remove.success 0
proxy.process.cache.volume_0.remove.failure 0
proxy.process.cache.volume_0.evacuate.active 0
proxy.process.cache.volume_0.evacuate.success 0
proxy.process.cache.volume_0.evacuate.failure 0
proxy.process.cache.volume_0.bytes_used 0
proxy.process.cache.volume_0.bytes_total 268312576
proxy.process.cache.volume_0.ram_cache.bytes_used 0
proxy.process.cache.volume_0.write.backlog.failure 0
proxy.process.cache.volume_0.write_bytes_stat 0
proxy.process.cache.volume_0.gc_bytes_evacuated 0
proxy.process.cache.volume_0.gc_frags_evacuated 0
proxy.process.cache.volume_0.wrap_count 0
proxy.process.cache.volume_0.span.errors.write 0

3. Create test files

echo -e "HTTP/1.1 200 OK\nContent-Length: 104857600\n" > /tmp/headers.txt
dd if=/dev/zero of=/tmp/100mbfile.1 bs=1M count=100
dd if=/dev/zero of=/tmp/100mbfile.2 bs=1M count=100
dd if=/dev/zero of=/tmp/100mbfile.3 bs=1M count=100
cat /tmp/headers.txt /tmp/100mbfile.1 > /tmp/100mbfile_wHeaders.1
cat /tmp/headers.txt /tmp/100mbfile.2 > /tmp/100mbfile_wHeaders.2
cat /tmp/headers.txt /tmp/100mbfile.3 > /tmp/100mbfile_wHeaders.3
rm /tmp/100mbfile.1 /tmp/100mbfile.2 /tmp/100mbfile.3 headers.txt

4. PUSH 100MB test file to cache twice

root@3dd966712d75:/tmp# wget --method=PUSH --header="Content-Type: application/octet-stream" --body-file=/tmp/100mbfile_wHeaders.1  http://cache:8081/1
00mbfile_wHeaders.1
--2024-11-26 21:47:21--  http://cache:8081/100mbfile_wHeaders.1
Resolving cache (cache)... <ip>
Connecting to cache (cache)|<ip>|:8081... connected.
HTTP request sent, awaiting response... 201 Created
Length: 0
Saving to: '100mbfile_wHeaders.1.1'

100mbfile_wHeaders.1.1                    [ <=>                                                                     ]       0  --.-KB/s    in 0s      

2024-11-26 21:47:21 (0.00 B/s) - '100mbfile_wHeaders.1.1' saved [0/0]

root@3dd966712d75:/tmp# wget --method=PUSH --header="Content-Type: application/octet-stream" --body-file=/tmp/100mbfile_wHeaders.2  http://cache:8081/1
00mbfile_wHeaders.2
--2024-11-26 21:47:36--  http://cache:8081/100mbfile_wHeaders.2
Resolving cache (cache)... <IP>
Connecting to cache (cache)|<IP>|:8081... connected.
HTTP request sent, awaiting response... 201 Created
Length: 0
Saving to: '100mbfile_wHeaders.2.1'

100mbfile_wHeaders.2.1                    [ <=>                                                                     ]       0  --.-KB/s    in 0s      

2024-11-26 21:47:36 (0.00 B/s) - '100mbfile_wHeaders.2.1' saved [0/0]

root@3dd966712d75:/tmp# wget --tries=1 --method=HEAD --header="Cache-Control: only-if-cached" ttp://cache:8081/1
00mbfile_wHeaders.1
ttp://cache:8081/1: Unsupported scheme 'ttp'.
bash: 00mbfile_wHeaders.1: command not found
root@3dd966712d75:/tmp# wget --tries=1 --method=HEAD --header="Cache-Control: only-if-cached" http://cache:8081/100mbfile_wHeaders.1
Spider mode enabled. Check if remote file exists.
--2024-11-26 21:49:21--  http://cache:8081/100mbfile_wHeaders.1
Resolving cache (cache)... <IP>
Connecting to cache (cache)|<IP>|:8081... connected.
HTTP request sent, awaiting response... 200 OK
Length: 104857600 (100M)
Remote file exists and could contain further links,
but recursion is disabled -- not retrieving.

root@3dd966712d75:/tmp# wget --tries=1 --method=HEAD --header="Cache-Control: only-if-cached" http://cache:8081/100mbfile_wHeaders.2
Spider mode enabled. Check if remote file exists.
--2024-11-26 21:49:29--  http://cache:8081/100mbfile_wHeaders.2
Resolving cache (cache)... <IP>
Connecting to cache (cache)|<IP>|:8081... connected.
HTTP request sent, awaiting response... 200 OK
Length: 104857600 (100M)
Remote file exists and could contain further links,
but recursion is disabled -- not retrieving.

5. Observe ATS metric "bytes_used" is ~200 MB and "wrap" = 0

$  traffic_ctl metric match volume_0 | grep -e wrap -e remove -e evacuate -e "bytes_total" -e "bytes_used" -e write
proxy.process.cache.volume_0.write.active 0
proxy.process.cache.volume_0.write.success 2
proxy.process.cache.volume_0.write.failure 0
proxy.process.cache.volume_0.remove.active 0
proxy.process.cache.volume_0.remove.success 0
proxy.process.cache.volume_0.remove.failure 0
proxy.process.cache.volume_0.evacuate.active 0
proxy.process.cache.volume_0.evacuate.success 0
proxy.process.cache.volume_0.evacuate.failure 0
proxy.process.cache.volume_0.bytes_used 209788928
proxy.process.cache.volume_0.bytes_total 268312576
proxy.process.cache.volume_0.ram_cache.bytes_used 1052928
proxy.process.cache.volume_0.write.backlog.failure 0
proxy.process.cache.volume_0.write_bytes_stat 0
proxy.process.cache.volume_0.gc_bytes_evacuated 0
proxy.process.cache.volume_0.gc_frags_evacuated 0
proxy.process.cache.volume_0.wrap_count 0
proxy.process.cache.volume_0.span.errors.write 0

6. PUSH third file to cache and observe 201 status code

root@3dd966712d75:/tmp# wget --method=PUSH --header="Content-Type: application/octet-stream" --body-file=/tmp/100mbfile_wHeaders.3  http://cache:8081/100mbfile_wHeaders.3
--2024-11-26 21:54:46--  http://cache:8081/100mbfile_wHeaders.3
Resolving cache (cache)... <ip>
Connecting to cache (cache)|<ip>|:8081... connected.
HTTP request sent, awaiting response... 201 Created
Length: 0
Saving to: '100mbfile_wHeaders.3.1'

100mbfile_wHeaders.3.1        [ <=>                               ]       0  --.-KB/s    in 0s      

2024-11-26 21:54:47 (0.00 B/s) - '100mbfile_wHeaders.3.1' saved [0/0]

7. Observe HEAD request returns 504

root@3dd966712d75:/tmp# wget --tries=1 --method=HEAD --header="Cache-Control: only-if-cached" http://
cache:8081/100mbfile_wHeaders.3
Spider mode enabled. Check if remote file exists.
--2024-11-26 21:56:14--  http://cache:8081/100mbfile_wHeaders.3
Resolving cache (cache)... <ip>
Connecting to cache (cache)|<ip>|:8081... connected.
HTTP request sent, awaiting response... 504 Not Cached
Giving up.

8. Observe ATS metrics indicate "write_success" and wrap count incremented to 3

siden@eff7fc749e6a:/siden$  traffic_ctl metric match volume_0 | grep -e wrap -e remove -e evacuate -e "bytes_total" -e "bytes_used" -e write
proxy.process.cache.volume_0.write.active 0
proxy.process.cache.volume_0.write.success 3
proxy.process.cache.volume_0.write.failure 0
proxy.process.cache.volume_0.remove.active 0
proxy.process.cache.volume_0.remove.success 0
proxy.process.cache.volume_0.remove.failure 0
proxy.process.cache.volume_0.evacuate.active 0
proxy.process.cache.volume_0.evacuate.success 0
proxy.process.cache.volume_0.evacuate.failure 0
proxy.process.cache.volume_0.bytes_used 259923968
proxy.process.cache.volume_0.bytes_total 268312576
proxy.process.cache.volume_0.ram_cache.bytes_used 1052928
proxy.process.cache.volume_0.write.backlog.failure 0
proxy.process.cache.volume_0.write_bytes_stat 0
proxy.process.cache.volume_0.gc_bytes_evacuated 0
proxy.process.cache.volume_0.gc_frags_evacuated 0
proxy.process.cache.volume_0.wrap_count 3
proxy.process.cache.volume_0.span.errors.write 0

9. Observe file 1 and 2 are still cached

root@3dd966712d75:/tmp# wget --tries=1 --method=HEAD --header="Cache-Control: only-if-cached" http://cache:8081/100mbfile_wHeaders.1
Spider mode enabled. Check if remote file exists.
--2024-11-26 21:59:58--  http://cache:8081/100mbfile_wHeaders.1
Resolving cache (cache)... <ip>
Connecting to cache (cache)|<ip>|:8081... connected.
HTTP request sent, awaiting response... 200 OK
Length: 104857600 (100M)
Remote file exists and could contain further links,
but recursion is disabled -- not retrieving.

root@3dd966712d75:/tmp# wget --tries=1 --method=HEAD --header="Cache-Control: only-if-cached" http://cache:8081/100mbfile_wHeaders.2
Spider mode enabled. Check if remote file exists.
--2024-11-26 22:00:01--  http://cache:8081/100mbfile_wHeaders.2
Resolving cache (cache)... <ip>
Connecting to cache (cache)|<ip>|:8081... connected.
HTTP request sent, awaiting response... 200 OK
Length: 104857600 (100M)
Remote file exists and could contain further links,
but recursion is disabled -- not retrieving.

The steps above show how ATS indicate a successful push and write to cache, but the file was not available.
The expectation is that the PUSH would fail since there is not enough space available due to pinned content.

Next, the pinned content is purged which should allow the third file to be cached, but similar behavior is observed

10. Purge file one and two and verify HEAD request fails

root@3dd966712d75:/tmp# curl -v -X PURGE http://cache:8081/100mbfile_wHeaders.1
*   Trying <ip>:8081...
* Connected to cache (<ip>) port 8081 (#0)
> PURGE /100mbfile_wHeaders.1 HTTP/1.1
> Host: cache:8081
> User-Agent: curl/7.88.1
> Accept: */*
> 
< HTTP/1.1 200 OK
< Date: Tue, 26 Nov 2024 22:01:24 GMT
< Connection: keep-alive
< Server: ATS/10.0.2
< Access-Control-Allow-Origin: *
< Access-Control-Allow-Credentials: true
< Access-Control-Allow-Headers: access-control-allow-origin,authorization,content-type,x-user-agent,x-grpc-web
< Access-Control-Allow-Methods: DELETE,GET,HEAD,OPTIONS,POST,PUT,PATCH
< Access-Control-Max-Age: 86400
< Content-Length: 0
< 
* Connection #0 to host cache left intact
root@3dd966712d75:/tmp# curl -v -X PURGE http://cache:8081/100mbfile_wHeaders.2
*   Trying <ip>:8081...
* Connected to cache (<ip>) port 8081 (#0)
> PURGE /100mbfile_wHeaders.2 HTTP/1.1
> Host: cache:8081
> User-Agent: curl/7.88.1
> Accept: */*
> 
< HTTP/1.1 200 OK
< Date: Tue, 26 Nov 2024 22:01:31 GMT
< Connection: keep-alive
< Server: ATS/10.0.2
< Access-Control-Allow-Origin: *
< Access-Control-Allow-Credentials: true
< Access-Control-Allow-Headers: access-control-allow-origin,authorization,content-type,x-user-agent,x-grpc-web
< Access-Control-Allow-Methods: DELETE,GET,HEAD,OPTIONS,POST,PUT,PATCH
< Access-Control-Max-Age: 86400
< Content-Length: 0
< 
* Connection #0 to host cache left intact
root@3dd966712d75:/tmp# wget --tries=1 --method=HEAD --header="Cache-Control: only-if-cached" http://cache:8081/100mbfile_wHeaders.1
Spider mode enabled. Check if remote file exists.
--2024-11-26 22:01:37--  http://cache:8081/100mbfile_wHeaders.1
Resolving cache (cache)... <ip>
Connecting to cache (cache)|<ip>|:8081... connected.
HTTP request sent, awaiting response... 504 Not Cached
Giving up.

root@3dd966712d75:/tmp# wget --tries=1 --method=HEAD --header="Cache-Control: only-if-cached" http://cache:8081/100mbfile_wHeaders.2
Spider mode enabled. Check if remote file exists.
--2024-11-26 22:01:40--  http://cache:8081/100mbfile_wHeaders.2
Resolving cache (cache)... <ip>
Connecting to cache (cache)|<ip>|:8081... connected.
HTTP request sent, awaiting response... 504 Not Cached
Giving up.

11. PUSH test file 3 and observe head request failure

root@3dd966712d75:/tmp# wget --method=PUSH --header="Content-Type: application/octet-stream" --body-file=/tmp/100mbfile_wHeaders.3  http://cache:8081/100mbfile_wHeaders.3
--2024-11-26 22:09:43--  http://cache:8081/100mbfile_wHeaders.3
Resolving cache (cache)... <ip>
Connecting to cache (cache)|<ip>|:8081... connected.
HTTP request sent, awaiting response... 201 Created
Length: 0
Saving to: '100mbfile_wHeaders.3.2'

100mbfile_wHeaders.3.2        [ <=>                               ]       0  --.-KB/s    in 0s      

2024-11-26 22:09:43 (0.00 B/s) - '100mbfile_wHeaders.3.2' saved [0/0]

root@3dd966712d75:/tmp# wget --tries=1 --method=HEAD --header="Cache-Control: only-if-cached" http://cache:8081/100mbfile_wHeaders.3
Spider mode enabled. Check if remote file exists.
--2024-11-26 22:10:03--  http://cache:8081/100mbfile_wHeaders.3
Resolving cache (cache)... <ip>
Connecting to cache (cache)|<ip>|:8081... connected.
HTTP request sent, awaiting response... 504 Not Cached
Giving up.

12. Observe ATS Metrics indicate Write success and multiple wraps

$  traffic_ctl metric match volume_0 | grep -e wrap -e remove -e evacuate -e "bytes_total" -e "bytes_used" -e write
proxy.process.cache.volume_0.write.active 0
proxy.process.cache.volume_0.write.success 4
proxy.process.cache.volume_0.write.failure 0
proxy.process.cache.volume_0.remove.active 0
proxy.process.cache.volume_0.remove.success 0
proxy.process.cache.volume_0.remove.failure 0
proxy.process.cache.volume_0.evacuate.active 0
proxy.process.cache.volume_0.evacuate.success 0
proxy.process.cache.volume_0.evacuate.failure 0
proxy.process.cache.volume_0.bytes_used 259923968
proxy.process.cache.volume_0.bytes_total 268312576
proxy.process.cache.volume_0.ram_cache.bytes_used 1057152
proxy.process.cache.volume_0.write.backlog.failure 0
proxy.process.cache.volume_0.write_bytes_stat 0
proxy.process.cache.volume_0.gc_bytes_evacuated 0
proxy.process.cache.volume_0.gc_frags_evacuated 0
proxy.process.cache.volume_0.wrap_count 5
proxy.process.cache.volume_0.span.errors.write 0

This shows yet another failure to cache on wrap. Multiple wrap counts are unexpected.

13. Observe wraps indicated in diags.log

[Nov 26 21:40:44.986] [TS_MAIN] NOTE: traffic server running
[Nov 26 21:54:47.004] [ET_AIO 7:53] NOTE: Cache volume 0 on disk '/var/cache/trafficserver/cache.db 16384:32766' wraps around
[Nov 26 21:54:47.405] [ET_AIO 1:53] NOTE: Cache volume 0 on disk '/var/cache/trafficserver/cache.db 16384:32766' wraps around
[Nov 26 21:54:47.774] [ET_AIO 2:53] NOTE: Cache volume 0 on disk '/var/cache/trafficserver/cache.db 16384:32766' wraps around
[Nov 26 22:09:43.191] [ET_AIO 4:53] NOTE: Cache volume 0 on disk '/var/cache/trafficserver/cache.db 16384:32766' wraps around
[Nov 26 22:09:43.532] [ET_AIO 1:53] NOTE: Cache volume 0 on disk '/var/cache/trafficserver/cache.db 16384:32766' wraps around

14. PUSH the file a fourth time and observe successful cache

root@3dd966712d75:/tmp# wget --method=PUSH --header="Content-Type: application/octet-stream" --body-file=/tmp/100mbfile_wHeaders.3  http://cache:8081/100mbfile_wHeaders.3
--2024-11-26 22:12:24--  http://cache:8081/100mbfile_wHeaders.3
Resolving cache (cache)... <ip>
Connecting to cache (cache)|<ip>|:8081... connected.
HTTP request sent, awaiting response... 201 Created
Length: 0
Saving to: '100mbfile_wHeaders.3.3'

100mbfile_wHeaders.3.3        [ <=>                               ]       0  --.-KB/s    in 0s      

2024-11-26 22:12:24 (0.00 B/s) - '100mbfile_wHeaders.3.3' saved [0/0]

root@3dd966712d75:/tmp# wget --tries=1 --method=HEAD --header="Cache-Control: only-if-cached" http://cache:8081/100mbfile_wHeaders.3
Spider mode enabled. Check if remote file exists.
--2024-11-26 22:12:28--  http://cache:8081/100mbfile_wHeaders.3
Resolving cache (cache)... <ip>
Connecting to cache (cache)|<ip>|:8081... connected.
HTTP request sent, awaiting response... 200 OK
Length: 104857600 (100M)
Remote file exists and could contain further links,
but recursion is disabled -- not retrieving.

15. Observe the ATS metrics indicate successful write, but wrap count has not incremented

$  traffic_ctl metric match volume_0 | grep -e wrap -e remove -e evacuate -e "bytes_total" -e "bytes_used" -e write
proxy.process.cache.volume_0.write.active 0
proxy.process.cache.volume_0.write.success 5
proxy.process.cache.volume_0.write.failure 0
proxy.process.cache.volume_0.remove.active 0
proxy.process.cache.volume_0.remove.success 0
proxy.process.cache.volume_0.remove.failure 0
proxy.process.cache.volume_0.evacuate.active 0
proxy.process.cache.volume_0.evacuate.success 0
proxy.process.cache.volume_0.evacuate.failure 0
proxy.process.cache.volume_0.bytes_used 259923968
proxy.process.cache.volume_0.bytes_total 268312576
proxy.process.cache.volume_0.ram_cache.bytes_used 1057152
proxy.process.cache.volume_0.write.backlog.failure 0
proxy.process.cache.volume_0.write_bytes_stat 0
proxy.process.cache.volume_0.gc_bytes_evacuated 0
proxy.process.cache.volume_0.gc_frags_evacuated 0
proxy.process.cache.volume_0.wrap_count 5
proxy.process.cache.volume_0.span.errors.write 0

The failure to cache on successful push appears to be isolated to wrap events.