[squid-users] Squid returns 500 on rapidly changing DNS records
Alex Rousskov
rousskov at measurement-factory.com
Fri Feb 17 18:55:51 UTC 2023
On 2/17/23 13:24, Maciej Leks wrote:
> I understand your last question but it's hard me to answer clearly -
> yes/no.
Yes, it is a difficult question to answer. Logging DNS traffic with
tcpdump might help, but it does require some non-trivial work to
correlate everything. For now, without that or similar additional
information, it is easy for us to assume that you are just seeing the
effects of DNS responses without IP addresses.
There is another way to confirm or reject a bug claim. Share a
compressed ALL,9 cache.log while reproducing the problem with as few
transactions as possible (privately if needed).
https://wiki.squid-cache.org/SquidFaq/BugReporting#debugging-a-single-transaction
> Instead of this let me show you this log:
> I suppose the A/AAAA records should already be in the DNS, but the
> last resort squid gave up.
Why do you think that the IP addresses should already be (or appear) in
the parent Squid IP cache during these logged transactions?
Cheers,
Alex.
> 17/Feb/2023:17:16:21 +0100 1676650581.827 103 100.121.11.70
> 100.121.11.70 NONE_NONE/500 0 CONNECT
> scala-module-5515.scratch.lightning.force.com:443 - HIER_NONE/- -
> 17/Feb/2023:17:16:22 +0100 1676650582.297 0 100.121.11.70
> 100.121.11.70 NONE_NONE/500 0 CONNECT
> scala-module-5515.scratch.lightning.force.com:443 - HIER_NONE/- -
> 17/Feb/2023:17:16:22 +0100 1676650582.893 0 100.121.11.70
> 100.121.11.70 NONE_NONE/500 0 CONNECT
> scala-module-5515.scratch.lightning.force.com:443 - HIER_NONE/- -
> 17/Feb/2023:17:16:23 +0100 1676650583.625 0 100.121.11.70
> 100.121.11.70 NONE_NONE/500 0 CONNECT
> scala-module-5515.scratch.lightning.force.com:443 - HIER_NONE/- -
> 17/Feb/2023:17:16:23 +0100 1676650583.711 0 100.121.11.70
> 100.121.11.70 NONE_NONE/500 0 CONNECT
> scala-module-5515.scratch.lightning.force.com:443 - HIER_NONE/- -
> 17/Feb/2023:17:16:25 +0100 1676650585.073 0 100.121.11.70
> 100.121.11.70 NONE_NONE/500 0 CONNECT
> scala-module-5515.scratch.lightning.force.com:443 - HIER_NONE/- -
> 17/Feb/2023:17:16:25 +0100 1676650585.799 0 100.121.11.70
> 100.121.11.70 NONE_NONE/500 0 CONNECT
> scala-module-5515.scratch.lightning.force.com:443 - HIER_NONE/- -
> 17/Feb/2023:17:16:25 +0100 1676650585.882 0 100.121.11.70
> 100.121.11.70 NONE_NONE/500 0 CONNECT
> scala-module-5515.scratch.lightning.force.com:443 - HIER_NONE/- -
> 17/Feb/2023:17:16:26 +0100 1676650586.258 0 100.121.11.70
> 100.121.11.70 NONE_NONE/500 0 CONNECT
> scala-module-5515.scratch.lightning.force.com:443 - HIER_NONE/- -
> 17/Feb/2023:17:16:26 +0100 1676650586.995 0 100.121.11.70
> 100.121.11.70 NONE_NONE/500 0 CONNECT
> scala-module-5515.scratch.lightning.force.com:443 - HIER_NONE/- -
> 17/Feb/2023:17:16:28 +0100 1676650588.468 0 100.121.11.70
> 100.121.11.70 NONE_NONE/500 0 CONNECT
> scala-module-5515.scratch.lightning.force.com:443 - HIER_NONE/- -
> 17/Feb/2023:17:16:29 +0100 1676650589.159 0 100.121.11.70
> 100.121.11.70 NONE_NONE/500 0 CONNECT
> scala-module-5515.scratch.lightning.force.com:443 - HIER_NONE/- -
> 17/Feb/2023:17:16:29 +0100 1676650589.560 0 100.121.11.70
> 100.121.11.70 NONE_NONE/500 0 CONNECT
> scala-module-5515.scratch.lightning.force.com:443 - HIER_NONE/- -
> 17/Feb/2023:17:16:30 +0100 1676650590.319 0 100.121.11.70
> 100.121.11.70 NONE_NONE/500 0 CONNECT
> scala-module-5515.scratch.lightning.force.com:443 - HIER_NONE/- -
>
> This is the last resort parent squid and the 100.121.11.70 is our
> downstream squid (child). I understand it as follows, thanks to
> connect_retries set to 10 (here we have more than 10 tries) try to
> connect.
> pt., 17 lut 2023 o 17:46 Alex Rousskov
> <rousskov at measurement-factory.com> napisał(a):
>>
>> On 2/17/23 09:31, Maciej Leks wrote:
>>
>>> We have being facing the 500 error codes in our squids (v5.7) when it
>>> comes to communicate with Salesforce DNS for ephemeral hosts
>>
>>> A cs128-fra.fra.r.salesforce.com. 30s 85.222.154.211
>>> A cs128-fra.fra.r.salesforce.com. 30s 160.8.252.83
>>> A cs128-fra.fra.r.salesforce.com. 30s 85.222.152.83
>>
>> 30s TTLs will naturally limit the time Squid can cache these IPs for.
>>
>>
>>> From time to time DNS answers only sending SOA record (no A,AAAA records)
>>
>> Squid will fail to forward traffic if Squid does not have the
>> destination IP address cached and its new DNS lookup returns no IPv4 or
>> IPv6 records. Moreover, I am not 100% sure -- needs checking/testing --
>> but Squid might cache that "negative" no-IPs result (see
>> negative_dns_ttl that defaults to 60 seconds).
>>
>> Do all 500 error cases correspond to DNS answers without IPs? In other
>> words, is there a 500 error case after a DNS answer with IPs (within 29
>> seconds from each other)?
>>
>> HTH,
>>
>> Alex.
>> P.S. Sorry for not answering your questions below directly. I do not
>> have the time to document what Squid debugging logs mean, and I
>> recommend sharing them without analysis (by non-developers).
>>
>>
>>> dig:
>>> IP address of sagittarius-oatmilk-722.scratch.my.salesforce.com is
>>> cs128.salesforce.com.
>>> cs128-fra.salesforce.com.
>>> cs128-fra.fra.r.salesforce.com.
>>> 160.8.255.83
>>> 160.8.249.83
>>> 85.222.154.211
>>> Failed to resolve sagittarius-oatmilk-722.scratch.my.salesforce.com
>>> Failed to resolve sagittarius-oatmilk-722.scratch.my.salesforce.com
>>> Failed to resolve sagittarius-oatmilk-722.scratch.my.salesforce.com
>>> Failed to resolve sagittarius-oatmilk-722.scratch.my.salesforce.com
>>> IP address of sagittarius-oatmilk-722.scratch.my.salesforce.com is
>>> cs128.salesforce.com.
>>> cs128-fra.salesforce.com.
>>> cs128-fra.fra.r.salesforce.com.
>>> 85.222.154.211
>>> 160.8.255.83
>>> 160.8.249.83
>>> IP address of sagittarius-oatmilk-722.scratch.my.salesforce.com is
>>> cs128.salesforce.com.
>>> cs128-fra.salesforce.com.
>>> cs128-fra.fra.r.salesforce.com.
>>> 160.8.253.83
>>>
>>> Squid outputs then:
>>> 16/Feb/2023:13:45:54 +0100 1676551554.420 107 100.113.24.84
>>> 100.113.24.84 NONE_NONE/500 0 CONNECT
>>> canal-trailblazer-1066.scratch.my.salesforce.com:443 - HIER_NONE/- - -
>>> - "/CN=gitlab-executor-stg.navio-services.opl-gcp.int"
>>> 16/Feb/2023:13:51:55 +0100 1676551915.973 82 100.113.25.178
>>> 100.113.25.178 NONE_NONE/500 0 CONNECT
>>> pumpkinspice-pisces-6588.scratch.my.salesforce.com:443 - HIER_NONE/- -
>>> - - "/CN=gitlab-executor-stg.navio-services.opl-gcp.int"
>>> 16/Feb/2023:13:52:44 +0100 1676551964.285 95 100.113.24.84
>>> 100.113.24.84 NONE_NONE/500 0 CONNECT
>>> trailblazer-builder-1043.scratch.file.force.com:443 - HIER_NONE/- - -
>>> Mozilla/5.0%20(X11;%20Linux%20x86_64)%20AppleWebKit/537.36%20(KHTML,%20like%20Gecko)%20HeadlessChrome/109.0.5414.74%20Safari/537.36
>>> "/CN=gitlab-executor-stg.navio-services.opl-gcp.int"
>>> 16/Feb/2023:13:56:11 +0100 1676552171.392 43 100.121.10.183
>>> 100.121.10.183 NONE_NONE/500 0 CONNECT
>>> pistachio-vente-806.scratch.my.salesforce.com:443 - HIER_NONE/- - - -
>>> "/CN=gitlab-executor-stg.navio-services.opl-gcp.int"
>>>
>>>
>>> Child squids get then (the same situation but different case):
>>> 17/Feb/2023:13:18:49 +0000 1676639929.989 88 100.121.10.104
>>> TCP_TUNNEL/500 0 CONNECT
>>> beans-goldengate-9524.scratch.my.salesforce.com:443 -
>>> ANY_OLD_PARENT/100.112.36.14 -
>>>
>>> Such a situation but not the same case from squid internals point of
>>> view I list below:
>>> 74,5| RequestParser.cc(377) doParse: request-line: retval 1:
>>> line={266, data='CONNECT
>>> baybridge-module-8155.scratch.my.salesforce.com:443 HTTP/1.1
>>> Host: baybridge-module-8155.scratch.my.salesforce.com:443
>>> 2023/02/15 15:44:24.223 kid1| 74,5| RequestParser.cc(379) doParse:
>>> request-line: url: baybridge-module-8155.scratch.my.salesforce.com:443
>>> 2023/02/15 15:44:24.223 kid1| 74,5| Parser.cc(192) grabMimeBlock: mime
>>> header (0-196) {Host:
>>> baybridge-module-8155.scratch.my.salesforce.com:443
>>> CONNECT baybridge-module-8155.scratch.my.salesforce.com:443 HTTP/1.1
>>> Host: baybridge-module-8155.scratch.my.salesforce.com:443
>>> Host: baybridge-module-8155.scratch.my.salesforce.com:443
>>> 2023/02/15 15:44:24.223 kid1| 23,3| Uri.cc(441) parse: Split URL
>>> 'baybridge-module-8155.scratch.my.salesforce.com:443' into proto='',
>>> host='baybridge-module-8155.scratch.my.salesforce.com', port='443',
>>> path=''
>>> 2023/02/15 15:44:24.223 kid1| 14,3| Address.cc(389) lookupHostIP:
>>> Given Non-IP 'baybridge-module-8155.scratch.my.salesforce.com': Name
>>> or service not known
>>> 2023/02/15 15:44:24.223 kid1| 33,5| Http1Server.cc(193)
>>> buildHttpRequest: normalize 1 Host header using
>>> baybridge-module-8155.scratch.my.salesforce.com:443
>>> 2023/02/15 15:44:24.224 kid1| 85,3| client_side_request.cc(637)
>>> hostHeaderVerify: validate
>>> host=baybridge-module-8155.scratch.my.salesforce.com, port=443,
>>> portStr=443
>>> 2023/02/15 15:44:24.224 kid1| 14,3| ipcache.cc(722)
>>> ipcache_gethostbyname: ipcache_gethostbyname:
>>> 'baybridge-module-8155.scratch.my.salesforce.com', flags=1
>>> 2023/02/15 15:44:24.224 kid1| 14,3| ipcache.cc(310) ipcacheRelease:
>>> ipcacheRelease: Releasing entry for
>>> 'baybridge-module-8155.scratch.my.salesforce.com'
>>> 2023/02/15 15:44:24.224 kid1| 14,3| Address.cc(389) lookupHostIP:
>>> Given Non-IP 'baybridge-module-8155.scratch.my.salesforce.com': Name
>>> or service not known
>>> 2023/02/15 15:44:24.224 kid1| 14,4| ipcache.cc(600)
>>> ipcache_nbgethostbyname:
>>> baybridge-module-8155.scratch.my.salesforce.com
>>> 2023/02/15 15:44:24.224 kid1| 14,3| Address.cc(389) lookupHostIP:
>>> Given Non-IP 'baybridge-module-8155.scratch.my.salesforce.com': Name
>>> or service not known
>>> 2023/02/15 15:44:24.224 kid1| 14,5| ipcache.cc(660)
>>> ipcache_nbgethostbyname_: ipcache_nbgethostbyname: MISS for
>>> 'baybridge-module-8155.scratch.my.salesforce.com'
>>> 2023/02/15 15:44:24.224 kid1| 78,3| dns_internal.cc(1788) idnsALookup:
>>> idnsALookup: buf is 65 bytes for
>>> baybridge-module-8155.scratch.my.salesforce.com, id = 0x9c4
>>> 2023/02/15 15:44:24.224 kid1| 78,3| dns_internal.cc(1724)
>>> idnsSendSlaveAAAAQuery: buf is 65 bytes for
>>> baybridge-module-8155.scratch.my.salesforce.com, id = 0x5b5e
>>> 2023/02/15 15:44:24.224 kid1| 28,3| DestinationIp.cc(78) match: can't
>>> yet compare 'to_localhost' ACL for
>>> baybridge-module-8155.scratch.my.salesforce.com
>>> 2023/02/15 15:44:24.224 kid1| 14,4| ipcache.cc(600)
>>> ipcache_nbgethostbyname:
>>> baybridge-module-8155.scratch.my.salesforce.com
>>> 2023/02/15 15:44:24.224 kid1| 14,3| Address.cc(389) lookupHostIP:
>>> Given Non-IP 'baybridge-module-8155.scratch.my.salesforce.com': Name
>>> or service not known
>>> 2023/02/15 15:44:24.224 kid1| 14,5| ipcache.cc(660)
>>> ipcache_nbgethostbyname_: ipcache_nbgethostbyname: MISS for
>>> 'baybridge-module-8155.scratch.my.salesforce.com'
>>> 2023/02/15 15:44:24.247 kid1| 14,3| ipcache.cc(456) latestError: DNS
>>> error while resolving baybridge-module-8155.scratch.my.salesforce.com:
>>> No DNS records
>>> 2023/02/15 15:44:24.248 kid1| 14,3| ipcache.cc(456) latestError: DNS
>>> error while resolving baybridge-module-8155.scratch.my.salesforce.com:
>>> No DNS records
>>> 2023/02/15 15:44:24.282 kid1| 14,3| ipcache.cc(477) ipcacheParse: 3
>>> answers for baybridge-module-8155.scratch.my.salesforce.com
>>> 2023/02/15 15:44:24.282 kid1| 14,3| ipcache.cc(576)
>>> ipcacheHandleReply: done with
>>> baybridge-module-8155.scratch.my.salesforce.com: [no cached IPs]
>>> 2023/02/15 15:44:24.282 kid1| 14,3| ipcache.cc(477) ipcacheParse: 3
>>> answers for baybridge-module-8155.scratch.my.salesforce.com
>>> 2023/02/15 15:44:24.282 kid1| 14,3| ipcache.cc(576)
>>> ipcacheHandleReply: done with
>>> baybridge-module-8155.scratch.my.salesforce.com: [no cached IPs]
>>> 2023/02/15 15:44:24.282 kid1| 14,3| ipcache.cc(310) ipcacheRelease:
>>> ipcacheRelease: Releasing entry for
>>> 'baybridge-module-8155.scratch.my.salesforce.com'
>>> 2023/02/15 15:44:24.282 kid1| 14,3| ipcache.cc(722)
>>> ipcache_gethostbyname: ipcache_gethostbyname:
>>> 'baybridge-module-8155.scratch.my.salesforce.com', flags=1
>>> 2023/02/15 15:44:24.282 kid1| 28,3| DomainData.cc(110) match:
>>> aclMatchDomainList: checking
>>> 'baybridge-module-8155.scratch.my.salesforce.com'
>>> 2023/02/15 15:44:24.282 kid1| 28,3| DomainData.cc(115) match:
>>> aclMatchDomainList: 'baybridge-module-8155.scratch.my.salesforce.com'
>>> NOT found
>>> 2023/02/15 15:44:24.283 kid1| 28,3| DomainData.cc(110) match:
>>> aclMatchDomainList: checking
>>> 'baybridge-module-8155.scratch.my.salesforce.com'
>>> 2023/02/15 15:44:24.283 kid1| 28,3| DomainData.cc(115) match:
>>> aclMatchDomainList: 'baybridge-module-8155.scratch.my.salesforce.com'
>>> found
>>> 2023/02/15 15:44:24.283 kid1| 85,2| client_side_request.cc(745)
>>> clientAccessCheckDone: The request CONNECT
>>> baybridge-module-8155.scratch.my.salesforce.com:443 is ALLOWED; last
>>> ACL checked: gitlab-executor-stg-dst
>>> 2023/02/15 15:44:24.284 kid1| 85,2| client_side_request.cc(745)
>>> clientAccessCheckDone: The request CONNECT
>>> baybridge-module-8155.scratch.my.salesforce.com:443 is ALLOWED; last
>>> ACL checked: gitlab-executor-stg-dst
>>> 2023/02/15 15:44:24.284 kid1| 85,4| client_side_request.cc(1514)
>>> processRequest: CONNECT
>>> baybridge-module-8155.scratch.my.salesforce.com:443
>>> 2023/02/15 15:44:24.284 kid1| 26,3| tunnel.cc(1140) tunnelStart:
>>> CONNECT baybridge-module-8155.scratch.my.salesforce.com:443 HTTP/1.1
>>> 2023/02/15 15:44:24.284 kid1| 44,3| peer_select.cc(612) selectMore:
>>> CONNECT baybridge-module-8155.scratch.my.salesforce.com
>>> 2023/02/15 15:44:24.284 kid1| 44,3| peer_select.cc(1098) addSelection:
>>> adding HIER_DIRECT#baybridge-module-8155.scratch.my.salesforce.com
>>> 2023/02/15 15:44:24.284 kid1| 44,2| peer_select.cc(460)
>>> resolveSelected: Find IP destination for:
>>> baybridge-module-8155.scratch.my.salesforce.com:443' via
>>> baybridge-module-8155.scratch.my.salesforce.com
>>> 2023/02/15 15:44:24.284 kid1| 14,4| ipcache.cc(607) nbgethostbyname:
>>> baybridge-module-8155.scratch.my.salesforce.com
>>> 2023/02/15 15:44:24.284 kid1| 14,3| Address.cc(389) lookupHostIP:
>>> Given Non-IP 'baybridge-module-8155.scratch.my.salesforce.com': Name
>>> or service not known
>>> 2023/02/15 15:44:24.284 kid1| 14,4| ipcache.cc(647)
>>> ipcache_nbgethostbyname_: ipcache_nbgethostbyname: HIT for
>>> 'baybridge-module-8155.scratch.my.salesforce.com'
>>> 2023/02/15 15:44:24.284 kid1| 44,2| peer_select.cc(479)
>>> resolveSelected: PeerSelector4664913 found all 0 destinations for
>>> baybridge-module-8155.scratch.my.salesforce.com:443
>>> 2023/02/15 15:44:24.284 kid1| 4,3| errorpage.cc(1249)
>>> compileLegacyCode: %U -->
>>> 'https://baybridge-module-8155.scratch.my.salesforce.com/*'
>>> 2023/02/15 15:44:24.284 kid1| 4,3| errorpage.cc(1249)
>>> compileLegacyCode: %U -->
>>> 'https://baybridge-module-8155.scratch.my.salesforce.com/*'
>>> 2023/02/15 15:44:24.284 kid1| 4,3| errorpage.cc(1249)
>>> compileLegacyCode: %W -->
>>> '?subject=CacheErrorInfo%20-%20ERR_CANNOT_FORWARD&body=CacheHost%3A%20opl-egress-proxy-vm-31vr%0D%0AErrPage%3A%20ERR_CANNOT_FORWARD%0D%0AErr%3A%20%5Bnone%5D%0D%0ATimeStamp%3A%20Wed,%2015%20Feb%202023%2014%3A44%3A24%20GMT%0D%0A%0D%0AClientIP%3A%20100.121.10.148%0D%0A%0D%0AHTTP%20Request%3A%0D%0ACONNECT%20%20HTTP%2F1.1%0AVia%3A%201.1%20gitlab-proxy-6d445dbd8d-mxtqv%20(squid%2F5.7)%0D%0AX-Forwarded-For%3A%20100.113.24.224%0D%0ACache-Control%3A%20max-age%3D259200%0D%0AConnection%3A%20close%0D%0AHost%3A%20baybridge-module-8155.scratch.my.salesforce.com%3A443%0D%0A%0D%0A%0D%0A'
>>> 2023/02/15 15:44:24.286 kid1| 33,3| client_side_request.cc(272)
>>> ~ClientHttpRequest: httpRequestFree:
>>> baybridge-module-8155.scratch.my.salesforce.com:443
>>> 2023/02/15 15:44:24.286 kid1| 33,5| client_side.cc(385) logRequest:
>>> logging half-baked transaction:
>>> baybridge-module-8155.scratch.my.salesforce.com:443
>>>
>>> Our parent proxy settings for DNS:
>>> negative_dns_ttl 3 seconds #if we set 1s it behaves the same
>>> dns_nameservers 8.8.8.8 1.1.1.1
>>>
>>> The question is:
>>> If you carefully look at the debug log you see:
>>> a. I(Squid) can't find IP for the name
>>> b. I've got 3 IPs from DNS
>>> c. OK, so I've got IP
>>> d. ...Oh, I cannot find any IP
>>> e. I can't find any destinations (what's that?)
>>> f. I'm outputing an error
>>>
>>> So, do you think it's ok or there is a bug?
>>>
>>> Rgds,
>>> Maciej Leks
>>> _______________________________________________
>>> squid-users mailing list
>>> squid-users at lists.squid-cache.org
>>> http://lists.squid-cache.org/listinfo/squid-users
>>
>> _______________________________________________
>> squid-users mailing list
>> squid-users at lists.squid-cache.org
>> http://lists.squid-cache.org/listinfo/squid-users
> _______________________________________________
> squid-users mailing list
> squid-users at lists.squid-cache.org
> http://lists.squid-cache.org/listinfo/squid-users
More information about the squid-users
mailing list