Re: [squid-users] squid TPROXY and empty access.log

> On Wed, Mar 25, 2009 at 12:00 PM, Amos Jeffries <squid3_at_treenet.co.nz>
> 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
Received on Wed Mar 25 2009 - 22:19:38 MDT