Re: [squid-users] the ctx errors in cache.log

On 10/10/2013 4:22 p.m., Ding Guigeng wrote:
> my server runs squid 3.3.9,and workers is set to be 3
> the following from cache.log:
> 2013/10/10 08:48:36 kid1| ctx: enter level 0:

Note the word is "enter" (with a N and T and missing 'o'). This message
means that a debug statement called a function to produce the string for
debug display. That function is itself trying to print a debug
statement. The ctx level gets +1 each time the recursion happens.
Not terribly important, but it helps sometimes to see that some action
being done is due to it being needed for a debug message printing, and
not part of normal Squid operation. For example a function which walks a
list of cache items and drops the already exired ones as it goes will
cause different behaviour in Squid. If it was run simply to display the
list for debugs it will change memory usage, content matches, etc from
when its normally run on occasional cleanup events.

Specifically in this case the function be run is generating a canonical
full-URL and attaching it to the transaction state. Simply in order to
be able to display the full-URL below. In normal operation the URL parts
might be left separated until much later in the transaction, if they
ever need combining at all.

> 'http://calendar.snsapp.qq.com/cgi-bin/my_calendar_app_flag?g_tk=1964882004'
> Server: QZHTTP-2.38.17}1| WARNING: suspicious CR characters in HTTP header

Problem #1: As the message says CR (0x0d) characters are being sent
inside the HTTP headers by the client.
  These are invalid characters, CR is only acceptibe as part of the CRLF
sequence meaning end-of-line. The client is being delivered a Invalid
Request error ...

