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

Tue Jan 24 20:09:08 UTC 2017

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: cache.zip
Type: application/x-zip-compressed
Size: 18074 bytes
Desc: not available
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20170125/50f3679a/attachment-0001.bin>
-------------- 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/50f3679a/attachment-0001.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/50f3679a/attachment-0001.sig>