plugins icon indicating copy to clipboard operation
plugins copied to clipboard

Published 20 hours ago • verified publisher icon opnsense

os-squid, os-OPNProxy not working - Coredump of squid child process

Open marvinwankersteen opened this issue 1 year ago • 6 comments

Important notices Before you add a new report, we ask you kindly to acknowledge the following:

  • [X] I have read the contributing guide lines at https://github.com/opnsense/plugins/blob/master/CONTRIBUTING.md
  • [X] I have searched the existing issues, open and closed, and I'm convinced that mine is new.
  • [X] The title contains the plugin to which this issue belongs

Describe the bug Hello,

we have purchased a subscription for the Business Edition so that we can use the os-OPNProxy plugin to give Active Directory users/groups access to certain pages. Unfortunately, there are major difficulties with Squid when setting it up. After much debugging, here is a bug report in the hope that the problem can be solved.

To Reproduce Steps to reproduce the behavior:

  1. Install os-OPNProxy, os-squid and os-redis
  2. Add LDAP/AD-server
  3. Test (successfully) some user of the AD with the tester
  4. Setup webproxy like described in https://docs.opnsense.org/vendor/deciso/opnproxy.html
  5. Enable redis
  6. Enable webproxy
  7. Set Authentication method to the previous added AD-Server
  8. Set Enable SSL inspection
  9. Set Log SNI information only
  10. Set two policies (See the config file below)
    1. First one with some domains which should be allowed
    2. Second one to deny all domains
  11. Set some browser to use the proxy http://192.168.0.1:3128
  12. Open allowed or denied domain does nothing, timeout.
  13. Squid produces coredumps

Expected behavior Browser should ask for the (basic) authentication. After successfully authentication, the website should be allowed or denied.

Relevant log files Stop squid/proxy in the GUI. Then start squid in debugmode on CLI and try with curl to open some websites. I will add some linebreaks in this code block after which curl is executed.

/usr/local/sbin/squid -d9 -N -f /usr/local/etc/squid/squid.conf
2024/02/15 09:43:38| Processing Configuration File: /usr/local/etc/squid/squid.conf (depth 0)
2024/02/15 09:43:38| WARNING: empty ACL: acl bump_nobumpsites ssl::server_name "/usr/local/etc/squid/nobumpsites.acl"
2024/02/15 09:43:38| Processing Configuration File: /usr/local/etc/squid/pre-auth/40-snmp.conf (depth 1)
2024/02/15 09:43:38| Processing Configuration File: /usr/local/etc/squid/pre-auth/debug.conf (depth 1)
2024/02/15 09:43:38| Processing Configuration File: /usr/local/etc/squid/pre-auth/dummy.conf (depth 1)
2024/02/15 09:43:38| Processing Configuration File: /usr/local/etc/squid/pre-auth/parentproxy.conf (depth 1)
2024/02/15 09:43:38| Processing Configuration File: /usr/local/etc/squid/auth/10-opnproxy-ext.auth.conf (depth 1)
2024/02/15 09:43:38| Processing Configuration File: /usr/local/etc/squid/auth/dummy.conf (depth 1)
2024/02/15 09:43:38| Processing Configuration File: /usr/local/etc/squid/post-auth/dummy.conf (depth 1)
2024/02/15 09:43:38| WARNING: HTTP requires the use of Via
2024/02/15 09:43:38| Created PID file (/var/run/squid/squid.pid)
2024/02/15 09:43:38| Set Current Directory to /var/squid/cache
2024/02/15 09:43:38| Starting Squid Cache version 6.6 for amd64-portbld-freebsd13.2...
2024/02/15 09:43:38| Service Name: squid
2024/02/15 09:43:38| Process ID 62241
2024/02/15 09:43:38| Process Roles: master worker
2024/02/15 09:43:38| With 234846 file descriptors available
2024/02/15 09:43:38| Initializing IP Cache...
2024/02/15 09:43:38| DNS IPv6 socket created at [::], FD 10
2024/02/15 09:43:38| DNS IPv4 socket created at 0.0.0.0, FD 11
2024/02/15 09:43:38| Adding domain domain.local from /etc/resolv.conf
2024/02/15 09:43:38| Adding nameserver 127.0.0.1 from /etc/resolv.conf
2024/02/15 09:43:38| Adding nameserver 192.168.0.1 from /etc/resolv.conf
2024/02/15 09:43:38| Adding nameserver 8.8.8.8 from /etc/resolv.conf
2024/02/15 09:43:38| Adding domain domain.local from /etc/resolv.conf
2024/02/15 09:43:38| helperOpenServers: Starting 5/5 'security_file_certgen' processes
2024/02/15 09:43:38| helperOpenServers: Starting 0/50 'basic_pam_auth' processes
2024/02/15 09:43:38| helperOpenServers: No 'basic_pam_auth' processes needed.
2024/02/15 09:43:38| helperOpenServers: Starting 0/5 'squid_acl_helper.py' processes
2024/02/15 09:43:38| helperOpenServers: No 'squid_acl_helper.py' processes needed.
2024/02/15 09:43:38| helperOpenServers: Starting 0/5 'squid_acl_helper.py' processes
2024/02/15 09:43:38| helperOpenServers: No 'squid_acl_helper.py' processes needed.
2024/02/15 09:43:38| Logfile: opening log stdio:/var/log/squid/access.log
2024/02/15 09:43:38| Local cache digest enabled; rebuild/rewrite every 3600/3600 sec
2024/02/15 09:43:38| Logfile: opening log stdio:/var/log/squid/store.log
2024/02/15 09:43:38| Swap maxSize 0 + 262144 KB, estimated 20164 objects
2024/02/15 09:43:38| Target number of buckets: 1008
2024/02/15 09:43:38| Using 8192 Store buckets
2024/02/15 09:43:38| Max Mem  size: 262144 KB
2024/02/15 09:43:38| Max Swap size: 0 KB
2024/02/15 09:43:38| Using Least Load store dir selection
2024/02/15 09:43:38| Set Current Directory to /var/squid/cache
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i \.gif$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i \.mime$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i ^internal-dirup$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i ^internal-dir$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i ^internal-link$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i ^internal-logo$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i ^internal-menu$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i ^internal-text$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i ^internal-index$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i ^internal-image$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i ^internal-sound$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i ^internal-movie$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i ^internal-telnet$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i ^internal-binary$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i ^internal-unknown$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i ^internal-view$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i ^internal-download$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i \.bin$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i \.oda$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i \.exe$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i \.pdf$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i \.ai$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i \.eps$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i \.ps$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i \.rtf$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i \.Z$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i \.gz$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i \.bz2$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i \.bz$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i \.tgz$
2024/02/15 09:43:38.765| 28,2| RegexPattern.cc(33) RegexPattern: -i \.csh$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.dvi$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.hdf$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.latex$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.lsm$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.nc$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.cdf$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.sh$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.tcl$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.tex$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.texi$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.texinfo$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.t$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.roff$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.tr$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.man$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.me$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.ms$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.src$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.zip$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.bcpio$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.cpio$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.gtar$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.rpm$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.shar$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.sv4cpio$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.sv4crc$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.tar$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.ustar$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.au$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.snd$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.mp2$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.mp3$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.mpga$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.aif$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.aiff$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.aifc$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.wav$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.bmp$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.ief$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.jpeg$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.jpg$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.jpe$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.tiff$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.tif$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.ras$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.pnm$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.pbm$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.pgm$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.ppm$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.rgb$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.xbm$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.xpm$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.xwd$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.html$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.htm$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.css$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.js$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.c$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.h$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.cc$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.cpp$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.hh$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.m$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.f90$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.txt$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.asc$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.rtx$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.tsv$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.etx$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.mpeg$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.mpg$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.mpe$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.qt$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.mov$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.avi$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.movie$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.cpt$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.hqx$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.mwrt$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.msw$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.doc$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.xls$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.ppt$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.wk[s1234]$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.mif$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.sit$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.pict$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.pic$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.arj$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.lzh$
2024/02/15 09:43:38.766| 28,2| RegexPattern.cc(33) RegexPattern: -i \.lha$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.zlib$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i README
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i ^core$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.core$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.png$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.cab$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.xpi$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.class$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.java$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.dcr$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.dir$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.dxr$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.djv$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.djvu$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.dll$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.dms$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.ez$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.ice$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.iges$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.igs$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.kar$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.mid$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.midi$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.mesh$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.silo$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.mxu$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.pdb$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.pgn$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.ra$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.ram$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.rm$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.sgml$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.sgm$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.skd$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.skm$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.skp$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.skt$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.smi$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.smil$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.so$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.spl$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.swf$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.vcd$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.vrml$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.wbmp$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.wbxml$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.wmlc$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.wmlsc$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.wmls$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.xht$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.xhtml$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.xml$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.xsl$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i \.xyz$
2024/02/15 09:43:38.767| 28,2| RegexPattern.cc(33) RegexPattern: -i .
2024/02/15 09:43:38| Finished loading MIME types and icons.
2024/02/15 09:43:38.775| 33,2| AsyncCall.cc(30) AsyncCall: The AsyncCall clientListenerConnectionOpened constructed, this=0x84643a3c0 [call17]
2024/02/15 09:43:38.775| 33,2| AsyncCall.cc(97) ScheduleCall: StartListening.cc(60) will call clientListenerConnectionOpened(conn13 local=192.168.0.1:3128 remote=[::] FD 24 flags=9, HTTP Socket port=0x84643a420) [call17]
2024/02/15 09:43:38| HTCP Disabled.
2024/02/15 09:43:38| Squid plugin modules loaded: 0
2024/02/15 09:43:38| Adaptation support is off.
2024/02/15 09:43:38.775| 33,2| AsyncCallQueue.cc(26) fire: entering clientListenerConnectionOpened(conn13 local=192.168.0.1:3128 remote=[::] FD 24 flags=9, HTTP Socket port=0x84643a420)
2024/02/15 09:43:38.775| 33,2| AsyncCall.cc(42) make: make call clientListenerConnectionOpened [call17]
2024/02/15 09:43:38| Accepting SSL bumped HTTP Socket connections at conn13 local=192.168.0.1:3128 remote=[::] FD 24 flags=9
    listening port: 192.168.0.1:3128
