[squid-users] File download fails through transparent Squid

From: Ivan Botnar <Ivan.Botnar_at_MCDEAN.COM>
Date: Mon, 30 Jul 2012 22:17:20 +0000

Hello,

I have Squid 3.1.19 installed on Ubuntu 12.04 86_64 from packages. I need a transparent proxy without disk cache for users working through Wi-Fi on non-Windows (mostly Apple) devices. I performed a configuration and Squid works for web surfing or streaming data but I'm experiencing issues with files downloading. Basically every download that lasts more than 10 seconds fails with error. I've been looking into logs and debugs, and tcpdump but no luck.

Here's my Squid:

# squid3 -v
Squid Cache: Version 3.1.19
configure options: '--build=x86_64-linux-gnu' '--prefix=/usr' '--includedir=${prefix}/include' '--mandir=${prefix}/share/man' '--infodir=${prefix}/share/info' '--sysconfdir=/etc' '--localstatedir=/var' '--libexecdir=${prefix}/lib/squid3' '--srcdir=.' '--disable-maintainer-mode' '--disable-dependency-tracking' '--disable-silent-rules' '--datadir=/usr/share/squid3' '--sysconfdir=/etc/squid3' '--mandir=/usr/share/man' '--with-cppunit-basedir=/usr' '--enable-inline' '--enable-async-io=8' '--enable-storeio=ufs,aufs,diskd' '--enable-removal-policies=lru,heap' '--enable-delay-pools' '--enable-cache-digests' '--enable-underscores' '--enable-icap-client' '--enable-follow-x-forwarded-for' '--enable-auth=basic,digest,ntlm,negotiate' '--enable-basic-auth-helpers=LDAP,MSNT,NCSA,PAM,SASL,SMB,YP,DB,POP3,getpwnam,squid_radius_auth,multi-domain-NTLM' '--enable-ntlm-auth-helpers=smb_lm,' '--enable-digest-auth-helpers=ldap,password' '--enable-negotiate-auth-helpers=squid_kerb_auth' '--enable-external-acl-helpers=ip_user,ldap_group,session,unix_group,wbinfo_group' '--enable-arp-acl' '--enable-esi' '--enable-zph-qos' '--enable-wccpv2' '--disable-translation' '--with-logdir=/var/log/squid3' '--with-pidfile=/var/run/squid3.pid' '--with-filedescriptors=65536' '--with-large-files' '--with-default-user=proxy' '--enable-linux-netfilter' 'build_alias=x86_64-linux-gnu' 'CFLAGS=-g -O2 -fPIE -fstack-protector --param=ssp-buffer-size=4 -Wformat -Wformat-security -Werror=format-security' 'LDFLAGS=-Wl,-Bsymbolic-functions -fPIE -pie -Wl,-z,relro -Wl,-z,now' 'CPPFLAGS=-D_FORTIFY_SOURCE=2' 'CXXFLAGS=-g -O2 -fPIE -fstack-protector --param=ssp-buffer-size=4 -Wformat -Wformat-security -Werror=format-security' --with-squid=/build/buildd/squid3-3.1.19

IP tables forward everything from 80 port to Squid on 3128 port:

-A PREROUTING -i eth0 -p tcp -m tcp --dport 80 -j REDIRECT --to-ports 3128

Here's my config:

acl my_networks src 192.168.110.0/24 10.21.40.0/24 10.20.40.0/24 192.168.109.0/24
cache deny all
acl manager proto cache_object
acl localhost src 127.0.0.1/32 ::1
acl to_localhost dst 127.0.0.0/8 0.0.0.0/32 ::1
acl SSL_ports port 443
acl Safe_ports port 80 # http
acl Safe_ports port 21 # ftp
acl Safe_ports port 443 # https
acl Safe_ports port 70 # gopher
acl Safe_ports port 210 # wais
acl Safe_ports port 1025-65535 # unregistered ports
acl Safe_ports port 280 # http-mgmt
acl Safe_ports port 488 # gss-http
acl Safe_ports port 591 # filemaker
acl Safe_ports port 777 # multiling http
acl CONNECT method CONNECT
http_access allow manager localhost
http_access deny manager
http_access deny !Safe_ports
http_access deny CONNECT !SSL_ports
http_access allow localhost
http_access allow my_networks
http_access deny all
cache_store_log /dev/null
http_port 3128 transparent
hierarchy_stoplist cgi-bin ?
coredump_dir /var/spool/squid3
refresh_pattern ^ftp: 1440 20% 10080
refresh_pattern ^gopher: 1440 0% 1440
refresh_pattern -i (/cgi-bin/|\?) 0 0% 0
refresh_pattern (Release|Packages(.gz)*)$ 0 20% 2880
refresh_pattern . 0 20% 4320
httpd_suppress_version_string On
error_directory /usr/share/squid-langpack/en

