[squid-users] Squid 5.2 Peer parent TCP connection to x.x.x.x/x failed
David Touzeau
david at articatech.com
Tue Nov 2 14:40:00 UTC 2021
Hi,
Take time to enable the debug log an parsing the 10GB of logs
Here the piece of code:
2021/11/01 16:50:48.786 kid1| 33,5| AsyncCall.cc(30) AsyncCall: The
AsyncCall Server::clientWriteDone constructed, this=0x55849cb132b0
[call252226641]
2021/11/01 16:50:48.786 kid1| 5,5| Write.cc(37) Write: conn9813869
local=10.33.50.22:3128 remote=10.33.50.109:50157 FD 95 flags=1: sz 4529:
asynCall 0x55849cb132b0*1
2021/11/01 16:50:48.786 kid1| 5,5| ModEpoll.cc(118) SetSelect: FD 95,
type=2, handler=1, client_data=0x7f1caaa1a2d0, timeout=0
2021/11/01 16:50:48.786 kid1| 20,3| store.cc(467) unlock:
store_client::copy unlocking key 115EFC00000000009915000001000000
e:=sXIV/0x55849dfec190*4
2021/11/01 16:50:48.786 kid1| 20,3| store.cc(467) unlock:
ClientHttpRequest::doCallouts-sslBumpNeeded unlocking key
115EFC00000000009915000001000000 e:=sXIV/0x55849dfec190*3
2021/11/01 16:50:48.786 kid1| 28,4| FilledChecklist.cc(67)
~ACLFilledChecklist: ACLFilledChecklist destroyed 0x55849316fc88
2021/11/01 16:50:48.786 kid1| 28,4| Checklist.cc(197) ~ACLChecklist:
ACLChecklist::~ACLChecklist: destroyed 0x55849316fc88
2021/11/01 16:50:48.786 kid1| 84,5| helper.cc(1319)
StatefulGetFirstAvailable: StatefulGetFirstAvailable: Running servers 4
2021/11/01 16:50:48.786 kid1| 84,5| helper.cc(1344)
StatefulGetFirstAvailable: StatefulGetFirstAvailable: returning srv-Hlpr469
2021/11/01 16:50:48.786 kid1| 5,4| AsyncCall.cc(30) AsyncCall: The
AsyncCall helperStatefulHandleRead constructed, this=0x55848ad88730
[call252226642]
2021/11/01 16:50:48.786 kid1| 5,5| Read.cc(58) comm_read_base:
comm_read, queueing read for conn9811325 local=[::] remote=[::] FD 49
flags=1; asynCall 0x55848ad88730*1
2021/11/01 16:50:48.786 kid1| 5,5| ModEpoll.cc(118) SetSelect: FD 49,
type=1, handler=1, client_data=0x7f1caaa18a20, timeout=0
2021/11/01 16:50:48.786 kid1| 5,4| AsyncCallQueue.cc(61) fireNext:
leaving helperStatefulHandleRead(conn9811325 local=[::] remote=[::] FD
49 flags=1, data=0x5584982781c8, size=300, buf=0x558498dde700)
2021/11/01 16:50:48.786 kid1| 1,5| CodeContext.cc(60) Entering:
master25501192
2021/11/01 16:50:48.786 kid1| 5,3| IoCallback.cc(112) finish: called for
conn9812727 local=127.0.0.1:23408 remote=127.0.0.1:2320 FIRSTUP_PARENT
FD 85 flags=1 (0, 0)
2021/11/01 16:50:48.786 kid1| 93,3| AsyncCall.cc(97) ScheduleCall:
IoCallback.cc(131) will call Http::Tunneler::handleReadyRead(conn9812727
local=127.0.0.1:23408 remote=127.0.0.1:2320 FIRSTUP_PARENT FD 85
flags=1, data=0x55849b747e18) [call252202273]
2021/11/01 16:50:48.786 kid1| 5,5| Write.cc(69) HandleWrite: conn9813869
local=10.33.50.22:3128 remote=10.33.50.109:50157 FD 95 flags=1: off 0,
sz 4529.
2021/11/01 16:50:48.786 kid1| 5,5| Write.cc(89) HandleWrite: write()
returns 4529
2021/11/01 16:50:48.787 kid1| 5,3| IoCallback.cc(112) finish: called for
conn9813869 local=10.33.50.22:3128 remote=10.33.50.109:50157 FD 95
flags=1 (0, 0)
2021/11/01 16:50:48.787 kid1| 33,5| AsyncCall.cc(97) ScheduleCall:
IoCallback.cc(131) will call Server::clientWriteDone(conn9813869
local=10.33.50.22:3128 remote=10.33.50.109:50157 FD 95 flags=1,
data=0x55849e4c8218) [call252226641]
2021/11/01 16:50:48.787 kid1| 1,5| CodeContext.cc(60) Entering:
master25501192
2021/11/01 16:50:48.787 kid1| 93,3| AsyncCallQueue.cc(59) fireNext:
entering Http::Tunneler::handleReadyRead(conn9812727
local=127.0.0.1:23408 remote=127.0.0.1:2320 FIRSTUP_PARENT FD 85
flags=1, data=0x55849b747e18)
2021/11/01 16:50:48.787 kid1| 93,3| AsyncCall.cc(42) make: make call
Http::Tunneler::handleReadyRead [call252202273]
2021/11/01 16:50:48.787 kid1| 93,3| AsyncJob.cc(123) callStart:
Http::Tunneler status in: [state:w FD 85 job26507207]
2021/11/01 16:50:48.787 kid1| 5,3| Read.cc(93) ReadNow: conn9812727
local=127.0.0.1:23408 remote=127.0.0.1:2320 FIRSTUP_PARENT FD 85
flags=1, size 65535, retval 7782, errno 0
2021/01 16:50:48.787 kid1| 24,5| Tokenizer.cc(27) consume: consuming 1 bytes
2021/11/01 16:50:48.787 kid1| 24,5| Tokenizer.cc(27) consume: consuming
3 bytes
2021/11/01 16:50:48.787 kid1| 24,5| Tokenizer.cc(27) consume: consuming
1 bytes
2021/11/01 16:50:48.787 kid1| 24,5| Tokenizer.cc(27) consume: consuming
19 bytes
2021/11/01 16:50:48.787 kid1| 24,5| Tokenizer.cc(27) consume: consuming
2 bytes
2021/11/01 16:50:48.787 kid1| 74,5| ResponseParser.cc(224) parse:
status-line: retval 1
2021/11/01 16:50:48.787 kid1| 74,5| ResponseParser.cc(225) parse:
status-line: proto HTTP/1.1
2021/11/01 16:50:48.787 kid1| 74,5| ResponseParser.cc(226) parse:
status-line: status-code 503
2021/11/01 16:50:48.787 kid1| 74,5| ResponseParser.cc(227) parse:
status-line: reason-phrase Service Unavailable
2021/11/01 16:50:48.787 kid1| 74,5| ResponseParser.cc(228) parse:
Parser: bytes processed=34
2021/11/01 16:50:48.787 kid1| 74,5| Parser.cc(192) grabMimeBlock: mime
header (0-171) {Server: squid^M
Mime-Version: 1.0^M
Date: Mon, 01 Nov 2021 15:50:48 GMT^M
Content-Type: text/html;charset=utf-8^M
Content-Length: 7577^M
X-Squid-Error: ERR_CONNECT_FAIL 110^M
^M
}
2021/11/01 16:50:48.787 kid1| 11,2| HttpTunneler.cc(323) handleResponse:
Tunnel Server conn9812727 local=127.0.0.1:23408 remote=127.0.0.1:2320
FIRSTUP_PARENT FD 85 flags=1
2021/11/01 16:50:48.787 kid1| 11,2| HttpTunneler.cc(326) handleResponse:
Tunnel Server RESPONSE:
---------
<!DOCTYPE HTML>
<html>
<head>
<title>ERROR: The requested URL could not be retrieved</title>
<script type="text/javascript" language="javascript"
src="/squid-internal-static/icons/silk/jquery-1.8.3.js"></s----------
2021/11/01 16:50:48.787 kid1| 83,3| HttpTunneler.cc(345)
bailOnResponseError: unsupported CONNECT response status code [state:w
FD 85 job26507207]
2021/11/01 16:50:48.787 kid1| TCP connection to 127.0.0.1/2320 failed
current master transaction: master25501192
2021/11/01 16:50:48.787 kid1| 83,5| HttpTunneler.cc(404) callBack:
conn9812727 local=127.0.0.1:23408 remote=127.0.0.1:2320 FIRSTUP_PARENT
FD 85 flags=1 [state:w FD 85 job26507207]
2021/11/01 16:50:48.787 kid1| 5,4| AsyncCall.cc(97) ScheduleCall:
HttpTunneler.cc(409) will call
TunnelStateData::tunnelEstablishmentDone([SquidErr:46 503]) [call252202269]
2021/11/01 16:50:48.787 kid1| 5,5| comm.cc(1042)
comm_remove_close_handler: comm_remove_close_handler: FD 85,
AsyncCall=0x558485cc45e0*2
2021/11/01 16:50:48.787 kid1| 9,5| AsyncCall.cc(60) cancel: will not
call Http::Tunneler::handleConnectionClosure [call252202270] because
comm_remove_close_handler
2021/11/01 16:50:48.787 kid1| 5,3| comm.cc(595) commUnsetConnTimeout:
Remove timeout for conn9812727 local=127.0.0.1:23408
remote=127.0.0.1:2320 FIRSTUP_PARENT FD 85 flags=1
2021/11/01 16:50:48.787 kid1| 5,3| comm.cc(569) commSetConnTimeout:
conn9812727 local=127.0.0.1:23408 remote=127.0.0.1:2320 FIRSTUP_PARENT
FD 85 flags=1 timeout -1
2021/11/01 16:50:48.787 kid1| 5,3| comm.cc(871) _comm_close: start
closing FD 85 by Connection.cc:89
2021/11/01 16:50:48.787 kid1| 5,3| comm.cc(556) commUnsetFdTimeout:
Remove timeout for FD 85
2021/11/01 16:50:48.787 kid1| 5,5| comm.cc(737) commCallCloseHandlers:
commCallCloseHandlers: FD 85
2021/11/01 16:50:48.787 kid1| 5,4| AsyncCall.cc(30) AsyncCall: The
AsyncCall comm_close_complete constructed, this=0x558484c02d30
[call252226643]
2021/11/01 16:50:48.787 kid1| 5,4| AsyncCall.cc(97) ScheduleCall:
comm.cc(942) will call comm_close_complete(FD 85) [call252226643]
2021/11/01 16:50:48.803 kid1| 93,5| AsyncJob.cc(139) callEnd:
Http::Tunneler::handleReadyRead(conn9812727 local=127.0.0.1:23408
remote=127.0.0.1:2320 FIRSTUP_PARENT flags=1, data=0x55849b747e18) ends
job [state:wx job26507207]
2021/11/01 16:50:48.803 kid1| 83,5| HttpTunneler.cc(52) ~Tunneler:
Http::Tunneler destructed, this=0x55849b747e18
2021/11/01 16:50:48.803 kid1| 93,5| AsyncJob.cc(40) ~AsyncJob: AsyncJob
destructed, this=0x55849b747ec8 type=Http::Tunneler [job26507207]
2021/11/01 16:50:48.803 kid1| 93,3| AsyncCallQueue.cc(61) fireNext:
leaving Http::Tunneler::handleReadyRead(conn9812727
local=127.0.0.1:23408 remote=127.0.0.1:2320 FIRSTUP_PARENT flags=1,
data=0x55849b747e18)
Le 01/11/2021 à 15:53, Alex Rousskov a écrit :
> On 11/1/21 7:55 AM, David Touzeau wrote:
>
>> The Squid uses the loopback as a parent.
>>
>> The same problem occurs:
>> 06:19:47 kid1| TCP connection to 127.0.0.1/2320 failed
>> 06:15:13 kid1| TCP connection to 127.0.0.1/2320 failed
>> 06:14:41 kid1| TCP connection to 127.0.0.1/2320 failed
>> 06:14:38 kid1| TCP connection to 127.0.0.1/2320 failed
>> 06:13:15 kid1| TCP connection to 127.0.0.1/2320 failed
>> 06:11:23 kid1| TCP connection to 127.0.0.1/2320 failed
>> cache_peer 127.0.0.1 parent 2320 0 name=Peer11 no-query default
>> connect-timeout=3 connect-fail-limit=5 no-tproxy
> It is impossible to tell for sure what is going on because Squid does
> not (unfortunately; yet) report the exact reason behind these connection
> establishment failures or even the context in which a failure has
> occurred. You may be able to tell more by collecting/analyzing packet
> captures. Developers may be able to tell more if you share, say, ALL,5
> debugging logs that show what led to the failure report.
>
> Alex.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20211102/6cc3266b/attachment.htm>
More information about the squid-users
mailing list