2024/02/15 09:43:38.775| 33,2| AsyncCallQueue.cc(28) fire: leaving clientListenerConnectionOpened(conn13 local=192.168.0.1:3128 remote=[::] FD 24 flags=9, HTTP Socket port=0x84643a420)
2024/02/15 09:43:39| storeLateRelease: released 0 objects



2024/02/15 09:46:03.985| 28,4| Eui48.cc(438) lookup: Got address 00:50:56:b1:ec:62
2024/02/15 09:46:03.985| 28,3| Checklist.cc(69) preCheck: 0x8464b3018 checking slow rules
2024/02/15 09:46:03.985| 28,5| Acl.cc(148) matches: checking http_access
2024/02/15 09:46:03.985| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/0' is not banned
2024/02/15 09:46:03.985| 28,5| Acl.cc(148) matches: checking http_access#1
2024/02/15 09:46:03.985| 28,5| Acl.cc(148) matches: checking ftp
2024/02/15 09:46:03.985| 28,3| Acl.cc(175) matches: checked: ftp = 0
2024/02/15 09:46:03.985| 28,3| Acl.cc(175) matches: checked: http_access#1 = 0
2024/02/15 09:46:03.985| 28,5| Checklist.cc(390) bannedAction: Action 'DENIED/0' is not banned
2024/02/15 09:46:03.985| 28,5| Acl.cc(148) matches: checking http_access#2
2024/02/15 09:46:03.985| 28,5| Acl.cc(148) matches: checking !Safe_ports
2024/02/15 09:46:03.985| 28,5| Acl.cc(148) matches: checking Safe_ports
2024/02/15 09:46:03.985| 28,3| Acl.cc(175) matches: checked: Safe_ports = 1
2024/02/15 09:46:03.985| 28,3| Acl.cc(175) matches: checked: !Safe_ports = 0
2024/02/15 09:46:03.985| 28,3| Acl.cc(175) matches: checked: http_access#2 = 0
2024/02/15 09:46:03.985| 28,5| Checklist.cc(390) bannedAction: Action 'DENIED/0' is not banned
2024/02/15 09:46:03.985| 28,5| Acl.cc(148) matches: checking http_access#3
2024/02/15 09:46:03.985| 28,5| Acl.cc(148) matches: checking CONNECT
2024/02/15 09:46:03.985| 28,3| Acl.cc(175) matches: checked: CONNECT = 1
2024/02/15 09:46:03.985| 28,5| Acl.cc(148) matches: checking !SSL_ports
2024/02/15 09:46:03.985| 28,5| Acl.cc(148) matches: checking SSL_ports
2024/02/15 09:46:03.985| 28,3| Acl.cc(175) matches: checked: SSL_ports = 1
2024/02/15 09:46:03.985| 28,3| Acl.cc(175) matches: checked: !SSL_ports = 0
2024/02/15 09:46:03.985| 28,3| Acl.cc(175) matches: checked: http_access#3 = 0
2024/02/15 09:46:03.985| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/0' is not banned
2024/02/15 09:46:03.985| 28,5| Acl.cc(148) matches: checking http_access#4
2024/02/15 09:46:03.985| 28,5| Acl.cc(148) matches: checking localhost
2024/02/15 09:46:03.985| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: 192.168.0.1:52166/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff] (192.168.0.1:52166)  vs [::1]-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]
2024/02/15 09:46:03.985| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: 192.168.0.1:52166/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff] (192.168.0.1:52166)  vs 127.0.0.1-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]
2024/02/15 09:46:03.985| 28,3| Ip.cc(538) match: aclIpMatchIp: '192.168.0.1:52166' NOT found
2024/02/15 09:46:03.985| 28,3| Acl.cc(175) matches: checked: localhost = 0
2024/02/15 09:46:03.985| 28,3| Acl.cc(175) matches: checked: http_access#4 = 0
2024/02/15 09:46:03.985| 28,5| Checklist.cc(390) bannedAction: Action 'DENIED/0' is not banned
2024/02/15 09:46:03.985| 28,5| Acl.cc(148) matches: checking http_access#5
2024/02/15 09:46:03.985| 28,5| Acl.cc(148) matches: checking manager
2024/02/15 09:46:03.985| 28,3| RegexData.cc(50) match: checking 'www.heise.de:443'
2024/02/15 09:46:03.985| 28,3| Acl.cc(175) matches: checked: manager = 0
2024/02/15 09:46:03.985| 28,3| Acl.cc(175) matches: checked: http_access#5 = 0
2024/02/15 09:46:03.985| 28,5| Checklist.cc(390) bannedAction: Action 'DENIED/0' is not banned
2024/02/15 09:46:03.985| 28,5| Acl.cc(148) matches: checking http_access#6
2024/02/15 09:46:03.985| 28,5| Acl.cc(148) matches: checking to_localhost
2024/02/15 09:46:03.985| 28,3| DestinationIp.cc(78) match: can't yet compare 'to_localhost' ACL for www.heise.de
2024/02/15 09:46:03.985| 28,3| Acl.cc(175) matches: checked: to_localhost = -1 async
2024/02/15 09:46:03.985| 28,3| Acl.cc(175) matches: checked: http_access#6 = -1 async
2024/02/15 09:46:03.985| 28,3| Acl.cc(175) matches: checked: http_access = -1 async
2024/02/15 09:46:03.985| 28,5| InnerNode.cc(97) resumeMatchingAt: checking http_access at 5
2024/02/15 09:46:03.985| 28,5| Checklist.cc(390) bannedAction: Action 'DENIED/0' is not banned
2024/02/15 09:46:03.985| 28,5| InnerNode.cc(97) resumeMatchingAt: checking http_access#6 at 0
2024/02/15 09:46:03.986| 28,5| Acl.cc(148) matches: checking to_localhost
2024/02/15 09:46:03.986| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: 193.99.144.85/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff] (193.99.144.85)  vs [::]-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]
2024/02/15 09:46:03.986| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: 193.99.144.85/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff] (193.99.144.85)  vs [::1]-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]
2024/02/15 09:46:03.986| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: 193.99.144.85/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff] (193.99.144.85)  vs 0.0.0.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]
2024/02/15 09:46:03.986| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: 193.99.144.85/[ffff:ffff:ffff:ffff:ffff:ffff:ff00:0] (193.0.0.0)  vs 127.0.0.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ff00:0]
2024/02/15 09:46:03.986| 28,3| Ip.cc(538) match: aclIpMatchIp: '193.99.144.85' NOT found
2024/02/15 09:46:03.986| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: [2a02:2e0:3fe:1001:7777:772e:2:85]/[ffff:ffff:ffff:ffff:ffff:ffff:ff00:0] ([2a02:2e0:3fe:1001:7777:772e::])  vs 127.0.0.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ff00:0]
2024/02/15 09:46:03.986| 28,3| Ip.cc(538) match: aclIpMatchIp: '[2a02:2e0:3fe:1001:7777:772e:2:85]' NOT found
2024/02/15 09:46:03.986| 28,3| Acl.cc(175) matches: checked: to_localhost = 0
2024/02/15 09:46:03.986| 28,3| InnerNode.cc(100) resumeMatchingAt: checked: http_access#6 = 0
2024/02/15 09:46:03.986| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/0' is not banned
2024/02/15 09:46:03.986| 28,5| Acl.cc(148) matches: checking http_access#7
2024/02/15 09:46:03.986| 28,5| Acl.cc(148) matches: checking opnproxy_ext_acl_net
2024/02/15 09:46:03.986| 28,3| AclIdent.cc(105) checkForAsync: Doing ident lookup
2024/02/15 09:46:03.986| 28,3| Acl.cc(175) matches: checked: opnproxy_ext_acl_net = -1 async
2024/02/15 09:46:03.986| 28,3| Acl.cc(175) matches: checked: http_access#7 = -1 async
2024/02/15 09:46:03.986| 28,3| InnerNode.cc(100) resumeMatchingAt: checked: http_access = -1 async
2024/02/15 09:46:14.086| 28,5| InnerNode.cc(97) resumeMatchingAt: checking http_access at 6
2024/02/15 09:46:14.086| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/0' is not banned
2024/02/15 09:46:14.086| 28,5| InnerNode.cc(97) resumeMatchingAt: checking http_access#7 at 0
2024/02/15 09:46:14.086| 28,5| Acl.cc(148) matches: checking opnproxy_ext_acl_net
2024/02/15 09:46:14| ERROR: ALE missing IDENT
    current master transaction: master53