> {Keep-Alive: timeout=5184000, max=1024
> 2013/10/10 08:54:56 kid3| WARNING: HTTP: Invalid Response: Bad header
> encountered from
> http://dc.funshion.com:5552/website/dc?mac=4437E615C913&uid=0&fpc=uoc_0_z2&pt=7&et=1&mid=&rat=&stp=CFRank&ht=&pn=&tag=&mis=110464%7C93069%7C110228%7C107197%7C106112%7C110429%7C92866%7C106910&fck=271EAA45A5CCB977CF64F336758C96C9
> AKA
> dc.funshion.com/website/dc?mac=4437E615C913&uid=0&fpc=uoc_0_z2&pt=7&et=1&mid=&rat=&stp=CFRank&ht=&pn=&tag=&mis=110464%7C93069%7C110228%7C107197%7C106112%7C110429%7C92866%7C106910&fck=271EAA45A5CCB977CF64F336758C96C9

Problem type #2: Again as the message said. Invalid HTTP protocol
headers coming back from the server supplying that URL.

Note that this is just "Bad Header". As in some HTTP header had a value
that did not parse according to its defined format. You will have to
locate the response headers for that URL and try to figure out which is
broken (might be several). I usually use the redbot.org tool for that,
sometimes the squidclient tool if specific HTTP request details are
necessary to reproduce the problem.

It happens again slightly later too...

> 2013/10/10 08:59:33 kid3| WARNING: HTTP: Invalid Response: Bad header
> encountered from
> http://dc.funshion.com:5552/website/dc?mac=EC55F9C5CB8B&uid=0&fpc=swm_0_z1&pt=7&et=1&mid=&rat=&stp=CFTopicRank&ht=&pn=&tag=&mis=88432%7C109043%7C110191%7C33796%7C107482%7C11540%7C109982%7C104307&fck=F25CE9EA7D383EEADE503E31FAF8543D
> AKA
> dc.funshion.com/website/dc?mac=EC55F9C5CB8B&uid=0&fpc=swm_0_z1&pt=7&et=1&mid=&rat=&stp=CFTopicRank&ht=&pn=&tag=&mis=88432%7C109043%7C110191%7C33796%7C107482%7C11540%7C109982%7C104307&fck=F25CE9EA7D383EEADE503E31FAF8543D
> 2013/10/10 09:10:48 kid1| ctx: exit level 0
> 2013/10/10 09:10:48 kid1| ctx: enter level 0:
> 'http://counter.itcpn.net/c_c.js'
> 2013/10/10 09:10:48 kid1| WARNING: HTTP header contains NULL characters

Problem #3: Exactly what the message says "HTTP header contains NULL
characters". The text below quotes the HTTP headers and highlights where
the NULL character was found.

To me this looks like a server script adding the Date header and
including the NULL byte (meaning end-of-string) when it should be
sending the CRLF bytes (meaning end-of-header-line).

NP: sometimes its obvious like this and people wonder why Squid cant
simply fix it automatically. But there is no way to separate simple
mistakes like this one and real malicious attacks.

> {Server: nginx/1.1.2
> Date: Thu, 10 Oct 2013 01:10:47}
> NULL
> {Server: nginx/1.1.2
> Date: Thu, 10 Oct 2013 01:10:47
> 2013/10/10 09:10:48 kid1| ctx: exit level 0
> 2013/10/10 09:10:48 kid1| WARNING: HTTP: Invalid Response: Bad header
> encountered from http://counter.itcpn.net/c_c.js AKA
> counter.itcpn.net/c_c.js

> 2013/10/10 09:15:47 kid2| ipcacheParse: No Address records in response to
> 'www.hzqm.net'

Problem #4: The domain name www.hzqm.net is a CNAME redirection to
hzqm.net which does not exist.
So while the www.* domain does _apparently_ exist there are no possible
IP addresses available to use.

> 2013/10/10 09:19:03 kid3| WARNING: Closing client connection due to lifetime
> timeout

May or may not be a problem.
This means the client was using a connection for more than
client_lifetime (default: 1 day). Some services like Facebook and
GoogleTalk chat sessions can stay open indefinitely with requests going
through. So the lifetime timeout is not uncommon.
The line directly after the WARNING indicates what the connection was
being used for when it was closed (in older Squid it indicates
*previous* usage on idle connections). Note that due to persistent
connections being re-used this does not necessarily mean that usage has
been the only one over the lietime, just that it was happening at that
particular time.

> 2013/10/10 09:19:03 kid3|
> http://61.155.167.220/data5/video07/2013/10/09/225823-102-007-1335.mp4
> 2013/10/10 09:20:16 kid1| WARNING: Closing client connection due to lifetime
> timeout
> 2013/10/10 09:20:16 kid1|
> http://61.155.167.220/data2/video07/2013/10/09/226653-102-007-2312.mp4
> 2013/10/10 10:21:22 kid2| ctx: enter level 0:
> 'http://mail.qq.com/cgi-bin/readmail?folderid=1&folderkey=1&t=readmail_conversation&mailid=C1T9AB4CCB6&mode=pre&maxage=3600&base=12.19&ver=19436&sid=NuX4cvD-5bfhMzVn'
> 2013/10/10 10:21:22 kid2| WARNING: unparseable HTTP header field {share
> memory not exist, need create new share memory!}

Problem #5: Strange looking HTTP protocol headers. yes?
Sounds like qq.com have some problems. Maybe even a security
vulnerability in their service if that can be triggered remotely.

<snip lots of repeats>
> 2013/10/10 10:46:53 kid3| SECURITY ALERT: Missing hostname in URL 'http://'.
> see access.log for detail

Problem #6: please look at the above closely. Very closely. Notice that
Squid is displaying the entire URL.
As it says you will find more details about this request in the
access.log, including client IP details. The URL parsing code in Squid
which detected this problem does not have access to all the details to
be more helpful in its report.

Either someone has delivered a NULL character at the start of the domain
name, or they are trying to request a URL without domain name or path
details. Neither one is good and this is usually seen on attack
requests. But there are possibilities, like that script above sending
Date with a NULL, this could be just a broken client not properly
validating the URLs it generates.

HTH
Amos
Received on Thu Oct 10 2013 - 06:09:59 MDT