[squid-users] Squid 4.x: Intermediate certificates downloader

[Yuri Voinov]

On my setup it is easy to reproduce.

It is enough to execute with wget:

wget -S https://yandex.com/company/

access.log immediately shows

0 - TCP_DENIED/403 3574 GET http://repository.certum.pl/ca.cer -
HIER_NONE/- text/html;charset=utf-8

before request to Yandex destination.

However it executes:

root @ khorne /patch # wget -S https://yandex.com/company/
--2017-01-25 02:37:52--  https://yandex.com/company/
Connecting to 127.0.0.1:3128... connected.
Proxy request sent, awaiting response...
  HTTP/1.1 200 OK
  Date: Tue, 24 Jan 2017 20:37:54 GMT
  Content-Type: text/html; charset="UTF-8"
  Set-Cookie: yandexuid=15112434331485290274; Domain=.yandex.com; Path=/
  Content-Security-Policy: default-src 'none'; frame-src 'self'
yastatic.net yandex.st music.yandex.ru download.yandex.ru
static.video.yandex.ru video.yandex.ru player.vimeo.com www.youtube.com
*.cdn.yandex.net; script-src 'unsafe-eval' 'unsafe-inline'
clck.yandex.ru pass.yandex.com yastatic.net mc.yandex.ru
api-maps.yandex.ru social.yandex.com
'nonce-728706f8-8c12-4f25-a00f-27d1e8c36f6f'; style-src 'unsafe-inline'
yastatic.net; connect-src 'self' yandex.st mail.yandex.com mc.yandex.ru
mc.yandex.com; font-src yastatic.net; img-src 'self' data:
avatars.yandex.net avatars.mds.yandex.net avatars.mdst.yandex.net
http://avatars.mds.yandex.net jing.yandex-team.ru download.yandex.ru
yandex.st mc.yandex.ru yastatic.net www.tns-counter.ru
yandexgacom.hit.gemius.pl *.cdn.yandex.net api-maps.yandex.ru
static-maps.yandex.ru *.maps.yandex.net i.ytimg.com company.yandex.com
yandex.com http://img-fotki.yandex.ru img-fotki.yandex.ru; media-src
*.cdn.yandex.net
  X-Content-Security-Policy: default-src 'none'; frame-src 'self'
yastatic.net yandex.st music.yandex.ru download.yandex.ru
static.video.yandex.ru video.yandex.ru player.vimeo.com www.youtube.com
*.cdn.yandex.net; script-src 'unsafe-eval' 'unsafe-inline'
clck.yandex.ru pass.yandex.com yastatic.net mc.yandex.ru
api-maps.yandex.ru social.yandex.com
'nonce-728706f8-8c12-4f25-a00f-27d1e8c36f6f'; style-src 'unsafe-inline'
yastatic.net; connect-src 'self' yandex.st mail.yandex.com mc.yandex.ru
mc.yandex.com; font-src yastatic.net; img-src 'self' data:
avatars.yandex.net avatars.mds.yandex.net avatars.mdst.yandex.net
http://avatars.mds.yandex.net jing.yandex-team.ru download.yandex.ru
yandex.st mc.yandex.ru yastatic.net www.tns-counter.ru
yandexgacom.hit.gemius.pl *.cdn.yandex.net api-maps.yandex.ru
static-maps.yandex.ru *.maps.yandex.net i.ytimg.com company.yandex.com
yandex.com http://img-fotki.yandex.ru img-fotki.yandex.ru; media-src
*.cdn.yandex.net
  X-WebKit-CSP: default-src 'none'; frame-src 'self' yastatic.net