2024/02/15 09:46:14.086| 28,2| Checklist.cc(128) goAsync: 0x8464b3018 a slow ACL resumes by going async again! (loop #0)
2024/02/15 09:46:14.086| 28,9| Acl.cc(121) FindByName: ACL::FindByName 'opnproxy_ext_acl_net'
2024/02/15 09:46:14| Starting new external_acl_type helpers...
    current master transaction: master53
2024/02/15 09:46:14| helperOpenServers: Starting 1/5 'squid_acl_helper.py' processes
    current master transaction: master53
2024/02/15 09:46:14.087| 28,3| Acl.cc(175) matches: checked: opnproxy_ext_acl_net = -1 async
2024/02/15 09:46:14.087| 28,3| InnerNode.cc(100) resumeMatchingAt: checked: http_access#7 = -1 async
2024/02/15 09:46:14.087| 28,3| InnerNode.cc(100) resumeMatchingAt: checked: http_access = -1 async
2024/02/15 09:46:14.176| 28,5| InnerNode.cc(97) resumeMatchingAt: checking http_access at 6
2024/02/15 09:46:14.176| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/0' is not banned
2024/02/15 09:46:14.176| 28,5| InnerNode.cc(97) resumeMatchingAt: checking http_access#7 at 0
2024/02/15 09:46:14.176| 28,5| Acl.cc(148) matches: checking opnproxy_ext_acl_net
2024/02/15 09:46:14.176| 28,3| Acl.cc(175) matches: checked: opnproxy_ext_acl_net = 0
2024/02/15 09:46:14.176| 28,3| InnerNode.cc(100) resumeMatchingAt: checked: http_access#7 = 0
2024/02/15 09:46:14.176| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/0' is not banned
2024/02/15 09:46:14.176| 28,5| Acl.cc(148) matches: checking http_access#8
2024/02/15 09:46:14.176| 28,5| Acl.cc(148) matches: checking opnproxy_ext_acl_usr
2024/02/15 09:46:14.176| 28,3| AclProxyAuth.cc(118) checkForAsync: checking password via authenticator
2024/02/15 09:46:14| Starting new basicauthenticator helpers...
    current master transaction: master53
2024/02/15 09:46:14| helperOpenServers: Starting 1/50 'basic_pam_auth' processes
    current master transaction: master53
2024/02/15 09:46:14.177| 28,4| Acl.cc(72) AuthenticateAcl: returning 2 sending credentials to helper.
2024/02/15 09:46:14.177| 28,3| Acl.cc(175) matches: checked: opnproxy_ext_acl_usr = -1 async
2024/02/15 09:46:14.177| 28,3| Acl.cc(175) matches: checked: http_access#8 = -1 async
2024/02/15 09:46:14.177| 28,3| InnerNode.cc(100) resumeMatchingAt: checked: http_access = -1 async
2024/02/15 09:46:14.384| 28,5| InnerNode.cc(97) resumeMatchingAt: checking http_access at 7
2024/02/15 09:46:14.384| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/0' is not banned
2024/02/15 09:46:14.384| 28,5| InnerNode.cc(97) resumeMatchingAt: checking http_access#8 at 0
2024/02/15 09:46:14.384| 28,5| Acl.cc(148) matches: checking opnproxy_ext_acl_usr
2024/02/15 09:46:14.384| 28,2| Checklist.cc(128) goAsync: 0x8464b3018 a slow ACL resumes by going async again! (loop #0)
2024/02/15 09:46:14.384| 28,9| Acl.cc(121) FindByName: ACL::FindByName 'opnproxy_ext_acl_usr'
2024/02/15 09:46:14| Starting new external_acl_type helpers...
    current master transaction: master53
2024/02/15 09:46:14| helperOpenServers: Starting 1/5 'squid_acl_helper.py' processes
    current master transaction: master53
2024/02/15 09:46:14.384| 28,3| Acl.cc(175) matches: checked: opnproxy_ext_acl_usr = -1 async
2024/02/15 09:46:14.384| 28,3| InnerNode.cc(100) resumeMatchingAt: checked: http_access#8 = -1 async
2024/02/15 09:46:14.384| 28,3| InnerNode.cc(100) resumeMatchingAt: checked: http_access = -1 async
2024/02/15 09:46:14.472| 28,5| InnerNode.cc(97) resumeMatchingAt: checking http_access at 7
2024/02/15 09:46:14.472| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/0' is not banned
2024/02/15 09:46:14.472| 28,5| InnerNode.cc(97) resumeMatchingAt: checking http_access#8 at 0
2024/02/15 09:46:14.472| 28,5| Acl.cc(148) matches: checking opnproxy_ext_acl_usr
2024/02/15 09:46:14.472| 28,3| Acl.cc(175) matches: checked: opnproxy_ext_acl_usr = 1
2024/02/15 09:46:14.472| 28,3| InnerNode.cc(100) resumeMatchingAt: checked: http_access#8 = 1
2024/02/15 09:46:14.472| 28,3| InnerNode.cc(100) resumeMatchingAt: checked: http_access = 1
2024/02/15 09:46:14.472| 28,3| Checklist.cc(62) markFinished: 0x8464b3018 answer ALLOWED for match
2024/02/15 09:46:14.472| 28,3| Checklist.cc(162) checkCallback: ACLChecklist::checkCallback: 0x8464b3018 answer=ALLOWED
2024/02/15 09:46:14| FATAL: assertion failed: FilledChecklist.cc:263: "!rfc931[0]"
    current master transaction: master53
Abort trap
  • curl -vI --proxy-header "Proxy-Authorization: Basic <BASE64>" --proxy "http://192.168.0.1:3128" https://www.heise.de 
*   Trying 192.168.0.1:3128...
* Connected to 192.168.0.1 (192.168.0.1) port 3128
* CONNECT tunnel: HTTP/1.1 negotiated
* allocate connect buffer
* Establish HTTP proxy tunnel to www.heise.de:443
> CONNECT www.heise.de:443 HTTP/1.1
> Host: www.heise.de:443
> User-Agent: curl/8.5.0
> Proxy-Connection: Keep-Alive
> Proxy-Authorization: Basic <BASE64>
> 
* Proxy CONNECT aborted
* Closing connection
curl: (56) Proxy CONNECT aborted
  • /var/log/system/latest.log 
<149>1 2024-02-15T09:57:33+01:00 WEBPROXY01.domain.local squid 39321 - [meta sequenceId="1"] ACL-REQ |opnproxy_ext_acl_net| |-| |192.168.0.1| |CONNECT| |www.heise.de:443| SNI only
<149>1 2024-02-15T09:57:33+01:00 WEBPROXY01.domain.local squid 39321 - [meta sequenceId="2"] ERR message="no (valid) IDENT -"
<13>1 2024-02-15T09:57:34+01:00 WEBPROXY01.domain.local opnsense-business 40832 - [meta sequenceId="3"] /usr/local/sbin/pluginctl: plugins_configure user_changed (1,activedirectoryuser)
<13>1 2024-02-15T09:57:34+01:00 WEBPROXY01.domain.local opnsense-business 40832 - [meta sequenceId="4"] /usr/local/sbin/pluginctl: plugins_configure user_changed (execute task : core_user_changed_groups(1,activedirectoryuser))
<13>1 2024-02-15T09:57:34+01:00 WEBPROXY01.domain.local opnsense-business 40832 - [meta sequenceId="5"] /usr/local/sbin/pluginctl: plugins_configure user_changed (execute task : opnproxy_user_changed(1,activedirectoryuser))
<173>1 2024-02-15T09:57:34+01:00 WEBPROXY01.domain.local php 40430 - [meta sequenceId="6"] user activedirectoryuser authenticated successfully for squid [using OPNsense\Auth\Services\Squid + OPNsense\Auth\LDAP]
<149>1 2024-02-15T09:57:34+01:00 WEBPROXY01.domain.local squid 43087 - [meta sequenceId="7"] ACL-REQ |opnproxy_ext_acl_usr| |activedirectoryuser| |192.168.0.1| |CONNECT| |www.heise.de:443| SNI only
<149>1 2024-02-15T09:57:34+01:00 WEBPROXY01.domain.local squid 43087 - [meta sequenceId="8"] OK message="whitelisted 1f6355a8-58ff-4aa2-af37-e7d49c30c1d6" user="activedirectoryuser"
<13>1 2024-02-15T09:57:34+01:00 WEBPROXY01.domain.local kernel - - [meta sequenceId="9"] <6>pid 27605 (squid), jid 0, uid 100: exited on signal 6
<13>1 2024-02-15T09:57:34+01:00 WEBPROXY01.domain.local configctl 15649 - [meta sequenceId="10"] event @ 1707987453.98 msg: Feb 15 09:57:33 WEBPROXY01.domain.local config[40430]: config-event: new_config /conf/backup/config-1707987453.9806.xml 
<13>1 2024-02-15T09:57:34+01:00 WEBPROXY01.domain.local configctl 15649 - [meta sequenceId="11"] event @ 1707987453.98 exec: system event config_changed

If we comment out line 2, 3 and 4 in /usr/local/etc/squid/auth/10-opnproxy-ext.auth.conf, the connection is possible and no errors logged. Also works if we replace in line 2 %IDENT with %LOGIN.

curl again:

*   Trying 192.168.0.1:3128...
* Connected to 192.168.0.1 (192.168.0.1) port 3128
* CONNECT tunnel: HTTP/1.1 negotiated
* allocate connect buffer
* Establish HTTP proxy tunnel to www.heise.de:443
> CONNECT www.heise.de:443 HTTP/1.1
> Host: www.heise.de:443
> User-Agent: curl/8.5.0
> Proxy-Connection: Keep-Alive
> Proxy-Authorization: Basic <BASE64>
> 
< HTTP/1.1 200 Connection established
HTTP/1.1 200 Connection established
< 

* CONNECT phase completed
* CONNECT tunnel established, response 200
* ALPN: curl offers h2,http/1.1
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256 / [blank] / UNDEF
* ALPN: server accepted h2
* Server certificate:
*  subject: CN=www.heise.de
*  start date: Jan 24 04:41:24 2024 GMT
*  expire date: Apr 23 04:41:23 2024 GMT
*  subjectAltName: host "www.heise.de" matched cert's "www.heise.de"
*  issuer: C=US; O=Let's Encrypt; CN=R3
*  SSL certificate verify ok.
*   Certificate level 0: Public key type ? (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
*   Certificate level 1: Public key type ? (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
*   Certificate level 2: Public key type ? (4096/128 Bits/secBits), signed using sha256WithRSAEncryption
* using HTTP/2
* [HTTP/2] [1] OPENED stream for https://www.heise.de/
* [HTTP/2] [1] [:method: HEAD]
* [HTTP/2] [1] [:scheme: https]
* [HTTP/2] [1] [:authority: www.heise.de]
* [HTTP/2] [1] [:path: /]
* [HTTP/2] [1] [user-agent: curl/8.5.0]
* [HTTP/2] [1] [accept: */*]
> HEAD / HTTP/2
> Host: www.heise.de
> User-Agent: curl/8.5.0
> Accept: */*
> 
< HTTP/2 200 
HTTP/2 200 
< server: nginx
server: nginx
< date: Thu, 15 Feb 2024 08:51:20 GMT
date: Thu, 15 Feb 2024 08:51:20 GMT
< content-type: text/html; charset=UTF-8
content-type: text/html; charset=UTF-8
< last-modified: Thu, 15 Feb 2024 08:51:20 GMT
last-modified: Thu, 15 Feb 2024 08:51:20 GMT
< age: 24
age: 24
< accept-ranges: bytes
accept-ranges: bytes
< strict-transport-security: max-age=15768000
strict-transport-security: max-age=15768000
< x-frame-options: DENY
x-frame-options: DENY
< x-xss-protection: 1; mode=block
x-xss-protection: 1; mode=block
< x-content-type-options: nosniff
x-content-type-options: nosniff
< x-hacc-refreshed: 
x-hacc-refreshed: 
< vary: Accept-Encoding, X-Export-Format, X-Export-Agent, X-Export-IAP
vary: Accept-Encoding, X-Export-Format, X-Export-Agent, X-Export-IAP
< cache-control: no-store
cache-control: no-store
< content-length: 934626
content-length: 934626

< 
* Connection #0 to host 192.168.0.1 left intact

/usr/local/sbin/squid -d9 -N -f /usr/local/etc/squid/squid.conf
..
..
..
2024/02/15 09:51:45.057| 28,4| Eui48.cc(438) lookup: Got address 00:50:56:b1:ec:62
2024/02/15 09:51:45.057| 28,3| Checklist.cc(69) preCheck: 0x8496c4018 checking slow rules
2024/02/15 09:51:45.057| 28,5| Acl.cc(148) matches: checking http_access
2024/02/15 09:51:45.057| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/0' is not banned
2024/02/15 09:51:45.057| 28,5| Acl.cc(148) matches: checking http_access#1
2024/02/15 09:51:45.057| 28,5| Acl.cc(148) matches: checking ftp
2024/02/15 09:51:45.057| 28,3| Acl.cc(175) matches: checked: ftp = 0
2024/02/15 09:51:45.057| 28,3| Acl.cc(175) matches: checked: http_access#1 = 0
2024/02/15 09:51:45.057| 28,5| Checklist.cc(390) bannedAction: Action 'DENIED/0' is not banned
2024/02/15 09:51:45.057| 28,5| Acl.cc(148) matches: checking http_access#2
2024/02/15 09:51:45.057| 28,5| Acl.cc(148) matches: checking !Safe_ports
2024/02/15 09:51:45.057| 28,5| Acl.cc(148) matches: checking Safe_ports
2024/02/15 09:51:45.057| 28,3| Acl.cc(175) matches: checked: Safe_ports = 1
2024/02/15 09:51:45.057| 28,3| Acl.cc(175) matches: checked: !Safe_ports = 0
2024/02/15 09:51:45.057| 28,3| Acl.cc(175) matches: checked: http_access#2 = 0
2024/02/15 09:51:45.057| 28,5| Checklist.cc(390) bannedAction: Action 'DENIED/0' is not banned
2024/02/15 09:51:45.057| 28,5| Acl.cc(148) matches: checking http_access#3
2024/02/15 09:51:45.057| 28,5| Acl.cc(148) matches: checking CONNECT
2024/02/15 09:51:45.057| 28,3| Acl.cc(175) matches: checked: CONNECT = 1
2024/02/15 09:51:45.057| 28,5| Acl.cc(148) matches: checking !SSL_ports
2024/02/15 09:51:45.057| 28,5| Acl.cc(148) matches: checking SSL_ports
2024/02/15 09:51:45.057| 28,3| Acl.cc(175) matches: checked: SSL_ports = 1
2024/02/15 09:51:45.057| 28,3| Acl.cc(175) matches: checked: !SSL_ports = 0
2024/02/15 09:51:45.057| 28,3| Acl.cc(175) matches: checked: http_access#3 = 0
2024/02/15 09:51:45.057| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/0' is not banned
2024/02/15 09:51:45.057| 28,5| Acl.cc(148) matches: checking http_access#4
2024/02/15 09:51:45.057| 28,5| Acl.cc(148) matches: checking localhost
2024/02/15 09:51:45.057| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: 192.168.0.1:20264/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff] (192.168.0.1:20264)  vs [::1]-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]
2024/02/15 09:51:45.057| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: 192.168.0.1:20264/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff] (192.168.0.1:20264)  vs 127.0.0.1-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]
2024/02/15 09:51:45.057| 28,3| Ip.cc(538) match: aclIpMatchIp: '192.168.0.1:20264' NOT found
2024/02/15 09:51:45.057| 28,3| Acl.cc(175) matches: checked: localhost = 0
2024/02/15 09:51:45.057| 28,3| Acl.cc(175) matches: checked: http_access#4 = 0
2024/02/15 09:51:45.057| 28,5| Checklist.cc(390) bannedAction: Action 'DENIED/0' is not banned
2024/02/15 09:51:45.057| 28,5| Acl.cc(148) matches: checking http_access#5
2024/02/15 09:51:45.057| 28,5| Acl.cc(148) matches: checking manager
2024/02/15 09:51:45.057| 28,3| RegexData.cc(50) match: checking 'www.heise.de:443'
2024/02/15 09:51:45.057| 28,3| Acl.cc(175) matches: checked: manager = 0
2024/02/15 09:51:45.057| 28,3| Acl.cc(175) matches: checked: http_access#5 = 0
2024/02/15 09:51:45.057| 28,5| Checklist.cc(390) bannedAction: Action 'DENIED/0' is not banned
2024/02/15 09:51:45.057| 28,5| Acl.cc(148) matches: checking http_access#6
2024/02/15 09:51:45.057| 28,5| Acl.cc(148) matches: checking to_localhost
2024/02/15 09:51:45.058| 28,3| DestinationIp.cc(78) match: can't yet compare 'to_localhost' ACL for www.heise.de
2024/02/15 09:51:45.058| 28,3| Acl.cc(175) matches: checked: to_localhost = -1 async
2024/02/15 09:51:45.058| 28,3| Acl.cc(175) matches: checked: http_access#6 = -1 async
2024/02/15 09:51:45.058| 28,3| Acl.cc(175) matches: checked: http_access = -1 async
2024/02/15 09:51:45.058| 28,5| InnerNode.cc(97) resumeMatchingAt: checking http_access at 5
2024/02/15 09:51:45.058| 28,5| Checklist.cc(390) bannedAction: Action 'DENIED/0' is not banned
2024/02/15 09:51:45.058| 28,5| InnerNode.cc(97) resumeMatchingAt: checking http_access#6 at 0
2024/02/15 09:51:45.058| 28,5| Acl.cc(148) matches: checking to_localhost
2024/02/15 09:51:45.058| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: 193.99.144.85/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff] (193.99.144.85)  vs [::]-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]
2024/02/15 09:51:45.058| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: 193.99.144.85/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff] (193.99.144.85)  vs [::1]-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]
2024/02/15 09:51:45.058| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: 193.99.144.85/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff] (193.99.144.85)  vs 0.0.0.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]
2024/02/15 09:51:45.058| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: 193.99.144.85/[ffff:ffff:ffff:ffff:ffff:ffff:ff00:0] (193.0.0.0)  vs 127.0.0.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ff00:0]
2024/02/15 09:51:45.058| 28,3| Ip.cc(538) match: aclIpMatchIp: '193.99.144.85' NOT found
2024/02/15 09:51:45.058| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: [2a02:2e0:3fe:1001:7777:772e:2:85]/[ffff:ffff:ffff:ffff:ffff:ffff:ff00:0] ([2a02:2e0:3fe:1001:7777:772e::])  vs 127.0.0.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ff00:0]
2024/02/15 09:51:45.058| 28,3| Ip.cc(538) match: aclIpMatchIp: '[2a02:2e0:3fe:1001:7777:772e:2:85]' NOT found
2024/02/15 09:51:45.058| 28,3| Acl.cc(175) matches: checked: to_localhost = 0
2024/02/15 09:51:45.058| 28,3| InnerNode.cc(100) resumeMatchingAt: checked: http_access#6 = 0
2024/02/15 09:51:45.058| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/0' is not banned
2024/02/15 09:51:45.058| 28,5| Acl.cc(148) matches: checking http_access#7
2024/02/15 09:51:45.058| 28,5| Acl.cc(148) matches: checking opnproxy_ext_acl_usr
2024/02/15 09:51:45.058| 28,3| AclProxyAuth.cc(118) checkForAsync: checking password via authenticator
2024/02/15 09:51:45| Starting new basicauthenticator helpers...
    current master transaction: master53
