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

[FredB]

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"

------------------------------------------

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.
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
forwarded_for off
cache_store_log none
buffered_logs on

request_header_access X-Forwarded-For deny all
request_header_access Via deny all

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 ?

Fred