[squid-users] Squid 3.5.23 X-forwader and log bug ?

Tue Apr 11 00:52:07 UTC 2017

On 10/04/2017 7:52 p.m., FredB wrote:
> Hello, 
> 
> I'm debugging e2guardian and I found something in squid log the X-forwarwed IP seems not always recorded? I saw nothing particular with tcpdumd so I made a change in code (e2guardian) to show the header passed 
> 
> ------------------- With problem -------------
> E2 Debug:
> Apr 10 09:07:49 proxytest1 e2guardian[27726]: Client: 192.168.0.5 START-------------------------------
> Apr 10 09:07:49 proxytest1 e2guardian[27726]: OUT: Client IP at 192.168.0.5 header: CONNECT avissec.centprod.com:443 HTTP/1.0
> Apr 10 09:07:49 proxytest1 e2guardian[27726]: OUT: Client IP at 192.168.0.5 header: User-Agent: Mozilla/5.0 (Windows NT 6.3; WOW64; rv:45.0) Gecko/20100101 Firefox/45.0
> Apr 10 09:07:49 proxytest1 e2guardian[27726]: OUT: Client IP at 192.168.0.5 header: Connection: close
> Apr 10 09:07:49 proxytest1 e2guardian[27726]: OUT: Client IP at 192.168.0.5 header: Connection: keep-alive
> Apr 10 09:07:49 proxytest1 e2guardian[27726]: OUT: Client IP at 192.168.0.5 header: Host: avissec.centprod.com
> Apr 10 09:07:49 proxytest1 e2guardian[27726]: OUT: Client IP at 192.168.0.5 header: Proxy-Authorization: Digest username="test", realm="PROXY", nonce="RS/rWAAAAADwSIzYAQAAADkmpUgAAAA", uri="avissec.centprod.com:443", response="b02fa966d373a2aaf06c43bc24a180b2", qop=auth, nc=00000001, cnonce="750b04766a809d18"
> Apr 10 09:07:49 proxytest1 e2guardian[27726]: OUT: Client IP at 192.168.0.5 header: X-Forwarded-For: 192.168.0.5
> Apr 10 09:07:49 proxytest1 e2guardian[27726]: Client: 192.168.0.5 END-------------------------------
>  
> Squid log:
> 127.0.0.1 - test [10/Apr/2017:09:07:54 +0200] "CONNECT avissec.centprod.com:443 HTTP/1.1" 200 33960 451 TCP_TUNNEL:HIER_DIRECT "Mozilla/5.0 (Windows NT 6.3; WOW64; rv:45.0) Gecko/20100101 Firefox/45.0"
> -------------------------------------------
> 
> -------------------- Without problem ------
> 
> E2:
> Apr 10 09:07:45 proxytest1 e2guardian[27726]: Client: 192.16.0.2 START-------------------------------
> Apr 10 09:07:45 proxytest1 e2guardian[27726]: OUT: Client IP at 192.16.0.2 header: CONNECT 0.client-channel.google.com:443 HTTP/1.0
> Apr 10 09:07:45 proxytest1 e2guardian[27726]: OUT: Client IP at 192.16.0.2 header: User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:45.0) Gecko/20100101 Firefox/45.0
> Apr 10 09:07:45 proxytest1 e2guardian[27726]: OUT: Client IP at 192.16.0.2 header: Connection: close
> Apr 10 09:07:45 proxytest1 e2guardian[27726]: OUT: Client IP at 192.16.0.2 header: Connection: keep-alive
> Apr 10 09:07:45 proxytest1 e2guardian[27726]: OUT: Client IP at 192.16.0.2 header: Host: 0.client-channel.google.com
> Apr 10 09:07:45 proxytest1 e2guardian[27726]: OUT: Client IP at 192.16.0.2 header: Proxy-Authorization: Digest username="test", realm="PROXY", nonce="NC/rWAAAAAAgRqZUAQAAAKXVAHcAAAA", uri="0.client-channel.google.com:443", response="ec5d46ce223d987f95393e2a35557bd0", qop=auth, nc=00000036, cnonce="877bd5e852b857c5"
> Apr 10 09:07:45 proxytest1 e2guardian[27726]: OUT: Client IP at 192.16.0.2 header: X-Forwarded-For: 192.16.0.2
> Apr 10 09:07:45 proxytest1 e2guardian[27726]: Client: 192.16.0.2 END-------------------------------
> 
> Squid log:
> 192.16.0.2 - test [10/Apr/2017:09:07:16 +0200] "CONNECT 0.client-channel.google.com:443 HTTP/1.0" 200 62701 486 TCP_TUNNEL:HIER_DIRECT "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:45.0) Gecko/20100101 Firefox/45.0"
> 