2024/02/15 09:51:45| helperOpenServers: Starting 1/50 'basic_pam_auth' processes
    current master transaction: master53
2024/02/15 09:51:45.058| 28,4| Acl.cc(72) AuthenticateAcl: returning 2 sending credentials to helper.
2024/02/15 09:51:45.058| 28,3| Acl.cc(175) matches: checked: opnproxy_ext_acl_usr = -1 async
2024/02/15 09:51:45.058| 28,3| Acl.cc(175) matches: checked: http_access#7 = -1 async
2024/02/15 09:51:45.058| 28,3| InnerNode.cc(100) resumeMatchingAt: checked: http_access = -1 async
2024/02/15 09:51:45.364| 28,5| InnerNode.cc(97) resumeMatchingAt: checking http_access at 6
2024/02/15 09:51:45.364| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/0' is not banned
2024/02/15 09:51:45.364| 28,5| InnerNode.cc(97) resumeMatchingAt: checking http_access#7 at 0
2024/02/15 09:51:45.364| 28,5| Acl.cc(148) matches: checking opnproxy_ext_acl_usr
2024/02/15 09:51:45.364| 28,2| Checklist.cc(128) goAsync: 0x8496c4018 a slow ACL resumes by going async again! (loop #0)
2024/02/15 09:51:45.364| 28,9| Acl.cc(121) FindByName: ACL::FindByName 'opnproxy_ext_acl_usr'
2024/02/15 09:51:45| Starting new external_acl_type helpers...
    current master transaction: master53
2024/02/15 09:51:45| helperOpenServers: Starting 1/5 'squid_acl_helper.py' processes
    current master transaction: master53
2024/02/15 09:51:45.365| 28,3| Acl.cc(175) matches: checked: opnproxy_ext_acl_usr = -1 async
2024/02/15 09:51:45.365| 28,3| InnerNode.cc(100) resumeMatchingAt: checked: http_access#7 = -1 async
2024/02/15 09:51:45.365| 28,3| InnerNode.cc(100) resumeMatchingAt: checked: http_access = -1 async
2024/02/15 09:51:45.454| 28,5| InnerNode.cc(97) resumeMatchingAt: checking http_access at 6
2024/02/15 09:51:45.454| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/0' is not banned
2024/02/15 09:51:45.455| 28,5| InnerNode.cc(97) resumeMatchingAt: checking http_access#7 at 0
2024/02/15 09:51:45.455| 28,5| Acl.cc(148) matches: checking opnproxy_ext_acl_usr
2024/02/15 09:51:45.455| 28,3| Acl.cc(175) matches: checked: opnproxy_ext_acl_usr = 1
2024/02/15 09:51:45.455| 28,3| InnerNode.cc(100) resumeMatchingAt: checked: http_access#7 = 1
2024/02/15 09:51:45.455| 28,3| InnerNode.cc(100) resumeMatchingAt: checked: http_access = 1
2024/02/15 09:51:45.455| 28,3| Checklist.cc(62) markFinished: 0x8496c4018 answer ALLOWED for match
2024/02/15 09:51:45.455| 28,3| Checklist.cc(162) checkCallback: ACLChecklist::checkCallback: 0x8496c4018 answer=ALLOWED
2024/02/15 09:51:45.455| 28,4| FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x820b46e08
2024/02/15 09:51:45.455| 28,4| Checklist.cc(196) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x820b46e08
2024/02/15 09:51:45.455| 28,3| Checklist.cc(69) preCheck: 0x8496c4218 checking slow rules
2024/02/15 09:51:45.455| 28,5| Acl.cc(148) matches: checking (ssl_bump rules)
2024/02/15 09:51:45.455| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/3' is not banned
2024/02/15 09:51:45.455| 28,5| Acl.cc(148) matches: checking (ssl_bump rule)
2024/02/15 09:51:45.455| 28,5| Acl.cc(148) matches: checking bump_step1
2024/02/15 09:51:45.455| 28,3| Acl.cc(175) matches: checked: bump_step1 = 1
2024/02/15 09:51:45.455| 28,5| Acl.cc(148) matches: checking all
2024/02/15 09:51:45.455| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: 192.168.0.1:20264/[::] ([::]:20264)  vs [::]-[::]/[::]
2024/02/15 09:51:45.455| 28,3| Ip.cc(538) match: aclIpMatchIp: '192.168.0.1:20264' found
2024/02/15 09:51:45.455| 28,3| Acl.cc(175) matches: checked: all = 1
2024/02/15 09:51:45.455| 28,3| Acl.cc(175) matches: checked: (ssl_bump rule) = 1
2024/02/15 09:51:45.455| 28,3| Acl.cc(175) matches: checked: (ssl_bump rules) = 1
2024/02/15 09:51:45.455| 28,3| Checklist.cc(62) markFinished: 0x8496c4218 answer ALLOWED for match
2024/02/15 09:51:45.455| 28,3| Checklist.cc(162) checkCallback: ACLChecklist::checkCallback: 0x8496c4218 answer=ALLOWED
2024/02/15 09:51:45.455| 28,4| FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x820b46ad8
2024/02/15 09:51:45.455| 28,4| Checklist.cc(196) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x820b46ad8
2024/02/15 09:51:45.455| 28,4| FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x8496c4218
2024/02/15 09:51:45.455| 28,4| Checklist.cc(196) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x8496c4218
2024/02/15 09:51:45.455| 28,4| FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x8496c4018
2024/02/15 09:51:45.455| 28,4| Checklist.cc(196) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x8496c4018
2024/02/15 09:51:45.455| 33,2| client_side.cc(522) setAuth: Adding connection-auth to conn15 local=192.168.0.1:3128 remote=192.168.0.1:20264 FD 13 flags=1 from SSL-bumped CONNECT
2024/02/15 09:51:45.455| 28,3| Checklist.cc(69) preCheck: 0x8496c4018 checking slow rules
2024/02/15 09:51:45.455| 28,5| Acl.cc(148) matches: checking (ssl_bump rules)
2024/02/15 09:51:45.455| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/3' is not banned
2024/02/15 09:51:45.455| 28,5| Acl.cc(148) matches: checking (ssl_bump rule)
2024/02/15 09:51:45.455| 28,5| Acl.cc(148) matches: checking bump_step1
2024/02/15 09:51:45.455| 28,3| Acl.cc(175) matches: checked: bump_step1 = 0
2024/02/15 09:51:45.455| 28,3| Acl.cc(175) matches: checked: (ssl_bump rule) = 0
2024/02/15 09:51:45.455| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/6' is not banned
2024/02/15 09:51:45.455| 28,5| Acl.cc(148) matches: checking (ssl_bump rule)
2024/02/15 09:51:45.455| 28,5| Acl.cc(148) matches: checking all
2024/02/15 09:51:45.455| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: 192.168.0.1:20264/[::] ([::]:20264)  vs [::]-[::]/[::]
2024/02/15 09:51:45.455| 28,3| Ip.cc(538) match: aclIpMatchIp: '192.168.0.1:20264' found
2024/02/15 09:51:45.455| 28,3| Acl.cc(175) matches: checked: all = 1
2024/02/15 09:51:45.455| 28,3| Acl.cc(175) matches: checked: (ssl_bump rule) = 1
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: (ssl_bump rules) = 1
2024/02/15 09:51:45.456| 28,3| Checklist.cc(62) markFinished: 0x8496c4018 answer ALLOWED for match
2024/02/15 09:51:45.456| 28,3| Checklist.cc(162) checkCallback: ACLChecklist::checkCallback: 0x8496c4018 answer=ALLOWED
2024/02/15 09:51:45.456| 33,2| client_side.cc(3201) initiateTunneledRequest: Request tunneling for splice
2024/02/15 09:51:45.456| 28,3| Checklist.cc(69) preCheck: 0x8496c4218 checking slow rules
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking http_access
2024/02/15 09:51:45.456| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/0' is not banned
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking http_access#1
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking ftp
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: ftp = 0
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: http_access#1 = 0
2024/02/15 09:51:45.456| 28,5| Checklist.cc(390) bannedAction: Action 'DENIED/0' is not banned
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking http_access#2
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking !Safe_ports
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking Safe_ports
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: Safe_ports = 1
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: !Safe_ports = 0
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: http_access#2 = 0
2024/02/15 09:51:45.456| 28,5| Checklist.cc(390) bannedAction: Action 'DENIED/0' is not banned
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking http_access#3
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking CONNECT
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: CONNECT = 1
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking !SSL_ports
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking SSL_ports
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: SSL_ports = 1
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: !SSL_ports = 0
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: http_access#3 = 0
2024/02/15 09:51:45.456| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/0' is not banned
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking http_access#4
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking localhost
2024/02/15 09:51:45.456| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: 192.168.0.1:20264/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff] (192.168.0.1:20264)  vs 127.0.0.1-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]
2024/02/15 09:51:45.456| 28,3| Ip.cc(538) match: aclIpMatchIp: '192.168.0.1:20264' NOT found
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: localhost = 0
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: http_access#4 = 0
2024/02/15 09:51:45.456| 28,5| Checklist.cc(390) bannedAction: Action 'DENIED/0' is not banned
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking http_access#5
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking manager
2024/02/15 09:51:45.456| 28,3| RegexData.cc(50) match: checking 'www.heise.de:443'
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: manager = 0
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: http_access#5 = 0
2024/02/15 09:51:45.456| 28,5| Checklist.cc(390) bannedAction: Action 'DENIED/0' is not banned
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking http_access#6
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking to_localhost
2024/02/15 09:51:45.456| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: 193.99.144.85/[ffff:ffff:ffff:ffff:ffff:ffff:ff00:0] (193.0.0.0)  vs 127.0.0.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ff00:0]
2024/02/15 09:51:45.456| 28,3| Ip.cc(538) match: aclIpMatchIp: '193.99.144.85' NOT found
2024/02/15 09:51:45.456| 28,9| Ip.cc(96) aclIpAddrNetworkCompare: aclIpAddrNetworkCompare: compare: [2a02:2e0:3fe:1001:7777:772e:2:85]/[ffff:ffff:ffff:ffff:ffff:ffff:ff00:0] ([2a02:2e0:3fe:1001:7777:772e::])  vs 127.0.0.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ff00:0]
2024/02/15 09:51:45.456| 28,3| Ip.cc(538) match: aclIpMatchIp: '[2a02:2e0:3fe:1001:7777:772e:2:85]' NOT found
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: to_localhost = 0
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: http_access#6 = 0
2024/02/15 09:51:45.456| 28,5| Checklist.cc(390) bannedAction: Action 'ALLOWED/0' is not banned
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking http_access#7
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking opnproxy_ext_acl_usr
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: opnproxy_ext_acl_usr = 1
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: http_access#7 = 1
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: http_access = 1
2024/02/15 09:51:45.456| 28,3| Checklist.cc(62) markFinished: 0x8496c4218 answer ALLOWED for match
2024/02/15 09:51:45.456| 28,3| Checklist.cc(162) checkCallback: ACLChecklist::checkCallback: 0x8496c4218 answer=ALLOWED
2024/02/15 09:51:45.456| 28,4| FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x820b46778
2024/02/15 09:51:45.456| 28,4| Checklist.cc(196) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x820b46778
2024/02/15 09:51:45.456| 28,4| FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x8496c4218
2024/02/15 09:51:45.456| 28,4| Checklist.cc(196) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x8496c4218
2024/02/15 09:51:45.456| 28,4| FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x8496c4018
2024/02/15 09:51:45.456| 28,4| Checklist.cc(196) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x8496c4018
2024/02/15 09:51:45.456| 28,3| Checklist.cc(69) preCheck: 0x820b47128 checking fast ACLs
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking access_log stdio:/var/log/squid/access.log
2024/02/15 09:51:45.456| 28,5| Acl.cc(148) matches: checking (access_log stdio:/var/log/squid/access.log line)
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: (access_log stdio:/var/log/squid/access.log line) = 1
2024/02/15 09:51:45.456| 28,3| Acl.cc(175) matches: checked: access_log stdio:/var/log/squid/access.log = 1
2024/02/15 09:51:45.456| 28,3| Checklist.cc(62) markFinished: 0x820b47128 answer ALLOWED for match
2024/02/15 09:51:45.456| 28,4| Eui48.cc(129) encode: id=0x82d059eb8 encoded 00:50:56:b1:ec:62
2024/02/15 09:51:45.456| 28,4| FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x820b47128
2024/02/15 09:51:45.456| 28,4| Checklist.cc(196) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x820b47128
2024/02/15 09:51:45.470| 28,3| Checklist.cc(69) preCheck: 0x820b47328 checking fast ACLs
2024/02/15 09:51:45.470| 28,5| Acl.cc(148) matches: checking access_log stdio:/var/log/squid/access.log
2024/02/15 09:51:45.470| 28,5| Acl.cc(148) matches: checking (access_log stdio:/var/log/squid/access.log line)
2024/02/15 09:51:45.470| 28,3| Acl.cc(175) matches: checked: (access_log stdio:/var/log/squid/access.log line) = 1
2024/02/15 09:51:45.470| 28,3| Acl.cc(175) matches: checked: access_log stdio:/var/log/squid/access.log = 1
2024/02/15 09:51:45.470| 28,3| Checklist.cc(62) markFinished: 0x820b47328 answer ALLOWED for match
2024/02/15 09:51:45.470| 28,4| Eui48.cc(129) encode: id=0x82d059eb8 encoded 00:50:56:b1:ec:62
2024/02/15 09:51:45.470| 28,4| FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x820b47328
2024/02/15 09:51:45.470| 28,4| Checklist.cc(196) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x820b47328
2024/02/15 09:51:45.470| 33,2| client_side.cc(617) swanSong: conn15 local=192.168.0.1:3128 remote=192.168.0.1:20264 flags=1
2024/02/15 09:51:45.470| 33,2| client_side.cc(572) setAuth: WARNING: Graceful closure on conn15 local=192.168.0.1:3128 remote=192.168.0.1:20264 flags=1 due to connection-auth erase from ConnStateData::SwanSong cleanup


