[squid-users] Squid sporadic performance - goes OFF every 5-10 minutes

Hello everyone,

I'm trying to implement Squid project at our non-protfit organization (Squid
+ Squid Guard) for web content filtering. I use Squid 3.0.

Because main focus is content filtering I disabled Squid's file caching
feature. I use Pentium 2 PC with 1 GB of RAM. Because caching is OFF I think
that is pretty capable machine for this task.

The worst problem that I faced is very sporadic performance: users would
have internet access, then after 5 minutes internet would be not accessible,
then after another 10 minutes it would come back again... Users were really
annoyed so I had to quit all my experiments... :)

From the browser error page it was clear that squid was not working
properly...

First I thought that the described problem was caused bu SquidGuard, but
after disabling it, problem didn't go away... So only Squid is left...

For me it looks like problems with DNS resolution, but I'm pretty new with
Squid and with Linux, so I'm just guessing here.

Attached are config files for Squid and SquidGuard and medley of squid logs
with my remarks.

If you will have time I would be very thakful for your help. Also it may be
something that other readers of your article may face.

Thank you!

Here is short exerpt from logs:

access.log

Here client could not connect:

1234909886.006 59821 10.127.35.1 TCP_MISS/503 0 CONNECT
urs.microsoft.com:443 - DIRECT/- -
1234909886.009 59784 10.127.35.1 TCP_MISS/503 0 CONNECT
urs.microsoft.com:443 - DIRECT/- -
1234909891.006 59297 10.127.35.1 TCP_MISS/503 0 CONNECT
urs.microsoft.com:443 - DIRECT/- -
1234909891.010 59253 10.127.35.1 TCP_MISS/503 0 CONNECT
urs.microsoft.com:443 - DIRECT/- -
1234910162.876 121219 10.127.35.19 TCP_MISS/503 2212 GET
http://dss2.siteadvisor.com/DSS/Ping? - DIRECT/dss2.siteadvisor.com
text/html
1234910163.897 121821 10.127.35.19 TCP_MISS/503 2797 GET http://www.msn.com/
- DIRECT/www.msn.com text/html
1234910310.867 121248 10.127.35.19 TCP_MISS/503 2287 GET
http://dss1.siteadvisor.com/DSS/Query? - DIRECT/dss1.siteadvisor.com
text/html
1234910310.870 117708 10.127.35.19 TCP_MISS/503 2212 GET
http://dss1.siteadvisor.com/DSS/Ping? - DIRECT/dss1.siteadvisor.com
text/html
1234910311.887 122186 10.127.35.19 TCP_MISS/503 2699 GET
http://www.bbc.co.uk/hindi - DIRECT/www.bbc.co.uk text/html
1234910314.927 121758 10.127.35.19 TCP_MISS/503 2212 GET
http://dss2.siteadvisor.com/DSS/Ping? - DIRECT/dss2.siteadvisor.com
text/html

After 5 mins client could connect:

1234910163.897 121821 10.127.35.19 TCP_MISS/503 2797 GET http://www.msn.com/
- DIRECT/www.msn.com text/html
1234910310.867 121248 10.127.35.19 TCP_MISS/503 2287 GET
http://dss1.siteadvisor.com/DSS/Query? - DIRECT/dss1.siteadvisor.com
text/html
1234910310.870 117708 10.127.35.19 TCP_MISS/503 2212 GET
http://dss1.siteadvisor.com/DSS/Ping? - DIRECT/dss1.siteadvisor.com
text/html
1234910311.887 122186 10.127.35.19 TCP_MISS/503 2699 GET
http://www.bbc.co.uk/hindi - DIRECT/www.bbc.co.uk text/html
1234910314.927 121758 10.127.35.19 TCP_MISS/503 2212 GET
http://dss2.siteadvisor.com/DSS/Ping? - DIRECT/dss2.siteadvisor.com
text/html
1234910323.044 11286 10.127.35.1 TCP_MISS/000 0 GET http://google.com/ -
DIRECT/google.com -
1234910337.217 17 10.127.35.19 TCP_MISS/503 2506 GET
http://www.bbc.co.uk/hindi - DIRECT/www.bbc.co.uk text/html
1234910422.223 99175 10.127.35.1 TCP_MISS/000 0 GET
http://www.ezlm.adp.com/ - DIRECT/www.ezlm.adp.com -
1234910433.107 9182 10.127.35.1 TCP_MISS/503 2536 GET http://google.com/ -
DIRECT/google.com text/html
1234910434.137 122161 10.127.35.19 TCP_MISS/503 2287 GET
http://dss1.siteadvisor.com/DSS/Query? - DIRECT/dss1.siteadvisor.com
text/html
1234910434.140 118636 10.127.35.19 TCP_MISS/503 2212 GET
http://dss1.siteadvisor.com/DSS/Ping? - DIRECT/dss1.siteadvisor.com
text/html
1234910437.178 121669 10.127.35.19 TCP_MISS/503 2212 GET
http://dss2.siteadvisor.com/DSS/Ping? - DIRECT/dss2.siteadvisor.com
text/html
1234910441.801 17 10.127.35.1 TCP_MISS/503 2536 GET http://google.com/ -
DIRECT/google.com text/html
1234910446.880 17 10.127.35.1 TCP_MISS/503 2774 GET http://google.com/ -
DIRECT/google.com text/html
1234910598.412 11689 10.127.35.1 TCP_MISS/000 0 GET http://google.com/ -
DIRECT/google.com -
1234910720.238 121823 10.127.35.1 TCP_MISS/503 2749 GET
http://www.google.com/ - DIRECT/www.google.com text/html
1234910918.519 223 10.127.35.19 TCP_MISS/301 589 GET
http://www.bbc.co.uk/hindi - DIRECT/212.58.251.197 text/html
1234910919.071 537 10.127.35.19 TCP_MISS/200 74824 GET
http://www.bbc.co.uk/hindi/ - NONE/- text/html
1234910919.084 321 10.127.35.19 TCP_MISS/200 7074 GET
http://www.bbc.co.uk/worldservice/includes/javascript/popupwindow.js -
DIRECT/212.58.251.197 application/x-javascript
1234910919.541 130 10.127.35.19 TCP_MISS/200 1136 GET
http://www.bbc.co.uk/worldservice/styles/main.css - NONE/- text/css
1234910919.794 128 10.127.35.19 TCP_MISS/200 4207 GET
http://www.bbc.co.uk/worldservice/styles/layoutltr.css - NONE/- text/css
1234910920.080 212 10.127.35.19 TCP_MISS/200 22552 GET
http://www.bbc.co.uk/hindi/style800.css? - NONE/- text/css
1234910920.259 126 10.127.35.19 TCP_MISS/200 4191 GET
http://www.bbc.co.uk/iftoolbar/styles/toolbar.css - NONE/- text/css
1234910920.349 87 10.127.35.19 TCP_MISS/200 1833 GET
http://dss1.siteadvisor.com/DSS/Query? - DIRECT/216.143.70.105 text/xml
1234910920.477 332 10.127.35.19 TCP_MISS/200 3167 GET
http://www.bbc.co.uk/iftoolbar/styles/banner.css - DIRECT/212.58.251.197
text/css

store.log

Here client could not connect:

1234910162.877 RELEASE -1 FFFFFFFF 92E54E67094541E8C8B5B88460E8892B 503
1234910162 0 -1 text/html 1832/1832 GET
http://dss2.siteadvisor.com/DSS/Ping?
1234910163.897 RELEASE -1 FFFFFFFF E4AF77DF11A0021CF666A25B5F7CA5CC 503
1234910163 0 -1 text/html 2417/2417 GET http://www.msn.com/
1234910310.868 RELEASE -1 FFFFFFFF 8DCB6D58B16A043E62E7F01DD3E24B01 503
1234910310 0 -1 text/html 1907/1907 GET
http://dss1.siteadvisor.com/DSS/Query?
1234910310.870 RELEASE -1 FFFFFFFF 8ED485FF6AE107A758376C6E266FB571 503
1234910310 0 -1 text/html 1832/1832 GET
http://dss1.siteadvisor.com/DSS/Ping?
1234910311.887 RELEASE -1 FFFFFFFF 5401C20DD9BECA31F1A4B03ECBB3D18B 503
1234910311 0 -1 text/html 2319/2319 GET
http://www.bbc.co.uk/hindi
1234910314.927 RELEASE -1 FFFFFFFF 561E626A92EE768541C7460474660238 503
1234910314 0 -1 text/html 1832/1832 GET
http://dss2.siteadvisor.com/DSS/Ping?

After 5 mins client could connect:

