You are viewing a plain text version of this content. The canonical link for it is here.
Posted to bugs@httpd.apache.org by bu...@apache.org on 2018/06/27 00:43:30 UTC
[Bug 62493] New: mod_cache_socache loses request bodies after
revalidation
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: bugs@httpd.apache.org
Reporter: apache@wheelhouse.org
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: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 62493] mod_cache_socache loses request bodies after
revalidation
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62493
--- Comment #2 from Jeff W <ap...@wheelhouse.org> ---
Created attachment 36000
--> https://bz.apache.org/bugzilla/attachment.cgi?id=36000&action=edit
preserve request bodies after 304 revalidation
After looking at the source code at some length, it appears that the issue here
is that mod_cache_disk writes headers and bodies separately, and
mod_cache_socache writes them together, but mod_cache assumes the former
behavior.
Consequently, mod_cache_socache is never given a request body.
This patch adds a "preserve_body" handler to cache providers that lets them
preserve the request body when only the headers are being changed.
Two implementations are provided.
The implementation for mod_cache_socache feeds the body brigade from the stale
cache entry to the store_body handler for the new entry.
The implementation for mod_cache_disk is a no-op.
This was the most efficient solution I could find; it seems like the only other
way for mod_cache_socache to preserve the request body while updating headers
would be to re-read the stale entry. Since it's already been read once,
reusing the existing one appears to be the better choice.
Nonetheless, this is probably not the best way to do this, so if there's a
better approach I would welcome the feedback.
Thanks!
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 62493] mod_cache_socache loses request bodies after
revalidation
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62493
--- Comment #1 from Jeff W <ap...@wheelhouse.org> ---
Here is a substantially shorter complete config that strips out everything
unusual or nonessential (TLS, HTTP2, etc), but still reproduces the issue:
https://pastebin.com/rYaxTr8w
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 62493] mod_cache_socache loses request bodies after
revalidation
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62493
Jeff W <ap...@wheelhouse.org> changed:
What |Removed |Added
----------------------------------------------------------------------------
CC| |apache@wheelhouse.org
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 62493] mod_cache_socache loses request bodies after
revalidation
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62493
William A. Rowe Jr. <wr...@apache.org> changed:
What |Removed |Added
----------------------------------------------------------------------------
Keywords| |PatchAvailable
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org