[squid-users] Identifying the source of Invalid-request (squid 3) -> error:transaction-end-before-headers (Squid 4)

Sat Oct 15 13:36:04 UTC 2016

Greetings!

I am running a transparent proxy for plain http traffic, memory caching
only, I have something like 500 devices that are using the proxy at any
given time over a satellite and I am averaging in the range of 2,000
requests per minute across the proxy (again, no SSL bump, I do not control
the devices at all).  I am using 3.5.22 compiled from sources (if it
matters).  I have been seeing lines in my access log like the following:

1476535967.570      0 xxx.xxx.xxx.xxx TAG_NONE/400 4538 NONE
error:invalid-request - HIER_NONE/- text/html

After some digging on this list I began to suspect websockets or other
non-http traffic coming across port 80.  After additional reading, and as
much as anything to test the hypothesis, I decided to try squid 4.0.15 with
on-unsupported-protocol.  I get what I am guessing to be the same result
with new error text around it:

1476536369.742      0 xxx.xxx.xxx.xxx NONE/000 0 NONE
error:transaction-end-before-headers - HIER_NONE/- -

An interesting point to interject here is that my "Hits as % bytes sent" in
3.5.x has always been in the 2 to 5% range, but there are periods (sometimes
long ones) where the inbound traffic to squid is much higher than the
outbound.  When I switch to 4.0.x, I am now running about -27% (note,
negative twenty-seven) as bytes, which makes me suspect it is logging the
higher inbound than outbound now.  So, apparently, this unsupported protocol
is triggering some sort of large download, but does not end up going to the
client.  Obviously, this is not good, so I'm digging deeper and I'd
appreciate any pointers that come to mind. 

I would like to know a couple things, first: is there some debugging level
other than ALL,9 that might give me some illumination?  ALL,9 generates
about 15 MB of debug log per second at my current load level, and these
errors aren't real frequent, so I end up with ~ 400 MB of text that needs to
be sifted through.  As you can imagine, that can be a bit brutal.  If I
could even identify the other end point, I would at least be able to figure
out if this is Apple, Microsoft, Android, something else, and perhaps get
closer to being able to replicate the error.  Thoughts would be appreciated.
In case its relevant, my compile options were:

./configure --prefix=/usr   --localstatedir=/var
--libexecdir=/usr/lib/squid    --srcdir=.   --datadir=/usr/share/squid
--sysconfdir=/etc/squid   --with-default-user=proxy   --with-logdir=/var/log
--with-pidfile=/var/run/squid.pid --enable-linux-netfilter
--enable-cache-digests --enable-storeio=ufs,aufs,diskd,rock
--enable-async-io=30 --enable-http-violations --enable-zph-qos
--with-netfilter-conntrack --with-filedescriptors=65536 --with-large-files

Note that, a lot of those are based on a very long and tedious
guess-and-check session last year, and some of them probably are totally
irrelevant to my setup (I'm looking at you --enable-http-violations and
--enable-zph-qos) but hey, what is life without the unnecessary noise from
lazily copy-and-pasting old compile lines.

My configuration, edited to eliminate my numerous comments and hashed out
lines of experiments and to hide network identifiers, is pasted below.  

///BEGIN /etc/squid/squid.conf

workers 4

acl localnet src 10.0.0.0/8     # RFC1918 possible internal network

acl localnet src 172.16.0.0/12  # RFC1918 possible internal network

acl localnet src 192.168.0.0/16 # RFC1918 possible internal network

acl localnet src fc00::/7       # RFC 4193 local private network range

acl localnet src fe80::/10      # RFC 4291 link-local (directly plugged)
machines

acl SSL_ports port 443

acl Safe_ports port 80          # http

acl Safe_ports port 21          # ftp

acl Safe_ports port 443         # https

acl Safe_ports port 70          # gopher

acl Safe_ports port 210         # wais

acl Safe_ports port 1025-65535  # unregistered ports

acl Safe_ports port 280         # http-mgmt

acl Safe_ports port 488         # gss-http

acl Safe_ports port 591         # filemaker

acl Safe_ports port 777         # multiling http

acl CONNECT method CONNECT

#Note that I added this line when testing Squid-4, it is commented out when
running Squid-3

on_unsupported_protocol tunnel all

http_access allow localnet

http_access allow localhost

http_access deny !Safe_ports

http_access deny CONNECT !SSL_Ports

# And finally deny all other access to this proxy

http_access deny all

http_port 3128

http_port 3129 tproxy

visible_hostname squid-proxy.mydomain.tld

acl updatesites dstdom_regex "/etc/squid/updatesites.txt"

icp_port 3130

htcp_port 4827

icp_access allow localnet

icp_access deny all

#Testing QoS Marks

qos_flows tos local-hit=0x30

qos_flows mark local-hit=0x30

qos_flows mark miss=0x0

maximum_object_size 800 MB updatesites

maximum_object_size 80 MB !updatesites

range_offset_limit 0

quick_abort_min 0 KB

store_id_program /usr/lib/squid/storeid_file_rewrite
/etc/squid/storeid_rewrite.conf

store_id_children 10 startup=3 idle=1 concurrency=0

cache_mem 16384 MB

maximum_object_size_in_memory 8 MB

cache_swap_low 90

cache_swap_high 95

cache_store_log daemon:/var/log/squid/store.log

access_log daemon:/var/log/squid/access.log squid

cache_log /var/log/squid/cache.log

logfile_rotate 40

max_open_disk_fds 64000

refresh_pattern ^ftp:           1440    20%     10080

refresh_pattern ^gopher:        1440    0%      1440

refresh_pattern -i (/cgi-bin/|\?) 0     0%      0

refresh_pattern .               0       20%     4320

cache_mgr someone at mydomain.td

cache_effective_user proxy

cache_effective_group proxy

///END /etc/squid/squid.conf

So, I have a few questions I guess:  

(1)    For one thing, what are the implications of "on_unsupported_protocol
tunnel all"?  I did it as a quick attempt to see if that had any new and
interesting impacts, but is it safe-ish?  Am I letting the bad-guys come
pouring through with that?

(2)    What debug levels should I be thinking about to try and figure out
what is happening.  Seems like we won't get very far without identifying
what is throwing that error.

(3)    Has anyone else seen this?  Right now, for example (after 10 minutes
of typing an email) I'm actually running -61% Hits as Bytes!  (Negative!)
Ouch! 

Thanks!

--Jester

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20161015/d90d60ad/attachment.html>