2022/09/26 09:07:52.381| 44,3| peer_select.cc(163) peerSelect: CONNECT
2022/09/26 09:07:52.381| 44,3| peer_select.cc(472) peerSelectFoo:
CONNECT api.gouv.fr
2022/09/26 09:07:52.381| 44,3| peer_select.cc(485) peerSelectFoo:
peerSelectFoo: direct = DIRECT_UNKNOWN (never_direct to be checked)
2022/09/26 09:07:52.381| 28,3| Checklist.cc(70) preCheck:
0x5653abfc4b68 checking slow rules
2022/09/26 09:07:52.381| 28,3| Ip.cc(538) match: aclIpMatchIp:
'10.25.41.21:34896' found
2022/09/26 09:07:52.381| 28,3| Acl.cc(151) matches: checked: all = 1
2022/09/26 09:07:52.381| 28,3| Acl.cc(151) matches: checked:
never_direct#1 = 1
2022/09/26 09:07:52.381| 28,3| Acl.cc(151) matches: checked:
never_direct = 1
2022/09/26 09:07:52.381| 28,3| Checklist.cc(63) markFinished:
0x5653abfc4b68 answer ALLOWED for match
2022/09/26 09:07:52.381| 28,3| Checklist.cc(163) checkCallback:
ACLChecklist::checkCallback: 0x5653abfc4b68 answer=ALLOWED
2022/09/26 09:07:52.381| 44,3| peer_select.cc(195)
peerCheckNeverDirectDone: peerCheckNeverDirectDone: ALLOWED
2022/09/26 09:07:52.381| 44,3| peer_select.cc(201)
peerCheckNeverDirectDone: direct = DIRECT_NO (never_direct allow)
2022/09/26 09:07:52.381| 44,3| peer_select.cc(472) peerSelectFoo:
CONNECT api.gouv.fr
2022/09/26 09:07:52.381| 44,3| peer_select.cc(712)
peerGetSomeParent: CONNECT api.gouv.fr
2022/09/26 09:07:52.381| 15,3| neighbors.cc(332)
getRoundRobinParent: returning NULL
2022/09/26 09:07:52.381| 15,3| neighbors.cc(382)
getWeightedRoundRobinParent: getWeightedRoundRobinParent: returning NULL
2022/09/26 09:07:52.381| 28,3| Checklist.cc(70) preCheck:
0x7ffd6220f030 checking fast rules
2022/09/26 09:07:52.381| 28,3| Ip.cc(538) match: aclIpMatchIp:
'10.25.41.21:34896' found
2022/09/26 09:07:52.381| 28,3| Acl.cc(151) matches: checked: all = 1
2022/09/26 09:07:52.381| 28,3| Acl.cc(151) matches: checked:
peer_access squid-2.inf-proxy03-d01.dc02#1 = 1
2022/09/26 09:07:52.381| 28,3| Acl.cc(151) matches: checked:
peer_access squid-2.inf-proxy03-d01.dc02 = 1
2022/09/26 09:07:52.381| 28,3| Checklist.cc(63) markFinished:
0x7ffd6220f030 answer ALLOWED for match
2022/09/26 09:07:52.381| 15,3| neighbors.cc(294) getFirstUpParent:
getFirstUpParent: returning 10.26.8.10
2022/09/26 09:07:52.381| 44,3| peer_select.cc(978) peerAddFwdServer:
adding FIRSTUP_PARENT/10.26.8.10
2022/09/26 09:07:52.381| 28,3| Checklist.cc(70) preCheck:
0x7ffd6220f0d0 checking fast rules
2022/09/26 09:07:52.381| 28,3| Ip.cc(538) match: aclIpMatchIp:
'10.25.41.21:34896' found
2022/09/26 09:07:52.381| 28,3| Acl.cc(151) matches: checked: all = 1
2022/09/26 09:07:52.382| 28,3| Acl.cc(151) matches: checked:
peer_access squid-2.inf-proxy03-d01.dc02#1 = 1
2022/09/26 09:07:52.382| 28,3| Acl.cc(151) matches: checked:
peer_access squid-2.inf-proxy03-d01.dc02 = 1
2022/09/26 09:07:52.382| 28,3| Checklist.cc(63) markFinished:
0x7ffd6220f0d0 answer ALLOWED for match
2022/09/26 09:07:52.382| 44,3| peer_select.cc(971) peerAddFwdServer:
skipping ANY_OLD_PARENT/10.26.8.10; have FIRSTUP_PARENT/10.26.8.10
2022/09/26 09:07:52.382| 28,3| Checklist.cc(70) preCheck:
0x7ffd6220f0d0 checking fast rules
2022/09/26 09:07:52.382| 28,3| Ip.cc(538) match: aclIpMatchIp:
'10.25.41.21:34896' found
2022/09/26 09:07:52.382| 28,3| Acl.cc(151) matches: checked: all = 1
2022/09/26 09:07:52.382| 28,3| Acl.cc(151) matches: checked:
peer_access squid-2.inf-proxy03-d01.dc01#1 = 1
2022/09/26 09:07:52.382| 28,3| Acl.cc(151) matches: checked:
peer_access squid-2.inf-proxy03-d01.dc01 = 1
2022/09/26 09:07:52.382| 28,3| Checklist.cc(63) markFinished:
0x7ffd6220f0d0 answer ALLOWED for match
2022/09/26 09:07:52.382| 44,3| peer_select.cc(978) peerAddFwdServer:
adding ANY_OLD_PARENT/127.0.0.1
2022/09/26 09:07:52.382| 15,3| neighbors.cc(472) getDefaultParent:
getDefaultParent: returning NULL
2022/09/26 09:07:52.382| 44,2| peer_select.cc(295)
peerSelectDnsPaths: Find IP destination for: api.gouv.fr:443' via
10.26.8.10
2022/09/26 09:07:52.382| 44,2| peer_select.cc(295)
peerSelectDnsPaths: Find IP destination for: api.gouv.fr:443' via
127.0.0.1
2022/09/26 09:07:52.382| 44,2| peer_select.cc(316)
peerSelectDnsPaths: Found sources for 'api.gouv.fr:443'
2022/09/26 09:07:52.382| 44,2| peer_select.cc(317)
peerSelectDnsPaths: always_direct = DENIED
2022/09/26 09:07:52.382| 44,2| peer_select.cc(318)
peerSelectDnsPaths: never_direct = ALLOWED
2022/09/26 09:07:52.382| 44,2| peer_select.cc(328)
peerSelectDnsPaths: cache_peer = local=0.0.0.0
remote=10.26.8.10:3129 flags=1
2022/09/26 09:07:52.382| 44,2| peer_select.cc(328)
peerSelectDnsPaths: cache_peer = local=0.0.0.0 remote=127.0.0.1:3129
flags=1
2022/09/26 09:07:52.382| 44,2| peer_select.cc(331)
peerSelectDnsPaths: timedout = 0
2022/09/26 09:07:52.382| 26,3| tunnel.cc(1249)
tunnelPeerSelectComplete: paths=2, p[0]={local=0.0.0.0
remote=10.26.8.10:3129 flags=1}, serverDest[0]={local=0.0.0.0
remote=10.26.8.10:3129 flags=1}
2022/09/26 09:07:52.382| 17,3| FwdState.cc(1369)
GetMarkingsToServer: from 0.0.0.0 netfilter mark 0
2022/09/26 09:07:52.382| 26,3| AsyncCall.cc(25) AsyncCall: The
AsyncCall tunnelConnectDone constructed, this=0x5653abf924a0 [call164]
2022/09/26 09:07:52.382| 5,3| ConnOpener.cc(43) ConnOpener: will
connect to local=0.0.0.0 remote=10.26.8.10:3129 flags=1 with 30 timeout
2022/09/26 09:07:52.382| 50,3| comm.cc(350) comm_openex:
comm_openex: Attempt open socket for: 0.0.0.0
2022/09/26 09:07:52.382| 50,3| comm.cc(393) comm_openex:
comm_openex: Opened socket local=0.0.0.0 remote=[::] FD 14 flags=1 :
family=2, type=1, protocol=6
2022/09/26 09:07:52.382| 51,3| fd.cc(198) fd_open: fd_open() FD 14
api.gouv.fr:443
2022/09/26 09:07:52.382| 5,3| ConnOpener.cc(291) createFd:
local=0.0.0.0 remote=10.26.8.10:3129 flags=1 will timeout in 30
2022/09/26 09:07:52.393| 26,3| AsyncCall.cc(92) ScheduleCall:
ConnOpener.cc(139) will call
tunnelConnectDone(local=10.25.8.10:58500 remote=10.26.8.10:3129 FD
14 flags=1, data=0x5653abfa3598) [call164]
2022/09/26 09:07:52.393| 26,3| AsyncCallQueue.cc(55) fireNext:
entering tunnelConnectDone(local=10.25.8.10:58500
remote=10.26.8.10:3129 FD 14 flags=1, data=0x5653abfa3598)
2022/09/26 09:07:52.393| 26,3| AsyncCall.cc(37) make: make call
tunnelConnectDone [call164]
2022/09/26 09:07:52.393| 14,3| Address.cc(382) lookupHostIP: Given
Non-IP 'api.gouv.fr': Name or service not known
2022/09/26 09:07:52.393| 38,3| net_db.cc(355) netdbSendPing:
netdbSendPing: pinging api.gouv.fr
2022/09/26 09:07:52.393| 37,2| IcmpSquid.cc(59) SendEcho: Socket
Closed. Aborted send to 10.26.8.10, opcode 3, len 10
2022/09/26 09:07:52.393| 26,3| tunnel.cc(1163)
tunnelRelayConnectRequest: local=10.25.8.10:58500
remote=10.26.8.10:3129 FD 14 flags=1, tunnelState=0x5653abfa3598
2022/09/26 09:07:52.393| 22,3| refresh.cc(648) getMaxAge: getMaxAge:
'api.gouv.fr:443'
2022/09/26 09:07:52.393| 11,2| tunnel.cc(1177)
tunnelRelayConnectRequest: Tunnel Server REQUEST:
local=10.25.8.10:58500 remote=10.26.8.10:3129 FD 14 flags=1:
----------
CONNECT api.gouv.fr:443 HTTP/1.1
User-Agent: curl/7.52.1
Host: api.gouv.fr:443
X-Forwarded-For: unknown
Cache-Control: max-age=259200
Connection: close
----------
2022/09/26 09:07:52.393| 5,3| comm.cc(559) commSetConnTimeout:
local=10.25.8.10:58500 remote=10.26.8.10:3129 FD 14 flags=1 timeout 900
2022/09/26 09:07:52.393| 5,3| comm.cc(559) commSetConnTimeout:
local=10.25.8.10:58500 remote=10.26.8.10:3129 FD 14 flags=1 timeout 900
2022/09/26 09:07:52.393| 26,3| AsyncCallQueue.cc(57) fireNext:
leaving tunnelConnectDone(local=10.25.8.10:58500
remote=10.26.8.10:3129 FD 14 flags=1, data=0x5653abfa3598)
2022/09/26 09:07:52.393| 5,3| IoCallback.cc(116) finish: called for
local=10.25.8.10:58500 remote=10.26.8.10:3129 FD 14 flags=1 (0, 0)
2022/09/26 09:07:52.393| 26,3| tunnel.cc(929)
tunnelConnectReqWriteDone: local=10.25.8.10:58500
remote=10.26.8.10:3129 FD 14 flags=1, flag=0
It seems /peerGetSomeParent/ is called and this method never issue an ICP :
staticvoid
peerGetSomeParent(ps_state * ps)
{
CachePeer *p;
HttpRequest *request = ps->request;
hier_code code = HIER_NONE;
debugs(44, 3, request->method << ' ' << request->url.host());
if (ps->direct == DIRECT_YES)
return;
if ((p = peerSourceHashSelectParent(request))) {
code = SOURCEHASH_PARENT;
#if USE_AUTH
} elseif ((p = peerUserHashSelectParent(request))) {
code = USERHASH_PARENT;
#endif
} elseif ((p = carpSelectParent(request))) {
code = CARP;
} elseif ((p = getRoundRobinParent(request))) {
code = ROUNDROBIN_PARENT;
} elseif ((p = getWeightedRoundRobinParent(request))) {
code = ROUNDROBIN_PARENT;
} elseif ((p = getFirstUpParent(request))) {
code = FIRSTUP_PARENT;
} elseif ((p = getDefaultParent(request))) {
code = DEFAULT_PARENT;
}
if (code != HIER_NONE) {
peerAddFwdServer(ps, p, code);
}
}
Instead of /peerGetSomeNeighbor/ :
/**
* peerGetSomeNeighbor
*
* Selects a neighbor (parent or sibling) based on one of the
* following methods:
* Cache Digests
* CARP
* ICMP Netdb RTT estimates
* ICP/HTCP queries
*/
staticvoid
peerGetSomeNeighbor(ps_state * ps)
{
StoreEntry *entry = ps->entry;
HttpRequest *request = ps->request;
CachePeer *p;
hier_code code = HIER_NONE;
assert(entry->ping_status == PING_NONE);
if (ps->direct == DIRECT_YES) {
entry->ping_status = PING_DONE;
return;
}
#if USE_CACHE_DIGESTS
if ((p = neighborsDigestSelect(request))) {
if (neighborType(p, request->url) == PEER_PARENT)
code = CD_PARENT_HIT;
else
code = CD_SIBLING_HIT;
} else
#endif
if ((p = netdbClosestParent(request))) {
code = CLOSEST_PARENT;
} elseif (peerSelectIcpPing(request, ps->direct, entry)) {
debugs(44, 3, "peerSelect: Doing ICP pings");
ps->ping.start = current_time;
ps->ping.n_sent = neighborsUdpPing(request,
entry,
peerHandlePingReply,
ps,
&ps->ping.n_replies_expected,
&ps->ping.timeout);
if (ps->ping.n_sent == 0)
debugs(44, DBG_CRITICAL, "WARNING: neighborsUdpPing returned 0");
debugs(44, 3, "peerSelect: " << ps->ping.n_replies_expected <<
" ICP replies expected, RTT " << ps->ping.timeout <<
" msec");
if (ps->ping.n_replies_expected > 0) {
entry->ping_status = PING_WAITING;
eventAdd("peerPingTimeout",
peerPingTimeout,
ps,
0.001 * ps->ping.timeout,
0);
return;
}
}
if (code != HIER_NONE) {
assert(p);
peerAddFwdServer(ps, p, code);
}
entry->ping_status = PING_DONE;
}
These functions are called from /peerSelectFoo/ :
staticvoid
peerSelectFoo(ps_state * ps)
{
if (!cbdataReferenceValid(ps->callback_data)) {
debugs(44, 3, "Aborting peer selection. Parent Job went away.");
delete ps;
return;
}
StoreEntry *entry = ps->entry;
HttpRequest *request = ps->request;
debugs(44, 3, request->method << ' ' << request->url.host());
/** If we don't know whether DIRECT is permitted ... */
if (ps->direct == DIRECT_UNKNOWN) {
if (ps->always_direct == ACCESS_DUNNO) {
debugs(44, 3, "peerSelectFoo: direct = " << DirectStr[ps->direct] <<
" (always_direct to be checked)");
/** check always_direct; */
ACLFilledChecklist *ch =
newACLFilledChecklist(Config.accessList.AlwaysDirect, request, NULL);
ch->al = ps->al;
ps->acl_checklist = ch;
ps->acl_checklist->nonBlockingCheck(peerCheckAlwaysDirectDone, ps);
return;
} elseif (ps->never_direct == ACCESS_DUNNO) {
debugs(44, 3, "peerSelectFoo: direct = " << DirectStr[ps->direct] <<
" (never_direct to be checked)");
/** check never_direct; */
ACLFilledChecklist *ch =
newACLFilledChecklist(Config.accessList.NeverDirect, request, NULL);
ch->al = ps->al;
ps->acl_checklist = ch;
ps->acl_checklist->nonBlockingCheck(peerCheckNeverDirectDone, ps);
return;
} elseif (request->flags.noDirect) {
/** if we are accelerating, direct is not an option. */
ps->direct = DIRECT_NO;
debugs(44, 3, "peerSelectFoo: direct = " << DirectStr[ps->direct] <<
" (forced non-direct)");
} elseif (request->flags.loopDetected) {
/** if we are in a forwarding-loop, direct is not an
option. */
ps->direct = DIRECT_YES;
debugs(44, 3, "peerSelectFoo: direct = " << DirectStr[ps->direct] <<
" (forwarding loop detected)");
} elseif (peerCheckNetdbDirect(ps)) {
ps->direct = DIRECT_YES;
debugs(44, 3, "peerSelectFoo: direct = " << DirectStr[ps->direct] <<
" (checkNetdbDirect)");
} else {
ps->direct = DIRECT_MAYBE;
debugs(44, 3, "peerSelectFoo: direct = " << DirectStr[ps->direct] <<
" (default)");
}
debugs(44, 3, "peerSelectFoo: direct = " << DirectStr[ps->direct]);
}
if (!entry || entry->ping_status == PING_NONE)
peerSelectPinned(ps);
if (entry == NULL) {
(void) 0;
} elseif (entry->ping_status == PING_NONE) {
peerGetSomeNeighbor(ps);
if (entry->ping_status == PING_WAITING)
return;
} elseif (entry->ping_status == PING_WAITING) {
peerGetSomeNeighborReplies(ps);
entry->ping_status = PING_DONE;
}
switch (ps->direct) {
case DIRECT_YES:
peerGetSomeDirect(ps);
break;
case DIRECT_NO:
peerGetSomeParent(ps);
peerGetAllParents(ps);
break;
default:
if (Config.onoff.prefer_direct)
peerGetSomeDirect(ps);
if (request->flags.hierarchical ||
!Config.onoff.nonhierarchical_direct) {
peerGetSomeParent(ps);
peerGetAllParents(ps);
}
if (!Config.onoff.prefer_direct)
peerGetSomeDirect(ps);
break;
}
// resolve the possible peers
peerSelectDnsPaths(ps);
}
/entry/ is /null/ so /peerGetSomeNeighbor/ is never called :
if (entry == NULL) {
(void) 0;
} elseif (entry->ping_status == PING_NONE) {
peerGetSomeNeighbor(ps);
if (entry->ping_status == PING_WAITING)
return;
} elseif (entry->ping_status == PING_WAITING) {
peerGetSomeNeighborReplies(ps);
entry->ping_status = PING_DONE;
}
Because of /tunnelStart/ method :
void
tunnelStart(ClientHttpRequest * http)
{
debugs(26, 3, HERE);
/* Create state structure. */
TunnelStateData *tunnelState = NULL;
ErrorState *err = NULL;
HttpRequest *request = http->request;
char *url = http->uri;
/*
* client_addr.isNoAddr() indicates this is an "internal" request
* from peer_digest.c, asn.c, netdb.c, etc and should always
* be allowed. yuck, I know.
*/
if (Config.accessList.miss && !request->client_addr.isNoAddr()) {
/*
* Check if this host is allowed to fetch MISSES from us
(miss_access)
* default is to allow.
*/
ACLFilledChecklist ch(Config.accessList.miss, request, NULL);
ch.al = http->al;
ch.src_addr = request->client_addr;
ch.my_addr = request->my_addr;
ch.syncAle(request, http->log_uri);
if (ch.fastCheck().denied()) {
debugs(26, 4, HERE << "MISS access forbidden.");
err = newErrorState(ERR_FORWARDING_DENIED,
Http::scForbidden, request);
http->al->http.code = Http::scForbidden;
errorSend(http->getConn()->clientConnection, err);
return;
}
}
debugs(26, 3, request->method << ' ' << url << ' ' <<
request->http_ver);
++statCounter.server.all.requests;
++statCounter.server.other.requests;
tunnelState = newTunnelStateData(http);
#if USE_DELAY_POOLS
//server.setDelayId called from tunnelConnectDone after server
side connection established
#endif
peerSelect(&(tunnelState->serverDestinations), request, http->al,
NULL,
tunnelPeerSelectComplete,
tunnelState);
}
Any ideas ?
Regards,
Théo BARRAGUÉ