Here's the last couple records I see in debug:

2012/07/30 18:06:27.339| clientReplyContext::sendMoreData: http://mirror.cst.temple.edu/opensuse/distribution/12.1/iso/openSUSE-12.1-DVD-x86_64.iso, 7131720 bytes (4096 new bytes)
2012/07/30 18:06:27.339| clientReplyContext::sendMoreData: FD 213 'http://mirror.cst.temple.edu/opensuse/distribution/12.1/iso/openSUSE-12.1-DVD-x86_64.iso' out.offset=7127299
2012/07/30 18:06:27.339| clientStreamCallback: Calling 1 with cbdata 0x7fe40c97bc30 from node 0x7fe40c890008
2012/07/30 18:06:27.339| cbdataReferenceValid: 0x7fe40c35ff98
2012/07/30 18:06:27.339| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.339| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.339| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.339| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.339| cbdataLock: 0x7fe40c97abc8=2
2012/07/30 18:06:27.339| cbdataLock: 0x7fe40c97abc8=3
2012/07/30 18:06:27.339| The AsyncCall clientWriteBodyComplete constructed, this=0x7fe40c34b630 [call778693]
2012/07/30 18:06:27.339| cbdataLock: 0x7fe40c97abc8=4
2012/07/30 18:06:27.339| cbdataUnlock: 0x7fe40c97abc8=3
2012/07/30 18:06:27.339| cbdataUnlock: 0x7fe40c97abc8=2
2012/07/30 18:06:27.339| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.340| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.340| comm_write: FD 213: sz 4096: asynCall 0x7fe40c34b630*1
2012/07/30 18:06:27.340| commSetSelect(FD 213,type=2,handler=1,client_data=0x7fe4065616d0,timeout=0)
2012/07/30 18:06:27.340| cbdataUnlock: 0x7fe40cc787d8=0
2012/07/30 18:06:27.340| cbdataUnlock: 0x7fe40c24a1c8=0
2012/07/30 18:06:27.340| leaving clientWriteBodyComplete(FD 213, data=0x7fe40c97abc8, size=4096, buf=0x7fe40c97abe0)
2012/07/30 18:06:27.340| cbdataUnlock: 0x7fe40c97abc8=1
2012/07/30 18:06:27.340| Engine 0x7fff8e10ec00 is idle.
2012/07/30 18:06:27.340| Engine 0x7fff8e10ec10 is idle.
2012/07/30 18:06:27.340| comm_select(): got FD 213 events=4 monitoring=1d F->read_handler=1 F->write_handler=1
2012/07/30 18:06:27.340| comm_select(): Calling write handler on FD 213
2012/07/30 18:06:27.340| commHandleWrite: FD 213: off 0, sz 4096.
2012/07/30 18:06:27.340| commHandleWrite: write() returns 4096
2012/07/30 18:06:27.340| commio_finish_callback: called for FD 213 (0, 0)
2012/07/30 18:06:27.340| comm.cc(165) will call clientWriteBodyComplete(FD 213, data=0x7fe40c97abc8, size=4096, buf=0x7fe40c97abe0) [call778693]
2012/07/30 18:06:27.341| entering clientWriteBodyComplete(FD 213, data=0x7fe40c97abc8, size=4096, buf=0x7fe40c97abe0)
2012/07/30 18:06:27.341| AsyncCall.cc(32) make: make call clientWriteBodyComplete [call778693]
2012/07/30 18:06:27.341| cbdataReferenceValid: 0x7fe40c97abc8
2012/07/30 18:06:27.341| client_side.cc(1349) clientWriteBodyComplete: clientWriteBodyComplete schedules clientWriteComplete
2012/07/30 18:06:27.341| clientWriteComplete: FD 213, sz 4096, err 0, off 7131804, len 0x7fe40c359660
2012/07/30 18:06:27.341| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.341| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.341| HttpReply.cc(558) receivedBodyTooLarge: 7127299 >? -1
2012/07/30 18:06:27.341| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.341| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.341| ClientSocketContext::pullData: FD 213 attempting to pull upstream data
2012/07/30 18:06:27.341| clientStreamRead: Calling 1 with cbdata 0x7fe40cc79890 from node 0x7fe40c35ff98
2012/07/30 18:06:27.341| cbdataReferenceValid: 0x7fe40c890008
2012/07/30 18:06:27.341| store_client::copy: C1A5C180C01DDCA5C32E5FFBE64D140A, from 7131720, for length 4096, cb 1, cbdata 0x7fe40cc787d8
2012/07/30 18:06:27.341| cbdataLock: 0x7fe40cc787d8=1
2012/07/30 18:06:27.341| comm_remove_close_handler: FD 246, AsyncCall=0x7fe40c77a990*2
2012/07/30 18:06:27.342| cbdataUnlock: 0x7fe40c41ccd8=0
2012/07/30 18:06:27.342| cbdataFree: 0x7fe40c41ccd8
2012/07/30 18:06:27.342| cbdataFree: Freeing 0x7fe40c41ccd8
2012/07/30 18:06:27.342| Kicking deferred read on FD 246
2012/07/30 18:06:27.342| Adding deferred read on FD 246
2012/07/30 18:06:27.342| cbdataLock: 0x7fe40c41ccd8=1
2012/07/30 18:06:27.342| cbdataLock: 0x7fe40c41ccd8=2
2012/07/30 18:06:27.342| The AsyncCall DeferredReadManager::CloseHandler constructed, this=0x7fe40c77a990 [call778694]
2012/07/30 18:06:27.342| cbdataLock: 0x7fe40c41ccd8=3
2012/07/30 18:06:27.342| cbdataUnlock: 0x7fe40c41ccd8=2
2012/07/30 18:06:27.342| cbdataUnlock: 0x7fe40c41ccd8=1
2012/07/30 18:06:27.342| comm_add_close_handler: FD 246, AsyncCall=0x7fe40c77a990*1
2012/07/30 18:06:27.342| storeClientCopy2: C1A5C180C01DDCA5C32E5FFBE64D140A
2012/07/30 18:06:27.342| cbdataLock: 0x7fe40c24a1c8=1
2012/07/30 18:06:27.342| store_client::doCopy: co: 7131720, hi: 7149992
2012/07/30 18:06:27.343| store_client::doCopy: Copying normal from memory
2012/07/30 18:06:27.343| memCopy: [7131720,7135816)
2012/07/30 18:06:27.343| cbdataReferenceValid: 0x7fe40cc787d8
2012/07/30 18:06:27.343| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.343| cbdataReferenceValid: 0x7fe40c890008
2012/07/30 18:06:27.343| clientReplyContext::sendMoreData: http://mirror.cst.temple.edu/opensuse/distribution/12.1/iso/openSUSE-12.1-DVD-x86_64.iso, 7135816 bytes (4096 new bytes)
2012/07/30 18:06:27.343| clientReplyContext::sendMoreData: FD 213 'http://mirror.cst.temple.edu/opensuse/distribution/12.1/iso/openSUSE-12.1-DVD-x86_64.iso' out.offset=7131395
2012/07/30 18:06:27.343| clientStreamCallback: Calling 1 with cbdata 0x7fe40c97bc30 from node 0x7fe40c890008
2012/07/30 18:06:27.343| cbdataReferenceValid: 0x7fe40c35ff98
2012/07/30 18:06:27.343| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.343| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.343| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.343| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.343| cbdataLock: 0x7fe40c97abc8=2
2012/07/30 18:06:27.344| cbdataLock: 0x7fe40c97abc8=3
2012/07/30 18:06:27.344| The AsyncCall clientWriteBodyComplete constructed, this=0x7fe40cd455d0 [call778695]
2012/07/30 18:06:27.344| cbdataLock: 0x7fe40c97abc8=4
2012/07/30 18:06:27.344| cbdataUnlock: 0x7fe40c97abc8=3
2012/07/30 18:06:27.344| cbdataUnlock: 0x7fe40c97abc8=2
2012/07/30 18:06:27.344| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.344| cbdataReferenceValid: 0x7fe40c5763d8
2012/07/30 18:06:27.344| comm_write: FD 213: sz 4096: asynCall 0x7fe40cd455d0*1
2012/07/30 18:06:27.344| commSetSelect(FD 213,type=2,handler=1,client_data=0x7fe4065616d0,timeout=0)
2012/07/30 18:06:27.344| cbdataUnlock: 0x7fe40cc787d8=0
2012/07/30 18:06:27.344| cbdataUnlock: 0x7fe40c24a1c8=0
2012/07/30 18:06:27.344| leaving clientWriteBodyComplete(FD 213, data=0x7fe40c97abc8, size=4096, buf=0x7fe40c97abe0)
2012/07/30 18:06:27.344| cbdataUnlock: 0x7fe40c97abc8=1
2012/07/30 18:06:27.344| Engine 0x7fff8e10ec00 is idle.
2012/07/30 18:06:27.344| Engine 0x7fff8e10ec10 is idle.
2012/07/30 18:06:27.711| Engine 0x7fff8e10ec00 is idle.
2012/07/30 18:06:27.711| Engine 0x7fff8e10ec10 is idle.
2012/07/30 18:06:27.711| Engine 0x7fff8e10ec00 is idle.
2012/07/30 18:06:27.711| Engine 0x7fff8e10ec10 is idle.
2012/07/30 18:06:27.711| Engine 0x7fff8e10ec00 is idle.
2012/07/30 18:06:27.711| Engine 0x7fff8e10ec10 is idle.
2012/07/30 18:06:27.711| Engine 0x7fff8e10ec00 is idle.
2012/07/30 18:06:27.712| event.cc(251) checkEvents: checkEvents
2012/07/30 18:06:27.712| The AsyncCall MaintainSwapSpace constructed, this=0x7fe40c796220 [call778696]
2012/07/30 18:06:27.712| event.cc(260) will call MaintainSwapSpace() [call778696]
2012/07/30 18:06:27.712| Engine 0x7fff8e10ec10 is idle.
2012/07/30 18:06:27.712| entering MaintainSwapSpace()
2012/07/30 18:06:27.712| AsyncCall.cc(32) make: make call MaintainSwapSpace [call778696]
2012/07/30 18:06:27.712| event.cc(343) schedule: schedule: Adding 'MaintainSwapSpace', in 1.00 seconds
2012/07/30 18:06:27.712| leaving MaintainSwapSpace()
2012/07/30 18:06:27.712| Engine 0x7fff8e10ec00 is idle.
2012/07/30 18:06:27.712| Engine 0x7fff8e10ec10 is idle.
2012/07/30 18:06:27.997| comm_select(): got FD 121 events=1 monitoring=19 F->read_handler=1 F->write_handler=0
2012/07/30 18:06:27.998| comm_select(): Calling read handler on FD 121
2012/07/30 18:06:27.998| comm_read_try: FD 121, size 4096, retval 0, errno 0
2012/07/30 18:06:27.998| commio_finish_callback: called for FD 121 (0, 0)
2012/07/30 18:06:27.998| comm.cc(165) will call SomeCommReadHandler(FD 121, data=0x7fe40c9563c8, size=0, buf=0x7fe40c9563f0) [call755623]
2012/07/30 18:06:27.998| entering SomeCommReadHandler(FD 121, data=0x7fe40c9563c8, size=0, buf=0x7fe40c9563f0)
2012/07/30 18:06:27.998| AsyncCall.cc(32) make: make call SomeCommReadHandler [call755623]
2012/07/30 18:06:27.998| cbdataReferenceValid: 0x7fe40c9563c8
2012/07/30 18:06:27.998| IdleConnList::read: 0 bytes from FD 121
2012/07/30 18:06:27.998| IdleConnList::removeFD: found FD 121 at index 0
2012/07/30 18:06:27.998| IdleConnList::removeFD: deleting pix.bit.ly:80
2012/07/30 18:06:27.998| cbdataFree: 0x7fe40c9563c8
2012/07/30 18:06:27.998| cbdataFree: 0x7fe40c9563c8 has 2 locks, not freeing
2012/07/30 18:06:27.998| comm_close: start closing FD 121
2012/07/30 18:06:27.998| The AsyncCall comm_close_start constructed, this=0x7fe40c796220 [call778697]
2012/07/30 18:06:27.998| comm.cc(1616) will call comm_close_start(FD 121) [call778697]
2012/07/30 18:06:27.998| comm.cc(1196) commSetTimeout: FD 121 timeout -1
2012/07/30 18:06:27.998| comm.cc(1207) commSetTimeout: FD 121 timeout -1
2012/07/30 18:06:27.998| cbdataUnlock: 0x7fe40c9563c8=1
2012/07/30 18:06:27.998| commCallCloseHandlers: FD 121
2012/07/30 18:06:27.998| The AsyncCall comm_close_complete constructed, this=0x7fe40c760010 [call778698]
2012/07/30 18:06:27.998| comm.cc(1648) will call comm_close_complete(FD 121) [call778698]
2012/07/30 18:06:27.998| leaving SomeCommReadHandler(FD 121, data=0x7fe40c9563c8, size=0, buf=0x7fe40c9563f0)
2012/07/30 18:06:27.998| cbdataUnlock: 0x7fe40c9563c8=0
2012/07/30 18:06:27.998| cbdataUnlock: Freeing 0x7fe40c9563c8
2012/07/30 18:06:27.998| entering comm_close_start(FD 121)
2012/07/30 18:06:27.998| AsyncCall.cc(32) make: make call comm_close_start [call778697]
2012/07/30 18:06:27.998| leaving comm_close_start(FD 121)
2012/07/30 18:06:27.998| entering comm_close_complete(FD 121)
2012/07/30 18:06:27.998| AsyncCall.cc(32) make: make call comm_close_complete [call778698]
2012/07/30 18:06:27.998| fd_close FD 121 pix.bit.ly idle connection
2012/07/30 18:06:27.998| commSetSelect(FD 121,type=1,handler=0,client_data=0,timeout=0)
2012/07/30 18:06:27.998| commSetSelect(FD 121,type=2,handler=0,client_data=0,timeout=0)
2012/07/30 18:06:27.998| leaving comm_close_complete(FD 121)
2012/07/30 18:06:27.998| Engine 0x7fff8e10ec00 is idle.
2012/07/30 18:06:27.998| Engine 0x7fff8e10ec10 is idle.

I would really appreciate if someone could help me.

________________________________

LEGAL DISCLAIMER: M.C. Dean, Inc. and its subsidiaries considers this e-mail and any files transmitted with it to be protected, proprietary or privileged information intended solely for the use of the named recipient(s). Any disclosure of this material or the information contained herein, in whole or in part, to anyone outside of the intended recipient or affiliates is strictly prohibited. M. C. Dean, Inc. accepts no liability for the content of this e-mail or for the consequences of any actions taken on the basis of the information contained in it, unless that information is subsequently confirmed in writing. Employees of M.C. Dean, Inc. are instructed not to infringe on any rights of the recipient; any such communication violates company policy. If you are not the intended recipient, any disclosure, copying, distribution, or action taken or omitted in reliance on this information is strictly prohibited by M.C. Dean, Inc.; please notify the sender immediately by return e-mail, delete this communication and destroy all copies.
Received on Mon Jul 30 2012 - 22:17:23 MDT

This archive was generated by hypermail 2.2.0 : Tue Jul 31 2012 - 12:00:02 MDT