Multiple responses in cache objects

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

Multiple responses in cache objects

Tobias Wolter
Cheers,

I'm having some pretty weird issues with a customer's squid
installation - we're seeing multiple responses in a single cache
object.

Sadly, this isn't a singular incident and seems to be happening more
often recently. We've rolled back all changes since the date people
first started noticing the issues, but it still hasn't helped.

This occasionally leads to e.g. fragged CSS files, which users see by
the way of the stylesheet not working.

I'm currently out of debugging ideas. Aside from the rollback, we've
thus far isolated it to the Squid; the Apache which is the originserver
for this successfully returns the correct site.

As far as the setup goes, this is the pipeline:
* Squid (terminates SSL)
* Apache (cache_peer, originserver, same host as squid)
* Tomcat (via AJP from Apache, different hos)

Apparently, there is a point when a request to the squid takes a while
(~15s), and after that, there's something corrupted in the cache.

Any hints and help would be greatly appreciated.

Some pastes, with examples and data:
/var/cache/squid # grep -acr 'HTTP/1.1' . | grep -v 1$ | grep -v
swap.state
./02/C9/0002C9D3:2
./02/55/000255F5:2
./01/B0/0001B001:2
./00/04/00000498:2
./00/7F/00007F1F:2
./00/28/0000282E:2


# grep -aA5 'HTTP/1.1' ./02/C9/0002C9D3
╚║HTTP/1.1 200 OK
Server: squid
Mime-Version: 1.0
Date: Mon, 23 Apr 2018 11:49:23 GMT
X-Transformed-From: HTTP/0.9

--
HTTP/1.1 304 Not Modified
Date: Mon, 23 Apr 2018 11:49:25 GMT
Server: Apache
Connection: Keep-Alive
Keep-Alive: timeout=15, max=87
ETag: "ca8-55ef60f57e009"


pws2:/var/cache/squid # grep -aA14 'HTTP/1.1' ./02/55/000255F5
FHTTP/1.1 200 OK
Server: squid
Mime-Version: 1.0
Date: Sat, 14 Apr 2018 12:07:30 GMT
X-Transformed-From: HTTP/0.9

<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">;
<html>
        <head>
                <script type="text/javascript">var contextPath = '';</script>

                <script type="text/javascript" src="/js/jquery-1.11.2.min.js"></script>
            <script type="text/javascript" src="/js/layer.js"></script>
                <script type="text/javascript" src="/js/jquery.colorbox-1.5.15.min.js"></script>
                <script type="text/javascript" src="/js/cookies.js"></script>
--
HTTP/1.1 200 OK
Date: Sat, 14 Apr 2018 12:07:30 GMT
Server: Apache
X-FRAME-OPTIONS: SAMEORIGIN
X-XSS-Protection: 1; mode=block
Last-Modified: Fri, 13 Apr 2018 13:31:28 GMT
Cache-Control: max-age=300
Expires: Sat, 14 Apr 2018 12:12:30 GMT
Vary: Accept-Encoding
Content-Encoding: gzip
Keep-Alive: timeout=15, max=97
Connection: Keep-Alive
Transfer-Encoding: chunked
Content-Type: text/html;charset=ISO-8859-1

# squidclient mgr:info:
Squid Object Cache: Version 3.5.21
Build Info:
Service Name: squid
Start Time:     Mon, 23 Apr 2018 11:50:30 GMT
Current Time:   Mon, 23 Apr 2018 12:41:11 GMT
Connection information for squid:
        Number of clients accessing cache:      407
        Number of HTTP requests received:       13262
        Number of ICP messages received:        0
        Number of ICP messages sent:    0
        Number of queued ICP replies:   0
        Number of HTCP messages received:       0
        Number of HTCP messages sent:   0
        Request failure ratio:   0.00
        Average HTTP requests per minute since start:   261.6
        Average ICP messages per minute since start:    0.0
        Select loop called: 197830 times, 15.374 ms avg
Cache information for squid:
        Hits as % of all requests:      5min: 52.3%, 60min: 64.0%
        Hits as % of bytes sent:        5min: 40.6%, 60min: 54.3%
        Memory hits as % of hit requests:       5min: 74.3%, 60min: 78.0%
        Disk hits as % of hit requests: 5min: 0.1%, 60min: 0.1%
        Storage Swap size:      3949688 KB
        Storage Swap capacity:  77.1% used, 22.9% free
        Storage Mem size:       36168 KB
        Storage Mem capacity:    4.6% used, 95.4% free
        Mean Object Size:       79.26 KB
        Requests given to unlinkd:      3272