yandex.st music.yandex.ru download.yandex.ru static.video.yandex.ru
video.yandex.ru player.vimeo.com www.youtube.com *.cdn.yandex.net;
script-src 'unsafe-eval' 'unsafe-inline' clck.yandex.ru pass.yandex.com
yastatic.net mc.yandex.ru api-maps.yandex.ru social.yandex.com
'nonce-728706f8-8c12-4f25-a00f-27d1e8c36f6f'; style-src 'unsafe-inline'
yastatic.net; connect-src 'self' yandex.st mail.yandex.com mc.yandex.ru
mc.yandex.com; font-src yastatic.net; img-src 'self' data:
avatars.yandex.net avatars.mds.yandex.net avatars.mdst.yandex.net
http://avatars.mds.yandex.net jing.yandex-team.ru download.yandex.ru
yandex.st mc.yandex.ru yastatic.net www.tns-counter.ru
yandexgacom.hit.gemius.pl *.cdn.yandex.net api-maps.yandex.ru
static-maps.yandex.ru *.maps.yandex.net i.ytimg.com company.yandex.com
yandex.com http://img-fotki.yandex.ru img-fotki.yandex.ru; media-src
*.cdn.yandex.net
  Content-Encoding: gzip
  X-XSS-Protection: 1; mode=block
  X-Content-Type-Options: nosniff
  Strict-Transport-Security: max-age=0; includeSubDomains
  X-Cache: MISS from khorne
  X-Cache-Lookup: HIT from khorne:3128
  Transfer-Encoding: chunked
  Connection: keep-alive
Length: unspecified [text/html]
Saving to: 'index.html'

index.html              [ <=>               ]   3.60K  --.-KB/s    in
0s     

2017-01-25 02:37:54 (7.44 MB/s) - 'index.html' saved [3688]

because intermediate certificates file is exists and configured.

