[squid-users] Squid drops connection after a minute

 
Hello, All!
 
I have squid 2.6.10 installed from port on freebsd 6.2 and a problem.
When a client downloads some big file, the download process stops in 1
minute. It looks like IE finishes downloading, but file size on disk is
less then actual size. This problem appeared after I had upgraded
freebsd from 6.0 to 6.2 and squid from 2.5.14 to 2.6.9. Upgrade to
2.6.10 did not solve the problem.
 I can see in access.log, that squid downloads only part of file and
that session lasts about a minute:
 
1173864244.072 58720 172.26.1.122 TCP_MISS/200 8469449 GET
http://www.iccm.ru/products/support/PFR_LOC.exe - DIRECT/212.45.27.50
application/force-download
1173864401.002 59747 172.26.1.122 TCP_MISS/200 8782609 GET
http://www.iccm.ru/products/support/PFR_LOC.exe - DIRECT/212.45.27.50
application/force-download
1173864485.003 58999 172.26.1.122 TCP_MISS/200 10073049 GET
http://www.iccm.ru/products/support/PFR_LOC.exe - DIRECT/212.45.27.50
application/force-download
1173866673.018 56194 172.21.11.84 TCP_MISS/200 2906063 GET
http://ftp-mozilla.netscape.com/pub/mozilla.org/firefox/releases/2.0.0.2
/win32/ru/Firefox%20Setup%202.0.0.2.exe - DIRECT/207.200.66.54
application/octet-stream
 
There is a "checkTimeouts: FD 13 Expired" in cache.log, but I didn't
change any timer settings in squid.conf. Only default settings there.
Any idea if it is squid problem or freebsd?

PS: here is a part of cache.log:

2007/03/14 12:24:03| clientWriteComplete: FD 13, sz 4096, err 0, off
8469342, len -1
2007/03/14 12:24:03| storeClientCopy: A789640C827C580899CB90C4A6559B2E,
seen 8469342, want 8469342, size 4096, cb 0x8068c00, cbdata 0x8874010
2007/03/14 12:24:03| cbdataLock: 0x8874010
2007/03/14 12:24:03| storeSwapOut:
http://www.iccm.ru/products/support/PFR_LOC.exe
2007/03/14 12:24:03| storeSwapOut: store_status = STORE_PENDING
2007/03/14 12:24:03| storeSwapOut: mem->inmem_lo = 8462336
2007/03/14 12:24:03| storeSwapOut: mem->inmem_hi = 8504237
2007/03/14 12:24:03| storeSwapOut: swapout.queue_offset = 0
2007/03/14 12:24:03| storeSwapOut: lowest_offset = 8469342
2007/03/14 12:24:03| cbdataLock: 0x884d590
2007/03/14 12:24:03| storeClientCopy2: A789640C827C580899CB90C4A6559B2E
2007/03/14 12:24:03| storeClientCopy3: Copying from memory
2007/03/14 12:24:03| memCopy: offset 8469342: size 4096
2007/03/14 12:24:03| storeSwapOut: lowest_offset = 8469342
2007/03/14 12:24:03| cbdataValid: 0x8874010
2007/03/14 12:24:03| clientSendMoreData:
http://www.iccm.ru/products/support/PFR_LOC.exe, 4096 bytes
2007/03/14 12:24:03| clientSendMoreData: FD 13
'http://www.iccm.ru/products/support/PFR_LOC.exe', out.offset=8469342
2007/03/14 12:24:03| comm_write: FD 13: sz 4096: hndl 0x8068f60: data
0x8874010.
2007/03/14 12:24:03| cbdataLock: 0x8874010
2007/03/14 12:24:03| commSetSelect: FD 13 type 2
2007/03/14 12:24:03| commSetEvents(fd=13)
2007/03/14 12:24:03| cbdataUnlock: 0x8874010
2007/03/14 12:24:03| cbdataUnlock: 0x884d590
2007/03/14 12:24:03| cbdataUnlock: 0x8874010
2007/03/14 12:24:03| commSetEvents(fd=13)
2007/03/14 12:24:04| comm_select: timeout 860
2007/03/14 12:24:04| checkTimeouts: FD 13 Expired
2007/03/14 12:24:04| checkTimeouts: FD 13: Call timeout handler
2007/03/14 12:24:04| requestTimeout: FD 13: lifetime is expired.
2007/03/14 12:24:04| comm_close: FD 13
2007/03/14 12:24:04| cbdataValid: 0x8874010
2007/03/14 12:24:04| clientWriteComplete: FD 13, sz 0, err -9, off
8473438, len -1
2007/03/14 12:24:04| comm_close: FD 13
2007/03/14 12:24:04| cbdataUnlock: 0x8874010
2007/03/14 12:24:04| commCallCloseHandlers: FD 13
2007/03/14 12:24:04| commCallCloseHandlers: ch->handler=0x8064540
2007/03/14 12:24:04| cbdataValid: 0x88a2510
2007/03/14 12:24:04| connStateFree: FD 13
2007/03/14 12:24:04| httpRequestFree:
http://www.iccm.ru/products/support/PFR_LOC.exe
2007/03/14 12:24:04| httpRequestFree:
al.url=/'http://www.iccm.ru/products/support/PFR_LOC.exe'
2007/03/14 12:24:04| cbdataLock: 0x8298470
2007/03/14 12:24:04| cbdataLock: 0x88a2510
2007/03/14 12:24:04| cbdataUnlock: 0x88a2510
2007/03/14 12:24:04| cbdataUnlock: 0x8298470
2007/03/14 12:24:04| cbdataFree: 0x8854010
2007/03/14 12:24:04| cbdataFree: Freeing 0x8854010
2007/03/14 12:24:04| storeClientUnregister: called for
'A789640C827C580899CB90C4A6559B2E'
2007/03/14 12:24:04| storeSwapOut: lowest_offset = 8504238
2007/03/14 12:24:04| commSetEvents(fd=14)
2007/03/14 12:24:04| storePendingNClients: returning 0
2007/03/14 12:24:04| CheckQuickAbort2: entry=0x88d08c0, mem=0x88d1100
2007/03/14 12:24:04| CheckQuickAbort2: YES KEY_PRIVATE
2007/03/14 12:24:04| storeAbort: A789640C827C580899CB90C4A6559B2E
2007/03/14 12:24:04| storeLockObject: key
'A789640C827C580899CB90C4A6559B2E' count=5
2007/03/14 12:24:04| cbdataLock: 0x8873890
2007/03/14 12:24:04| eventAdd: Adding 'mem->abort.callback', in 0.000000
seconds
2007/03/14 12:24:04| InvokeHandlers: A789640C827C580899CB90C4A6559B2E
2007/03/14 12:24:04| storeSwapOutFileClose:
A789640C827C580899CB90C4A6559B2E
2007/03/14 12:24:04| storeSwapOutFileClose: sio = 0x0
2007/03/14 12:24:04| storeUnlockObject: key
'A789640C827C580899CB90C4A6559B2E' count=4
2007/03/14 12:24:04| storeUnlockObject: key
'A789640C827C580899CB90C4A6559B2E' count=3
2007/03/14 12:24:04| cbdataFree: 0x884d590
2007/03/14 12:24:04| cbdataFree: Freeing 0x884d590
2007/03/14 12:24:04| storeUnlockObject: key
'A789640C827C580899CB90C4A6559B2E' count=2
2007/03/14 12:24:04| destroying rep: 0x87f8e80
2007/03/14 12:24:04| cleaning hdr: 0x87f8ec0 owner: 2
2007/03/14 12:24:04| destroying entry 0x88d20e0: 'Date: Wed, 14 Mar 2007
09:23:05 GMT'
2007/03/14 12:24:04| destroying entry 0x88d20c0: 'Server: Apache/2.2.2
(Fedora)'
2007/03/14 12:24:04| destroying entry 0x88d2040: 'X-Powered-By:
PHP/4.4.2'
2007/03/14 12:24:04| destroying entry 0x88d2060: 'P3P:
policyref="/bitrix/p3p.xml", CP="NON DSP COR CUR ADM DEV PSA PSD OUR UNR
BUS UNI COM NAV INT DEM STA"'
2007/03/14 12:24:04| destroying entry 0x88d2020: 'X-Powered-CMS: Bitrix
Site Manager (9b6a00650c5035ff130042da9fea6de7)'
2007/03/14 12:24:04| destroying entry 0x88cbfe0: 'Expires: 0'
2007/03/14 12:24:04| destroying entry 0x88cbfc0: 'Cache-Control:
must-revalidate, post-check=0, pre-check=0'
2007/03/14 12:24:04| destroying entry 0x88cbfa0: 'Pragma: public'
2007/03/14 12:24:04| destroying entry 0x88cbf80: 'Set-Cookie:
BITRIX_SM_GUEST_ID=49599; expires=Sat, 08 Mar 2008 09:23:05 GMT; path=/;
domain=www.iccm.ru'
2007/03/14 12:24:04| destroying entry 0x88cbf60: 'Set-Cookie:
BITRIX_SM_LAST_VISIT=14.03.2007+12%3A23%3A05; expires=Sat, 08 Mar 2008
09:23:05 GMT; path=/; domain=www.iccm.ru'
2007/03/14 12:24:04| destroying entry 0x88cbf40:
'Content-Transfer-Encoding: binary'
2007/03/14 12:24:04| destroying entry 0x88cbdc0: 'Content-Length:
41847978'
2007/03/14 12:24:04| destroying entry 0x88cbda0: 'Accept-Ranges: bytes'
2007/03/14 12:24:04| destroying entry 0x88cbd80: 'Content-Range: bytes
0-41847977/41847978'
2007/03/14 12:24:04| destroying entry 0x88cb080: 'Content-Type:
application/force-download; name="PFR_LOC.exe"'
2007/03/14 12:24:04| destroying entry 0x889dc80: 'X-Cache: MISS from
as2new.globaltel.ru'
2007/03/14 12:24:04| destroying entry 0x88cbe40: 'Via: 1.0
as2new.globaltel.ru:8089 (squid/2.6.STABLE10)'
2007/03/14 12:24:04| destroying entry 0x88cbe60: 'Proxy-Connection:
keep-alive'
2007/03/14 12:24:04| cbdataFree: 0x8874010
2007/03/14 12:24:04| cbdataFree: Freeing 0x8874010
2007/03/14 12:24:04| cbdataFree: 0x88a2510
2007/03/14 12:24:04| cbdataFree: 0x88a2510 has 1 locks, not freeing
2007/03/14 12:24:04| cbdataUnlock: 0x88a2510
2007/03/14 12:24:04| cbdataUnlock: Freeing 0x88a2510
2007/03/14 12:24:04| fd_close FD 13
http://www.iccm.ru/products/support/PFR_LOC.exe
2007/03/14 12:24:04| commSetEvents(fd=13)
2007/03/14 12:24:04| comm_select: kqueue event error: (9) Bad file
descriptor
2007/03/14 12:24:04| comm_select: kqueue event error: (9) Bad file
descriptor
2007/03/14 12:24:04| eventRun: RUN ID 448
2007/03/14 12:24:04| cbdataValid: 0x8873890
2007/03/14 12:24:04| cbdataUnlock: 0x8873890
2007/03/14 12:24:04| eventRun: Running 'mem->abort.callback', id 447
2007/03/14 12:24:04| fwdAbort:
http://www.iccm.ru/products/support/PFR_LOC.exe
2007/03/14 12:24:04| fwdStateFree: 0x8873890
2007/03/14 12:24:04| storePendingNClients: returning 0
2007/03/14 12:24:04| storeUnlockObject: key
'A789640C827C580899CB90C4A6559B2E' count=1
2007/03/14 12:24:04| comm_remove_close_handler: FD 14,
handler=0x807a250, data=0x8873890
2007/03/14 12:24:04| cbdataUnlock: 0x8873890
2007/03/14 12:24:04| fwdStateFree: closing FD 14
2007/03/14 12:24:04| comm_close: FD 14
2007/03/14 12:24:04| commCallCloseHandlers: FD 14
2007/03/14 12:24:04| commCallCloseHandlers: ch->handler=0x8087f30
2007/03/14 12:24:04| cbdataValid: 0x87f8a10
2007/03/14 12:24:04| storeUnlockObject: key
'A789640C827C580899CB90C4A6559B2E' count=0
Received on Wed Mar 14 2007 - 07:25:08 MDT