|
I will take a look, thank's for help 🙂
Regards,
Théo BARRAGUÉ
From: Alex Rousskov <rousskov@xxxxxxxxxxxxxxxxxxxxxxx>
Sent: Monday, September 26, 2022 3:25 PM To: Théo BARRAGUE <Theo.BARRAGUE.ext@xxxxxxxxxxxxx>; squid-users@xxxxxxxxxxxxxxxxxxxxx <squid-users@xxxxxxxxxxxxxxxxxxxxx> Cc: Olivier HANESSE <Olivier.HANESSE@xxxxxxxxxxxxx> Subject: Re: [squid-users] Use ICP RTT with HTTPS request 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="" [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=""> > 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=""> > 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 = ""> > > /* > * 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É |
_______________________________________________ squid-users mailing list squid-users@xxxxxxxxxxxxxxxxxxxxx http://lists.squid-cache.org/listinfo/squid-users
