You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@httpd.apache.org by Alexander Härtig <Al...@dmc.de> on 2015/12/21 17:25:46 UTC
[users@httpd] AW: mod_cache/mod_cache_disk responses missing Content-Type header
By taking a closer look at the log-files I found a lot error entries with the following message:
AH00717: Premature end of cache headers.
I tried to google but I couldn't find anything about what causes these problems. I'm not even sure which headers are meant in this context, cache entry header or request header?
I'm pretty sure this errors caused the problem mentioned in my previous post. Although the AH00717 occurred at least for the last three month every day. But only for one specific site, not all the sites the cache is responsible for.
Von: Alexander Härtig [mailto:Alexander.Haertig@dmc.de]
Gesendet: Freitag, 18. Dezember 2015 18:28
An: users@httpd.apache.org
Betreff: [users@httpd] mod_cache/mod_cache_disk responses missing Content-Type header
Hello,
for our customer we set up several Apache httpds (Server version: Apache/2.4.16 (Amazon)) in Amazon Web Services EC2 instances across the world. These httpds act mainly as caching proxies that are connected to a central web application. For caching we use mod_cache_disk.
A couple of days ago one instance served responses with missing Content-Type and Content-Encoding header, resulting in download dialogs popping up when customer tried to open the page, as the content was interpreted as application/octet-stream. The downloaded data was the expected response: a gzip-compressed html-file. We could tell that the data was served from the cache as we add a custom response header that states if there was a cache-hit or not. So we took a look at the relevant *.header-file of the cache entry of the page but it didn't have any abnormalities.
After clearing the cache manually everything went back to normal.
Does this behavior sound familiar to anybody?
Regards,
Alexander
--
Alexander Härtig
software engineer
dmc 030 GmbH
Kohlfurter Strasse 41/43
10999 Berlin (Germany)
Telefon: +49 30 308 3393 - 70
Telefax: +49 30 308 3393 - 93
E-Mail: alexander.haertig@dmc.de
Internet: www.dmc.de<http://www.dmc.de>
Handelsregister: AG Berlin Charlottenburg HRB 129396 B
Geschäftsführer: Daniel Elsässer, Andreas Magg
---------------------------------------------
// the diconium companies:
dmc commerce consultants | dmc digital media center | dmc 030 | ro11 | embitel | CINTEO
stuttgart // berlin // karlsruhe // bangalore // detroit
---------------------------------------------
Diese E-Mail enthält vertrauliche und/oder rechtlich geschützte Informationen. Wenn Sie
nicht der richtige Adressat sind oder diese E-Mail irrtümlich erhalten haben, informieren
Sie bitte sofort den Absender und vernichten Sie diese E-Mail. Das unerlaubte Kopieren
und die unbefugte Weitergabe dieser E-Mail sind nicht gestattet.
This e-mail may contain confidential and/or privileged information. If you are not the intended
recipient or have received this e-mail in error please notify the sender immediately and delete
this e-mail. Any unauthorized copying, disclosure or distribution of the material in this e-mail
is strictly forbidden.
Re: [users@httpd] AW: mod_cache/mod_cache_disk responses missing
Content-Type header
Posted by Raphaël <ra...@gmail.com>.
On Mon, Dec 21, 2015 at 11:39:55AM -0500, Eric Covener wrote:
> On Mon, Dec 21, 2015 at 11:25 AM, Alexander Hrtig
> <Al...@dmc.de> wrote:
> > AH00717: Premature end of cache headers.
>
> The error reporting is very poor there. Are you able to patch
> mod_cache_disk and run with at least LogLevel debug?
>
> http://svn.apache.org/viewvc/httpd/httpd/trunk/modules/cache/mod_cache_disk.c?r1=1721210&r2=1721209&pathrev=1721210
trace8 brings nothing new w.r.t debug (as sent in my previous email)
I found the following behavior interesting :
GET / => OK # put in cache
POST / => OK # invalidate cache
POST / => not OK # cache_disk:error AH00717
My guess is that it comes from following patch from 2013:
> mod_cache: Invalidate cached entities in response to RFC2616 Section
https://mail-archives.apache.org/mod_mbox/httpd-cvs/201305.mbox/%3C20130528203005.1A55D2388A32@eris.apache.org%3E
* It seems it introduced a CACHE_INVALIDATE filter (for which, sadly, I
didn't find much documentation)
* I guess it introduced an invalid code path triggering
invalidate_entity() => recall_headers() for an already invalidated entity.
Maybe this error it just the symptom of trying to invalidate a "removed"
entity twice.
When doing tests I was also able to encouter easily:
> AH02468: cache: Attempted to invalidate cached entity with key: http://xxxx:80/index.php?
by just playing a bit with htcacheclean
(side note: htcacheclean -A <URL> is an incorrect usage, but an unexpected behavior)
Going further, I guess that the second invalidation shows this issue because
the first invalidation (in during the first POST) failed to output a
valid mod_cache file.
Attached the initial cache header file (GET.txt, just after a GET), copied from
/var/cache/apache2/mod_cache_disk/6q/m_/*.header.vary/ou/Ye/*.header
and then just after a POST was issued (successive POSTs cause the error
but don't change this file anymore) : POST.txt
I hope it makes things clearer and could help bringing up a full
explanation + fix + workaround.
thank you
Re: [users@httpd] AW: mod_cache/mod_cache_disk responses missing
Content-Type header
Posted by Eric Covener <co...@gmail.com>.
On Mon, Dec 21, 2015 at 11:25 AM, Alexander Härtig
<Al...@dmc.de> wrote:
> AH00717: Premature end of cache headers.
The error reporting is very poor there. Are you able to patch
mod_cache_disk and run with at least LogLevel debug?
http://svn.apache.org/viewvc/httpd/httpd/trunk/modules/cache/mod_cache_disk.c?r1=1721210&r2=1721209&pathrev=1721210
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org
Re: [users@httpd] AW: mod_cache/mod_cache_disk responses missing
Content-Type header
Posted by Raphaël Droz <ra...@gmail.com>.
On Mon, Dec 21, 2015 at 04:25:46PM +0000, Alexander Hrtig wrote:
> By taking a closer look at the log-files I found a lot error entries with the following message:
> AH00717: Premature end of cache headers.
> I tried to google but I couldn't find anything about what causes these problems. I'm not even sure which headers are meant in this context, cache entry header or request header?
I just probably stumbled upon the very same issue.
The issue arise when a POST was issued on an URL (for which GET would be
cached).
The first POST seems fine, but the second one isn't.
See log below (Apache 2.4.10-10+deb8u4)
(I'm simply POSTing x=y)
## FIRST POST on /
> [Mon Jun 06 05:13:26.861453 2016] [cache:debug] [pid 25898:tid 139847851255552] mod_cache.c(440): [client x.x.x.x:49398] AH02463: PUT/POST/DELETE: Adding CACHE_INVALIDATE filter for /index.php
> [Mon Jun 06 05:13:27.202134 2016] [cache:debug] [pid 25898:tid 139847851255552] mod_cache.c(1731): [client x.x.x.x:49398] AH00777: cache: CACHE filter was added twice, or was added where the cache has been bypassed and will be ignored: /
> [Mon Jun 06 05:13:27.202225 2016] [cache:debug] [pid 25898:tid 139847851255552] mod_cache.c(1677): [client x.x.x.x:49398] AH02467: cache: Invalidating all cached entities in response to 'POST' request for /index.php
> [Mon Jun 06 05:13:27.202246 2016] [cache:debug] [pid 25898:tid 139847851255552] cache_storage.c(664): [client x.x.x.x:49398] AH00698: cache: Key for entity /index.php?(null) is http://mywebsite.test:80/index.php?
> [Mon Jun 06 05:13:27.202356 2016] [cache_disk:debug] [pid 25898:tid 139847851255552] mod_cache_disk.c(572): [client x.x.x.x:49398] AH00709: Recalled cached URL info header http://mywebsite.test:80/index.php?
> [Mon Jun 06 05:13:27.202368 2016] [cache_disk:debug] [pid 25898:tid 139847851255552] mod_cache_disk.c(885): [client x.x.x.x:49398] AH00720: Recalled headers for URL http://mywebsite.test:80/index.php?
> [Mon Jun 06 05:13:27.202545 2016] [cache_disk:debug] [pid 25898:tid 139847851255552] mod_cache_disk.c(1350): [client x.x.x.x:49398] AH00737: commit_entity: Headers and body for URL http://mywebsite.test:80/index.php? cached.
> [Mon Jun 06 05:13:27.202559 2016] [cache:debug] [pid 25898:tid 139847851255552] cache_storage.c(752): [client x.x.x.x:49398] AH02468: cache: Attempted to invalidate cached entity with key: http://mywebsite.test:80/index.php?
## SECOND POST on /
> [Mon Jun 06 05:13:40.044414 2016] [cache:debug] [pid 25899:tid 139847842862848] mod_cache.c(440): [client x.x.x.x:49402] AH02463: PUT/POST/DELETE: Adding CACHE_INVALIDATE filter for /index.php
> [Mon Jun 06 05:13:40.283025 2016] [cache:debug] [pid 25899:tid 139847842862848] mod_cache.c(1731): [client x.x.x.x:49402] AH00777: cache: CACHE filter was added twice, or was added where the cache has been bypassed and will be ignored: /
> [Mon Jun 06 05:13:40.283099 2016] [cache:debug] [pid 25899:tid 139847842862848] mod_cache.c(1677): [client x.x.x.x:49402] AH02467: cache: Invalidating all cached entities in response to 'POST' request for /index.php
> [Mon Jun 06 05:13:40.283125 2016] [cache:debug] [pid 25899:tid 139847842862848] cache_storage.c(664): [client x.x.x.x:49402] AH00698: cache: Key for entity /index.php?(null) is http://mywebsite.test:80/index.php?
> [Mon Jun 06 05:13:40.283183 2016] [cache_disk:debug] [pid 25899:tid 139847842862848] mod_cache_disk.c(572): [client x.x.x.x:49402] AH00709: Recalled cached URL info header http://mywebsite.test:80/index.php?
> [Mon Jun 06 05:13:40.283189 2016] [cache_disk:error] [pid 25899:tid 139847842862848] [client x.x.x.x:49402] AH00717: Premature end of cache headers.
> [Mon Jun 06 05:13:40.283201 2016] [cache_disk:error] [pid 25899:tid 139847842862848] [client x.x.x.x:49402] AH00717: Premature end of cache headers.
> [Mon Jun 06 05:13:40.283204 2016] [cache_disk:debug] [pid 25899:tid 139847842862848] mod_cache_disk.c(885): [client x.x.x.x:49402] AH00720: Recalled headers for URL http://mywebsite.test:80/index.php?
> [Mon Jun 06 05:13:40.283304 2016] [cache_disk:debug] [pid 25899:tid 139847842862848] mod_cache_disk.c(1350): [client x.x.x.x:49402] AH00737: commit_entity: Headers and body for URL http://mywebsite.test:80/index.php? cached.
> [Mon Jun 06 05:13:40.283311 2016] [cache:debug] [pid 25899:tid 139847842862848] cache_storage.c(752): [client x.x.x.x:49402] AH02468: cache: Attempted to invalidate cached entity with key: http://mywebsite.test:80/index.php?
Here are two samples responses of :
### (cached) GET /
> 200 OK
> Cache-Control: public, max-age=300
> Connection: close
> Date: Mon, 06 Jun 2016 03:22:54 GMT
> Age: 6
> Server: Apache/2.4
> Vary: Cookie,Accept-Encoding
> Content-Length: 35658
> Content-Type: text/html; charset=UTF-8
> Last-Modified: Sun, 03 Apr 2016 16:21:51 GMT
> Client-Date: Mon, 06 Jun 2016 03:23:03 GMT
> Client-Peer: x.x.x.x:80
> Client-Response-Num: 1
### (non-cached) POST /
> 200 OK
> Cache-Control: public, max-age=300
> Connection: close
> Date: Mon, 06 Jun 2016 03:24:42 GMT
> Server: Apache/2.4
> Vary: Cookie,Accept-Encoding
> Content-Type: text/html; charset=UTF-8
> Last-Modified: Sun, 03 Apr 2016 16:21:51 GMT
> Client-Date: Mon, 06 Jun 2016 03:24:51 GMT
> Client-Peer: x.x.x.x:80
> Client-Response-Num: 1
> Client-Transfer-Encoding: chunked
It lets me realize one (related or not?) issue: webapp should not issue
Cache-Control for POST requests.
hope this help tracking this down
best regards
--
GPG id: 0xF41572CEBD4218F4
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org