Median Service Times (seconds)  5 min    60 min:
        HTTP Requests (All):   0.01309  0.00179
        Cache Misses:          0.02317  0.02592
        Cache Hits:            0.00000  0.00000
        Near Hits:             0.01745  0.01745
        Not-Modified Replies:  0.00000  0.00000
        DNS Lookups:           0.02231  0.02336
        ICP Queries:           0.00000  0.00000
Resource usage for squid:
        UP Time:        3041.448 seconds
        CPU Time:       49.352 seconds
        CPU Usage:      1.62%
        CPU Usage, 5 minute avg:        1.63%
        CPU Usage, 60 minute avg:       1.63%
        Maximum Resident Size: 340384 KB
        Page faults with physical i/o: 1
Memory accounted for:
        Total accounted:        49999 KB
        memPoolAlloc calls:   3344459
        memPoolFree calls:    3360309
File descriptor usage for squid:
        Maximum number of file descriptors:   4096
        Largest file desc currently in use:    101
        Number of file desc currently in use:   69
        Files queued for open:                   0
        Available number of file descriptors: 4027
        Reserved number of file descriptors:   100
        Store Disk files open:                   0
Internal Data Structures:
         49856 StoreEntries
          1421 StoreEntries with MemObjects
          1420 Hot Object Cache Items
         49829 on-disk objects

# mgr:storedir:
Store Directory Statistics:
Store Entries          : 49863
Maximum Swap Size      : 5120000 KB
Current Store Swap Size: 3949940.00 KB
Current Capacity       : 77.15% used, 22.85% free

Store Directory #0 (ufs): /var/cache/squid
FS Block Size 4096 Bytes
First level subdirectories: 16
Second level subdirectories: 256
Maximum Size: 5120000 KB
Current Size: 3949940.00 KB
Percent Used: 77.15%
Filemap bits in use: 49835 of 262144 (19%)
Filesystem Space in use: 16453040/41153856 KB (40%)
Filesystem Inodes in use: 441511/2621440 (17%)
Flags: SELECTED
Removal policy: lru
LRU reference age: 12.80 days

-towo
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users

signature.asc (849 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Multiple responses in cache objects

Amos Jeffries
Administrator
On 24/04/18 00:43, Tobias Wolter wrote:
> Cheers,
>
> I'm having some pretty weird issues with a customer's squid
> installation - we're seeing multiple responses in a single cache
> object.
>

Please note the:

> X-Transformed-From: HTTP/0.9

... in your example cached objects.

Squid should not be caching these. Which implies that a) you have some
config settings forcing things to cache when they are not supposed to,
and b) either upstream server or client is broken.


 * do you have any refresh_pattern rules forcing it to do so?

 * what version of Squid are you running?

 * have you tried the latest Squid version?
 there have been a few fixes in detection this protocol version for Squid-4.


> Sadly, this isn't a singular incident and seems to be happening more
> often recently. We've rolled back all changes since the date people
> first started noticing the issues, but it still hasn't helped.
>
> This occasionally leads to e.g. fragged CSS files, which users see by
> the way of the stylesheet not working.
>
> I'm currently out of debugging ideas. Aside from the rollback, we've
> thus far isolated it to the Squid; the Apache which is the originserver
> for this successfully returns the correct site.


Squid is apparently receiving HTTP/0.9 response objects (a raw data
stream of octets) not HTTP 1.0 or 1.1 objects (stream of messages with
specific start and end points to each message object).


How do you determine that "successful" for the server?
 using any tool that hides away the protocols octet-level format details
 (eg curl, wget, browser, etc) can hide the HTTP/0.9 oddity from view.

Locate the URL which was originally requested by the client. The first
line of the cache file should be a single byte representing the
request-method, then the URL in plain-text ending with newline (\n). Use
squidclient to fetch that URL directly from the server like so:

  squidclient -h example.com -p 80 -V "-" http://example.com/




This is what a normal HTTP/1.x response message is supposed to look like:

( from "squidclient -h example.com -p 80 /" )

"
HTTP/1.0 404 Not Found
Content-Type: text/html
Date: Mon, 23 Apr 2018 13:56:18 GMT
Server: ECS (oxr/837F)
Content-Length: 345
Connection: close

<?xml version="1.0" encoding="iso-8859-1"?>
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
         "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en" lang="en">
        <head>
                <title>404 - Not Found</title>
        </head>
        <body>
                <h1>404 - Not Found</h1>
        </body>
</html>
"

And this is what your cache file 000255F5 says Squid is receiving from
the upstream server (for the URL you should see in the very start of
that 000255F5 file):

"
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
"http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">;
<html>
        <head>
                <script type="text/javascript">var contextPath =
'';</script>

                <script type="text/javascript"
src="/js/jquery-1.11.2.min.js"></script>
            <script type="text/javascript" src="/js/layer.js"></script>
                <script type="text/javascript"
src="/js/jquery.colorbox-1.5.15.min.js"></script>
                <script type="text/javascript"