^C2024/02/15 09:51:48| Preparing for shutdown after 2 requests
2024/02/15 09:51:48| Waiting 0 seconds for active connections to finish
2024/02/15 09:51:48| Closing HTTP(S) port 192.168.0.1:3128
    listening port: 192.168.0.1:3128
2024/02/15 09:51:49| Shutdown: Negotiate authentication.
2024/02/15 09:51:49| Shutdown: Digest authentication.
2024/02/15 09:51:49| Shutdown: Basic authentication.
2024/02/15 09:51:49| Shutting down...
2024/02/15 09:51:49| storeDirWriteCleanLogs: Starting...
2024/02/15 09:51:49|   Finished.  Wrote 0 entries.
2024/02/15 09:51:49|   Took 0.00 seconds (  0.00 entries/sec).
2024/02/15 09:51:49| Logfile: closing log stdio:/var/log/squid/store.log
2024/02/15 09:51:49| Logfile: closing log stdio:/var/log/squid/access.log
2024/02/15 09:51:49| Open FD UNSTARTED     0 stdin
2024/02/15 09:51:49| Open FD UNSTARTED     1 stdout
2024/02/15 09:51:49| Open FD UNSTARTED     2 stderr
2024/02/15 09:51:49| Open FD UNSTARTED    12 security_file_certgen #1
2024/02/15 09:51:49| Open FD UNSTARTED    14 security_file_certgen #2
2024/02/15 09:51:49| Open FD READ/WRITE   15 basic_pam_auth #1
2024/02/15 09:51:49| Open FD UNSTARTED    16 security_file_certgen #3
2024/02/15 09:51:49| Open FD UNSTARTED    18 security_file_certgen #4
2024/02/15 09:51:49| Open FD READ/WRITE   19 squid_acl_helper.py #1
2024/02/15 09:51:49| Open FD UNSTARTED    20 security_file_certgen #5
2024/02/15 09:51:49| Squid Cache (Version 6.6): Exiting normally.
2024/02/15 09:51:49| Removing PID file (/var/run/squid/squid.pid)

