[squid-users] Use ICP RTT with HTTPS request
Alex Rousskov
rousskov at measurement-factory.com
Mon Sep 26 13:25:58 UTC 2022
On 9/26/22 05:51, Théo BARRAGUE wrote:
> entry is null so peerGetSomeNeighbor is never called
I did not check all the details, but it looks like Squid ICMP code
(ab)uses StoreEntry-linked metadata. Basic CONNECT tunnels lack
StoreEntry because they are not reading/writing data from/to Store. The
combination is essentially a Squid bug -- basic CONNECT tunnels cannot
use ICMP features.
Most likely, the correct long-term solution here is to remove StoreEntry
use from ICMP code -- I bet that code does not have a genuine need for
Store access and should store its essential metadata elsewhere. That
proper solution will require non-trivial development. For a possibly
simpler workaround, one could consider creating a temporary StoreEntry
object for ICMP use (instead of disabling ICMP for entry-less use cases).
https://wiki.squid-cache.org/SquidFaq/AboutSquid#How_to_add_a_new_Squid_feature.2C_enhance.2C_of_fix_something.3F
HTH,
Alex.
> 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É
More information about the squid-users
mailing list