src="/js/cookies.js"></script>
...
"

Amos
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Multiple responses in cache objects

Tobias Wolter
Hey Amos,

On Tue, 2018-04-24 at 02:20 +1200, Amos Jeffries wrote:

> On 24/04/18 00:43, Tobias Wolter wrote:
> > Cheers,
> >
> > I'm having some pretty weird issues with a customer's squid
> > installation - we're seeing multiple responses in a single cache
> > object.
> >
>
> Please note the:
>
> > X-Transformed-From: HTTP/0.9
>
> ... in your example cached objects.
>
> Squid should not be caching these. Which implies that a) you have
> some config settings forcing things to cache when they are not
> supposed to, and b) either upstream server or client is broken.
I was wondering about these, that's a good hint.

>  * do you have any refresh_pattern rules forcing it to do so?

Aye, some files were CSS files which are forced into caching. I was
speculating that the refresh_patterns might be involved, but didn't
see the connection.

>  * what version of Squid are you running?

3.5.21 on whatever patches SUSE baked into it.


>  * have you tried the latest Squid version?
>  there have been a few fixes in detection this protocol version for
> Squid-4.

Sadly non-negotiable, I'll have to make do (or tell them, ultimatively,
that it can't be done).

> Squid is apparently receiving HTTP/0.9 response objects (a raw data
> stream of octets) not HTTP 1.0 or 1.1 objects (stream of messages
> with specific start and end points to each message object).

Yup, will look into how *that* is happening.

> How do you determine that "successful" for the server?
>  using any tool that hides away the protocols octet-level format
> details
>  (eg curl, wget, browser, etc) can hide the HTTP/0.9 oddity from
> view.

Yeah, I've only been loooking at high-level clients since that's pretty
much where it broke; since it at least by assumption had always been
"working" (read: no visible/reported breakage) thus far, I didn't
bother to check for this; especially as the application hasn't been
updated in the timeframe where errors were reported.

> Locate the URL which was originally requested by the client. The
> first line of the cache file should be a single byte representing the
> request-method, then the URL in plain-text ending with newline (\n).

my grep line handily found those; another option is to grep for '-1\s*-
1 unknown' in the cache_store_log, as there's a direct connection
between broken object storage and lack of cache timing, as we've found
out since I wrote the mail.

Kudos for the hints, Amos, they're great and'll help me a lot
(tomorrow, it's 22.54 local here).

-towo
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users

signature.asc (849 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: [SOLVED-ish] Multiple responses in cache objects

Tobias Wolter
Cheers,

On Mon, 2018-04-23 at 22:54 +0200, Tobias Wolter wrote:
> Kudos for the hints, Amos, they're great and'll help me a lot
> (tomorrow, it's 22.54 local here).

Welp, we haven't really come that far, but what we can tell is that
Squid isn't at fault by itself, as we merely forced it to cache some
bad responses from the Apache.

For anyone interested: We've narrowed it down to issues accessing files
on the local filesystem or remotely; Apache seems to hang trying to put
the file into an existing HTTP/1.1 keep-alive connection. If you turn
off KeepAlive, it works (delay still present, <10s); if KeepAlive is
on, we can see from tcpdump that Apache will happily respond to
KeepAlive requests, but then dump one of the previous response joined
with another response, without <CR><LF> in between.

Not sure what's causing the hang yet, but apparently not Squid, so
thanks!

-towo
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users

signature.asc (849 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: [SOLVED-ish] Multiple responses in cache objects

Amos Jeffries
Administrator
On 25/04/18 01:41, Tobias Wolter wrote:

> Cheers,
>
> On Mon, 2018-04-23 at 22:54 +0200, Tobias Wolter wrote:
>> Kudos for the hints, Amos, they're great and'll help me a lot
>> (tomorrow, it's 22.54 local here).
>
> Welp, we haven't really come that far, but what we can tell is that
> Squid isn't at fault by itself, as we merely forced it to cache some
> bad responses from the Apache.
>
> For anyone interested: We've narrowed it down to issues accessing files
> on the local filesystem or remotely; Apache seems to hang trying to put
> the file into an existing HTTP/1.1 keep-alive connection. If you turn
> off KeepAlive, it works (delay still present, <10s); if KeepAlive is
> on, we can see from tcpdump that Apache will happily respond to
> KeepAlive requests, but then dump one of the previous response joined
> with another response, without <CR><LF> in between.
>
> Not sure what's causing the hang yet, but apparently not Squid, so
> thanks!

Welcome and good luck.

FWIW; CRLF is not required between responses. If the first response has
a Content-Length the payload ends at the exact byte indicated and the
second response starts the byte after - no need for a CRLF. So don't
think that absence necessarily a bug in itself.

Amos
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users