opnsense / plugins

OPNsense plugin collection
https://opnsense.org/
BSD 2-Clause "Simplified" License
835 stars 621 forks source link

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

Closed marvinwankersteen closed 6 months ago

marvinwankersteen commented 7 months ago

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

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

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 commented 7 months ago

Additional context

setup ssl re-cert

sslcrtd_program /usr/local/libexec/squid/security_file_certgen -s /var/squid/ssl_crtd -M 4MB sslcrtd_children 5

tls_outgoing_options options=NO_TLSv1 cipher=HIGH:MEDIUM:!RC4:!aNULL:!eNULL:!LOW:!3DES:!MD5:!EXP:!PSK:!SRP:!DSS

setup ssl bump acl's

acl bump_step1 at_step SslBump1 acl bump_step2 at_step SslBump2 acl bump_step3 at_step SslBump3 acl bump_nobumpsites ssl::server_name "/usr/local/etc/squid/nobumpsites.acl"

configure bump

ssl_bump peek bump_step1 all ssl_bump splice all ssl_bump peek bump_step2 all ssl_bump splice bump_step3 all ssl_bump bump

sslproxy_cert_error deny all

acl ftp proto FTP http_access allow ftp

Setup ftp proxy

Rules allowing access from your local networks.

Generated list of (internal) IP networks from where browsing

should be allowed. (Allow interface subnets).

Default allow for local-link and private networks

acl localnet src fc00::/7 # RFC 4193 local private network range acl localnet src fe80::/10 # RFC 4291 link-local (directly plugged) machines

ACL - Allow localhost for PURGE cache if enabled

ACL lists

ACL - Remote fetched Blacklist (remoteblacklist)

ACL - Block browser/user-agent - User defined (browser)

ACL - SSL ports, default are configured in config.xml

Configured SSL ports (if defaults are not listed, then they have been removed from the configuration!):

acl SSL_ports port 443 # https

Default Safe ports are now defined in config.xml

Configured Safe ports (if defaults are not listed, then they have been removed from the configuration!):

ACL - Safe_ports

acl Safe_ports port 443 # https acl CONNECT method CONNECT

ICAP SETTINGS

disable icap

icap_enable off

Pre-auth plugins

