https://bz.apache.org/bugzilla/show_bug.cgi?id=62493
Bug ID: 62493
Summary: mod_cache_socache loses request bodies after
revalidation
Product: Apache httpd-2
Version: 2.4-HEAD
Hardware: PC
OS: FreeBSD
Status: NEW
Severity: major
Priority: P2
Component: mod_socache_(dbm|dc|memcache|shmcb)
Assignee: [email protected]
Reporter: [email protected]
Target Milestone: ---
When using mod_cache with mod_cache_socache to implement a caching reverse
proxy, we see cases where cached responses lose their bodies.
After a revalidation with the origin server that returns a 304 response to the
cache, the cached record’s header will remain intact, but the body will be
empty. So after the request that causes revalidation, the cache will start
serving the original headers with a zero-length body in response to future
requests. (The request the causes revalidation receives the correct response.)
In all known cases, the file being served by the origin server is a static file
with valid ETag:, Last-Modified: and Expires: headers.
To reproduce the behavior, we used mod_cache + mod_cache_socache +
mod_cache_memcache and simply request the same URL via curl 4 times at specific
intervals with: curl -si https://www.example.com/testfile3.txt
The times of the four requests (which are important in the context of the
30-second max-age) were:
Wed Jun 27 00:23:18 UTC 2018 (Initial +0 - cache empty, origin fetch w/200,
served correctly)
Wed Jun 27 00:23:30 UTC 2018 (Initial +12 - cache hit, served correctly from
cache)
Wed Jun 27 00:23:57 UTC 2018 (Initial +39 - stale, origin revalidation w/304,
served correctly from cache)
Wed Jun 27 00:24:03 UTC 2018 (Initial +45 - cache hit, served from cache WITH 0
SIZE!)
Response 1: (Results OK, served from origin.)
HTTP/2 200
date: Wed, 27 Jun 2018 00:23:18 GMT
server: Apache
x-extra-header: yes
last-modified: Tue, 26 Jun 2018 23:25:52 GMT
etag: "11c-56f93d1abcd00"
accept-ranges: bytes
content-length: 284
cache-control: max-age=30
expires: Wed, 27 Jun 2018 00:23:48 GMT
content-type: text/plain; charset=UTF-8
Test file. Test file. Test file. Test file. Test file. Test file.
Test file. Test file. Test file. Test file. Test file. Test file.
Test file. Test file. Test file. Test file. Test file. Test file.
Test file. Test file. Test file. Test file. Test file. Test file.
Response 2: (Results OK, served from cache.)
HTTP/2 200
date: Wed, 27 Jun 2018 00:23:18 GMT
server: Apache
x-extra-header: yes
last-modified: Tue, 26 Jun 2018 23:25:52 GMT
etag: "11c-56f93d1abcd00"
accept-ranges: bytes
content-length: 284
cache-control: max-age=30
expires: Wed, 27 Jun 2018 00:23:48 GMT
age: 12
content-type: text/plain; charset=UTF-8
Test file. Test file. Test file. Test file. Test file. Test file.
Test file. Test file. Test file. Test file. Test file. Test file.
Test file. Test file. Test file. Test file. Test file. Test file.
Test file. Test file. Test file. Test file. Test file. Test file.
Response 3: (Results OK, served from cache after revalidation with 304 from
origin.)
HTTP/2 200
date: Wed, 27 Jun 2018 00:23:57 GMT
server: Apache
x-extra-header: yes
last-modified: Tue, 26 Jun 2018 23:25:52 GMT
accept-ranges: bytes
content-length: 284
etag: "11c-56f93d1abcd00"
expires: Wed, 27 Jun 2018 00:24:27 GMT
cache-control: max-age=30
content-type: text/plain; charset=UTF-8
Test file. Test file. Test file. Test file. Test file. Test file.
Test file. Test file. Test file. Test file. Test file. Test file.
Test file. Test file. Test file. Test file. Test file. Test file.
Test file. Test file. Test file. Test file. Test file. Test file.
Response 4: (INCORRECT results served from cache after cache hit with no body,
note 0 content-length!)
HTTP/2 200
date: Wed, 27 Jun 2018 00:23:57 GMT
server: Apache
x-extra-header: yes
last-modified: Tue, 26 Jun 2018 23:25:52 GMT
accept-ranges: bytes
content-length: 0
etag: "11c-56f93d1abcd00"
expires: Wed, 27 Jun 2018 00:24:27 GMT
cache-control: max-age=30
age: 6
content-type: text/plain; charset=UTF-8
Here are some associated logs showing the cache and proxy behavior:
1530058998.090 3 - 10.0.19.22 200 459 "GET
https://www.example.com/testfile3.txt"; 200 "cache miss: attempting entity save"
1530059010.106 0 - 10.0.19.22 200 464 "GET
https://www.example.com/testfile3.txt"; - "cache hit"
1530059037.900 2 - 10.0.19.22 200 459 "GET
https://www.example.com/testfile3.txt"; 304 "conditional cache hit: entity
refreshed"
1530059043.074 0 - 10.0.19.22 200 177 "GET
https://www.example.com/testfile3.txt"; - "cache hit"
These correspond to the LogFormat:
"%{end:%s}t.%{end:msec_frac}t %{ms}T %L %a %>s %O \"%m
%{REQUEST_SCHEME}x://%{Host}i%U%q\" %{proxy-status}n \"%{cache-status}e\""
The test shown here was performed with mod_socache_dbm as the backend, but we
re-ran the test with mod_socache_memcache and got the same results.
The caching and proxy config directives in use are:
## General proxy config
ProxyPreserveHost On
ProxyStatus On
ProxyPass / http://172.17.1.59/
## General cache config
CacheQuickHandler off
SetOutputFilter CACHE
## Caching config (socache + memcache or dbm)
CacheEnable socache /
#CacheSocache memcache:127.0.0.1:11211
CacheSocache dbm:/data/apache/run/cache.dbm
CacheSocacheMaxSize 10485760
CacheSocacheMaxTime 3600
#CacheEnable disk /
#CacheDirLength 1
#CacheDirLevels 2
#CacheMaxFileSize 10485760
#CacheRoot /data/apache/cache
The full config is here: https://pastebin.com/zJJH36rB
Repeating the test with mod_cache_disk instead of mod_cache_socache did not
reproduce this problem. This, plus the persistence of the problem between
mod_socache_dbm and mod_socache_memcache would appear to implicate
mod_cache_socache as the likely source of the issue.
All tests were done against the 2.4.x SVN repository as retrieved today.
How can we help to troubleshoot this further?
Thanks for any feedback or advice!
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
