[squid-users] url_rewrite (with rewrite-url): PinnedConnection failure results in total failure
Andreas Weigel
andreas.weigel at securepoint.de
Tue Jun 18 15:34:57 UTC 2024
Hi,
updating from a (security-patched) Squidv4 to Squidv6, problems
occurred with regard to url_rewrite Feature used for
content-filtering. The external helper uses "OK rewrite-url=" to point
to a custom page that Squid used to retrieve and present to the
Client. This used to work with SSL-Interception, but it does no longer
in Squidv6. It does not matter in that regard if peek+splice or
stare+bump is used, Squid always fails with ERR_CANNOT_FORWARD.
Digging into the codebase, I can see that with v4, Squid first checked
the validity of any pinned connection and if none is found, still
retrieves the "replacement page". It seems that
daf80700130b6f98256b75c511916d1a79b23597 changed the logic in that
regard, causing the FwdState to fail hard and not try any of the
remaining peer options (see log excerpts below), although I can see
that it added two selections (PINNED and HIER_DIRECT).
I understand that using the rewrite-url mechanism is discouraged, but
would still like to understand if this is intended behavior (and the
reasoning behind it) or if this has to be considered a bug. Any
pointers to additional ressources or explanations to understand the
behavior would be much appreciated.
Kind regards,
Andreas Weigel
PS:
log excerpt from squid-v4.16 (successful rewrite-url)
2024/06/14 14:46:30.750 kid1| 61,2| /client_side_request.cc(1266)
clientRedirectDone: URL-rewriter diverts URL from https://youtube.com/
to
http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f&shortener=
2024/06/14 14:46:30.750 kid1| 33,5| /store_client.cc(317) doCopy:
store_client::doCopy: co: 0, hi: 0
2024/06/14 14:46:30.750 kid1| 17,3| /FwdState.cc(340) Start:
'http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f&shortener='
2024/06/14 14:46:30.750 kid1| 17,2| /FwdState.cc(142) FwdState:
Forwarding client request local=172.217.13.206:443
remote=192.168.180.10:33836 FD 11 flags=33,
url=http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f
2024/06/14 14:46:30.750 kid1| 17,3| /FwdState.cc(149) FwdState:
FwdState constructed, this=0x559ad7e89b88
2024/06/14 14:46:30.750 kid1| 44,3| /peer_select.cc(161) peerSelect:
e:=XIV/0x559ad7e89500*2
http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f&shortener=
2024/06/14 14:46:30.750 kid1| 44,3| /peer_select.cc(472)
peerSelectFoo: GET 127.0.0.1
2024/06/14 14:46:30.750 kid1| 44,3| /peer_select.cc(477)
peerSelectFoo: peerSelectFoo: direct = DIRECT_UNKNOWN (always_direct
to be checked)
2024/06/14 14:46:30.750 kid1| 44,3| /peer_select.cc(218)
peerCheckAlwaysDirectDone: peerCheckAlwaysDirectDone: ALLOWED
2024/06/14 14:46:30.750 kid1| 44,3| /peer_select.cc(224)
peerCheckAlwaysDirectDone: direct = DIRECT_YES (always_direct allow)
2024/06/14 14:46:30.750 kid1| 44,3| /peer_select.cc(472)
peerSelectFoo: GET 127.0.0.1
2024/06/14 14:46:30.750 kid1| 33,7| /client_side.cc(4119)
validatePinnedConnection: local=192.168.41.35:47842
remote=172.217.13.206:443 FD 13 flags=1
2024/06/14 14:46:30.750 kid1| 33,3| /client_side.cc(4154)
unpinConnection: local=192.168.41.35:47842 remote=172.217.13.206:443
FD 13 flags=1
2024/06/14 14:46:30.750 kid1| 33,5| src/base/AsyncCall.cc(54) cancel:
will not call ConnStateData::clientPinnedConnectionClosed [call63]
because comm_remove_close_handler
2024/06/14 14:46:30.750 kid1| 33,3| src/base/AsyncCall.cc(54) cancel:
will not call ConnStateData::clientPinnedConnectionRead [call64]
because comm_read_cancel
2024/06/14 14:46:30.750 kid1| 33,3| src/base/AsyncCall.cc(54) cancel:
will not call ConnStateData::clientPinnedConnectionRead [call64] also
because comm_read_cancel
2024/06/14 14:46:30.750 kid1| 44,3| /peer_select.cc(978)
peerAddFwdServer: adding HIER_DIRECT#127.0.0.1
2024/06/14 14:46:30.750 kid1| 44,2| /peer_select.cc(295)
peerSelectDnsPaths: Find IP destination for:
http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f&shortener=' via
127.0.0.1
2024/06/14 14:46:30.750 kid1| 44,2| /peer_select.cc(316)
peerSelectDnsPaths: Found sources for
'http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f&shortener='
2024/06/14 14:46:30.750 kid1| 44,2| /peer_select.cc(317)
peerSelectDnsPaths: always_direct = ALLOWED
2024/06/14 14:46:30.750 kid1| 44,2| /peer_select.cc(318)
peerSelectDnsPaths: never_direct = DENIED
2024/06/14 14:46:30.750 kid1| 44,2| /peer_select.cc(322)
peerSelectDnsPaths: DIRECT = local=0.0.0.0
remote=127.0.0.1:8081 flags=1
2024/06/14 14:46:30.750 kid1| 44,2| /peer_select.cc(331)
peerSelectDnsPaths: timedout = 0
2024/06/14 14:46:30.750 kid1| 17,3| /FwdState.cc(418)
startConnectionOrFail:
http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f&shortener=
2024/06/14 14:46:30.750 kid1| 17,3| /FwdState.cc(832) connectStart:
fwdConnectStart:
http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f&shortener=
2024/06/14 14:46:30.750 kid1| 17,3| src/base/AsyncCall.cc(25)
AsyncCall: The AsyncCall fwdConnectDoneWrapper constructed,
this=0x559ad7e16a00 [call81]
2024/06/14 14:46:30.750 kid1| 44,3| /peer_select.cc(103) ~ps_state:
http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f&shortener=
2024/06/14 14:46:30.750 kid1| 17,3| src/base/AsyncCall.cc(92)
ScheduleCall: ../../../squid-4.16/src/comm/ConnOpener.cc(139) will
call fwdConnectDoneWrapper(local=127.0.0.1:45660 remote=127.0.0.1:8081
FD 13 flags=1, data=0x559ad7e89b88) [call81]
2024/06/14 14:46:30.750 kid1| 17,3| src/base/AsyncCallQueue.cc(55)
fireNext: entering fwdConnectDoneWrapper(local=127.0.0.1:45660
remote=127.0.0.1:8081 FD 13 flags=1, data=0x559ad7e89b88)
2024/06/14 14:46:30.750 kid1| 17,3| src/base/AsyncCall.cc(37) make:
make call fwdConnectDoneWrapper [call81]
2024/06/14 14:46:30.750 kid1| 17,3| /FwdState.cc(706) connectDone:
local=127.0.0.1:45660 remote=127.0.0.1:8081 FD 13 flags=1:
'http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f&shortener='
log excerpt for the same setup from squid-v6.9 (Squid reporting
ERR_CANNOT_FORWARD)
024/06/14 14:59:40.463 kid1| 61,5| /redirect.cc(83)
redirectHandleReply: reply={result=OK, notes={rewrite-url:
http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f&shortener=; cf-info:
DENIED,proxy%2dnet%5cnoyoutub
2024/06/14 14:59:40.463 kid1| 61,2| /client_side_request.cc(1236)
clientRedirectDone: URL-rewriter diverts URL from https://youtube.com/
to
http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f&shortener=
2024/06/14 14:59:40.463 kid1| 33,5| /store_client.cc(374) doCopy:
0x55a9d80fc678 into ioBuf(@0, len=4096, 0x55a9d8127770) hi: 0
objectLen: -1 past_answers: 0
2024/06/14 14:59:40.463 kid1| 17,3| /FwdState.cc(373) Start:
'http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f&shortener='
2024/06/14 14:59:40.463 kid1| 17,2| /FwdState.cc(133) FwdState:
Forwarding client request conn19 local=172.217.13.206:443
remote=192.168.180.10:55036 FD 11 flags=33,
url=http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2
2024/06/14 14:59:40.463 kid1| 17,3| /FwdState.cc(140) FwdState:
FwdState constructed, this=0x55a9d812ceb8
2024/06/14 14:59:40.463 kid1| 17,4| src/base/AsyncCall.cc(29)
AsyncCall: The AsyncCall FwdState::Abort constructed,
this=0x55a9d80fc790 [call90]
2024/06/14 14:59:40.463 kid1| 44,3| /peer_select.cc(309) peerSelect:
e:=XIV/0x55a9d80fc5f0*3
http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f&shortener=
2024/06/14 14:59:40.463 kid1| 44,3| /peer_select.cc(612) selectMore:
GET 127.0.0.1
2024/06/14 14:59:40.463 kid1| 44,3| /peer_select.cc(617) selectMore:
direct = DIRECT_UNKNOWN (always_direct to be checked)
2024/06/14 14:59:40.463 kid1| 44,3| /peer_select.cc(373)
checkAlwaysDirectDone: ALLOWED
2024/06/14 14:59:40.463 kid1| 44,3| /peer_select.cc(379)
checkAlwaysDirectDone: direct = DIRECT_YES (always_direct allow)
2024/06/14 14:59:40.463 kid1| 44,3| /peer_select.cc(612) selectMore:
GET 127.0.0.1
2024/06/14 14:59:40.463 kid1| 44,3| /peer_select.cc(1102)
addSelection: adding PINNED#127.0.0.1
2024/06/14 14:59:40.463 kid1| 44,3| /peer_select.cc(1102)
addSelection: adding HIER_DIRECT#127.0.0.1
2024/06/14 14:59:40.463 kid1| 44,2| /peer_select.cc(1176) handlePath:
PeerSelector2 found pinned, destination #1 for
http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f&shortener=
2024/06/14 14:59:40.463 kid1| 44,2| /peer_select.cc(1180) handlePath:
always_direct = ALLOWED
2024/06/14 14:59:40.463 kid1| 44,2| /peer_select.cc(1181) handlePath:
never_direct = DENIED
2024/06/14 14:59:40.463 kid1| 44,2| /peer_select.cc(1182) handlePath:
timedout = 0
2024/06/14 14:59:40.463 kid1| 33,7| /client_side.cc(3954)
borrowPinnedConnection: conn30 local=192.168.41.35:50322
remote=172.217.13.206:443 ORIGINAL_DST FD 13 flags=1
2024/06/14 14:59:40.463 kid1| 33,3| /client_side.cc(3997)
unpinConnection: conn30 local=192.168.41.35:50322
remote=172.217.13.206:443 ORIGINAL_DST FD 13 flags=1
2024/06/14 14:59:40.463 kid1| 33,5| src/base/AsyncCall.cc(58) cancel:
will not call ConnStateData::clientPinnedConnectionClosed [call73]
because comm_remove_close_handler
2024/06/14 14:59:40.463 kid1| 33,3| src/base/AsyncCall.cc(58) cancel:
will not call ConnStateData::clientPinnedConnectionRead [call74]
because comm_read_cancel
2024/06/14 14:59:40.463 kid1| 33,3| src/base/AsyncCall.cc(58) cancel:
will not call ConnStateData::clientPinnedConnectionRead [call74] also
because comm_read_cancel
2024/06/14 14:59:40.465 kid1| 17,3| /FwdState.cc(471) fail:
ERR_CANNOT_FORWARD "Service Unavailable"
http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f&shortener=
2024/06/14 14:59:40.465 kid1| 17,3| /FwdState.cc(185) stopAndDestroy:
for pinned connection failure
2024/06/14 14:59:40.465 kid1| 44,3| /peer_select.cc(1149)
interestedInitiator: PeerSelector2 initiator lost interest
2024/06/14 14:59:40.465 kid1| 44,3| /peer_select.cc(405)
selectionAborted: Aborting peer selection: Initiator gone or lost
interest.
2024/06/14 14:59:40.465 kid1| 44,3| /peer_select.cc(241)
~PeerSelector:
http://127.0.0.1:8081/?cat=&cat_all=&action=URLLIST&srv=&url=https%3a%2f%2fyoutube%2ecom%2f&shortener=
2024/06/14 14:59:40.465 kid1| 17,3| /FwdState.cc(310) ~FwdState:
FwdState destructor start
2024/06/14 14:59:40.466 kid1| 33,5| /store_client.cc(374) doCopy:
0x55a9d80fc678 into ioBuf(@0, len=4096, 0x55a9d8127770) hi: 148495
objectLen: -1 past_answers: 0
2024/06/14 14:59:40.466 kid1| 33,5| /store_client.cc(422) doCopy: just
send HTTP headers: 207
2024/06/14 14:59:40.466 kid1| 17,4| src/base/AsyncCall.cc(58) cancel:
will not call FwdState::Abort [call90] because FwdState object
destructed
2024/06/14 14:59:40.466 kid1| 17,3| /FwdState.cc(332) ~FwdState:
FwdState destructed, this=0x55a9d812ceb8
--
Andreas Weigel
UTM Backend Developer
Securepoint GmbH
Bleckeder Landstraße 28
D-21337 Lüneburg
https://www.securepoint.de
Geschäftsführer: René Hofmann
Amtsgericht Lüneburg HRB 1776
More information about the squid-users
mailing list