> On Wed, Mar 25, 2009 at 12:00 PM, Amos Jeffries <squid3@xxxxxxxxxxxxx> > wrote: >> Sounds like a bug, but there are a few things below you need to clear up >> before you can be sure its not them... > > Thank you for your fast reply. I tried your suggestion but it didn't > work. Here some details: > >> "Obsolete --enable-tproxy option. Remains only for legacy v2.2 cttproxy >> support." >> >> It does things to the kernel TPROXYv4 may not like. Kill it. >> >> the err options are also DEAD. > > Done. > > # squid -v > Squid Cache: Version 3.1.0.6 > configure options: '--enable-linux-netfilter' '--enable-ssl' > '--with-openssl=/usr/include/openssl/' '--disable-htcp' > '--with-large-files' '--prefix=/usr' '--exec_prefix=/usr' > '--bindir=/usr/sbin' '--sbindir=/usr/sbin' '--libdir=/usr/lib/squid' > '--libexecdir=/usr/lib/squid' '--docdir=/usr/share/doc/squid' > '--datarootdir=/usr/share/squid' '--datadir=/usr/share/squid' > '--sysconfdir=/etc/squid' '--localstatedir=/var/spool/squid' > '--mandir=/usr/share/man' '--with-logdir=/var/log/squid' > '--enable-inline' '--enable-async-io=8' '--with-pthreads' > '--enable-storeio=ufs,aufs,diskd' '--enable-removal-policies=lru,heap' > '--enable-snmp' '--enable-delay-pools' '--enable-cache-digests' > '--enable-underscores' '--enable-icap-client' '--enable-referer-log' > '--enable-useragent-log' '--enable-follow-x-forwarded-for' > '--enable-auth=basic,digest,ntlm' '--enable-basic-auth-helpers=NCSA' > '--enable-digest-auth-helpers=password' > '--enable-external-acl-helpers=ip_user,unix_group' > '--with-filedescriptors=65536' '--with-default-user=proxy' > --with-squid=/usr/src/squid-3.1.0.6 --enable-ltdl-convenience > >>> http_port 3128 tproxy >>> #http_port 3128 >> >> "NP: A dedicated squid port for tproxy is REQUIRED" >> >>> log_access allow all >>> cache allow all >> >> Two very redundant settings. > > Ok, I've reduced squid.conf to a minimal configuration > > # cat /etc/squid/squid.conf > acl localnet src 172.31.1.0/24 > acl SSL_ports port 443 > acl Safe_ports port 80 > http_access allow localnet > http_access deny all > http_port 3128 > http_port 3129 tproxy > coredump_dir /var/spool/squid/cache > cache_effective_user proxy > cache_effective_group proxy > access_log /var/log/squid/access.log squid > cache_store_log /var/log/squid/store.log > > # iptables -t mangle -L > Chain PREROUTING (policy ACCEPT) > target prot opt source destination > DIVERT tcp -- anywhere anywhere socket > TPROXY tcp -- anywhere anywhere tcp > dpt:www TPROXY redirect 0.0.0.0:3129 mark 0x1/0x1 > > (...) > > Chain DIVERT (1 references) > target prot opt source destination > MARK all -- anywhere anywhere MARK xset > 0x1/0xffffffff > ACCEPT all -- anywhere anywhere > > # squid -X -d1 -N -f /etc/squid/squid.conf > 2009/03/25 12:50:33.512| command-line -X overrides: ALL,7 > 2009/03/25 12:50:33.512| CacheManager::registerAction: registering legacy > mem > 2009/03/25 12:50:33.512| CacheManager::findAction: looking for action mem > 2009/03/25 12:50:33.512| Action not found. > 2009/03/25 12:50:33.512| CacheManager::registerAction: registered mem > 2009/03/25 12:50:33.512| CacheManager::registerAction: registering > legacy squidaio_counts > 2009/03/25 12:50:33.512| CacheManager::findAction: looking for action > squidaio_counts > 2009/03/25 12:50:33.512| Action not found. > 2009/03/25 12:50:33.512| CacheManager::registerAction: registered > squidaio_counts > 2009/03/25 12:50:33.512| CacheManager::registerAction: registering legacy > diskd > 2009/03/25 12:50:33.512| CacheManager::findAction: looking for action > diskd > 2009/03/25 12:50:33.512| Action not found. > 2009/03/25 12:50:33.512| CacheManager::registerAction: registered diskd > 2009/03/25 12:50:33.512| aclDestroyACLs: invoked > 2009/03/25 12:50:33.512| ACL::Prototype::Registered: invoked for type src > 2009/03/25 12:50:33.512| ACL::Prototype::Registered: yes > 2009/03/25 12:50:33.512| ACL::FindByName 'all' > 2009/03/25 12:50:33.512| ACL::FindByName found no match > 2009/03/25 12:50:33.512| aclParseAclLine: Creating ACL 'all' > 2009/03/25 12:50:33.512| ACL::Prototype::Factory: cloning an object > for type 'src' > 2009/03/25 12:50:33.512| aclIpParseIpData: all > 2009/03/25 12:50:33.513| aclParseAccessLine: looking for ACL name 'all' > 2009/03/25 12:50:33.513| ACL::FindByName 'all' > 2009/03/25 12:50:33.513| Processing Configuration File: > /etc/squid/squid.conf (depth 0) > 2009/03/25 12:50:33.514| Processing: 'acl localnet src 172.31.1.0/24' > 2009/03/25 12:50:33.514| ACL::Prototype::Registered: invoked for type src > 2009/03/25 12:50:33.514| ACL::Prototype::Registered: yes > 2009/03/25 12:50:33.514| ACL::FindByName 'localnet' > 2009/03/25 12:50:33.514| ACL::FindByName found no match > 2009/03/25 12:50:33.514| aclParseAclLine: Creating ACL 'localnet' > 2009/03/25 12:50:33.514| ACL::Prototype::Factory: cloning an object > for type 'src' > 2009/03/25 12:50:33.514| aclIpParseIpData: 172.31.1.0/24 > 2009/03/25 12:50:33.514| Processing: 'acl SSL_ports port 443' > 2009/03/25 12:50:33.514| ACL::Prototype::Registered: invoked for type port > 2009/03/25 12:50:33.514| ACL::Prototype::Registered: yes > 2009/03/25 12:50:33.514| ACL::FindByName 'SSL_ports' > 2009/03/25 12:50:33.514| ACL::FindByName found no match > 2009/03/25 12:50:33.514| aclParseAclLine: Creating ACL 'SSL_ports' > 2009/03/25 12:50:33.514| ACL::Prototype::Factory: cloning an object > for type 'port' > 2009/03/25 12:50:33.514| Processing: 'acl Safe_ports port 80' > 2009/03/25 12:50:33.514| ACL::Prototype::Registered: invoked for type port > 2009/03/25 12:50:33.514| ACL::Prototype::Registered: yes > 2009/03/25 12:50:33.514| ACL::FindByName 'Safe_ports' > 2009/03/25 12:50:33.514| ACL::FindByName found no match > 2009/03/25 12:50:33.514| aclParseAclLine: Creating ACL 'Safe_ports' > 2009/03/25 12:50:33.514| ACL::Prototype::Factory: cloning an object > for type 'port' > 2009/03/25 12:50:33.515| Processing: 'http_access allow localnet' > 2009/03/25 12:50:33.515| aclParseAccessLine: looking for ACL name > 'localnet' > 2009/03/25 12:50:33.515| ACL::FindByName 'localnet' > 2009/03/25 12:50:33.515| Processing: 'http_access deny all' > 2009/03/25 12:50:33.515| aclParseAccessLine: looking for ACL name 'all' > 2009/03/25 12:50:33.515| ACL::FindByName 'all' > 2009/03/25 12:50:33.515| Processing: 'http_port 3128' > 2009/03/25 12:50:33.515| http(s)_port: found Listen on Port: 3128 > 2009/03/25 12:50:33.515| http(s)_port: found Listen on wildcard > address: 0.0.0.0:3128 > 2009/03/25 12:50:33.515| Processing: 'http_port 3129 tproxy' > 2009/03/25 12:50:33.515| http(s)_port: found Listen on Port: 3129 > 2009/03/25 12:50:33.515| http(s)_port: found Listen on wildcard > address: 0.0.0.0:3129 > 2009/03/25 12:50:33.515| Starting IP Spoofing on port 0.0.0.0:3129 > 2009/03/25 12:50:33.515| Disabling Authentication on port 0.0.0.0:3129 > (Ip spoofing enabled) > 2009/03/25 12:50:33.515| Processing: 'coredump_dir /var/spool/squid/cache' > 2009/03/25 12:50:33.515| Processing: 'cache_effective_user proxy' > 2009/03/25 12:50:33.515| Processing: 'cache_effective_group proxy' > 2009/03/25 12:50:33.515| Processing: 'access_log > /var/log/squid/access.log squid' > 2009/03/25 12:50:33.515| Log definition name 'squid' file > '/var/log/squid/access.log' > 2009/03/25 12:50:33.515| Processing: 'cache_store_log > /var/log/squid/store.log' > 2009/03/25 12:50:33.515| aclParseAccessLine: looking for ACL name 'all' > 2009/03/25 12:50:33.515| ACL::FindByName 'all' > 2009/03/25 12:50:33.515| aclParseAccessLine: looking for ACL name 'all' > 2009/03/25 12:50:33.515| ACL::FindByName 'all' > 2009/03/25 12:50:33.515| aclParseAccessLine: looking for ACL name 'all' > 2009/03/25 12:50:33.515| ACL::FindByName 'all' > 2009/03/25 12:50:33.515| aclParseAccessLine: looking for ACL name 'all' > 2009/03/25 12:50:33.515| ACL::FindByName 'all' > 2009/03/25 12:50:33.515| aclParseAccessLine: looking for ACL name 'all' > 2009/03/25 12:50:33.515| ACL::FindByName 'all' > 2009/03/25 12:50:33.515| wccp2_add_service_list: added service id 0 > 2009/03/25 12:50:33.515| aclParseAccessLine: looking for ACL name 'all' > 2009/03/25 12:50:33.515| ACL::FindByName 'all' > 2009/03/25 12:50:33.515| tools.cc(671) uniqueHostname: Config: ' > 2009/03/25 12:50:33.516| getMyHostname: 'netflow' has rDNS. > 2009/03/25 12:50:33.516| tools.cc(671) uniqueHostname: Config: ' > 2009/03/25 12:50:33.516| acl_access::containsPURGE: invoked for > 'http_access allow localnet' > 2009/03/25 12:50:33.516| acl_access::containsPURGE: can't create tempAcl > 2009/03/25 12:50:33.516| acl_access::containsPURGE: can't create tempAcl > 2009/03/25 12:50:33.516| acl_access::containsPURGE: returning false > 2009/03/25 12:50:33.516| Initializing https proxy context > 2009/03/25 12:50:33.519| Using SSLv2/SSLv3. > 2009/03/25 12:50:33.519| Setting RSA key generation callback. > 2009/03/25 12:50:33.519| Setting certificate verification callback. > 2009/03/25 12:50:33.519| Setting CA certificate locations. > 2009/03/25 12:50:33.519| leave_suid: PID 1941 called > 2009/03/25 12:50:33.519| leave_suid: PID 1941 giving up root, becoming > 'proxy' > 2009/03/25 12:50:33.519| command-line -X overrides: ALL,1 > 2009/03/25 12:50:33.520| Starting Squid Cache version 3.1.0.6 for > i686-pc-linux-gnu... > 2009/03/25 12:50:33.520| Process ID 1941 > 2009/03/25 12:50:33.520| With 1024 file descriptors available > 2009/03/25 12:50:33.520| Initializing IP Cache... > 2009/03/25 12:50:33.521| ipcacheAddEntryFromHosts: Bad IP address '::1' > 2009/03/25 12:50:33.521| ipcacheAddEntryFromHosts: Bad IP address > 'fe00::0' > 2009/03/25 12:50:33.521| ipcacheAddEntryFromHosts: Bad IP address > 'ff00::0' > 2009/03/25 12:50:33.521| ipcacheAddEntryFromHosts: Bad IP address > 'ff02::1' > 2009/03/25 12:50:33.521| ipcacheAddEntryFromHosts: Bad IP address > 'ff02::2' > 2009/03/25 12:50:33.521| ipcacheAddEntryFromHosts: Bad IP address > 'ff02::3' > 2009/03/25 12:50:33.521| DNS Socket created at 0.0.0.0, FD 5 > 2009/03/25 12:50:33.521| Adding nameserver 213.144.64.1 from > /etc/resolv.conf > 2009/03/25 12:50:33.521| Adding nameserver 213.144.66.1 from > /etc/resolv.conf > 2009/03/25 12:50:33.522| User-Agent logging is disabled. > 2009/03/25 12:50:33.522| Referer logging is disabled. > 2009/03/25 12:50:33.789| Unlinkd pipe opened on FD 10 > 2009/03/25 12:50:33.793| Local cache digest enabled; rebuild/rewrite > every 3600/3600 sec > 2009/03/25 12:50:33.793| Swap maxSize 0 KB, estimated 0 objects > 2009/03/25 12:50:33.793| Target number of buckets: 0 > 2009/03/25 12:50:33.793| Using 8192 Store buckets > 2009/03/25 12:50:33.793| Max Mem size: 262144 KB > 2009/03/25 12:50:33.793| Max Swap size: 0 KB > 2009/03/25 12:50:33.793| Using Least Load store dir selection > 2009/03/25 12:50:33.794| Set Current Directory to /var/spool/squid/cache > 2009/03/25 12:50:33.888| Loaded Icons. > 2009/03/25 12:50:33.889| Accepting HTTP connections at 0.0.0.0:3128, FD > 12. > 2009/03/25 12:50:33.889| Accepting spoofing HTTP connections at > 0.0.0.0:3129, FD 13. > 2009/03/25 12:50:33.889| HTCP Disabled. > 2009/03/25 12:50:33.891| Squid modules loaded: 0 > 2009/03/25 12:50:33.891| Adaptation support is off. > 2009/03/25 12:50:33.891| Ready to serve requests. > > from cache.log: > > 2009/03/25 12:50:33.519| enter_suid: PID 1941 taking root priveleges > 2009/03/25 12:50:33.519| CacheManager::registerAction: registering legacy > config > 2009/03/25 12:50:33.519| CacheManager::findAction: looking for action > config > 2009/03/25 12:50:33.519| Action not found. > 2009/03/25 12:50:33.519| CacheManager::registerAction: registered config > 2009/03/25 12:50:33.519| Memory pools are 'on'; limit: 5.000 MB > 2009/03/25 12:50:33.520| CacheManager::registerAction: registering > legacy comm_epoll_incoming > 2009/03/25 12:50:33.520| CacheManager::findAction: looking for action > comm_epoll_incoming > 2009/03/25 12:50:33.520| Action not found. > 2009/03/25 12:50:33.520| CacheManager::registerAction: registered > comm_epoll_incoming > 2009/03/25 12:50:33.520| fd_open() FD 0 stdin > 2009/03/25 12:50:33.520| fd_open() FD 1 stdout > 2009/03/25 12:50:33.520| fd_open() FD 2 stderr > 2009/03/25 12:50:33.520| leave_suid: PID 1941 called > 2009/03/25 12:50:33.520| leave_suid: PID 1941 giving up root, becoming > 'proxy' > 2009/03/25 12:50:33.520| command-line -X overrides: ALL,1 > 2009/03/25 12:50:33.520| fd_open() FD 3 /var/log/squid/cache.log > 2009/03/25 12:50:33.520| Starting Squid Cache version 3.1.0.6 for > i686-pc-linux-gnu... > 2009/03/25 12:50:33.520| Process ID 1941 > 2009/03/25 12:50:33.520| With 1024 file descriptors available > 2009/03/25 12:50:33.520| Initializing IP Cache... > 2009/03/25 12:50:33.520| CacheManager::registerAction: registering > legacy ipcache > 2009/03/25 12:50:33.520| CacheManager::findAction: looking for action > ipcache > 2009/03/25 12:50:33.520| Action not found. > 2009/03/25 12:50:33.520| CacheManager::registerAction: registered ipcache > 2009/03/25 12:50:33.520| CacheManager::registerAction: registering > legacy fqdncache > 2009/03/25 12:50:33.520| CacheManager::findAction: looking for action > fqdncache > 2009/03/25 12:50:33.520| Action not found. > 2009/03/25 12:50:33.520| CacheManager::registerAction: registered > fqdncache > 2009/03/25 12:50:33.520| Initializing FQDN Cache... > 2009/03/25 12:50:33.520| etc_hosts: line is '127.0.0.1 localhost > > (...) > > 2009/03/25 12:50:33.527| fd_open() FD 6 /etc/squid/errorpage.css > 2009/03/25 12:50:33.527| file_close: FD 6 really closing > 2009/03/25 12:50:33.527| fd_close FD 6 /etc/squid/errorpage.css > 2009/03/25 12:50:33.527| commSetSelect(FD > 6,type=1,handler=0,client_data=0,timeout=0) > 2009/03/25 12:50:33.527| commSetSelect(FD > 6,type=2,handler=0,client_data=0,timeout=0) > 2009/03/25 12:50:33.527| file_open: FD 6 > 2009/03/25 12:50:33.527| fd_open() FD 6 /var/log/squid/access.log > 2009/03/25 12:50:33.527| snmpInit: Building SNMP mib tree structure > > (...) > > 2009/03/25 12:50:33.793| cacheDigestInit: capacity: 1 entries, bpe: 5; > size: 1 bytes > 2009/03/25 12:50:33.793| Local cache digest enabled; rebuild/rewrite > every 3600/3600 sec > 2009/03/25 12:50:33.793| CacheManager::registerAction: registering > legacy store_log_tags > 2009/03/25 12:50:33.793| CacheManager::findAction: looking for action > store_log_tags > 2009/03/25 12:50:33.793| Action not found. > 2009/03/25 12:50:33.793| CacheManager::registerAction: registered > store_log_tags > 2009/03/25 12:50:33.793| file_open: FD 11 > 2009/03/25 12:50:33.793| fd_open() FD 11 /var/log/squid/store.log > 2009/03/25 12:50:33.793| event.cc(343) schedule: schedule: Adding > 'storeLateRelease', in 1.00 seconds > 2009/03/25 12:50:33.793| Swap maxSize 0 KB, estimated 0 objects > 2009/03/25 12:50:33.793| Target number of buckets: 0 > 2009/03/25 12:50:33.793| Using 8192 Store buckets > 2009/03/25 12:50:33.793| Max Mem size: 262144 KB > 2009/03/25 12:50:33.793| Max Swap size: 0 KB > 2009/03/25 12:50:33.793| Using Least Load store dir selection > > but all log files are still empty: > > # ls -l /var/log/squid/ > totale 1160 > -rw-r----- 1 proxy proxy 0 25 mar 12:50 access.log > -rw-r----- 1 proxy proxy 1177420 25 mar 12:54 cache.log > -rw-r--r-- 1 root proxy 5 25 mar 12:50 squid.pid > -rw-r----- 1 proxy proxy 0 25 mar 12:50 store.log > >> Once the above issues are resolved. I think you will need a cache.log >> trace >> of whats happening when a request goes through. > > And this is a trace from cache.log of whats happening when the client > request a page: http://pastebin.com/m2f38a88b > > If there are any further details you need do not hesitate to contact me. > Thank you again for your reply. > Okay. It looks like the requests are not actually going through Squid. What cache.log is incrementing by is the startup operational info. No actual requests. Once squid reaches a state where it can receive requests it justs sits idle and checks the garbage collection occasionally. Amos
