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

From: Jack Daniels <mlrepos_at_gmail.com>
Date: Wed, 25 Mar 2009 13:16:40 +0100

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.
Received on Wed Mar 25 2009 - 12:16:51 MDT

This archive was generated by hypermail 2.2.0 : Thu Mar 26 2009 - 12:00:02 MDT