[squid-users] File download fails through transparent Squid

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.
Received on Tue Jul 31 2012 - 12:13:26 MDT