include /usr/local/etc/squid/pre-auth/*.conf

Authentication Settings

Configure Local User Authentication helper

auth_param basic program /usr/local/libexec/squid/basic_pam_auth -o auth_param basic realm proxy authentication auth_param basic credentialsttl 1 hours auth_param basic children 50

ACL - Local Authorized Users - local_auth

acl local_auth proxy_auth REQUIRED

Google Suite Filter

YouTube Filter

Deny requests to certain unsafe ports

http_access deny !Safe_ports

Deny CONNECT to other than secure SSL ports

http_access deny CONNECT !SSL_ports

Only allow cachemgr access from localhost

http_access allow localhost manager http_access deny manager

We strongly recommend the following be uncommented to protect innocent

web applications running on the proxy server who think the only

one who can access services on "localhost" is a local user

http_access deny to_localhost

Auth plugins

include /usr/local/etc/squid/auth/*.conf

#

Access Permission configuration:

#

Deny request from unauthorized clients

http_access allow local_auth

#

ACL - localnet - default these include ranges from selected interfaces (Allow local subnets)

http_access allow localnet

ACL - localhost

http_access allow localhost

Deny all other access to this proxy

http_access deny all

Post-auth plugins

include /usr/local/etc/squid/post-auth/*.conf

Caching settings

cache_mem 256 MB

Leave coredumps in the first cache dir

coredump_dir /var/squid/cache

#

Add any of your own refresh_pattern entries above these.

#

refresh_pattern ^ftp: 1440 20% 10080 refresh_pattern ^gopher: 1440 0% 1440 refresh_pattern -i (/cgi-bin/|\?) 0 0% 0 refresh_pattern . 0 20% 4320

Squid Options

pinger_enable off logformat opnsense %>a %[ui %>eui %[un [%tl] "%rm %ru HTTP/%rv" %>Hs %<st "%{Referer}>h" "%{User-Agent}>h" %Ss:%Sh access_log stdio:/var/log/squid/access.log opnsense cache_store_log stdio:/var/log/squid/store.log

Disable via Header

via off

Suppress http version string (default=off)

httpd_suppress_version_string on

URI handling with Whitespaces (default=strip)

uri_whitespace strip

X-Forwarded header handling (default=on)

forwarded_for delete

Disable squid logfile rotate to use system defaults

logfile_rotate 0

Define visible email

cache_mgr info@domain.local

Set error directory language

error_directory /usr/local/etc/squid/errors/local


- `/usr/local/etc/squid/proxy_policies.conf`

[policy_1f6355a8-58ff-4aa2-af37-e7d49c30c1d6] policy_type=custom description=Allow .heise.de content=.heise.de applies_on=u:root,u:activedirectoryuser source_net=192.168.0.0/24 action=allow

[policy_8d1b92d9-7222-4ad3-b1e3-2c2a18176d93] policy_type=custom description=Deny .com content=* applies_on=g:all_ad_users,u:root source_net=0.0.0.0/0 action=deny

[source] blacklist=/usr/local/opnsense/data/proxy/blacklists.tar.gz blacklist_download_uri=https://opnsense-update.deciso.com//blacklists.tar.gz blacklist_ttl=86300


- `/usr/local/etc/squid/auth/10-opnproxy-ext.auth.conf`

Ident based authentication, used to query by network, as long as we don't use IDENT, the "username" will match -

external_acl_type ext_opnproxy_helper_net ttl=30 negative_ttl=5 %ACL %IDENT %SRC %METHOD %URI /usr/local/opnsense/scripts/OPNProxy/squid_acl_helper.py --sslurlonly acl opnproxy_ext_acl_net external ext_opnproxy_helper_net http_access allow opnproxy_ext_acl_net

Login based authentication

external_acl_type ext_opnproxy_helper_usr ttl=30 negative_ttl=5 %ACL %LOGIN %SRC %METHOD %URI /usr/local/opnsense/scripts/OPNProxy/squid_acl_helper.py --sslurlonly acl opnproxy_ext_acl_usr external ext_opnproxy_helper_usr http_access allow opnproxy_ext_acl_usr

explicit disable default allow authenticated users clause

http_access deny local_auth all



**Environment**
- OPNsense 23.10.2-amd64
- Intel(R) Xeon(R) Gold 6444Y (4 cores, 4 threads)
- FreeBSD 13.2-RELEASE-p7
- OpenSSL 1.1.1w
- Licensed until 2025-01-20
- VMware Virtual Platform
- os-OPNProxy   1.0.3
- os-squid 1.0.d
- os-redis 1.1_2
- squid 6.6
- redis-server 7.2.3

**Conclusion**
The problem seems to be squid and/or the `%IDENT` variable.

I don't quite understand the meaning behind this variable, because according to the documentation you need an IDENT server for this, but as far as I know this is not available on the OPNsense and we don't have such a server running either.

I hope that someone can help us here, as we only bought the Business Edition for this plugin.

We have also tested all possible variants of the configuration, but none of this changes anything.
marvinwankersteen commented 6 months ago

Does anyone else have the problem or does anyone have an idea what the problem could be? We need the plugin we bought and it does not work.

Maybe @AdSchellevis?

AdSchellevis commented 6 months ago

@marvinwankersteen IDENT is supported in combination with stunnel (https://docs.opnsense.org/manual/how-tos/stunnel.html#enable-identd). When there is no ident server, squid shouldn't mind (never did in the past), but the overal stability of squid seemed to have declined over the years unfortunately.

Can you try to replace the %IDENT phrase to '-' and test again? Maybe we can think of a work-around and ship an updated plugin.

marvinwankersteen commented 6 months ago

@AdSchellevis: Thanks for your reply!

Yes, if we replace %IDENT with - it works. But as soon as we make changes in the GUI, the file /usr/local/etc/squid/auth/10-opnproxy-ext.auth.conf is overwritten again.

To get the plugin to work, however, it would be sufficient to comment out lines 2, 3 and 4 in /usr/local/etc/squid/auth/10-opnproxy-ext.auth.conf.

AdSchellevis commented 6 months ago

@marvinwankersteen we will first try to build the latest squid version to see of that fixes any issues, in the mean time you can disable the ident/network match in /usr/local/opnsense/service/templates/Deciso/Proxy/10-opnproxy-ext.auth.conf, which should be persistent.

marvinwankersteen commented 6 months ago

We tested it again today. The replacement of %IDENT with - did not work after all. In the /var/log/squid/cache.log the following lines appear again and again:

..
..
2024/03/04 12:04:09 kid1| Too few external_acl_type processes are running (need 1/5)
    current master transaction: master56
2024/03/04 12:04:09 kid1| Starting new helpers
    current master transaction: master56
2024/03/04 12:04:09 kid1| helperOpenServers: Starting 1/5 '-' processes
    current master transaction: master56
2024/03/04 12:04:09 kid1| ipcCreate: -: (2) No such file or directory
    current master transaction: master56
2024/03/04 12:04:09 kid1| WARNING: external_acl_type #Hlpr28293 exited
    current master transaction: master56
2024/03/04 12:04:09 kid1| Too few external_acl_type processes are running (need 1/5)
    current master transaction: master56
2024/03/04 12:04:09 kid1| Starting new helpers
    current master transaction: master56
2024/03/04 12:04:09 kid1| helperOpenServers: Starting 1/5 '-' processes
    current master transaction: master56
2024/03/04 12:04:09 kid1| ipcCreate: -: (2) No such file or directory
    current master transaction: master56
2024/03/04 12:04:09 kid1| WARNING: external_acl_type #Hlpr28294 exited
    current master transaction: master56
2024/03/04 12:04:09 kid1| Too few external_acl_type processes are running (need 1/5)
    current master transaction: master56
2024/03/04 12:04:09 kid1| Starting new helpers
    current master transaction: master56
2024/03/04 12:04:09 kid1| helperOpenServers: Starting 1/5 '-' processes
    current master transaction: master56
2024/03/04 12:04:09 kid1| ipcCreate: -: (2) No such file or directory
    current master transaction: master56
2024/03/04 12:04:09 kid1| WARNING: external_acl_type #Hlpr28295 exited
    current master transaction: master56
2024/03/04 12:04:09 kid1| Too few external_acl_type processes are running (need 1/5)
    current master transaction: master56
2024/03/04 12:04:09 kid1| Starting new helpers
    current master transaction: master56
2024/03/04 12:04:09 kid1| helperOpenServers: Starting 1/5 '-' processes
    current master transaction: master56
..
..

We then commented out lines 2, 3 and 4 in /usr/local/opnsense/service/templates/Deciso/Proxy/10-opnproxy-ext.auth.conf, as you suggested, and that made it work. Thank you.

AdSchellevis commented 6 months ago

A fix is stashed on our end which removes ident support. I expect this to be released in 24.4

jaohbib commented 3 months ago

Iam currently migrating a legacy project from squid 3.5 to 6 may i ask which version of squid you are running ?

Monviech commented 3 months ago

Thats easy, you can check the versions of all ports in their makefiles.

Here: https://github.com/opnsense/ports/blob/master/www/squid/Makefile