1234910441.801 RELEASE -1 FFFFFFFF 13E1C83F6253226327DF0986997EC1BC 503
1234910441 0 -1 text/html 2156/2156 GET http://google.com/
1234910446.881 RELEASE -1 FFFFFFFF D66658DD6304DB63BA07196696AC4153 503
1234910446 0 -1 text/html 2394/2394 GET http://google.com/
1234910598.414 RELEASE -1 FFFFFFFF 56437102BE24C34D4B3EF905869541C8 0
-1 -1 -1 unknown -1/0 GET http://google.com/
1234910671.726 RELEASE -1 FFFFFFFF C21630A03D085804B99B1685F27D8BCB 200
1234907071 1234907071 -1 application/cache-digest 184/184 GET
http://mbccopproxy:3128/squid-internal-periodic/store_digest
1234910720.238 RELEASE -1 FFFFFFFF 2CEA2B378C5F0EEEC7898C5775679DD1 503
1234910720 0 -1 text/html 2369/2369 GET
http://www.google.com/
1234910918.520 RELEASE -1 FFFFFFFF B266B310D2355AF3D961E1E38B4069CC 301
1234910916 -1 -1 text/html 235/235 GET
http://www.bbc.co.uk/hindi
1234910919.071 RELEASE -1 FFFFFFFF 17E5F2DA609BF74CE9134998732B8224 200
1234910916 -1 -1 text/html -1/74548 GET
http://www.bbc.co.uk/hindi/
1234910919.085 RELEASE -1 FFFFFFFF D2929DD3B7C69F9F4D63BEE93E4CDD7B 200
1234910916 1174326715 -1 application/x-javascript 6657/6657 GET
http://www.bbc.co.uk/worldservice/includes/javascript/popupwindow.js
1234910919.542 RELEASE -1 FFFFFFFF ACB3A37A05C4CC7E5AAB0C26D433A7BB 200
1234910917 1187000310 -1 text/css 738/738 GET
http://www.bbc.co.uk/worldservice/styles/main.css
1234910919.795 RELEASE -1 FFFFFFFF 282A7EF6D3BAABE5EBAA5036D13C8E3A 200
1234910917 1167992077 -1 text/css 3807/3807 GET
http://www.bbc.co.uk/worldservice/styles/layoutltr.css
1234910920.081 RELEASE -1 FFFFFFFF 6541121033D0C156475935C62B4B8266 200
1234910917 1218458445 -1 text/css 22150/22150 GET
http://www.bbc.co.uk/hindi/style800.css?
1234910920.260 RELEASE -1 FFFFFFFF C95BBDCB1D15DFD37A01A6634847C78B 200
1234910917 1139997332 -1 text/css 3791/3791 GET
http://www.bbc.co.uk/iftoolbar/styles/toolbar.css
1234910920.349 RELEASE -1 FFFFFFFF 3A7C9D2D2C4F34D1B8888933E6EAC859 200
1234910917 -1 1234954117 text/xml -1/1489 GET
http://dss1.siteadvisor.com/DSS/Query?
1234910920.478 RELEASE -1 FFFFFFFF CB2704FBFB7B617BCDD07FD394DC1F40 200
1234910917 1140705001 -1 text/css 2767/2767 GET
http://www.bbc.co.uk/iftoolbar/styles/banner.css
1234910920.670 RELEASE -1 FFFFFFFF 08460F59EFB46C280F248F4644B247E3 200
1234910918 1182841901 -1 application/x-javascript 1501/1501 GET

cache.log

Here client could not connect:

2009/02/17 16:38:35.484| comm_calliocallback: 0
2009/02/17 16:38:35.484| comm_calliocallback: 0
2009/02/17 16:38:35.493| comm_read_try: FD 18, size 4095, retval 0, errno 0
2009/02/17 16:38:35.493| commio_complete_callback: called for 18 (0, 0)
2009/02/17 16:38:35.493| comm_iocallbackpending: 0
2009/02/17 16:38:35.493| comm_calliocallback: 0
2009/02/17 16:38:35.493| comm_calliocallback: 0
2009/02/17 16:38:35.493| commio_call_callback: called for 18
2009/02/17 16:38:35.493| client_side.cc(2442) clientReadRequest FD 18 size 0
2009/02/17 16:38:35.493| clientReadRequest: FD 18 closed?
2009/02/17 16:38:35.493| AbortChecker::monitor: monitoring half closed FD 18
for aborts
2009/02/17 16:38:35.493| clientParseRequest: FD 18: attempting to parse
2009/02/17 16:38:35.493| comm_iocallbackpending: 0
2009/02/17 16:38:35.493| comm_calliocallback: 0
2009/02/17 16:38:35.493| comm_calliocallback: 0
2009/02/17 16:38:35.493| comm_iocallbackpending: 0
2009/02/17 16:38:35.494| comm_calliocallback: 0
2009/02/17 16:38:35.494| comm_calliocallback: 0
2009/02/17 16:38:35.501| fd_open FD 20 HTTP Request
2009/02/17 16:38:35.501| fdc_t::acceptOne accepted: FD 15 handler: 0x80785d0
newfd: 20
2009/02/17 16:38:35.501| comm_accept: FD 15 handler: 0x80785d0
2009/02/17 16:38:35.501| httpAccept: FD 20: accepted
2009/02/17 16:38:35.501| comm_add_close_handler: FD 20, handler=1,
data=0x8598728
2009/02/17 16:38:35.501| commSetTimeout: FD 20 timeout 300
2009/02/17 16:38:35.501| aclCheckFast: list: 0x8324d40
2009/02/17 16:38:35.501| ACLChecklist::preCheck: 0xbfda3854 checking
'ident_lookup_access deny all'
2009/02/17 16:38:35.501| ACLList::matches: checking all
2009/02/17 16:38:35.501| ACL::checklistMatches: checking 'all'
2009/02/17 16:38:35.501| aclMatchIp: '10.127.35.19' found
2009/02/17 16:38:35.502| ACL::ChecklistMatches: result for 'all' is 1
2009/02/17 16:38:35.502| ACLList::matches: result is true
2009/02/17 16:38:35.502| aclmatchAclList: 0xbfda3854 returning true (AND
list satisfied)
2009/02/17 16:38:35.502| ACLChecklist::markFinished: 0xbfda3854 checklist
processing finished
2009/02/17 16:38:35.502| clientReadSomeData: FD 20: reading request...
2009/02/17 16:38:35.502| comm_read, queueing read for FD 20
2009/02/17 16:38:35.502| ACLChecklist::~ACLChecklist: destroyed 0xbfda3854
2009/02/17 16:38:35.502| fd_open FD 21 HTTP Request
2009/02/17 16:38:35.502| fdc_t::acceptOne accepted: FD 15 handler: 0x80785d0
newfd: 21
2009/02/17 16:38:35.502| comm_accept: FD 15 handler: 0x80785d0
2009/02/17 16:38:35.502| httpAccept: FD 21: accepted
2009/02/17 16:38:35.502| comm_add_close_handler: FD 21, handler=1,
data=0x859850c
2009/02/17 16:38:35.502| commSetTimeout: FD 21 timeout 300
2009/02/17 16:38:35.502| aclCheckFast: list: 0x8324d40
2009/02/17 16:38:35.503| ACLChecklist::preCheck: 0xbfda3854 checking
'ident_lookup_access deny all'

2009/02/17 16:38:36.924| comm_calliocallback: 0
2009/02/17 16:38:36.933| comm_iocallbackpending: 0
2009/02/17 16:38:36.934| comm_calliocallback: 0
2009/02/17 16:38:36.934| comm_calliocallback: 0
2009/02/17 16:38:36.934| event.cc(225) checkEvents
2009/02/17 16:38:36.943| EventDispatcher::dispatch: Running 'idnsCheckQueue'
2009/02/17 16:38:36.944| idnsCheckQueue: ID 0x1fa2timeout
2009/02/17 16:38:36.944| event.cc(315) schedule: Adding 'idnsCheckQueue', in
1.00 seconds
2009/02/17 16:38:36.944| comm_iocallbackpending: 0
2009/02/17 16:38:36.944| comm_calliocallback: 0
2009/02/17 16:38:36.944| comm_calliocallback: 0
2009/02/17 16:38:36.953| comm_iocallbackpending: 0

After 5 mins client could connect:

2009/02/17 16:40:37.154| event.cc(225) checkEvents
2009/02/17 16:40:37.163| EventDispatcher::dispatch: Running 'idnsCheckQueue'
2009/02/17 16:40:37.164| idnsCheckQueue: ID 0x0404timeout
2009/02/17 16:40:37.164| idnsCheckQueue: ID 404: giving up after 16 tries
and 121.65 seconds
2009/02/17 16:40:37.164| ipcacheParse: Lookup failed 'Timeout' for
'dss2.siteadvisor.com'
2009/02/17 16:40:37.164| ipcacheParse: Lookup failed 'Timeout' for
'dss2.siteadvisor.com'
2009/02/17 16:40:37.164| ipcacheRelease: Releasing entry for
'dss2.siteadvisor.com'
2009/02/17 16:40:37.164| commConnectDnsHandle: Unknown host:
dss2.siteadvisor.com
2009/02/17 16:40:37.164| commConnectCallback: FD 14, data 0x85bb438
2009/02/17 16:40:37.164| comm_remove_close_handler: FD 14, handler=1,
data=0x85c73d0
2009/02/17 16:40:37.164| commSetTimeout: FD 14 timeout -1
2009/02/17 16:40:37.164| fwdConnectDone: Unknown host: dss2.siteadvisor.com
2009/02/17 16:40:37.164| fwdFail: ERR_DNS_FAIL "Service Unavailable"