25.01.2017 2:09, Yuri Voinov пишет:
> This is mentioned debug for this transaction.
>
> I see no anomalies. Just DENIED finally.
>
>
> 25.01.2017 1:45, Yuri Voinov пишет:
>> Under detailed ACL debug got this transaction:
>>
>> 2017/01/25 01:36:35.772 kid1| 28,3| DomainData.cc(110) match:
>> aclMatchDomainList: checking 'repository.certum.pl'
>> 2017/01/25 01:36:35.772 kid1| 28,3| DomainData.cc(115) match:
>> aclMatchDomainList: 'repository.certum.pl' NOT found
>> 2017/01/25 01:36:35.772 kid1| 28,3| Acl.cc(290) matches: checked:
>> block_tld = 0
>> 2017/01/25 01:36:35.772 kid1| 28,3| Acl.cc(290) matches: checked:
>> http_access#11 = 0
>> 2017/01/25 01:36:35.772 kid1| 28,5| Checklist.cc(397) bannedAction:
>> Action 'ALLOWED/0' is not banned
>> 2017/01/25 01:36:35.772 kid1| 28,5| Acl.cc(263) matches: checking
>> http_access#12
>> 2017/01/25 01:36:35.772 kid1| 28,5| Acl.cc(263) matches: checking CONNECT
>> 2017/01/25 01:36:35.772 kid1| 28,3| Acl.cc(290) matches: checked:
>> CONNECT = 0
>> 2017/01/25 01:36:35.772 kid1| 28,3| Acl.cc(290) matches: checked:
>> http_access#12 = 0
>> 2017/01/25 01:36:35.772 kid1| 28,5| Checklist.cc(397) bannedAction:
>> Action 'ALLOWED/0' is not banned
>> 2017/01/25 01:36:35.772 kid1| 28,5| Acl.cc(263) matches: checking
>> http_access#13
>> 2017/01/25 01:36:35.772 kid1| 28,5| Acl.cc(263) matches: checking CONNECT
>> 2017/01/25 01:36:35.772 kid1| 28,3| Acl.cc(290) matches: checked:
>> CONNECT = 0
>> 2017/01/25 01:36:35.772 kid1| 28,3| Acl.cc(290) matches: checked:
>> http_access#13 = 0
>> 2017/01/25 01:36:35.772 kid1| 28,5| Checklist.cc(397) bannedAction:
>> Action 'ALLOWED/0' is not banned
>> 2017/01/25 01:36:35.772 kid1| 28,5| Acl.cc(263) matches: checking
>> http_access#14
>> 2017/01/25 01:36:35.772 kid1| 28,5| Acl.cc(263) matches: checking
>> windowsupdate
>> 2017/01/25 01:36:35.772 kid1| 28,3| DomainData.cc(110) match:
>> aclMatchDomainList: checking 'repository.certum.pl'
>> 2017/01/25 01:36:35.772 kid1| 28,3| DomainData.cc(115) match:
>> aclMatchDomainList: 'repository.certum.pl' NOT found
>> 2017/01/25 01:36:35.772 kid1| 28,3| Acl.cc(290) matches: checked:
>> windowsupdate = 0
>> 2017/01/25 01:36:35.772 kid1| 28,3| Acl.cc(290) matches: checked:
>> http_access#14 = 0
>> 2017/01/25 01:36:35.772 kid1| 28,5| Checklist.cc(397) bannedAction:
>> Action 'ALLOWED/0' is not banned
>> 2017/01/25 01:36:35.772 kid1| 28,5| Acl.cc(263) matches: checking
>> http_access#15
>> 2017/01/25 01:36:35.772 kid1| 28,5| Acl.cc(263) matches: checking
>> windowsupdate
>> 2017/01/25 01:36:35.773 kid1| 28,3| DomainData.cc(110) match:
>> aclMatchDomainList: checking 'repository.certum.pl'
>> 2017/01/25 01:36:35.773 kid1| 28,3| DomainData.cc(115) match:
>> aclMatchDomainList: 'repository.certum.pl' NOT found
>> 2017/01/25 01:36:35.773 kid1| 28,3| Acl.cc(290) matches: checked:
>> windowsupdate = 0
>> 2017/01/25 01:36:35.773 kid1| 28,3| Acl.cc(290) matches: checked:
>> http_access#15 = 0
>> 2017/01/25 01:36:35.773 kid1| 28,5| Checklist.cc(397) bannedAction:
>> Action 'ALLOWED/0' is not banned
>> 2017/01/25 01:36:35.773 kid1| 28,5| Acl.cc(263) matches: checking
>> http_access#16
>> 2017/01/25 01:36:35.773 kid1| 28,5| Acl.cc(263) matches: checking localnet
>> 2017/01/25 01:36:35.773 kid1| 28,9| Ip.cc(96) aclIpAddrNetworkCompare:
>> aclIpAddrNetworkCompare: compare:
>> [ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]/[ffff:ffff:ffff:ffff:ffff:ffff:ffc0:0]
>> ([ffff:ffff:ffff:ffff:ffff:ffff:ffc0:0])  vs
>> 100.64.0.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffc0:0]
>> 2017/01/25 01:36:35.773 kid1| 28,9| Ip.cc(96) aclIpAddrNetworkCompare:
>> aclIpAddrNetworkCompare: compare:
>> [ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]/[ffff:ffff:ffff:ffff:ffff:ffff:fff0:0]
>> ([ffff:ffff:ffff:ffff:ffff:ffff:fff0:0])  vs
>> 172.16.0.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:fff0:0]
>> 2017/01/25 01:36:35.773 kid1| 28,9| Ip.cc(96) aclIpAddrNetworkCompare:
>> aclIpAddrNetworkCompare: compare:
>> [ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:0]
>> ([ffff:ffff:ffff:ffff:ffff:ffff:ffff:0])  vs
>> 192.168.0.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:0]
>> 2017/01/25 01:36:35.773 kid1| 28,3| Ip.cc(540) match: aclIpMatchIp:
>> '[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]' NOT found
>> 2017/01/25 01:36:35.773 kid1| 28,3| Acl.cc(290) matches: checked:
>> localnet = 0
>> 2017/01/25 01:36:35.773 kid1| 28,3| Acl.cc(290) matches: checked:
>> http_access#16 = 0
>> 2017/01/25 01:36:35.773 kid1| 28,5| Checklist.cc(397) bannedAction:
>> Action 'ALLOWED/0' is not banned
>> 2017/01/25 01:36:35.773 kid1| 28,5| Acl.cc(263) matches: checking
>> http_access#17
>> 2017/01/25 01:36:35.773 kid1| 28,5| Acl.cc(263) matches: checking localhost
>> 2017/01/25 01:36:35.773 kid1| 28,9| Ip.cc(96) aclIpAddrNetworkCompare:
>> aclIpAddrNetworkCompare: compare:
>> [ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]
>> ([ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff])  vs
>> 127.0.0.1-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]
>> 2017/01/25 01:36:35.773 kid1| 28,3| Ip.cc(540) match: aclIpMatchIp:
>> '[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]' NOT found
>> 2017/01/25 01:36:35.773 kid1| 28,3| Acl.cc(290) matches: checked:
>> localhost = 0
>> 2017/01/25 01:36:35.773 kid1| 28,3| Acl.cc(290) matches: checked:
>> http_access#17 = 0
>> 2017/01/25 01:36:35.773 kid1| 28,5| Checklist.cc(397) bannedAction:
>> Action 'DENIED/0' is not banned
>> 2017/01/25 01:36:35.773 kid1| 28,5| Acl.cc(263) matches: checking
>> http_access#18
>> 2017/01/25 01:36:35.773 kid1| 28,5| Acl.cc(263) matches: checking all
>> 2017/01/25 01:36:35.773 kid1| 28,9| Ip.cc(96) aclIpAddrNetworkCompare:
>> aclIpAddrNetworkCompare: compare:
>> [ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]/[::] ([::])  vs [::]-[::]/[::]
>> 2017/01/25 01:36:35.773 kid1| 28,3| Ip.cc(540) match: aclIpMatchIp:
>> '[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]' found
>> 2017/01/25 01:36:35.773 kid1| 28,3| Acl.cc(290) matches: checked: all = 1
>> 2017/01/25 01:36:35.773 kid1| 28,3| Acl.cc(290) matches: checked:
>> http_access#18 = 1
>> 2017/01/25 01:36:35.773 kid1| 28,3| Acl.cc(290) matches: checked:
>> http_access = 1
>> 2017/01/25 01:36:35.773 kid1| 28,3| Checklist.cc(63) markFinished:
>> 0x4b781938 answer DENIED for match
>> 2017/01/25 01:36:35.773 kid1| 28,3| Checklist.cc(163) checkCallback:
>> ACLChecklist::checkCallback: 0x4b781938 answer=DENIED
>>
>> It seems like bug.
>>
>> 25.01.2017 1:10, Alex Rousskov пишет:
>>> On 01/24/2017 11:33 AM, Yuri Voinov wrote:
>>>
>>>>> 1485279884.648      0 - TCP_DENIED/403 3574 GET
>>>>> http://repository.certum.pl/ca.cer - HIER_NONE/- text/html;charset=utf-8
>>>> http_access deny !Safe_ports
>>> Probably does not match -- 80 is a safe port.
>>>
>>>
>>>> # Instant messengers include
>>>> include "/usr/local/squid/etc/acl.im.include"
>>> I am guessing these do not match or are irrelevant.
>>>
>>>
>>>> # Deny CONNECT to other than SSL ports
>>>> http_access deny CONNECT !SSL_ports
>>> Does not match. This is a GET request.
>>>
>>>
>>>> # Only allow cachemgr access from localhost
>>>> http_access allow localhost manager
>>>> http_access deny manager
>>> Probably do not match. This is not a cache manager request although I
>>> have not checked how Squid identifies those exactly.
>>>
>>>
>>>> http_access deny to_localhost
>>> Does not match. The destination is not localhost.
>>>
>>>
>>>> # Allow purge from localhost
>>>> http_access allow PURGE localhost
>>>> http_access deny PURGE
>>> Do not match. This is a GET request, not PURGE.
>>>
>>>
>>>> # Block torrent files
>>>> acl TorrentFiles rep_mime_type mime-type application/x-bittorrent
>>>> http_reply_access deny TorrentFiles
>>> Does not match. There was no response [with an application/x-bittorrent
>>> MIME type].
>>>
>>>
>>>> # Windows updates rules
>>>> http_access allow CONNECT wuCONNECT localnet
>>>> http_access allow CONNECT wuCONNECT localhost
>>> Do not match. This is a GET request, not CONNECT.
>>>
>>>
>>>> http_access allow windowsupdate localnet
>>>> http_access allow windowsupdate localhost
>>> Probably do not match. The internal transaction is not associated with a
>>> to-Squid connection coming from localnet or localhost.
>>>
>>>
>>>> # Rule allowing access from local networks
>>>> http_access allow localnet
>>>> http_access allow localhost
>>> Probably do not match. The internal transaction is not associated with a
>>> to-Squid connection coming from localnet or localhost.
>>>
>>>
>>>> # And finally deny all other access to this proxy
>>>> http_access deny all
>>> Matches!
>>>
>>>
>>>> I have no idea, what can block access.
>>> That much was clear from the time you asked the question. I bet your
>>> last http_access rule that denies all other connection matches, but I
>>> would still ask Squid. Squid knows why it blocks (or does not allow)
>>> access. There are several ways to ask Squid, including increasing
>>> debugging verbosity when reproducing the problem, adding the matching
>>> ACL to the error message, using custom error messages for different
>>> http_access deny lines, etc.
>>>
>>> These methods are not easy, pleasant, quick, or human-friendly,
>>> unfortunately, but you are a very capable sysadmin with more than enough
>>> Squid knowledge to find the blocking directive/ACL, especially for a
>>> problem that can be isolated to two HTTP transactions.
>>>
>>> Once we know what directive/ACL blocks, we may be able to figure out a
>>> workaround, propose a bug fix, etc. For example, if my guess is correct
>>> -- the "deny all" rule has matched -- then you would need to add a rule
>>> to allow internal requests, including the ones that fetch those missing
>>> certificates.
>>>
>>>
>>> HTH,
>>>
>>> Alex.
>>>
>>>
>>>> 25.01.2017 0:27, Alex Rousskov пишет:
>>>>> On 01/24/2017 11:19 AM, Yuri Voinov wrote:
>>>>>
>>>>>> It is downloads directly via proxy from localhost:
>>>>>> As I understand, downloader also access via localhost, right? 
>>>>> This is incorrect. Downloader does not have a concept of an HTTP client
>>>>> which sends the request to Squid so "via localhost" or "via any client
>>>>> source address" does not apply to Downloader transactions. In other
>>>>> words, there is no client [source address] for Downloader requests.
>>>>>
>>>>> Unfortunately, I do not know exactly what effect that lack of info has
>>>>> on what ACLs (in part because there are too many of them and because
>>>>> lack of info is often treated inconsistently by various ACLs). Thus, I
>>>>> continue to recommend finding out which directive/ACL denied Downloader
>>>>> access as the first step.
>>>>>
>>>>> Alex.
>>>>>
>>>>>
>>>>>> 25.01.2017 0:16, Alex Rousskov пишет:
>>>>>>> On 01/24/2017 10:48 AM, Yuri Voinov wrote:
>>>>>>>
>>>>>>>> It seems 4.0.17 tries to download certs but gives deny somewhere.
>>>>>>>> However, same URL with wget via same proxy works
>>>>>>>> Why?
>>>>>>> Most likely, your http_access or similar rules deny internal download
>>>>>>> transactions but allow external ones. This is possible, for example, if
>>>>>>> your access rules use client information. Internal transactions (ESI,
>>>>>>> missing certificate fetching, Cache Digests, etc.) do not have an
>>>>>>> associated client.
>>>>>>>
>>>>>>> The standard denial troubleshooting procedure applies here: Start with
>>>>>>> finding out which directive/ACL denies access. I am _not_ implying that
>>>>>>> this is easy to do.

-------------- next part --------------
A non-text attachment was scrubbed...
Name: 0x613DEC46.asc
Type: application/pgp-keys
Size: 2437 bytes
Desc: not available
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20170125/639ded32/attachment.key>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 473 bytes
Desc: OpenPGP digital signature
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20170125/639ded32/attachment.sig>