[squid-users] Use ICP RTT with HTTPS request
Théo BARRAGUE
Theo.BARRAGUE.ext at boursorama.fr
Mon Sep 26 09:51:40 UTC 2022
Hello,
Thank's for answer. I increased output level and get this :
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 :
static void
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
} else if ((p = peerUserHashSelectParent(request))) {
code = USERHASH_PARENT;
#endif
} else if ((p = carpSelectParent(request))) {
code = CARP;
} else if ((p = getRoundRobinParent(request))) {
code = ROUNDROBIN_PARENT;
} else if ((p = getWeightedRoundRobinParent(request))) {
code = ROUNDROBIN_PARENT;
} else if ((p = getFirstUpParent(request))) {
code = FIRSTUP_PARENT;
} else if ((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
*/
static void
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;
} else if (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 :
static void
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 = new ACLFilledChecklist(Config.accessList.AlwaysDirect, request, NULL);
ch->al = ps->al;
ps->acl_checklist = ch;
ps->acl_checklist->nonBlockingCheck(peerCheckAlwaysDirectDone, ps);
return;
} else if (ps->never_direct == ACCESS_DUNNO) {
debugs(44, 3, "peerSelectFoo: direct = " << DirectStr[ps->direct] << " (never_direct to be checked)");
/** check never_direct; */
ACLFilledChecklist *ch = new ACLFilledChecklist(Config.accessList.NeverDirect, request, NULL);
ch->al = ps->al;
ps->acl_checklist = ch;
ps->acl_checklist->nonBlockingCheck(peerCheckNeverDirectDone, ps);
return;
} else if (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)");
} else if (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)");
} else if (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;
} else if (entry->ping_status == PING_NONE) {
peerGetSomeNeighbor(ps);
if (entry->ping_status == PING_WAITING)
return;
} else if (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;
} else if (entry->ping_status == PING_NONE) {
peerGetSomeNeighbor(ps);
if (entry->ping_status == PING_WAITING)
return;
} else if (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 = new ErrorState(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 = new TunnelStateData(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É
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20220926/cccf5fd1/attachment-0001.htm>
More information about the squid-users
mailing list