http://dss2.siteadvisor.com/DSS/Ping?version=2&client_ver=ie_1.5.1.3&locale=en-US&aff_id=0
2009/02/17 16:40:37.164| comm_close: FD 14
2009/02/17 16:40:37.164| commSetTimeout: FD 14 timeout -1
2009/02/17 16:40:37.164| commCallCloseHandlers: FD 14
2009/02/17 16:40:37.164| commCallCloseHandlers: ch->handler=1 data=0x85bb438
2009/02/17 16:40:37.164| fwdServerClosed: FD 14
http://dss2.siteadvisor.com/DSS/Ping?version=2&client_ver=ie_1.5.1.3&locale=en-US&aff_id=0
2009/02/17 16:40:37.164| forward.cc(166) FwdState destructor starting
2009/02/17 16:40:37.164| Creating an error page for entry 0xb7a48380 with
errorstate 0x8420db8 page id 11
2009/02/17 16:40:37.164| StoreEntry::lock: key
'33B25D1B0A774775FB21FE9C7AB78BF7' count=3
2009/02/17 16:40:37.164| init-ing hdr: 0x85672d8 owner: 3
2009/02/17 16:40:37.165| errorConvert: %%U -->
'http://dss2.siteadvisor.com/DSS/Ping?'
2009/02/17 16:40:37.165| errorConvert: %%U -->
'http://dss2.siteadvisor.com/DSS/Ping?'
2009/02/17 16:40:37.165| errorConvert: %%H --> 'dss2.siteadvisor.com'
2009/02/17 16:40:37.165| errorConvert: %%z --> 'Timeout'
2009/02/17 16:40:37.165| errorConvert: %%w --> 'webmaster_at_mbccopnetwork.org'
2009/02/17 16:40:37.165| packing hdr: (0x856f7b4)
2009/02/17 16:40:37.165| errorConvert: %%W -->
'?subject=CacheErrorInfo%20-%20ERR_DNS_FAIL&body=CacheHost%3A%20MBCCOPproxy%0D%0AErrPage%3A%20ERR_DNS_FAIL%0D%0AErr%3A%20%5Bnone%5D%0D%0ADNS%20Server%20ErrMsg%3A%20Timeout%0D%0ATimeStamp%3A%20Tue,%2017%20Feb%202009%2022%3A40%3A37%20GMT%0D%0A%0D%0AClientIP%3A%2010.127.35.19%0D%0AServerIP%3A%20dss2.siteadvisor.com%0D%0A%0D%0AHTTP%20Request%3A%0D%0AGET%20%2FDSS%2FPing%3Fversion%3D2%26client_ver%3Die_1.5.1.3%26locale%3Den-US%26aff_id%3D0%20HTTP%2F1.0%0AAccept%3A%20*%2F*%0D%0AUser-Agent%3A%20SiteAdvisor%0D%0AHost%3A%20dss2.siteadvisor.com%0D%0AProxy-Connection%3A%20Keep-Alive%0D%0APragma%3A%20no-cache%0D%0A%0D%0A%0D%0A'
2009/02/17 16:40:37.165| errorConvert: %%w --> 'webmaster_at_mbccopnetwork.org'
2009/02/17 16:40:37.165| errorConvert: %%T --> 'Tue, 17 Feb 2009 22:40:37
GMT'
2009/02/17 16:40:37.165| errorConvert: %%h --> 'MBCCOPproxy'
2009/02/17 16:40:37.165| errorConvert: %%s --> 'squid/3.0.STABLE1'
2009/02/17 16:40:37.165| errorConvert: %%S --> '
<BR clear="all">
<HR noshade size="1px">
<ADDRESS>
Generated Tue, 17 Feb 2009 22:40:37 GMT by MBCCOPproxy (squid/3.0.STABLE1)
</ADDRESS>
</BODY></HTML>

-- 
View this message in context: http://www.nabble.com/Squid-sporadic-performance---goes-OFF-every-5-10-minutes-tp23639820p23639820.html
Sent from the Squid - Users mailing list archive at Nabble.com.