[squid-users] ACLs allow/deny logic

Vieri rentorbuy at yahoo.com
Mon Jun 26 08:46:56 UTC 2017


Hi,

I'd like to allow by default and deny only according to the ACLs I define.

Here's an example with Telegram. I'd like to deny all application/octet-stream mime types in requests and replies except for a set of IP addresses or domains.

acl denied_restricted1_mimetypes_req req_mime_type -i "/usr/local/proxy-settings/denied.restricted1.mimetypes"
acl denied_restricted1_mimetypes_rep rep_mime_type -i "/usr/local/proxy-settings/denied.restricted1.mimetypes"
acl allowed_restricted1_domains dstdomain -i "/usr/local/proxy-settings/allowed.restricted1.domains"
acl allowed_restricted1_ips dst "/usr/local/proxy-settings/allowed.restricted1.ips"
http_access deny denied_restricted1_mimetypes_req !allowed_restricted1_domains !allowed_restricted1_ips
http_reply_access deny denied_restricted1_mimetypes_rep !allowed_restricted1_domains !allowed_restricted1_ips

# cat /usr/local/proxy-settings/allowed.restricted1.domains
.telegram.org

# cat /usr/local/proxy-settings/allowed.restricted1.ips
149.154.167.91
149.154.165.120

# cat /usr/local/proxy-settings/denied.restricted1.mimetypes
^application/octet-stream$

I see this in access.log:

1498463484.530    413 10.215.144.237 TCP_DENIED_REPLY/403 4085 POST http://149.154.165.120/api - ORIGINAL_DST/149.154.165.120 text/html

I searched for the relevant parts in cache.log:

# grep -e "^2017/06/26 09:51:24.48[0-4]" /var/log/squid/cache.test.log_JL
2017/06/26 09:51:24.480 kid1| 28,3| Checklist.cc(70) preCheck: 0x80de0648 checking slow rules
2017/06/26 09:51:24.480 kid1| 28,5| Acl.cc(138) matches: checking http_reply_access
2017/06/26 09:51:24.480 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'DENIED/0is not banned
2017/06/26 09:51:24.480 kid1| 28,5| Acl.cc(138) matches: checking http_reply_access#1
2017/06/26 09:51:24.480 kid1| 28,5| Acl.cc(138) matches: checking denied_filetypes
2017/06/26 09:51:24.480 kid1| 28,3| RegexData.cc(51) match: aclRegexData::match: checking '/api'
2017/06/26 09:51:24.480 kid1| 28,3| RegexData.cc(62) match: aclRegexData::match: looking for '(\.ade(\?.*)?$)|(\.adp(\?.*)?$)|(\.app(\?.*)?$)|(\.asd(\?.*)?$)|(\.asf(\?.*)?$)|(\.asx(\?.*)?$)|(\.avi(\?.*)?$)|(\.bas(\?.*)?$)|(\.bat(\?.*)?$)|(\.cab(\?.*)?$)|(\.chm(\?.*)?$)|(\.cmd(\?.*)?$)|(\.cpl(\?.*)?$)|(\.dll$)|(\.exe(\?.*)?$)|(\.fxp(\?.*)?$)|(\.hlp(\?.*)?$)|(\.hta(\?.*)?$)|(\.hto(\?.*)?$)|(\.inf(\?.*)?$)|(\.ini(\?.*)?$)|(\.ins(\?.*)?$)|(\.iso(\?.*)?$)|(\.isp(\?.*)?$)|(\.jse(.?)(\?.*)?$)|(\.jse(\?.*)?$)|(\.lib(\?.*)?$)|(\.lnk(\?.*)?$)|(\.mar(\?.*)?$)|(\.mdb(\?.*)?$)|(\.mde(\?.*)?$)|(\.mp3(\?.*)?$)|(\.mpeg(\?.*)?$)|(\.mpg(\?.*)?$)|(\.msc(\?.*)?$)|(\.msi(\?.*)?$)|(\.msp(\?.*)?$)|(\.mst(\?.*)?$)|(\.ocx(\?.*)?$)|(\.pcd(\?.*)?$)|(\.pif(\?.*)?$)|(\.prg(\?.*)?$)|(\.reg(\?.*)?$)|(\.scr(\?.*)?$)|(\.sct(\?.*)?$)|(\.sh(\?.*)?$)|(\.shb(\?.*)?$)|(\.shs(\?.*)?$)|(\.sys(\?.*)?$)|(\.url(\?.*)?$)|(\.vb(\?.*)?$)|(\.vbe(\?.*)?$)|(\.vbs(\?.*)?$)|(\.vcs(\?.*)?$)|(\.vxd(\?.*)?$)|(\.wmd(\?.*)?$)|(\.wms(\?.*)?$)|(\.wmv(\?.*)?$)|(\.wmz(\?.*)?$)|(\.wsc(\?.*)?$)|(\.wsf(\?.*)?$)|(\.wsh(\?.*)?$)'
2017/06/26 09:51:24.480 kid1| 28,3| Acl.cc(158) matches: checked: denied_filetypes = 0
2017/06/26 09:51:24.480 kid1| 28,3| Acl.cc(158) matches: checked: http_reply_access#1 = 0
2017/06/26 09:51:24.480 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'DENIED/0is not banned
2017/06/26 09:51:24.480 kid1| 28,5| Acl.cc(138) matches: checking http_reply_access#2
2017/06/26 09:51:24.480 kid1| 28,5| Acl.cc(138) matches: checking denied_mimetypes_rep
2017/06/26 09:51:24.480 kid1| 28,3| RegexData.cc(51) match: aclRegexData::match: checking 'application/octet-stream'
2017/06/26 09:51:24.480 kid1| 28,3| RegexData.cc(62) match: aclRegexData::match: looking for '(^application/ecmascript$)|(^application/oebps-package+xml$)|(^application/vnd.amazon.ebook$)|(^application/vnd.android.package-archive$)|(^application/vnd.gmx$)|(^application/vnd.google-earth.kml+xml$)|(^application/vnd.google-earth.kmz$)|(^application/vnd.ms-cab-compressed$)|(^application/vnd.ms-excel.addin.macroenabled.12$)|(^application/vnd.ms-excel.sheet.binary.macroenabled.12$)|(^application/vnd.ms-excel.sheet.macroenabled.12$)|(^application/vnd.ms-excel.template.macroenabled.12$)|(^application/vnd.ms-powerpoint.addin.macroenabled.12$)|(^application/vnd.ms-powerpoint.presentation.macroenabled.12$)|(^application/vnd.ms-powerpoint.slide.macroenabled.12$)|(^application/vnd.ms-powerpoint.slideshow.macroenabled.12$)|(^application/vnd.ms-powerpoint.template.macroenabled.12$)|(^application/vnd.ms-wpl$)|(^application/vnd.ms.wms-hdr.asfv1$)|(^application/vnd.realvnc.bed$)|(^application/vnd.tmobile-livetv$)|(^application/x-authorware-bin$)|(^application/x-cab$)|(^application/x-iso9660-image$)|(^application/x-mms-framed$)|(^application/x-ms-wm$)|(^application/x-msdos-program$)|(^application/x-msdownload$)|(^application/x-shar$)|(^application/x-vbs$)|(^text/vbs$)|(^text/vbscript$)'
2017/06/26 09:51:24.480 kid1| 28,3| Acl.cc(158) matches: checked: denied_mimetypes_rep = 0
2017/06/26 09:51:24.480 kid1| 28,3| Acl.cc(158) matches: checked: http_reply_access#2 = 0
2017/06/26 09:51:24.480 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'DENIED/0is not banned
2017/06/26 09:51:24.480 kid1| 28,5| Acl.cc(138) matches: checking http_reply_access#3
2017/06/26 09:51:24.480 kid1| 28,5| Acl.cc(138) matches: checking denied_extra1_mimetypes_rep
2017/06/26 09:51:24.480 kid1| 28,3| RegexData.cc(51) match: aclRegexData::match: checking 'application/octet-stream'
2017/06/26 09:51:24.480 kid1| 28,3| RegexData.cc(62) match: aclRegexData::match: looking for '(^application/mp21$)|(^application/mp4$)|(^application/vnd.rn-realmedia$)|(^application/vnd.tmobile-livetv$)|(^audio/)|(^video/)'
2017/06/26 09:51:24.480 kid1| 28,3| Acl.cc(158) matches: checked: denied_extra1_mimetypes_rep = 0
2017/06/26 09:51:24.480 kid1| 28,3| Acl.cc(158) matches: checked: http_reply_access#3 = 0
2017/06/26 09:51:24.480 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'DENIED/0is not banned
2017/06/26 09:51:24.480 kid1| 28,5| Acl.cc(138) matches: checking http_reply_access#4
2017/06/26 09:51:24.480 kid1| 28,5| Acl.cc(138) matches: checking denied_restricted1_mimetypes_rep
2017/06/26 09:51:24.480 kid1| 28,3| RegexData.cc(51) match: aclRegexData::match: checking 'application/octet-stream'
2017/06/26 09:51:24.480 kid1| 28,3| RegexData.cc(62) match: aclRegexData::match: looking for '(^application/octet-stream$)'
2017/06/26 09:51:24.480 kid1| 28,2| RegexData.cc(73) match: aclRegexData::match: match '(^application/octet-stream$)' found in 'application/octet-stream'
2017/06/26 09:51:24.480 kid1| 28,3| Acl.cc(158) matches: checked: denied_restricted1_mimetypes_rep = 1
2017/06/26 09:51:24.480 kid1| 28,5| Acl.cc(138) matches: checking !allowed_ips
2017/06/26 09:51:24.480 kid1| 28,5| Acl.cc(138) matches: checking allowed_ips
2017/06/26 09:51:24.480 kid1| 28,3| Ip.cc(539) match: aclIpMatchIp: '10.215.144.237' NOT found
2017/06/26 09:51:24.480 kid1| 28,3| Acl.cc(158) matches: checked: allowed_ips = 0
2017/06/26 09:51:24.480 kid1| 28,3| Acl.cc(158) matches: checked: !allowed_ips = 1
2017/06/26 09:51:24.480 kid1| 28,5| Acl.cc(138) matches: checking !allowed_restricted1_domains
2017/06/26 09:51:24.480 kid1| 28,5| Acl.cc(138) matches: checking allowed_restricted1_domains
2017/06/26 09:51:24.480 kid1| 28,3| DomainData.cc(108) match: aclMatchDomainList: checking '149.154.165.120'
2017/06/26 09:51:24.480 kid1| 28,3| DomainData.cc(113) match: aclMatchDomainList: '149.154.165.120' NOT found
2017/06/26 09:51:24.481 kid1| 14,4| ipcache.cc(810) ipcacheCheckNumeric: ipcacheCheckNumeric: HIT_BYPASS for '149.154.165.120' == 149.154.165.120
2017/06/26 09:51:24.481 kid1| 28,3| DestinationDomain.cc(85) match: aclMatchAcl: Can't yet compare 'allowed_restricted1_domains' ACL for '149.154.165.120'
2017/06/26 09:51:24.481 kid1| 35,4| fqdncache.cc(425) fqdncache_nbgethostbyaddr: fqdncache_nbgethostbyaddr: Name '149.154.165.120'.
2017/06/26 09:51:24.481 kid1| 35,4| fqdncache.cc(447) fqdncache_nbgethostbyaddr: fqdncache_nbgethostbyaddr: HIT for '149.154.165.120'
2017/06/26 09:51:24.481 kid1| 28,3| DomainData.cc(108) match: aclMatchDomainList: checking 'none'
2017/06/26 09:51:24.481 kid1| 28,3| DomainData.cc(113) match: aclMatchDomainList: 'none' NOT found
2017/06/26 09:51:24.481 kid1| 28,3| Acl.cc(158) matches: checked: allowed_restricted1_domains = 0
2017/06/26 09:51:24.481 kid1| 28,3| Acl.cc(158) matches: checked: !allowed_restricted1_domains = 1
2017/06/26 09:51:24.481 kid1| 28,5| Acl.cc(138) matches: checking !allowed_restricted1_ips
2017/06/26 09:51:24.481 kid1| 28,5| Acl.cc(138) matches: checking allowed_restricted1_ips
2017/06/26 09:51:24.481 kid1| 28,3| Ip.cc(539) match: aclIpMatchIp: '149.154.165.120:80' NOT found
2017/06/26 09:51:24.481 kid1| 28,3| Acl.cc(158) matches: checked: allowed_restricted1_ips = 0
2017/06/26 09:51:24.481 kid1| 28,3| Acl.cc(158) matches: checked: !allowed_restricted1_ips = 1
2017/06/26 09:51:24.481 kid1| 28,3| Acl.cc(158) matches: checked: http_reply_access#4 = 1
2017/06/26 09:51:24.481 kid1| 28,3| Acl.cc(158) matches: checked: http_reply_access = 1
2017/06/26 09:51:24.481 kid1| 28,3| Checklist.cc(63) markFinished: 0x80de0648 answer DENIED for match
2017/06/26 09:51:24.481 kid1| 28,3| Checklist.cc(163) checkCallback: ACLChecklist::checkCallback: 0x80de0648 answer=DENIED
2017/06/26 09:51:24.481 kid1| 88,2| client_side_reply.cc(2001) processReplyAccessResult: The reply for POST http://149.154.165.120/api is DENIED, because it matched allowed_restricted1_ips
2017/06/26 09:51:24.481 kid1| 90,3| store_client.cc(664) storeUnregister: storeUnregister: called for '3333CC1501BBE277B139F5F07A4F1141'
2017/06/26 09:51:24.481 kid1| 20,3| store.cc(484) lock: storeUnregister locked key 3333CC1501BBE277B139F5F07A4F1141 e:=p2XDIV/0x80d96640*4
2017/06/26 09:51:24.481 kid1| 90,3| store_client.cc(758) storePendingNClients: storePendingNClients: returning 0
2017/06/26 09:51:24.481 kid1| 90,3| store_client.cc(768) CheckQuickAbortIsReasonable: entry=0x80d96640, mem=0x814b8720
2017/06/26 09:51:24.481 kid1| 90,3| store_client.cc(771) CheckQuickAbortIsReasonable: quick-abort? YES !mem->request->flags.cachable
2017/06/26 09:51:24.481 kid1| 20,3| store.cc(484) lock: StoreEntry::abort locked key 3333CC1501BBE277B139F5F07A4F1141 e:=p2XDIV/0x80d96640*5
2017/06/26 09:51:24.481 kid1| 90,3| store_client.cc(732) invokeHandlers: InvokeHandlers: 3333CC1501BBE277B139F5F07A4F1141
2017/06/26 09:51:24.481 kid1| 20,3| store_swapout.cc(273) swapOutFileClose: storeSwapOutFileClose: 3333CC1501BBE277B139F5F07A4F1141 how=1
2017/06/26 09:51:24.481 kid1| 20,3| store_swapout.cc(274) swapOutFileClose: storeSwapOutFileClose: sio = 0
2017/06/26 09:51:24.481 kid1| 20,3| store.cc(522) unlock: StoreEntry::abort unlocking key 3333CC1501BBE277B139F5F07A4F1141 e:=sp2XDINVA/0x80d96640*5
2017/06/26 09:51:24.481 kid1| 20,3| store.cc(522) unlock: storeUnregister unlocking key 3333CC1501BBE277B139F5F07A4F1141 e:=sp2XDINVA/0x80d96640*4
2017/06/26 09:51:24.481 kid1| 20,3| store.cc(522) unlock: clientReplyContext::removeStoreReference unlocking key 3333CC1501BBE277B139F5F07A4F1141 e:=sp2XDINVA/0x80d96640*3
2017/06/26 09:51:24.481 kid1| 20,3| store.cc(779) storeCreatePureEntry: storeCreateEntry: 'http://149.154.165.120/api'
2017/06/26 09:51:24.481 kid1| 20,5| store.cc(371) StoreEntry: StoreEntry constructed, this=0x80ba5460
2017/06/26 09:51:24.481 kid1| 20,3| MemObject.cc(97) MemObject: new MemObject 0x80b902e8
2017/06/26 09:51:24.481 kid1| 20,3| store.cc(500) setReleaseFlag: StoreEntry::setReleaseFlag: '[null_store_key]'
2017/06/26 09:51:24.481 kid1| 20,3| store_key_md5.cc(89) storeKeyPrivate: storeKeyPrivate: POST http://149.154.165.120/api
2017/06/26 09:51:24.481 kid1| 20,3| store.cc(448) hashInsert: StoreEntry::hashInsert: Inserting Entry e:=XI/0x80ba5460*0 key 'CCEA5776796B6352934736B5664CDAEA'
2017/06/26 09:51:24.481 kid1| 20,3| store.cc(484) lock: storeCreateEntry locked key CCEA5776796B6352934736B5664CDAEA e:=XIV/0x80ba5460*1
2017/06/26 09:51:24.481 kid1| 90,3| store_client.cc(200) copy: store_client::copy: CCEA5776796B6352934736B5664CDAEA, from 0, for length 4096, cb 1, cbdata 0x8172e1a0
2017/06/26 09:51:24.481 kid1| 20,3| store.cc(484) lock: store_client::copy locked key CCEA5776796B6352934736B5664CDAEA e:=XIV/0x80ba5460*2
2017/06/26 09:51:24.481 kid1| 90,3| store_client.cc(297) storeClientCopy2: storeClientCopy2: CCEA5776796B6352934736B5664CDAEA
2017/06/26 09:51:24.482 kid1| 33,5| store_client.cc(329) doCopy: store_client::doCopy: co: 0, hi: 0
2017/06/26 09:51:24.482 kid1| 90,3| store_client.cc(341) doCopy: store_client::doCopy: Waiting for more
2017/06/26 09:51:24.482 kid1| 20,3| store.cc(522) unlock: store_client::copy unlocking key CCEA5776796B6352934736B5664CDAEA e:=XIV/0x80ba5460*2
2017/06/26 09:51:24.482 kid1| 4,4| errorpage.cc(603) errorAppendEntry: Creating an error page for entry 0x80ba5460 with errorstate 0x80e430e0 page id 1
2017/06/26 09:51:24.482 kid1| 6,5| disk.cc(71) file_open: file_open: FD 79
2017/06/26 09:51:24.482 kid1| 51,3| fd.cc(198) fd_open: fd_open() FD 79 /usr/share/squid/errors/ERR_ACCESS_DENIED
2017/06/26 09:51:24.482 kid1| 6,5| disk.cc(126) file_close: file_close: FD 79 really closing
2017/06/26 09:51:24.482 kid1| 51,3| fd.cc(93) fd_close: fd_close FD 79 /usr/share/squid/errors/ERR_ACCESS_DENIED
2017/06/26 09:51:24.482 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 79, type=1, handler=0, client_data=0, timeout=0
2017/06/26 09:51:24.482 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 79, type=2, handler=0, client_data=0, timeout=0
2017/06/26 09:51:24.482 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%l --> '/*
2017/06/26 09:51:24.482 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%; --> '%;'
2017/06/26 09:51:24.482 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%c --> 'ERR_ACCESS_DENIED'
2017/06/26 09:51:24.482 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%U --> 'http://149.154.165.120/api'
[trimmed]
2017/06/26 09:51:24.483 kid1| 20,2| store.cc(954) checkCachable: StoreEntry::checkCachable: NO: not cachable
2017/06/26 09:51:24.483 kid1| 20,3| store_swapout.cc(381) mayStartSwapOut: not cachable
2017/06/26 09:51:24.483 kid1| 20,2| store.cc(954) checkCachable: StoreEntry::checkCachable: NO: not cachable
2017/06/26 09:51:24.483 kid1| 90,3| store_client.cc(732) invokeHandlers: InvokeHandlers: CCEA5776796B6352934736B5664CDAEA
2017/06/26 09:51:24.483 kid1| 90,3| store_client.cc(738) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0
2017/06/26 09:51:24.483 kid1| 90,3| store_client.cc(297) storeClientCopy2: storeClientCopy2: CCEA5776796B6352934736B5664CDAEA
2017/06/26 09:51:24.483 kid1| 33,5| store_client.cc(329) doCopy: store_client::doCopy: co: 0, hi: 3960
2017/06/26 09:51:24.483 kid1| 90,3| store_client.cc(433) scheduleMemRead: store_client::doCopy: Copying normal from memory
2017/06/26 09:51:24.483 kid1| 88,5| client_side_reply.cc(2154) sendMoreData: clientReplyContext::sendMoreData: http://149.154.165.120/api, 3960 bytes (3960 new bytes)
2017/06/26 09:51:24.483 kid1| 88,5| client_side_reply.cc(2158) sendMoreData: clientReplyContext::sendMoreData:local=149.154.165.120:80 remote=10.215.144.237 FD 56 flags=17 'http://149.154.165.120/api' out.offset=0
2017/06/26 09:51:24.483 kid1| 88,2| client_side_reply.cc(2001) processReplyAccessResult: The reply for POST http://149.154.165.120/api is ALLOWED, because it matched allowed_restricted1_ips
2017/06/26 09:51:24.483 kid1| 20,3| store.cc(484) lock: ClientHttpRequest::loggingEntry locked key CCEA5776796B6352934736B5664CDAEA e:=XIV/0x80ba5460*3
2017/06/26 09:51:24.483 kid1| 88,3| client_side_reply.cc(2039) processReplyAccessResult: clientReplyContext::sendMoreData: Appending 3711 bytes after 249 bytes of headers
2017/06/26 09:51:24.484 kid1| 87,3| clientStream.cc(162) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0x8172e184 from node 0x80b74508
2017/06/26 09:51:24.484 kid1| 11,2| client_side.cc(1391) sendStartOfMessage: HTTP Client local=149.154.165.120:80 remote=10.215.144.237 FD 56 flags=17
2017/06/26 09:51:24.484 kid1| 11,2| client_side.cc(1392) sendStartOfMessage: HTTP Client REPLY:

I see 2 apparently contradictory log messages (well, for me that is -- I'm still learning how to read the log):
The reply for POST http://149.154.165.120/api is DENIED, because it matched allowed_restricted1_ips
The reply for POST http://149.154.165.120/api is ALLOWED, because it matched allowed_restricted1_ips

Why is this happening?

Thanks,

Vieri


More information about the squid-users mailing list