slipthebit opened a new issue, #11884: URL: https://github.com/apache/trafficserver/issues/11884
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. -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: issues-unsubscr...@trafficserver.apache.org.apache.org For queries about this service, please contact Infrastructure at: us...@infra.apache.org