In the /var/log/system/latest.log you can see that squid starts (two) subprocesses with the Python script /usr/local/opnsense/scripts/OPNProxy/squid_acl_helper.py.
The first apparently with the first external_acl_type to the %IDENT variable, which is probably set with -. The second call calls the second external_acl_type, which probably has no content (NULL byte) in $IDENT and the child process of squid dies. The relevant code in Squid (src/acl/FilledChecklist.cc is:

ACLFilledChecklist::setIdent(const char *ident)
{
#if USE_IDENT
    assert(!rfc931[0]);
    if (ident)
        xstrncpy(rfc931, ident, USER_IDENT_SZ);
#else
    (void)ident;
#endif
}

See stderr from squid:

2024/02/15 09:46:14.086| 28,5| Acl.cc(148) matches: checking opnproxy_ext_acl_net
2024/02/15 09:46:14| ERROR: ALE missing IDENT
    current master transaction: master53
2024/02/15 09:46:14.086| 28,2| Checklist.cc(128) goAsync: 0x8464b3018 a slow ACL resumes by going async again! (loop #0)
..
..
2024/02/15 09:46:14| FATAL: assertion failed: FilledChecklist.cc:263: "!rfc931[0]"
    current master transaction: master53
Abort trap

marvinwankersteen avatar Feb 15 '24 09:02 marvinwankersteen