[squid-users] Use ICP RTT with HTTPS request

Théo BARRAGUE Theo.BARRAGUE.ext at boursorama.fr
Tue Sep 27 11:38:22 UTC 2022


I will take a look, thank's for help 🙂

Regards,
Théo BARRAGUÉ

________________________________
From: Alex Rousskov <rousskov at measurement-factory.com>
Sent: Monday, September 26, 2022 3:25 PM
To: Théo BARRAGUE <Theo.BARRAGUE.ext at boursorama.fr>; squid-users at lists.squid-cache.org <squid-users at lists.squid-cache.org>
Cc: Olivier HANESSE <Olivier.HANESSE at boursorama.fr>
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=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É

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20220927/fee3ba0f/attachment-0001.htm>


More information about the squid-users mailing list