<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
</head>
<body text="#464646" bgcolor="#FFFFFF">
<font face="Arial">Hi, <br>
<br>
Take time to enable the debug log an parsing the 10GB of logs<br>
<br>
Here the piece of code:<br>
<br>
2021/11/01 16:50:48.786 kid1| 33,5| AsyncCall.cc(30) AsyncCall:
The AsyncCall Server::clientWriteDone constructed,
this=0x55849cb132b0 [call252226641]<br>
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<br>
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<br>
2021/11/01 16:50:48.786 kid1| 20,3| store.cc(467) unlock:
store_client::copy unlocking key 115EFC00000000009915000001000000
e:=sXIV/0x55849dfec190*4<br>
2021/11/01 16:50:48.786 kid1| 20,3| store.cc(467) unlock:
ClientHttpRequest::doCallouts-sslBumpNeeded unlocking key
115EFC00000000009915000001000000 e:=sXIV/0x55849dfec190*3<br>
2021/11/01 16:50:48.786 kid1| 28,4| FilledChecklist.cc(67)
~ACLFilledChecklist: ACLFilledChecklist destroyed 0x55849316fc88<br>
2021/11/01 16:50:48.786 kid1| 28,4| Checklist.cc(197)
~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed
0x55849316fc88<br>
2021/11/01 16:50:48.786 kid1| 84,5| helper.cc(1319)
StatefulGetFirstAvailable: StatefulGetFirstAvailable: Running
servers 4<br>
2021/11/01 16:50:48.786 kid1| 84,5| helper.cc(1344)
StatefulGetFirstAvailable: StatefulGetFirstAvailable: returning
srv-Hlpr469<br>
2021/11/01 16:50:48.786 kid1| 5,4| AsyncCall.cc(30) AsyncCall: The
AsyncCall helperStatefulHandleRead constructed,
this=0x55848ad88730 [call252226642]<br>
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<br>
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<br>
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)<br>
2021/11/01 16:50:48.786 kid1| 1,5| CodeContext.cc(60) Entering:
master25501192<br>
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)<br>
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]<br>
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.<br>
2021/11/01 16:50:48.786 kid1| 5,5| Write.cc(89) HandleWrite:
write() returns 4529<br>
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)<br>
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]<br>
2021/11/01 16:50:48.787 kid1| 1,5| CodeContext.cc(60) Entering:
master25501192<br>
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)<br>
2021/11/01 16:50:48.787 kid1| 93,3| AsyncCall.cc(42) make: make
call Http::Tunneler::handleReadyRead [call252202273]<br>
2021/11/01 16:50:48.787 kid1| 93,3| AsyncJob.cc(123) callStart:
Http::Tunneler status in: [state:w FD 85 job26507207]<br>
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<br>
2021/01 16:50:48.787 kid1| 24,5| Tokenizer.cc(27) consume:
consuming 1 bytes<br>
2021/11/01 16:50:48.787 kid1| 24,5| Tokenizer.cc(27) consume:
consuming 3 bytes<br>
2021/11/01 16:50:48.787 kid1| 24,5| Tokenizer.cc(27) consume:
consuming 1 bytes<br>
2021/11/01 16:50:48.787 kid1| 24,5| Tokenizer.cc(27) consume:
consuming 19 bytes<br>
2021/11/01 16:50:48.787 kid1| 24,5| Tokenizer.cc(27) consume:
consuming 2 bytes<br>
2021/11/01 16:50:48.787 kid1| 74,5| ResponseParser.cc(224) parse:
status-line: retval 1<br>
2021/11/01 16:50:48.787 kid1| 74,5| ResponseParser.cc(225) parse:
status-line: proto HTTP/1.1<br>
2021/11/01 16:50:48.787 kid1| 74,5| ResponseParser.cc(226) parse:
status-line: status-code 503<br>
2021/11/01 16:50:48.787 kid1| 74,5| ResponseParser.cc(227) parse:
status-line: reason-phrase Service Unavailable<br>
2021/11/01 16:50:48.787 kid1| 74,5| ResponseParser.cc(228) parse:
Parser: bytes processed=34<br>
2021/11/01 16:50:48.787 kid1| 74,5| Parser.cc(192) grabMimeBlock:
mime header (0-171) {Server: squid^M<br>
Mime-Version: 1.0^M<br>
Date: Mon, 01 Nov 2021 15:50:48 GMT^M<br>
Content-Type: text/html;charset=utf-8^M<br>
Content-Length: 7577^M<br>
X-Squid-Error: ERR_CONNECT_FAIL 110^M<br>
^M<br>
}<br>
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<br>
2021/11/01 16:50:48.787 kid1| 11,2| HttpTunneler.cc(326)
handleResponse: Tunnel Server RESPONSE:<br>
---------<br>
<!DOCTYPE HTML><br>
<html><br>
<head><br>
<title>ERROR: The requested URL could not be
retrieved</title><br>
<script type="text/javascript" language="javascript"
src="/squid-internal-static/icons/silk/jquery-1.8.3.js"></s----------<br>
2021/11/01 16:50:48.787 kid1| 83,3| HttpTunneler.cc(345)
bailOnResponseError: unsupported CONNECT response status code
[state:w FD 85 job26507207]<br>
2021/11/01 16:50:48.787 kid1| TCP connection to 127.0.0.1/2320
failed<br>
current master transaction: master25501192<br>
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]<br>
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]<br>
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<br>
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<br>
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<br>
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<br>
2021/11/01 16:50:48.787 kid1| 5,3| comm.cc(871) _comm_close: start
closing FD 85 by Connection.cc:89<br>
2021/11/01 16:50:48.787 kid1| 5,3| comm.cc(556)
commUnsetFdTimeout: Remove timeout for FD 85<br>
2021/11/01 16:50:48.787 kid1| 5,5| comm.cc(737)
commCallCloseHandlers: commCallCloseHandlers: FD 85<br>
2021/11/01 16:50:48.787 kid1| 5,4| AsyncCall.cc(30) AsyncCall: The
AsyncCall comm_close_complete constructed, this=0x558484c02d30
[call252226643]<br>
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]<br>
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]<br>
2021/11/01 16:50:48.803 kid1| 83,5| HttpTunneler.cc(52) ~Tunneler:
Http::Tunneler destructed, this=0x55849b747e18<br>
2021/11/01 16:50:48.803 kid1| 93,5| AsyncJob.cc(40) ~AsyncJob:
AsyncJob destructed, this=0x55849b747ec8 type=Http::Tunneler
[job26507207]<br>
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)<br>
<br>
</font><br>
<div class="moz-cite-prefix">Le 01/11/2021 à 15:53, Alex Rousskov a
écrit :<br>
</div>
<blockquote type="cite"
cite="mid:f29e9040-61c3-f91f-b2a5-6849b99964fd@measurement-factory.com">
<pre class="moz-quote-pre" wrap="">On 11/1/21 7:55 AM, David Touzeau wrote:
</pre>
<blockquote type="cite">
<pre class="moz-quote-pre" wrap="">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
</pre>
</blockquote>
<pre class="moz-quote-pre" wrap="">
</pre>
<blockquote type="cite">
<pre class="moz-quote-pre" wrap="">cache_peer 127.0.0.1 parent 2320 0 name=Peer11 no-query default
connect-timeout=3 connect-fail-limit=5 no-tproxy
</pre>
</blockquote>
<pre class="moz-quote-pre" wrap="">
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.
</pre>
</blockquote>
<br>
</body>
</html>