[squid-users] Squid intermittently not sending host header to peer

Wed Sep 5 09:04:57 UTC 2018

Thanks Amos,

I updated both servers to Squid 4.2 and the issue persisted. I understand
what you're saying about the configuration and lack of security - in
production, this will be in place. I was removed to try and resolve the
issue we encountered.

After adding the additional configuration to debug_options, I noticed that
the issue occurs when the same socket is re-used for a second request.

I believe what's happening is that Squid is 'forgetting' that it's not
connecting to the origin when a persistent connection is in use.
Setting server_persistent_connections off resolves the issue, albeit in a
way that will likely harm performance.

Here is an excerpt from cache.log on Squid1

Successful Request:
2018/09/05 08:20:19.401 kid1| 11,2| client_side.cc(1274) parseHttpRequest:
HTTP Client local=1.1.1.1:3128 remote=3.3.3.3:52210 FD 14 flags=1
2018/09/05 08:20:19.401 kid1| 11,2| client_side.cc(1278) parseHttpRequest:
HTTP Client REQUEST:
---------
GET http://redacted.com/messages/391/ HTTP/1.1
Host: redacted.com
Proxy-Connection: keep-alive
Cache-Control: max-age=0
Upgrade-Insecure-Requests: 1
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36
(KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36
Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
Accept-Encoding: gzip, deflate
Accept-Language: en-US,en;q=0.9,en-GB;q=0.8
Cookie: __cfduid=redacted; csrftoken=redacted; sessionid=redacted;
_ga=redacted
AlexaToolbar-ALX_NS_PH: AlexaToolbar/alx-4.0.3

----------
2018/09/05 08:20:19.401 kid1| 44,3| peer_select.cc(161) peerSelect:
e:=IV/0x21f7e50*2 http://redacted.com/messages/391/
2018/09/05 08:20:19.401 kid1| 44,3| peer_select.cc(458) peerSelectFoo: GET
redacted.com
2018/09/05 08:20:19.401 kid1| 44,3| peer_select.cc(463) peerSelectFoo:
peerSelectFoo: direct = DIRECT_UNKNOWN (always_direct to be checked)
2018/09/05 08:20:19.401 kid1| 44,3| peer_select.cc(218)
peerCheckAlwaysDirectDone: peerCheckAlwaysDirectDone: DENIED
2018/09/05 08:20:19.401 kid1| 44,3| peer_select.cc(458) peerSelectFoo: GET
redacted.com
2018/09/05 08:20:19.401 kid1| 44,3| peer_select.cc(471) peerSelectFoo:
peerSelectFoo: direct = DIRECT_UNKNOWN (never_direct to be checked)
2018/09/05 08:20:19.401 kid1| 44,3| peer_select.cc(195)
peerCheckNeverDirectDone: peerCheckNeverDirectDone: ALLOWED
2018/09/05 08:20:19.401 kid1| 44,3| peer_select.cc(201)
peerCheckNeverDirectDone: direct = DIRECT_NO (never_direct allow)
2018/09/05 08:20:19.401 kid1| 44,3| peer_select.cc(458) peerSelectFoo: GET
redacted.com
2018/09/05 08:20:19.401 kid1| 44,3| peer_select.cc(134) peerSelectIcpPing:
peerSelectIcpPing: http://redacted.com/messages/391/
2018/09/05 08:20:19.401 kid1| 44,3| peer_select.cc(145) peerSelectIcpPing:
peerSelectIcpPing: counted 0 neighbors
2018/09/05 08:20:19.401 kid1| 44,3| peer_select.cc(698) peerGetSomeParent:
GET redacted.com
2018/09/05 08:20:19.401 kid1| 44,3| peer_select.cc(964) peerAddFwdServer:
adding FIRSTUP_PARENT/2.2.2.2
2018/09/05 08:20:19.401 kid1| 44,3| peer_select.cc(958) peerAddFwdServer:
skipping ANY_OLD_PARENT/2.2.2.2; have FIRSTUP_PARENT/2.2.2.2
2018/09/05 08:20:19.401 kid1| 44,3| peer_select.cc(958) peerAddFwdServer:
skipping DEFAULT_PARENT/2.2.2.2; have FIRSTUP_PARENT/2.2.2.2
2018/09/05 08:20:19.401 kid1| 44,2| peer_select.cc(281) peerSelectDnsPaths:
Find IP destination for: http://redacted.com/messages/391/' via 2.2.2.2
2018/09/05 08:20:19.401 kid1| 44,2| peer_select.cc(302) peerSelectDnsPaths:
Found sources for 'http://redacted.com/messages/391/'
2018/09/05 08:20:19.401 kid1| 44,2| peer_select.cc(303)
peerSelectDnsPaths:   always_direct = DENIED
2018/09/05 08:20:19.401 kid1| 44,2| peer_select.cc(304)
peerSelectDnsPaths:    never_direct = ALLOWED
2018/09/05 08:20:19.401 kid1| 44,2| peer_select.cc(314)
peerSelectDnsPaths:      cache_peer = local=0.0.0.0 remote=2.2.2.2:3128
flags=1
2018/09/05 08:20:19.401 kid1| 44,2| peer_select.cc(317)
peerSelectDnsPaths:        timedout = 0
2018/09/05 08:20:19.401 kid1| 44,3| peer_select.cc(103) ~ps_state:
http://redacted.com/messages/391/
2018/09/05 08:20:19.401 kid1| 51,3| fd.cc(198) fd_open: fd_open() FD 9
2018/09/05 08:20:19.402 kid1| 11,2| http.cc(2260) sendRequest: HTTP Server
local=1.1.1.1:45688 remote=2.2.2.2:3128 FD 9 flags=1
2018/09/05 08:20:19.402 kid1| 11,2| http.cc(2261) sendRequest: HTTP Server
REQUEST:
---------
GET http://redacted.com/messages/391/ HTTP/1.1
Upgrade-Insecure-Requests: 1
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36
(KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36
Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
Accept-Encoding: gzip, deflate
Accept-Language: en-US,en;q=0.9,en-GB;q=0.8
Cookie: __cfduid=redacted; csrftoken=redacted; sessionid=redacted;
_ga=redacted
AlexaToolbar-ALX_NS_PH: AlexaToolbar/alx-4.0.3
Host: redacted.com
Via: 1.1 smtp01 (squid/4.2)
X-Forwarded-For: 3.3.3.3
Cache-Control: max-age=0
Connection: keep-alive

Failed Request, note: FD 9 is not closed/opened between these requests:
2018/09/05 08:20:22.124 kid1| 11,2| client_side.cc(1274) parseHttpRequest:
HTTP Client local=1.1.1.1:3128 remote=3.3.3.3:52219 FD 15 flags=1
2018/09/05 08:20:22.124 kid1| 11,2| client_side.cc(1278) parseHttpRequest:
HTTP Client REQUEST:
---------
GET http://redacted.com/messages/391/ HTTP/1.1
Host: redacted.com
Proxy-Connection: keep-alive
Cache-Control: max-age=0
Upgrade-Insecure-Requests: 1
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36
(KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36
Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
Accept-Encoding: gzip, deflate
Accept-Language: en-US,en;q=0.9,en-GB;q=0.8
Cookie: __cfduid=redacted; csrftoken=redacted; sessionid=redacted;
_ga=redacted
AlexaToolbar-ALX_NS_PH: AlexaToolbar/alx-4.0.3

----------
2018/09/05 08:20:22.124 kid1| 44,3| peer_select.cc(161) peerSelect:
e:=IV/0x21f7e50*2 http://redacted.com/messages/391/
2018/09/05 08:20:22.124 kid1| 44,3| peer_select.cc(458) peerSelectFoo: GET
redacted.com
2018/09/05 08:20:22.124 kid1| 44,3| peer_select.cc(463) peerSelectFoo:
peerSelectFoo: direct = DIRECT_UNKNOWN (always_direct to be checked)
2018/09/05 08:20:22.124 kid1| 44,3| peer_select.cc(218)
peerCheckAlwaysDirectDone: peerCheckAlwaysDirectDone: DENIED
2018/09/05 08:20:22.124 kid1| 44,3| peer_select.cc(458) peerSelectFoo: GET
redacted.com
2018/09/05 08:20:22.124 kid1| 44,3| peer_select.cc(471) peerSelectFoo:
peerSelectFoo: direct = DIRECT_UNKNOWN (never_direct to be checked)
2018/09/05 08:20:22.124 kid1| 44,3| peer_select.cc(195)
peerCheckNeverDirectDone: peerCheckNeverDirectDone: ALLOWED
2018/09/05 08:20:22.124 kid1| 44,3| peer_select.cc(201)
peerCheckNeverDirectDone: direct = DIRECT_NO (never_direct allow)
2018/09/05 08:20:22.124 kid1| 44,3| peer_select.cc(458) peerSelectFoo: GET
redacted.com
2018/09/05 08:20:22.124 kid1| 44,3| peer_select.cc(134) peerSelectIcpPing:
peerSelectIcpPing: http://redacted.com/messages/391/
2018/09/05 08:20:22.124 kid1| 44,3| peer_select.cc(145) peerSelectIcpPing:
peerSelectIcpPing: counted 0 neighbors
2018/09/05 08:20:22.124 kid1| 44,3| peer_select.cc(698) peerGetSomeParent:
GET redacted.com
2018/09/05 08:20:22.124 kid1| 44,3| peer_select.cc(964) peerAddFwdServer:
adding FIRSTUP_PARENT/2.2.2.2
2018/09/05 08:20:22.124 kid1| 44,3| peer_select.cc(958) peerAddFwdServer:
skipping ANY_OLD_PARENT/2.2.2.2; have FIRSTUP_PARENT/2.2.2.2
2018/09/05 08:20:22.124 kid1| 44,3| peer_select.cc(958) peerAddFwdServer:
skipping DEFAULT_PARENT/2.2.2.2; have FIRSTUP_PARENT/2.2.2.2
2018/09/05 08:20:22.124 kid1| 44,2| peer_select.cc(281) peerSelectDnsPaths:
Find IP destination for: http://redacted.com/messages/391/' via 2.2.2.2
2018/09/05 08:20:22.124 kid1| 44,2| peer_select.cc(302) peerSelectDnsPaths:
Found sources for 'http://redacted.com/messages/391/'
2018/09/05 08:20:22.124 kid1| 44,2| peer_select.cc(303)
peerSelectDnsPaths:   always_direct = DENIED
2018/09/05 08:20:22.124 kid1| 44,2| peer_select.cc(304)
peerSelectDnsPaths:    never_direct = ALLOWED
2018/09/05 08:20:22.124 kid1| 44,2| peer_select.cc(314)
peerSelectDnsPaths:      cache_peer = local=0.0.0.0 remote=2.2.2.2:3128
flags=1
2018/09/05 08:20:22.124 kid1| 44,2| peer_select.cc(317)
peerSelectDnsPaths:        timedout = 0
2018/09/05 08:20:22.125 kid1| 44,3| peer_select.cc(103) ~ps_state:
http://redacted.com/messages/391/
2018/09/05 08:20:22.125 kid1| 11,2| http.cc(2260) sendRequest: HTTP Server
local=1.1.1.1:45688 remote=2.2.2.2:3128 FD 9 flags=1
2018/09/05 08:20:22.125 kid1| 11,2| http.cc(2261) sendRequest: HTTP Server
REQUEST:
---------
GET /messages/391/ HTTP/1.1
Upgrade-Insecure-Requests: 1
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36
(KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36
Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
Accept-Encoding: gzip, deflate
Accept-Language: en-US,en;q=0.9,en-GB;q=0.8
Cookie: __cfduid=redacted; csrftoken=redacted; sessionid=redacted;
_ga=redacted
AlexaToolbar-ALX_NS_PH: AlexaToolbar/alx-4.0.3
Host: redacted.com
Via: 1.1 smtp01 (squid/4.2)
X-Forwarded-For: 3.3.3.3
Cache-Control: max-age=0
Connection: keep-alive
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20180905/50f7f79d/attachment-0001.html>