When doing this debugging *the* most critical thing is to get the
correlation between logs correct.

a) e2guardian records are not loggig their UTC offset. Your correlation
may be off by up to 4 hrs judging by the Squid offset.

b) you are not logging milliseconds in either log. Since transactions
can take place fully within 1ms that is important, or you will in
best-case be off in the logs by 1 second (over 2000 requests).

c) you are not logging duration for any of these transactions. Since
Squid logs on completion that means these transactions may be off by up
to a week, or when you last restarted Squid - whichever is smaller.

 - at the very least esure e2guardian is logging on send to Squid and
have Squid log the %tr value.

So in aggregate the above Squid log entry may be for any request
e2guardian logged in the 1 week 4 hours 1 seconds beforehand.

(Realistically its only in the time since you restarted e2guardian or
Squid, but taking it to the extreme there I hope demonstrates the
reasons Squid does not log in human local time - and no other program
recording machine activity should either.)

> ------------------------------------------
> 
> This not related with user, the same machine have no problem at all every day but sometime one request is logged as 127.0.0.1, of course exactly the same request have not problem at another time.

Until you fix the above correlation issue your statement of "exact same
request" is not possible to be known.

> More strange there is no problem at all with HTTP requests, only HTTPS
> 
> I'm not using SSLBump just basic proxy chaining 
> 
> strip_query_terms off
> logformat mylog %>a %[ui %[un [%tl] "%rm %ru HTTP/%rv" %>Hs %<st %>st %Ss:%Sh "%{User-Agent}>h"
> access_log stdio:/var/log/squid/access.log mylog
> cache_log /var/log/squid/cache.log
> logfile_daemon /var/log/squid/log_file_daemon
> log_icp_queries off
> shutdown_lifetime 1 second
> 
> coredump_dir /home/squid
> 
> pid_filename /var/run/squid.pid
> 
> follow_x_forwarded_for allow all

This is extremely dangerous. Any client can send an X-Forwarded-For
header and have Squid trust it. See
<http://www.squid-cache.org/Doc/config/follow_x_forwarded_for/> for more
details, pay attention to the "SECURITY CONSIDERATIONS" note.

The proper use of this directive is to create a src ACL that matches the
IPs Squid is supposed to be directly receiving traffic from. Then *only*
allow traffic matching that ACL to be 'followed'. As per the config
example in that documentation page.

As far as I know right now that ACL should only contain the IP
address(es) used by your e2guardian to send to Squid.

NP: When you are adjusting the e2guardian logs you may also want to
record the X-Forwaded-For headers so it records the details this
directive is trying to cope with.

> forwarded_for off
> cache_store_log none
> buffered_logs on
> 
> request_header_access X-Forwarded-For deny all
> request_header_access Via deny all
> 

FYI, the above two line are a complex and slow way of performing:

 forwarded_for delete
 via off

... especially bad since your earlier use of "forwarded_for off" is
expicitly adding an "X-Forwarded-For: unknown" header to outgoing
request traffic.

> acl_uses_indirect_client on
> log_uses_indirect_client on
> client_db off
> half_closed_clients off
> quick_abort_min 0 KB
> quick_abort_max 0 KB
> 
> Perhaps 2/5 % of requests are wrong. 
> 
> What do you think, I open a bug ticket ?

Firstly fix your squid.conf and your logging. The re-evaluate.

One other thing to consider is whether the '127.0.0.1' request is an
internal request being made by e2guardian or Squid, or some service on
the Squid machine. If it can be tracked down to any of those cases -
then it is not a bug.

Amos