﻿http://www.moovie.cc/images/movies/17031/poster.jpg

------------------------

2014/03/10 12:25:22.967 kid1| ufs/UFSSwapDir.cc(480) maintain: /var/spool/squid removed 0/80 f=1.0000 max_scan=500
2014/03/10 12:25:23.379 kid1| ufs/UFSSwapDir.cc(1296) DirClean: Cleaning directory /var/spool/squid/1B/18
2014/03/10 12:25:23.968 kid1| ufs/UFSSwapDir.cc(456) maintain: f=1.00, max_scan=500, max_remove=80
2014/03/10 12:25:23.968 kid1| ufs/UFSSwapDir.cc(480) maintain: /var/spool/squid removed 0/80 f=1.0000 max_scan=500
2014/03/10 12:25:24.952 kid1| TcpAcceptor.cc(197) doAccept: New connection on FD 13
2014/03/10 12:25:24.952 kid1| TcpAcceptor.cc(272) acceptNext: connection on local=192.168.50.200:3128 remote=[::] FD 13 flags=9
2014/03/10 12:25:24.953 kid1| fd.cc(221) fd_open: fd_open() FD 11 HTTP Request
2014/03/10 12:25:24.973 kid1| Eui48.cc(537) lookup: 192.168.50.200 NOT found
2014/03/10 12:25:24.973 kid1| comm.cc(773) commSetConnTimeout: local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 timeout 300
2014/03/10 12:25:24.973 kid1| ufs/UFSSwapDir.cc(456) maintain: f=1.00, max_scan=500, max_remove=80
2014/03/10 12:25:24.973 kid1| ufs/UFSSwapDir.cc(480) maintain: /var/spool/squid removed 0/80 f=1.0000 max_scan=500
2014/03/10 12:25:24.974 kid1| comm.cc(145) commHandleRead: comm_read_try: FD 11, size 4095, retval 638, errno 0
2014/03/10 12:25:24.974 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 (0, 0)
2014/03/10 12:25:24.974 kid1| client_side.cc(2232) parseHttpRequest: parseHttpRequest: req_hdr = {Host: www.moovie.cc
User-Agent: Links (2.6; Linux 3.13.5-202.fc20.i686+PAE i686; GNU C 4.8.1; text)
Accept: */*
Accept-Encoding: gzip,deflate,bzip2
Accept-Charset: us-ascii,ISO-8859-1,ISO-8859-2,ISO-8859-3,ISO-8859-4,ISO-8859-5,ISO-8859-6,ISO-8859-7,ISO-8859-8,ISO-8859-9,ISO-8859-10,ISO-8859-13,ISO-8859-14,ISO-8859-15,ISO-8859-16,windows-1250,windows-1251,windows-1252,windows-1256,windows-1257,cp437,cp737,cp850,cp852,cp866,x-cp866-u,x-mac,x-mac-ce,x-kam-cs,koi8-r,koi8-u,koi8-ru,TCVN-5712,VISCII,utf-8
Accept-Language: en,*;q=0.1
Proxy-Connection: keep-alive

}
2014/03/10 12:25:24.975 kid1| client_side.cc(2236) parseHttpRequest: parseHttpRequest: end = {
}
2014/03/10 12:25:24.975 kid1| client_side.cc(2240) parseHttpRequest: parseHttpRequest: prefix_sz = 638, req_line_sz = 66
2014/03/10 12:25:24.975 kid1| clientStream.cc(167) clientStreamInsertHead: clientStreamInsertHead: Inserted node 0xb941e0e0 with data 0xb941ce3c after head
2014/03/10 12:25:24.975 kid1| client_side.cc(2316) parseHttpRequest: HTTP Client local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1
2014/03/10 12:25:24.976 kid1| client_side.cc(2317) parseHttpRequest: HTTP Client REQUEST:
---------
GET http://www.moovie.cc/images/movies/17031/poster.jpg HTTP/1.1
Host: www.moovie.cc
User-Agent: Links (2.6; Linux 3.13.5-202.fc20.i686+PAE i686; GNU C 4.8.1; text)
Accept: */*
Accept-Encoding: gzip,deflate,bzip2
Accept-Charset: us-ascii,ISO-8859-1,ISO-8859-2,ISO-8859-3,ISO-8859-4,ISO-8859-5,ISO-8859-6,ISO-8859-7,ISO-8859-8,ISO-8859-9,ISO-8859-10,ISO-8859-13,ISO-8859-14,ISO-8859-15,ISO-8859-16,windows-1250,windows-1251,windows-1252,windows-1256,windows-1257,cp437,cp737,cp850,cp852,cp866,x-cp866-u,x-mac,x-mac-ce,x-kam-cs,koi8-r,koi8-u,koi8-ru,TCVN-5712,VISCII,utf-8
Accept-Language: en,*;q=0.1
Proxy-Connection: keep-alive


----------
2014/03/10 12:25:24.976 kid1| comm.cc(773) commSetConnTimeout: local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 timeout 86400
2014/03/10 12:25:24.976 kid1| url.cc(386) urlParse: urlParse: Split URL 'http://www.moovie.cc/images/movies/17031/poster.jpg' into proto='http', host='www.moovie.cc', port='80', path='/images/movies/17031/poster.jpg'
2014/03/10 12:25:24.976 kid1| Address.cc(409) LookupHostIP: Given Non-IP 'www.moovie.cc': Name or service not known
2014/03/10 12:25:24.977 kid1| client_side.cc(840) clientSetKeepaliveFlag: clientSetKeepaliveFlag: http_ver = 1.1
2014/03/10 12:25:24.977 kid1| client_side.cc(842) clientSetKeepaliveFlag: clientSetKeepaliveFlag: method = GET
2014/03/10 12:25:24.977 kid1| client_side_request.cc(162) ClientRequestContext: 0xb941e058 ClientRequestContext constructed
2014/03/10 12:25:24.978 kid1| client_side_request.cc(1554) doCallouts: Doing calloutContext->hostHeaderVerify()
2014/03/10 12:25:24.978 kid1| client_side_request.cc(674) hostHeaderVerify: validate host=www.moovie.cc, port=0, portStr=NULL
2014/03/10 12:25:24.978 kid1| client_side_request.cc(688) hostHeaderVerify: validate skipped.
2014/03/10 12:25:24.978 kid1| client_side_request.cc(1561) doCallouts: Doing calloutContext->clientAccessCheck()
2014/03/10 12:25:24.978 kid1| Checklist.cc(153) preCheck: 0xb941eb50 checking slow rules
2014/03/10 12:25:24.978 kid1| Checklist.cc(160) checkAccessList: 0xb941eb50 checking 'http_access allow manager localhost'
2014/03/10 12:25:24.979 kid1| Acl.cc(336) matches: ACLList::matches: checking manager
2014/03/10 12:25:24.979 kid1| Acl.cc(319) checklistMatches: ACL::checklistMatches: checking 'manager'
2014/03/10 12:25:24.979 kid1| RegexData.cc(71) match: aclRegexData::match: checking 'http://www.moovie.cc/images/movies/17031/poster.jpg'
2014/03/10 12:25:24.979 kid1| RegexData.cc(82) match: aclRegexData::match: looking for '(^cache_object://)'
2014/03/10 12:25:24.979 kid1| RegexData.cc(82) match: aclRegexData::match: looking for '(^https?://[^/]+/squid-internal-mgr/)'
2014/03/10 12:25:24.979 kid1| Acl.cc(321) checklistMatches: ACL::ChecklistMatches: result for 'manager' is 0
2014/03/10 12:25:24.979 kid1| Checklist.cc(275) matchNode: 0xb941eb50 matched=0 async=0 finished=0
2014/03/10 12:25:24.979 kid1| Checklist.cc(299) matchNode: 0xb941eb50 simple mismatch
2014/03/10 12:25:24.979 kid1| Checklist.cc(160) checkAccessList: 0xb941eb50 checking 'http_access deny manager'
2014/03/10 12:25:24.980 kid1| Acl.cc(336) matches: ACLList::matches: checking manager
2014/03/10 12:25:24.980 kid1| Acl.cc(319) checklistMatches: ACL::checklistMatches: checking 'manager'
2014/03/10 12:25:24.980 kid1| RegexData.cc(71) match: aclRegexData::match: checking 'http://www.moovie.cc/images/movies/17031/poster.jpg'
2014/03/10 12:25:24.980 kid1| RegexData.cc(82) match: aclRegexData::match: looking for '(^cache_object://)'
2014/03/10 12:25:24.980 kid1| RegexData.cc(82) match: aclRegexData::match: looking for '(^https?://[^/]+/squid-internal-mgr/)'
2014/03/10 12:25:24.980 kid1| Acl.cc(321) checklistMatches: ACL::ChecklistMatches: result for 'manager' is 0
2014/03/10 12:25:24.980 kid1| Checklist.cc(275) matchNode: 0xb941eb50 matched=0 async=0 finished=0
2014/03/10 12:25:24.980 kid1| Checklist.cc(299) matchNode: 0xb941eb50 simple mismatch
2014/03/10 12:25:24.980 kid1| Checklist.cc(160) checkAccessList: 0xb941eb50 checking 'http_access deny block_site'
2014/03/10 12:25:24.980 kid1| Acl.cc(336) matches: ACLList::matches: checking block_site
2014/03/10 12:25:24.980 kid1| Acl.cc(319) checklistMatches: ACL::checklistMatches: checking 'block_site'
2014/03/10 12:25:24.980 kid1| RegexData.cc(71) match: aclRegexData::match: checking 'http://www.moovie.cc/images/movies/17031/poster.jpg'
2014/03/10 12:25:24.981 kid1| RegexData.cc(82) match: aclRegexData::match: looking for '(safebrowsing)|(amung.us)|(google-analytics.com)|(netadclick.com)|(gemius.pl)|(scarabresearch.com)|(statcounter.com)|(chartbeat.net)|(audit.median.hu)|(doubleclick)|(virtual-hideout.net/banner)|(vodo.net/static/images/promotion/utorrent_plus_buy.png)|(vonradio.com/grfx/banners)|(wardsauto.com/pm_doubleclick)|(washingtonpost.com/wp-srv/ad/ad_)|(watchseries.eu/images/affiliate_buzz.gif)|(watchseries.eu/images/download.png)|(watchseries.eu/js/csspopup.js)|(wcast.tv/js/mehar.js?)|(wdwinfo.com/js/swap.js)|(weatheroffice.gc.ca/banner)|(webmaster.extabit.com)|(webmastercrunch.com)|(weselectmodels.com)|(whatismyip.com)|(whistleout.com.au)|(windowsitpro.com/roadblock.js)|(winnfm.com/grfx/banners)|(wishlistproducts.com)|(wordreference.com)|(worldmag.com)|(worthofweb.com)'
2014/03/10 12:25:24.982 kid1| Acl.cc(321) checklistMatches: ACL::ChecklistMatches: result for 'block_site' is 0
2014/03/10 12:25:24.982 kid1| Checklist.cc(275) matchNode: 0xb941eb50 matched=0 async=0 finished=0
2014/03/10 12:25:24.982 kid1| Checklist.cc(299) matchNode: 0xb941eb50 simple mismatch
2014/03/10 12:25:24.982 kid1| Checklist.cc(160) checkAccessList: 0xb941eb50 checking 'http_access deny !Safe_ports'
2014/03/10 12:25:24.982 kid1| Acl.cc(336) matches: ACLList::matches: checking !Safe_ports
2014/03/10 12:25:24.982 kid1| Acl.cc(319) checklistMatches: ACL::checklistMatches: checking 'Safe_ports'
2014/03/10 12:25:24.983 kid1| Acl.cc(321) checklistMatches: ACL::ChecklistMatches: result for 'Safe_ports' is 1
2014/03/10 12:25:24.983 kid1| Checklist.cc(275) matchNode: 0xb941eb50 matched=0 async=0 finished=0
2014/03/10 12:25:24.983 kid1| Checklist.cc(299) matchNode: 0xb941eb50 simple mismatch
2014/03/10 12:25:24.983 kid1| Checklist.cc(160) checkAccessList: 0xb941eb50 checking 'http_access allow localnet'
2014/03/10 12:25:24.983 kid1| Acl.cc(336) matches: ACLList::matches: checking localnet
2014/03/10 12:25:24.983 kid1| Acl.cc(319) checklistMatches: ACL::checklistMatches: checking 'localnet'
2014/03/10 12:25:24.983 kid1| Ip.cc(560) match: aclIpMatchIp: '192.168.50.200:53191' found
2014/03/10 12:25:24.983 kid1| Acl.cc(321) checklistMatches: ACL::ChecklistMatches: result for 'localnet' is 1
2014/03/10 12:25:24.983 kid1| Checklist.cc(275) matchNode: 0xb941eb50 matched=1 async=0 finished=0
2014/03/10 12:25:24.984 kid1| Checklist.cc(260) matchNodes: 0xb941eb50 success: all ACLs matched
2014/03/10 12:25:24.984 kid1| Checklist.cc(146) markFinished: 0xb941eb50 answer ALLOWED for first matching rule won
2014/03/10 12:25:24.984 kid1| Checklist.cc(88) matchNonBlocking: ACLChecklist::check: 0xb941eb50 match found, calling back with ALLOWED
2014/03/10 12:25:24.984 kid1| Checklist.cc(182) checkCallback: ACLChecklist::checkCallback: 0xb941eb50 answer=ALLOWED
2014/03/10 12:25:24.984 kid1| client_side_request.cc(786) clientAccessCheckDone: The request GET http://www.moovie.cc/images/movies/17031/poster.jpg is ALLOWED, because it matched 'localnet'
2014/03/10 12:25:24.984 kid1| AccessCheck.cc(32) Start: adaptation off, skipping
2014/03/10 12:25:24.984 kid1| client_side_request.cc(1590) doCallouts: Doing calloutContext->clientAccessCheck2()
2014/03/10 12:25:24.984 kid1| client_side_request.cc(760) clientAccessCheck2: No adapted_http_access configuration. default: ALLOW
2014/03/10 12:25:24.984 kid1| client_side_request.cc(786) clientAccessCheckDone: The request GET http://www.moovie.cc/images/movies/17031/poster.jpg is ALLOWED, because it matched 'localnet'
2014/03/10 12:25:24.985 kid1| client_side_request.cc(1597) doCallouts: Doing clientInterpretRequestHeaders()
2014/03/10 12:25:24.985 kid1| client_side_request.cc(1606) doCallouts: Doing calloutContext->checkNoCache()
2014/03/10 12:25:24.985 kid1| Checklist.cc(153) preCheck: 0xb9424ee8 checking slow rules
2014/03/10 12:25:24.985 kid1| Checklist.cc(160) checkAccessList: 0xb9424ee8 checking 'cache allow KEPEK'
2014/03/10 12:25:24.985 kid1| Acl.cc(336) matches: ACLList::matches: checking KEPEK
2014/03/10 12:25:24.985 kid1| Acl.cc(319) checklistMatches: ACL::checklistMatches: checking 'KEPEK'
2014/03/10 12:25:24.985 kid1| RegexData.cc(71) match: aclRegexData::match: checking '/images/movies/17031/poster.jpg'
2014/03/10 12:25:24.985 kid1| RegexData.cc(82) match: aclRegexData::match: looking for '(.)'
2014/03/10 12:25:24.985 kid1| RegexData.cc(93) match: aclRegexData::match: match '(.)' found in '/images/movies/17031/poster.jpg'
2014/03/10 12:25:24.986 kid1| Acl.cc(321) checklistMatches: ACL::ChecklistMatches: result for 'KEPEK' is 1
2014/03/10 12:25:24.986 kid1| Checklist.cc(275) matchNode: 0xb9424ee8 matched=1 async=0 finished=0
2014/03/10 12:25:24.986 kid1| Checklist.cc(260) matchNodes: 0xb9424ee8 success: all ACLs matched
2014/03/10 12:25:24.986 kid1| Checklist.cc(146) markFinished: 0xb9424ee8 answer ALLOWED for first matching rule won
2014/03/10 12:25:24.986 kid1| Checklist.cc(88) matchNonBlocking: ACLChecklist::check: 0xb9424ee8 match found, calling back with ALLOWED
2014/03/10 12:25:24.986 kid1| Checklist.cc(182) checkCallback: ACLChecklist::checkCallback: 0xb9424ee8 answer=ALLOWED
2014/03/10 12:25:24.986 kid1| client_side_request.cc(150) ~ClientRequestContext: 0xb941e058 ClientRequestContext destructed
2014/03/10 12:25:24.987 kid1| client_side_request.cc(1686) doCallouts: calling processRequest()
2014/03/10 12:25:24.987 kid1| clientStream.cc(207) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0xb941e008 from node 0xb941e0e0
2014/03/10 12:25:24.987 kid1| store_dir.cc(935) get: storeGet: looking up 9F5C91C8456A9B3B8B81DAE4DD035FE8
2014/03/10 12:25:24.987 kid1| client_side_reply.cc(1626) identifyFoundObject: clientProcessRequest2: StoreEntry is NULL -  MISS
2014/03/10 12:25:24.987 kid1| store.cc(825) storeCreateEntry: storeCreateEntry: 'http://www.moovie.cc/images/movies/17031/poster.jpg'
2014/03/10 12:25:24.987 kid1| store.cc(401) StoreEntry: new StoreEntry 0xb9425460
2014/03/10 12:25:24.988 kid1| MemObject.cc(88) MemObject: new MemObject 0xb94254a8
2014/03/10 12:25:24.988 kid1| store_key_md5.cc(109) storeKeyPrivate: storeKeyPrivate: GET http://www.moovie.cc/images/movies/17031/poster.jpg
2014/03/10 12:25:24.988 kid1| store.cc(487) hashInsert: StoreEntry::hashInsert: Inserting Entry 0xb9425460 key '4366A7DE8B491EB929F21A29388E7E7A'
2014/03/10 12:25:24.988 kid1| store_client.cc(237) copy: store_client::copy: 4366A7DE8B491EB929F21A29388E7E7A, from 0, for length 4096, cb 1, cbdata 0xb941cfa0
2014/03/10 12:25:24.988 kid1| store_client.cc(332) storeClientCopy2: storeClientCopy2: 4366A7DE8B491EB929F21A29388E7E7A
2014/03/10 12:25:24.988 kid1| store_client.cc(376) doCopy: store_client::doCopy: Waiting for more
2014/03/10 12:25:24.988 kid1| store.cc(570) unlock: StoreEntry::unlock: key '4366A7DE8B491EB929F21A29388E7E7A' count=1
2014/03/10 12:25:24.988 kid1| forward.cc(317) Start: 'http://www.moovie.cc/images/movies/17031/poster.jpg'
2014/03/10 12:25:24.989 kid1| forward.cc(121) FwdState: Forwarding client request local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1, url=http://www.moovie.cc/images/movies/17031/poster.jpg
2014/03/10 12:25:24.989 kid1| store.cc(530) lock: StoreEntry::lock: key '4366A7DE8B491EB929F21A29388E7E7A' count=2
2014/03/10 12:25:24.989 kid1| peer_select.cc(155) peerSelect: peerSelect: http://www.moovie.cc/images/movies/17031/poster.jpg
2014/03/10 12:25:24.989 kid1| store.cc(530) lock: StoreEntry::lock: key '4366A7DE8B491EB929F21A29388E7E7A' count=3
2014/03/10 12:25:24.989 kid1| peer_select.cc(438) peerSelectFoo: peerSelectFoo: 'GET www.moovie.cc'
2014/03/10 12:25:24.989 kid1| peer_select.cc(467) peerSelectFoo: peerSelectFoo: direct = DIRECT_MAYBE (default)
2014/03/10 12:25:24.989 kid1| peer_select.cc(470) peerSelectFoo: peerSelectFoo: direct = DIRECT_MAYBE
2014/03/10 12:25:24.989 kid1| peer_select.cc(129) peerSelectIcpPing: peerSelectIcpPing: http://www.moovie.cc/images/movies/17031/poster.jpg
2014/03/10 12:25:24.990 kid1| neighbors.cc(276) neighborsCount: neighborsCount: 0
2014/03/10 12:25:24.990 kid1| peer_select.cc(140) peerSelectIcpPing: peerSelectIcpPing: counted 0 neighbors
2014/03/10 12:25:24.990 kid1| peer_select.cc(678) peerGetSomeParent: peerGetSomeParent: GET www.moovie.cc
2014/03/10 12:25:24.990 kid1| neighbors.cc(337) getRoundRobinParent: returning NULL
2014/03/10 12:25:24.990 kid1| neighbors.cc(387) getWeightedRoundRobinParent: getWeightedRoundRobinParent: returning NULL
2014/03/10 12:25:24.990 kid1| neighbors.cc(299) getFirstUpParent: getFirstUpParent: returning NULL
2014/03/10 12:25:24.990 kid1| neighbors.cc(475) getDefaultParent: getDefaultParent: returning NULL
2014/03/10 12:25:24.990 kid1| neighbors.cc(475) getDefaultParent: getDefaultParent: returning NULL
2014/03/10 12:25:24.990 kid1| peer_select.cc(268) peerSelectDnsPaths: Find IP destination for: http://www.moovie.cc/images/movies/17031/poster.jpg' via www.moovie.cc
2014/03/10 12:25:24.990 kid1| Address.cc(409) LookupHostIP: Given Non-IP 'www.moovie.cc': Name or service not known
2014/03/10 12:25:24.991 kid1| dns_internal.cc(1721) idnsALookup: idnsALookup: buf is 31 bytes for www.moovie.cc, id = 0xe9a
2014/03/10 12:25:24.991 kid1| comm.cc(1197) comm_udp_sendto: comm_udp_sendto: Attempt to send UDP packet to 192.168.50.1:53 using FD 8 using Port 34698
2014/03/10 12:25:24.991 kid1| dns_internal.cc(1660) idnsSendSlaveAAAAQuery: buf is 31 bytes for www.moovie.cc, id = 0x5a22
2014/03/10 12:25:24.991 kid1| comm.cc(1197) comm_udp_sendto: comm_udp_sendto: Attempt to send UDP packet to 192.168.50.1:53 using FD 8 using Port 34698
2014/03/10 12:25:25.007 kid1| dns_internal.cc(1259) idnsRead: idnsRead: starting with FD 8
2014/03/10 12:25:25.008 kid1| dns_internal.cc(1305) idnsRead: idnsRead: FD 8: received 63 bytes from 192.168.50.1:53
2014/03/10 12:25:25.008 kid1| dns_internal.cc(1112) idnsGrokReply: idnsGrokReply: QID 0xe9a, 2 answers
2014/03/10 12:25:25.018 kid1| dns_internal.cc(1259) idnsRead: idnsRead: starting with FD 8
2014/03/10 12:25:25.019 kid1| dns_internal.cc(1305) idnsRead: idnsRead: FD 8: received 93 bytes from 192.168.50.1:53
2014/03/10 12:25:25.019 kid1| dns_internal.cc(1112) idnsGrokReply: idnsGrokReply: QID 0x5a22, 0 answers
2014/03/10 12:25:25.019 kid1| ipcache.cc(497) ipcacheParse: ipcacheParse: 2 answers for 'www.moovie.cc'
2014/03/10 12:25:25.019 kid1| ipcache.cc(555) ipcacheParse: ipcacheParse: www.moovie.cc #0 141.101.118.23
2014/03/10 12:25:25.019 kid1| ipcache.cc(555) ipcacheParse: ipcacheParse: www.moovie.cc #1 141.101.118.22
2014/03/10 12:25:25.019 kid1| peer_select.cc(289) peerSelectDnsPaths: Found sources for 'http://www.moovie.cc/images/movies/17031/poster.jpg'
2014/03/10 12:25:25.019 kid1| peer_select.cc(290) peerSelectDnsPaths:   always_direct = DENIED
2014/03/10 12:25:25.019 kid1| peer_select.cc(291) peerSelectDnsPaths:    never_direct = DENIED
2014/03/10 12:25:25.019 kid1| peer_select.cc(295) peerSelectDnsPaths:          DIRECT = local=0.0.0.0 remote=141.101.118.23:80 flags=1
2014/03/10 12:25:25.019 kid1| peer_select.cc(295) peerSelectDnsPaths:          DIRECT = local=0.0.0.0 remote=141.101.118.22:80 flags=1
2014/03/10 12:25:25.019 kid1| peer_select.cc(304) peerSelectDnsPaths:        timedout = 0
2014/03/10 12:25:25.019 kid1| forward.cc(368) startConnectionOrFail: http://www.moovie.cc/images/movies/17031/poster.jpg
2014/03/10 12:25:25.020 kid1| forward.cc(936) connectStart: fwdConnectStart: http://www.moovie.cc/images/movies/17031/poster.jpg
2014/03/10 12:25:25.020 kid1| pconn.cc(436) pop: lookup for key {141.101.118.23:80/www.moovie.cc} failed.
2014/03/10 12:25:25.020 kid1| forward.cc(1060) connectStart: fwdConnectStart: got outgoing addr 0.0.0.0, tos 0, netfilter mark 0
2014/03/10 12:25:25.020 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall fwdConnectDoneWrapper constructed, this=0xb942a268 [call429]
2014/03/10 12:25:25.020 kid1| peer_select.cc(96) peerSelectStateFree: http://www.moovie.cc/images/movies/17031/poster.jpg
2014/03/10 12:25:25.020 kid1| store.cc(570) unlock: StoreEntry::unlock: key '4366A7DE8B491EB929F21A29388E7E7A' count=2
2014/03/10 12:25:25.020 kid1| comm.cc(554) comm_openex: comm_openex: Attempt open socket for: 0.0.0.0
2014/03/10 12:25:25.020 kid1| comm.cc(595) comm_openex: comm_openex: Opened socket local=0.0.0.0 remote=[::] FD 12 flags=1 : family=2, type=1, protocol=6
2014/03/10 12:25:25.020 kid1| fd.cc(221) fd_open: fd_open() FD 12 www.moovie.cc
2014/03/10 12:25:25.021 kid1| ConnOpener.cc(270) createFd: local=0.0.0.0 remote=141.101.118.23:80 flags=1 will timeout in 60
2014/03/10 12:25:25.050 kid1| AsyncCall.cc(85) ScheduleCall: ConnOpener.cc(132) will call fwdConnectDoneWrapper(local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1, data=0xb94257c8) [call429]
2014/03/10 12:25:25.050 kid1| AsyncCallQueue.cc(51) fireNext: entering fwdConnectDoneWrapper(local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1, data=0xb94257c8)
2014/03/10 12:25:25.050 kid1| AsyncCall.cc(30) make: make call fwdConnectDoneWrapper [call429]
2014/03/10 12:25:25.051 kid1| forward.cc(883) connectDone: local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1: 'http://www.moovie.cc/images/movies/17031/poster.jpg'
2014/03/10 12:25:25.051 kid1| forward.cc(1076) dispatch: local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1: Fetching 'GET http://www.moovie.cc/images/movies/17031/poster.jpg'
2014/03/10 12:25:25.051 kid1| http.cc(2269) httpStart: httpStart: "GET http://www.moovie.cc/images/movies/17031/poster.jpg"
2014/03/10 12:25:25.051 kid1| store.cc(530) lock: StoreEntry::lock: key '4366A7DE8B491EB929F21A29388E7E7A' count=3
2014/03/10 12:25:25.052 kid1| AsyncCallQueue.cc(53) fireNext: leaving fwdConnectDoneWrapper(local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1, data=0xb94257c8)
2014/03/10 12:25:25.052 kid1| comm.cc(773) commSetConnTimeout: local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 timeout 86400
2014/03/10 12:25:25.053 kid1| refresh.cc(540) getMaxAge: getMaxAge: 'http://www.moovie.cc/images/movies/17031/poster.jpg'
2014/03/10 12:25:25.053 kid1| http.cc(2225) sendRequest: HTTP Server local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.053 kid1| http.cc(2226) sendRequest: HTTP Server REQUEST:
---------
GET /images/movies/17031/poster.jpg HTTP/1.1
Host: www.moovie.cc
User-Agent: Links (2.6; Linux 3.13.5-202.fc20.i686+PAE i686; GNU C 4.8.1; text)
Accept: */*
Accept-Encoding: gzip,deflate,bzip2
Accept-Charset: us-ascii,ISO-8859-1,ISO-8859-2,ISO-8859-3,ISO-8859-4,ISO-8859-5,ISO-8859-6,ISO-8859-7,ISO-8859-8,ISO-8859-9,ISO-8859-10,ISO-8859-13,ISO-8859-14,ISO-8859-15,ISO-8859-16,windows-1250,windows-1251,windows-1252,windows-1256,windows-1257,cp437,cp737,cp850,cp852,cp866,x-cp866-u,x-mac,x-mac-ce,x-kam-cs,koi8-r,koi8-u,koi8-ru,TCVN-5712,VISCII,utf-8
Accept-Language: en,*;q=0.1
X-Forwarded-For: unknown
Cache-Control: max-age=31536000
Connection: keep-alive


----------
2014/03/10 12:25:25.054 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 (0, 0)
2014/03/10 12:25:25.055 kid1| comm.cc(773) commSetConnTimeout: local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 timeout 900
2014/03/10 12:25:25.097 kid1| comm.cc(145) commHandleRead: comm_read_try: FD 12, size 16383, retval 1440, errno 0
2014/03/10 12:25:25.097 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 (0, 0)
2014/03/10 12:25:25.098 kid1| ctx: enter level  0: 'http://www.moovie.cc/images/movies/17031/poster.jpg'
2014/03/10 12:25:25.098 kid1| http.cc(718) processReplyHeader: processReplyHeader: key '4366A7DE8B491EB929F21A29388E7E7A'
2014/03/10 12:25:25.098 kid1| http.cc(761) processReplyHeader: HTTP Server local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.099 kid1| http.cc(762) processReplyHeader: HTTP Server REPLY:
---------
HTTP/1.1 200 OK
Server: cloudflare-nginx
Date: Mon, 10 Mar 2014 11:25:25 GMT
Content-Type: image/jpeg
Content-Length: 49540
Connection: keep-alive
Set-Cookie: __cfduid=d6865dd8f19d5eb104d92c28561b2c7881394450725072; expires=Mon, 23-Dec-2019 23:50:00 GMT; path=/; domain=.moovie.cc; HttpOnly
Last-Modified: Sun, 29 Dec 2013 16:40:10 GMT
CF-Cache-Status: HIT
Vary: Accept-Encoding
Expires: Sun, 11 May 2014 11:25:25 GMT
Cache-Control: public, max-age=5356800
Accept-Ranges: bytes
CF-RAY: 108f26c7b23d047f-FRA

▒▒▒▒
----------
2014/03/10 12:25:25.099 kid1| ctx: exit level  0
2014/03/10 12:25:25.101 kid1| AccessCheck.cc(32) Start: adaptation off, skipping
2014/03/10 12:25:25.101 kid1| store.cc(1834) replaceHttpReply: StoreEntry::replaceHttpReply: http://www.moovie.cc/images/movies/17031/poster.jpg
2014/03/10 12:25:25.101 kid1| ctx: enter level  0: 'http://www.moovie.cc/images/movies/17031/poster.jpg'
2014/03/10 12:25:25.101 kid1| http.cc(930) haveParsedReplyHeaders: haveParsedReplyHeaders: HTTP CODE: 200
2014/03/10 12:25:25.101 kid1| store_dir.cc(935) get: storeGet: looking up 9F5C91C8456A9B3B8B81DAE4DD035FE8
2014/03/10 12:25:25.101 kid1| store_dir.cc(935) get: storeGet: looking up D38FDB47B3AC2F7C390242E9CFCB7D96
2014/03/10 12:25:25.101 kid1| http.cc(669) httpMakeVaryMark: httpMakeVaryMark: accept-encoding="gzip,deflate,bzip2"
2014/03/10 12:25:25.102 kid1| refresh.cc(247) refreshCheck: refreshCheck: 'http://www.moovie.cc/images/movies/17031/poster.jpg'
2014/03/10 12:25:25.102 kid1| refresh.cc(262) refreshCheck: refreshCheck: Matched '. 31536000 100%% 31536000'
2014/03/10 12:25:25.102 kid1| refresh.cc(264) refreshCheck:     age:    60
2014/03/10 12:25:25.102 kid1| refresh.cc(266) refreshCheck:     check_time:     Mon, 10 Mar 2014 11:26:25 GMT
2014/03/10 12:25:25.102 kid1| refresh.cc(268) refreshCheck:     entry->timestamp:       Mon, 10 Mar 2014 11:25:25 GMT
2014/03/10 12:25:25.102 kid1| refresh.cc(171) refreshStaleness: FRESH: expires 1399807525 >= check_time 1394450785
2014/03/10 12:25:25.102 kid1| refresh.cc(288) refreshCheck: Staleness = -1
2014/03/10 12:25:25.102 kid1| refresh.cc(373) refreshCheck: refreshCheck: object isn't stale..
2014/03/10 12:25:25.102 kid1| refresh.cc(375) refreshCheck: refreshCheck: returning FRESH_EXPIRES
2014/03/10 12:25:25.102 kid1| http.cc(495) cacheableReply: YES because HTTP status 200
2014/03/10 12:25:25.102 kid1| http.cc(669) httpMakeVaryMark: httpMakeVaryMark: accept-encoding="gzip,deflate,bzip2"
2014/03/10 12:25:25.102 kid1| store_dir.cc(935) get: storeGet: looking up 9F5C91C8456A9B3B8B81DAE4DD035FE8
2014/03/10 12:25:25.103 kid1| store.cc(825) storeCreateEntry: storeCreateEntry: 'http://www.moovie.cc/images/movies/17031/poster.jpg'
2014/03/10 12:25:25.104 kid1| store.cc(401) StoreEntry: new StoreEntry 0xb942f9a0
2014/03/10 12:25:25.104 kid1| MemObject.cc(88) MemObject: new MemObject 0xb942f9e8
2014/03/10 12:25:25.104 kid1| store_key_md5.cc(109) storeKeyPrivate: storeKeyPrivate: GET http://www.moovie.cc/images/movies/17031/poster.jpg
2014/03/10 12:25:25.105 kid1| store.cc(487) hashInsert: StoreEntry::hashInsert: Inserting Entry 0xb942f9a0 key 'D160095DCB99976A89C6BF7410008A03'
2014/03/10 12:25:25.105 kid1| store.cc(1834) replaceHttpReply: StoreEntry::replaceHttpReply: http://www.moovie.cc/images/movies/17031/poster.jpg
2014/03/10 12:25:25.107 kid1| store.cc(1009) checkCachable: StoreEntry::checkCachable: NO: private key
2014/03/10 12:25:25.107 kid1| store.cc(541) setReleaseFlag: StoreEntry::setReleaseFlag: 'D160095DCB99976A89C6BF7410008A03'
2014/03/10 12:25:25.107 kid1| store_swapout.cc(393) mayStartSwapOut: not cachable
2014/03/10 12:25:25.107 kid1| store_client.cc(776) invokeHandlers: InvokeHandlers: D160095DCB99976A89C6BF7410008A03
2014/03/10 12:25:25.107 kid1| store.cc(1068) complete: storeComplete: 'D160095DCB99976A89C6BF7410008A03'
2014/03/10 12:25:25.107 kid1| store.cc(1369) validLength: storeEntryValidLength: Checking 'D160095DCB99976A89C6BF7410008A03'
2014/03/10 12:25:25.107 kid1| store_swapout.cc(375) mayStartSwapOut:  already rejected
2014/03/10 12:25:25.107 kid1| store_client.cc(776) invokeHandlers: InvokeHandlers: D160095DCB99976A89C6BF7410008A03
2014/03/10 12:25:25.107 kid1| store.cc(570) unlock: StoreEntry::unlock: key 'D160095DCB99976A89C6BF7410008A03' count=0
2014/03/10 12:25:25.108 kid1| store_client.cc(801) storePendingNClients: storePendingNClients: returning 0
2014/03/10 12:25:25.108 kid1| store.cc(1261) release: storeRelease: Releasing: 'D160095DCB99976A89C6BF7410008A03'
2014/03/10 12:25:25.108 kid1| store.cc(466) destroyStoreEntry: destroyStoreEntry: destroying 0xb942f9a4
2014/03/10 12:25:25.108 kid1| store.cc(444) destroyMemObject: destroyMemObject 0xb942f9e8
2014/03/10 12:25:25.108 kid1| MemObject.cc(111) ~MemObject: del MemObject 0xb942f9e8
2014/03/10 12:25:25.108 kid1| store.cc(487) hashInsert: StoreEntry::hashInsert: Inserting Entry 0xb9425460 key '53804C3A926E06BC3760A15E5F9E6E0D'
2014/03/10 12:25:25.108 kid1| ctx: exit level  0
2014/03/10 12:25:25.108 kid1| store_client.cc(776) invokeHandlers: InvokeHandlers: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.108 kid1| store_client.cc(782) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0
2014/03/10 12:25:25.108 kid1| store_client.cc(332) storeClientCopy2: storeClientCopy2: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.108 kid1| store_client.cc(465) scheduleMemRead: store_client::doCopy: Copying normal from memory
2014/03/10 12:25:25.109 kid1| client_side_reply.cc(1982) processReplyAccessResult: The reply for GET http://www.moovie.cc/images/movies/17031/poster.jpg is ALLOWED, because it matched 'KEPEK'
2014/03/10 12:25:25.109 kid1| store.cc(530) lock: StoreEntry::lock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=4
2014/03/10 12:25:25.110 kid1| client_side_reply.cc(2020) processReplyAccessResult: clientReplyContext::sendMoreData: Appending 0 bytes after 523 bytes of headers
2014/03/10 12:25:25.110 kid1| clientStream.cc(185) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0xb941ce3c from node 0xb941bda8
2014/03/10 12:25:25.113 kid1| client_side.cc(1377) sendStartOfMessage: HTTP Client local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1
2014/03/10 12:25:25.116 kid1| client_side.cc(1378) sendStartOfMessage: HTTP Client REPLY:
---------
HTTP/1.1 200 OK
Server: cloudflare-nginx
Date: Mon, 10 Mar 2014 11:25:25 GMT
Content-Type: image/jpeg
Content-Length: 49540
Set-Cookie: __cfduid=d6865dd8f19d5eb104d92c28561b2c7881394450725072; expires=Mon, 23-Dec-2019 23:50:00 GMT; path=/; domain=.moovie.cc; HttpOnly
Last-Modified: Sun, 29 Dec 2013 16:40:10 GMT
CF-Cache-Status: HIT
Vary: Accept-Encoding
Expires: Sun, 11 May 2014 11:25:25 GMT
Cache-Control: public, max-age=5356800
Accept-Ranges: bytes
CF-RAY: 108f26c7b23d047f-FRA
X-Cache: MISS from tradestation5.warbird
X-Cache-Lookup: MISS from tradestation5.warbird:3128
Connection: keep-alive


----------
2014/03/10 12:25:25.116 kid1| store_swapout.cc(381) mayStartSwapOut: already allowed
2014/03/10 12:25:25.116 kid1| store_client.cc(776) invokeHandlers: InvokeHandlers: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.118 kid1| store_client.cc(782) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0
2014/03/10 12:25:25.118 kid1| http.cc(1076) persistentConnStatus: local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 eof=0
2014/03/10 12:25:25.118 kid1| comm.cc(773) commSetConnTimeout: local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 timeout 900
2014/03/10 12:25:25.118 kid1| comm.cc(145) commHandleRead: comm_read_try: FD 12, size 16383, retval 12960, errno 0
2014/03/10 12:25:25.118 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 (0, 0)
2014/03/10 12:25:25.120 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 (0, 0)
2014/03/10 12:25:25.121 kid1| store_swapout.cc(381) mayStartSwapOut: already allowed
2014/03/10 12:25:25.121 kid1| store_swapmeta.cc(71) storeSwapMetaBuild: storeSwapMetaBuild: http://www.moovie.cc/images/movies/17031/poster.jpg
2014/03/10 12:25:25.122 kid1| store_io.cc(34) storeCreate: storeCreate: Selected dir 0 for -1@-1=0/2/1/1
2014/03/10 12:25:25.123 kid1| ufs/UFSStrategy.cc(121) create: fileno 00000000
2014/03/10 12:25:25.124 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(78) DiskThreadsDiskFile: UFSFile::UFSFile: /var/spool/squid/00/00/00000000
2014/03/10 12:25:25.125 kid1| fd.cc(221) fd_open: fd_open() FD 14 async-io completion event: main
2014/03/10 12:25:25.126 kid1| fd.cc(221) fd_open: fd_open() FD 15 async-io completion event: threads
2014/03/10 12:25:25.130 kid1| heap/store_heap_replacement.cc(91) HeapKeyGen_StoreEntry_LFUDA: HeapKeyGen_StoreEntry_LFUDA: 53804C3A926E06BC3760A15E5F9E6E0D refcnt=1 lastref=1394450725 heap_age=1.00 tie=0.00 -> 2.00
2014/03/10 12:25:25.131 kid1| heap/store_heap_replacement.cc(94) HeapKeyGen_StoreEntry_LFUDA: HeapKeyGen_StoreEntry_LFUDA: url=http://www.moovie.cc/images/movies/17031/poster.jpg
2014/03/10 12:25:25.131 kid1| store.cc(530) lock: StoreEntry::lock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=5
2014/03/10 12:25:25.131 kid1| ufs/UFSStoreState.cc(197) write: UFSStoreState::write: dirn 0, fileno 00000000
2014/03/10 12:25:25.132 kid1| ufs/UFSStoreState.cc(504) queueWrite: 0xb9434a78 UFSStoreState::queueWrite: queueing write of size 171
2014/03/10 12:25:25.132 kid1| store_swapout.cc(153) doPages: storeSwapOut: swap_buf_len = 4096
2014/03/10 12:25:25.134 kid1| store_swapout.cc(157) doPages: storeSwapOut: swapping out 4096 bytes from 0
2014/03/10 12:25:25.137 kid1| ufs/UFSStoreState.cc(197) write: UFSStoreState::write: dirn 0, fileno 00000000
2014/03/10 12:25:25.138 kid1| ufs/UFSStoreState.cc(504) queueWrite: 0xb9434a78 UFSStoreState::queueWrite: queueing write of size 4096
2014/03/10 12:25:25.139 kid1| store_swapout.cc(153) doPages: storeSwapOut: swap_buf_len = 4096
2014/03/10 12:25:25.140 kid1| store_swapout.cc(157) doPages: storeSwapOut: swapping out 4096 bytes from 4096
2014/03/10 12:25:25.141 kid1| ufs/UFSStoreState.cc(197) write: UFSStoreState::write: dirn 0, fileno 00000000
2014/03/10 12:25:25.142 kid1| ufs/UFSStoreState.cc(504) queueWrite: 0xb9434a78 UFSStoreState::queueWrite: queueing write of size 4096
2014/03/10 12:25:25.143 kid1| store_swapout.cc(153) doPages: storeSwapOut: swap_buf_len = 4096
2014/03/10 12:25:25.144 kid1| store_swapout.cc(157) doPages: storeSwapOut: swapping out 4096 bytes from 8192
2014/03/10 12:25:25.145 kid1| ufs/UFSStoreState.cc(197) write: UFSStoreState::write: dirn 0, fileno 00000000
2014/03/10 12:25:25.146 kid1| ufs/UFSStoreState.cc(504) queueWrite: 0xb9434a78 UFSStoreState::queueWrite: queueing write of size 4096
2014/03/10 12:25:25.147 kid1| store_client.cc(776) invokeHandlers: InvokeHandlers: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.148 kid1| store_client.cc(782) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0
2014/03/10 12:25:25.149 kid1| http.cc(1076) persistentConnStatus: local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 eof=0
2014/03/10 12:25:25.149 kid1| comm.cc(773) commSetConnTimeout: local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 timeout 900
2014/03/10 12:25:25.150 kid1| HttpReply.cc(562) receivedBodyTooLarge: -4096 >? -1
2014/03/10 12:25:25.151 kid1| clientStream.cc(207) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0xb941e008 from node 0xb941e0e0
2014/03/10 12:25:25.152 kid1| store_client.cc(237) copy: store_client::copy: 53804C3A926E06BC3760A15E5F9E6E0D, from 523, for length 4096, cb 1, cbdata 0xb941cfa0
2014/03/10 12:25:25.153 kid1| store_client.cc(332) storeClientCopy2: storeClientCopy2: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.154 kid1| store_client.cc(465) scheduleMemRead: store_client::doCopy: Copying normal from memory
2014/03/10 12:25:25.154 kid1| clientStream.cc(185) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0xb941ce3c from node 0xb941bda8
2014/03/10 12:25:25.155 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=5
2014/03/10 12:25:25.156 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(185) openDone: DiskThreadsDiskFile::openDone: FD 16, errflag 0
2014/03/10 12:25:25.175 kid1| fd.cc(221) fd_open: fd_open() FD 16 /var/spool/squid/00/00/00000000
2014/03/10 12:25:25.176 kid1| ufs/UFSStoreState.cc(82) ioCompletedNotification: UFSStoreState::ioCompletedNotification: dirno 0, fileno 00000000 status 0
2014/03/10 12:25:25.177 kid1| ufs/UFSStoreState.cc(219) doWrite: 0xb9434a78 UFSStoreState::doWrite
2014/03/10 12:25:25.178 kid1| ufs/UFSStoreState.cc(254) doWrite: 0xb9434a78 calling theFile->write(171)
2014/03/10 12:25:25.179 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(253) write: DiskThreadsDiskFile::write: FD 16
2014/03/10 12:25:25.180 kid1| disk.cc(233) diskHandleWrite: diskHandleWrite: FD 16
2014/03/10 12:25:25.180 kid1| disk.cc(243) diskHandleWrite: diskHandleWrite: FD 16 writing 171 bytes at 0
2014/03/10 12:25:25.181 kid1| disk.cc(254) diskHandleWrite: diskHandleWrite: FD 16 len = 171
2014/03/10 12:25:25.182 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(361) writeDone: DiskThreadsDiskFile::writeDone: FD 16, len 171, err=0
2014/03/10 12:25:25.183 kid1| ufs/UFSStoreState.cc(308) writeCompleted: dirno 0, fileno 00000000, len AB
2014/03/10 12:25:25.184 kid1| ufs/UFSStoreState.cc(219) doWrite: 0xb9434a78 UFSStoreState::doWrite
2014/03/10 12:25:25.185 kid1| ufs/UFSStoreState.cc(254) doWrite: 0xb9434a78 calling theFile->write(4096)
2014/03/10 12:25:25.186 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(253) write: DiskThreadsDiskFile::write: FD 16
2014/03/10 12:25:25.186 kid1| disk.cc(233) diskHandleWrite: diskHandleWrite: FD 16
2014/03/10 12:25:25.187 kid1| disk.cc(243) diskHandleWrite: diskHandleWrite: FD 16 writing 4096 bytes at -1
2014/03/10 12:25:25.189 kid1| disk.cc(254) diskHandleWrite: diskHandleWrite: FD 16 len = 4096
2014/03/10 12:25:25.190 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(361) writeDone: DiskThreadsDiskFile::writeDone: FD 16, len 4096, err=0
2014/03/10 12:25:25.191 kid1| ufs/UFSStoreState.cc(308) writeCompleted: dirno 0, fileno 00000000, len 1000
2014/03/10 12:25:25.192 kid1| ufs/UFSStoreState.cc(219) doWrite: 0xb9434a78 UFSStoreState::doWrite
2014/03/10 12:25:25.192 kid1| ufs/UFSStoreState.cc(254) doWrite: 0xb9434a78 calling theFile->write(4096)
2014/03/10 12:25:25.193 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(253) write: DiskThreadsDiskFile::write: FD 16
2014/03/10 12:25:25.194 kid1| disk.cc(233) diskHandleWrite: diskHandleWrite: FD 16
2014/03/10 12:25:25.195 kid1| disk.cc(243) diskHandleWrite: diskHandleWrite: FD 16 writing 4096 bytes at -1
2014/03/10 12:25:25.197 kid1| disk.cc(254) diskHandleWrite: diskHandleWrite: FD 16 len = 4096
2014/03/10 12:25:25.198 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(361) writeDone: DiskThreadsDiskFile::writeDone: FD 16, len 4096, err=0
2014/03/10 12:25:25.199 kid1| ufs/UFSStoreState.cc(308) writeCompleted: dirno 0, fileno 00000000, len 1000
2014/03/10 12:25:25.199 kid1| ufs/UFSStoreState.cc(219) doWrite: 0xb9434a78 UFSStoreState::doWrite
2014/03/10 12:25:25.200 kid1| ufs/UFSStoreState.cc(254) doWrite: 0xb9434a78 calling theFile->write(4096)
2014/03/10 12:25:25.202 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(253) write: DiskThreadsDiskFile::write: FD 16
2014/03/10 12:25:25.202 kid1| disk.cc(233) diskHandleWrite: diskHandleWrite: FD 16
2014/03/10 12:25:25.202 kid1| disk.cc(243) diskHandleWrite: diskHandleWrite: FD 16 writing 4096 bytes at -1
2014/03/10 12:25:25.203 kid1| disk.cc(254) diskHandleWrite: diskHandleWrite: FD 16 len = 4096
2014/03/10 12:25:25.203 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(361) writeDone: DiskThreadsDiskFile::writeDone: FD 16, len 4096, err=0
2014/03/10 12:25:25.203 kid1| ufs/UFSStoreState.cc(308) writeCompleted: dirno 0, fileno 00000000, len 1000
2014/03/10 12:25:25.203 kid1| ufs/UFSStoreState.cc(121) openDone: UFSStoreState::openDone: exiting
2014/03/10 12:25:25.203 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(205) openDone: DiskThreadsDiskFile::openDone: exiting
2014/03/10 12:25:25.204 kid1| comm.cc(145) commHandleRead: comm_read_try: FD 12, size 16383, retval 16383, errno 0
2014/03/10 12:25:25.204 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 (0, 0)
2014/03/10 12:25:25.205 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 (0, 0)
2014/03/10 12:25:25.206 kid1| store_swapout.cc(153) doPages: storeSwapOut: swap_buf_len = 4096
2014/03/10 12:25:25.208 kid1| store_swapout.cc(157) doPages: storeSwapOut: swapping out 4096 bytes from 12288
2014/03/10 12:25:25.208 kid1| ufs/UFSStoreState.cc(197) write: UFSStoreState::write: dirn 0, fileno 00000000
2014/03/10 12:25:25.208 kid1| ufs/UFSStoreState.cc(504) queueWrite: 0xb9434a78 UFSStoreState::queueWrite: queueing write of size 4096
2014/03/10 12:25:25.209 kid1| ufs/UFSStoreState.cc(219) doWrite: 0xb9434a78 UFSStoreState::doWrite
2014/03/10 12:25:25.209 kid1| ufs/UFSStoreState.cc(254) doWrite: 0xb9434a78 calling theFile->write(4096)
2014/03/10 12:25:25.209 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(253) write: DiskThreadsDiskFile::write: FD 16
2014/03/10 12:25:25.209 kid1| disk.cc(233) diskHandleWrite: diskHandleWrite: FD 16
2014/03/10 12:25:25.209 kid1| disk.cc(243) diskHandleWrite: diskHandleWrite: FD 16 writing 4096 bytes at -1
2014/03/10 12:25:25.209 kid1| disk.cc(254) diskHandleWrite: diskHandleWrite: FD 16 len = 4096
2014/03/10 12:25:25.209 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(361) writeDone: DiskThreadsDiskFile::writeDone: FD 16, len 4096, err=0
2014/03/10 12:25:25.210 kid1| ufs/UFSStoreState.cc(308) writeCompleted: dirno 0, fileno 00000000, len 1000
2014/03/10 12:25:25.210 kid1| store_swapout.cc(153) doPages: storeSwapOut: swap_buf_len = 4096
2014/03/10 12:25:25.210 kid1| store_swapout.cc(157) doPages: storeSwapOut: swapping out 4096 bytes from 16384
2014/03/10 12:25:25.210 kid1| ufs/UFSStoreState.cc(197) write: UFSStoreState::write: dirn 0, fileno 00000000
2014/03/10 12:25:25.210 kid1| ufs/UFSStoreState.cc(504) queueWrite: 0xb9434a78 UFSStoreState::queueWrite: queueing write of size 4096
2014/03/10 12:25:25.210 kid1| ufs/UFSStoreState.cc(219) doWrite: 0xb9434a78 UFSStoreState::doWrite
2014/03/10 12:25:25.212 kid1| ufs/UFSStoreState.cc(254) doWrite: 0xb9434a78 calling theFile->write(4096)
2014/03/10 12:25:25.213 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(253) write: DiskThreadsDiskFile::write: FD 16
2014/03/10 12:25:25.213 kid1| disk.cc(233) diskHandleWrite: diskHandleWrite: FD 16
2014/03/10 12:25:25.217 kid1| disk.cc(243) diskHandleWrite: diskHandleWrite: FD 16 writing 4096 bytes at -1
2014/03/10 12:25:25.218 kid1| disk.cc(254) diskHandleWrite: diskHandleWrite: FD 16 len = 4096
2014/03/10 12:25:25.219 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(361) writeDone: DiskThreadsDiskFile::writeDone: FD 16, len 4096, err=0
2014/03/10 12:25:25.220 kid1| ufs/UFSStoreState.cc(308) writeCompleted: dirno 0, fileno 00000000, len 1000
2014/03/10 12:25:25.222 kid1| store_swapout.cc(153) doPages: storeSwapOut: swap_buf_len = 4096
2014/03/10 12:25:25.223 kid1| store_swapout.cc(157) doPages: storeSwapOut: swapping out 4096 bytes from 20480
2014/03/10 12:25:25.223 kid1| ufs/UFSStoreState.cc(197) write: UFSStoreState::write: dirn 0, fileno 00000000
2014/03/10 12:25:25.223 kid1| ufs/UFSStoreState.cc(504) queueWrite: 0xb9434a78 UFSStoreState::queueWrite: queueing write of size 4096
2014/03/10 12:25:25.224 kid1| ufs/UFSStoreState.cc(219) doWrite: 0xb9434a78 UFSStoreState::doWrite
2014/03/10 12:25:25.226 kid1| ufs/UFSStoreState.cc(254) doWrite: 0xb9434a78 calling theFile->write(4096)
2014/03/10 12:25:25.227 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(253) write: DiskThreadsDiskFile::write: FD 16
2014/03/10 12:25:25.228 kid1| disk.cc(233) diskHandleWrite: diskHandleWrite: FD 16
2014/03/10 12:25:25.229 kid1| disk.cc(243) diskHandleWrite: diskHandleWrite: FD 16 writing 4096 bytes at -1
2014/03/10 12:25:25.230 kid1| disk.cc(254) diskHandleWrite: diskHandleWrite: FD 16 len = 4096
2014/03/10 12:25:25.232 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(361) writeDone: DiskThreadsDiskFile::writeDone: FD 16, len 4096, err=0
2014/03/10 12:25:25.232 kid1| ufs/UFSStoreState.cc(308) writeCompleted: dirno 0, fileno 00000000, len 1000
2014/03/10 12:25:25.233 kid1| store_swapout.cc(153) doPages: storeSwapOut: swap_buf_len = 4096
2014/03/10 12:25:25.234 kid1| store_swapout.cc(157) doPages: storeSwapOut: swapping out 4096 bytes from 24576
2014/03/10 12:25:25.236 kid1| ufs/UFSStoreState.cc(197) write: UFSStoreState::write: dirn 0, fileno 00000000
2014/03/10 12:25:25.237 kid1| ufs/UFSStoreState.cc(504) queueWrite: 0xb9434a78 UFSStoreState::queueWrite: queueing write of size 4096
2014/03/10 12:25:25.237 kid1| ufs/UFSStoreState.cc(219) doWrite: 0xb9434a78 UFSStoreState::doWrite
2014/03/10 12:25:25.237 kid1| ufs/UFSStoreState.cc(254) doWrite: 0xb9434a78 calling theFile->write(4096)
2014/03/10 12:25:25.238 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(253) write: DiskThreadsDiskFile::write: FD 16
2014/03/10 12:25:25.238 kid1| disk.cc(233) diskHandleWrite: diskHandleWrite: FD 16
2014/03/10 12:25:25.238 kid1| disk.cc(243) diskHandleWrite: diskHandleWrite: FD 16 writing 4096 bytes at -1
2014/03/10 12:25:25.239 kid1| disk.cc(254) diskHandleWrite: diskHandleWrite: FD 16 len = 4096
2014/03/10 12:25:25.239 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(361) writeDone: DiskThreadsDiskFile::writeDone: FD 16, len 4096, err=0
2014/03/10 12:25:25.240 kid1| ufs/UFSStoreState.cc(308) writeCompleted: dirno 0, fileno 00000000, len 1000
2014/03/10 12:25:25.240 kid1| store_client.cc(776) invokeHandlers: InvokeHandlers: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.241 kid1| store_client.cc(782) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0
2014/03/10 12:25:25.241 kid1| http.cc(1076) persistentConnStatus: local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 eof=0
2014/03/10 12:25:25.242 kid1| comm.cc(773) commSetConnTimeout: local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 timeout 900
2014/03/10 12:25:25.244 kid1| comm.cc(1967) delayRead: Adding deferred read on local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.244 kid1| HttpReply.cc(562) receivedBodyTooLarge: 0 >? -1
2014/03/10 12:25:25.246 kid1| clientStream.cc(207) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0xb941e008 from node 0xb941e0e0
2014/03/10 12:25:25.247 kid1| store_client.cc(237) copy: store_client::copy: 53804C3A926E06BC3760A15E5F9E6E0D, from 4619, for length 4096, cb 1, cbdata 0xb941cfa0
2014/03/10 12:25:25.248 kid1| comm.cc(2066) kickARead: Kicking deferred read on local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.248 kid1| comm.cc(1967) delayRead: Adding deferred read on local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.249 kid1| store_client.cc(332) storeClientCopy2: storeClientCopy2: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.250 kid1| store_client.cc(465) scheduleMemRead: store_client::doCopy: Copying normal from memory
2014/03/10 12:25:25.251 kid1| clientStream.cc(185) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0xb941ce3c from node 0xb941bda8
2014/03/10 12:25:25.252 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=5
2014/03/10 12:25:25.253 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 (0, 0)
2014/03/10 12:25:25.254 kid1| HttpReply.cc(562) receivedBodyTooLarge: 4096 >? -1
2014/03/10 12:25:25.255 kid1| clientStream.cc(207) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0xb941e008 from node 0xb941e0e0
2014/03/10 12:25:25.255 kid1| store_client.cc(237) copy: store_client::copy: 53804C3A926E06BC3760A15E5F9E6E0D, from 8715, for length 4096, cb 1, cbdata 0xb941cfa0
2014/03/10 12:25:25.256 kid1| comm.cc(2066) kickARead: Kicking deferred read on local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.257 kid1| comm.cc(1967) delayRead: Adding deferred read on local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.258 kid1| store_client.cc(332) storeClientCopy2: storeClientCopy2: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.258 kid1| store_client.cc(465) scheduleMemRead: store_client::doCopy: Copying normal from memory
2014/03/10 12:25:25.259 kid1| clientStream.cc(185) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0xb941ce3c from node 0xb941bda8
2014/03/10 12:25:25.260 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=5
2014/03/10 12:25:25.261 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 (0, 0)
2014/03/10 12:25:25.262 kid1| HttpReply.cc(562) receivedBodyTooLarge: 8192 >? -1
2014/03/10 12:25:25.263 kid1| clientStream.cc(207) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0xb941e008 from node 0xb941e0e0
2014/03/10 12:25:25.263 kid1| store_client.cc(237) copy: store_client::copy: 53804C3A926E06BC3760A15E5F9E6E0D, from 12811, for length 4096, cb 1, cbdata 0xb941cfa0
2014/03/10 12:25:25.264 kid1| comm.cc(2066) kickARead: Kicking deferred read on local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.265 kid1| comm.cc(1967) delayRead: Adding deferred read on local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.265 kid1| store_client.cc(332) storeClientCopy2: storeClientCopy2: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.265 kid1| store_client.cc(465) scheduleMemRead: store_client::doCopy: Copying normal from memory
2014/03/10 12:25:25.266 kid1| clientStream.cc(185) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0xb941ce3c from node 0xb941bda8
2014/03/10 12:25:25.266 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=5
2014/03/10 12:25:25.267 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 (0, 0)
2014/03/10 12:25:25.267 kid1| HttpReply.cc(562) receivedBodyTooLarge: 12288 >? -1
2014/03/10 12:25:25.268 kid1| clientStream.cc(207) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0xb941e008 from node 0xb941e0e0
2014/03/10 12:25:25.268 kid1| store_client.cc(237) copy: store_client::copy: 53804C3A926E06BC3760A15E5F9E6E0D, from 16907, for length 4096, cb 1, cbdata 0xb941cfa0
2014/03/10 12:25:25.268 kid1| comm.cc(2066) kickARead: Kicking deferred read on local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.269 kid1| store_client.cc(332) storeClientCopy2: storeClientCopy2: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.269 kid1| store_client.cc(465) scheduleMemRead: store_client::doCopy: Copying normal from memory
2014/03/10 12:25:25.270 kid1| clientStream.cc(185) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0xb941ce3c from node 0xb941bda8
2014/03/10 12:25:25.270 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=5
2014/03/10 12:25:25.271 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 (0, 0)
2014/03/10 12:25:25.272 kid1| comm.cc(145) commHandleRead: comm_read_try: FD 12, size 16383, retval 16383, errno 0
2014/03/10 12:25:25.272 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 (0, 0)
2014/03/10 12:25:25.273 kid1| HttpReply.cc(562) receivedBodyTooLarge: 16384 >? -1
2014/03/10 12:25:25.274 kid1| clientStream.cc(207) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0xb941e008 from node 0xb941e0e0
2014/03/10 12:25:25.274 kid1| store_client.cc(237) copy: store_client::copy: 53804C3A926E06BC3760A15E5F9E6E0D, from 21003, for length 4096, cb 1, cbdata 0xb941cfa0
2014/03/10 12:25:25.275 kid1| store_client.cc(332) storeClientCopy2: storeClientCopy2: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.276 kid1| store_client.cc(465) scheduleMemRead: store_client::doCopy: Copying normal from memory
2014/03/10 12:25:25.276 kid1| clientStream.cc(185) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0xb941ce3c from node 0xb941bda8
2014/03/10 12:25:25.277 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=5
2014/03/10 12:25:25.277 kid1| store_swapout.cc(153) doPages: storeSwapOut: swap_buf_len = 4096
2014/03/10 12:25:25.278 kid1| store_swapout.cc(157) doPages: storeSwapOut: swapping out 4096 bytes from 28672
2014/03/10 12:25:25.278 kid1| ufs/UFSStoreState.cc(197) write: UFSStoreState::write: dirn 0, fileno 00000000
2014/03/10 12:25:25.279 kid1| ufs/UFSStoreState.cc(504) queueWrite: 0xb9434a78 UFSStoreState::queueWrite: queueing write of size 4096
2014/03/10 12:25:25.280 kid1| ufs/UFSStoreState.cc(219) doWrite: 0xb9434a78 UFSStoreState::doWrite
2014/03/10 12:25:25.280 kid1| ufs/UFSStoreState.cc(254) doWrite: 0xb9434a78 calling theFile->write(4096)
2014/03/10 12:25:25.281 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(253) write: DiskThreadsDiskFile::write: FD 16
2014/03/10 12:25:25.281 kid1| disk.cc(233) diskHandleWrite: diskHandleWrite: FD 16
2014/03/10 12:25:25.282 kid1| disk.cc(243) diskHandleWrite: diskHandleWrite: FD 16 writing 4096 bytes at -1
2014/03/10 12:25:25.283 kid1| disk.cc(254) diskHandleWrite: diskHandleWrite: FD 16 len = 4096
2014/03/10 12:25:25.283 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(361) writeDone: DiskThreadsDiskFile::writeDone: FD 16, len 4096, err=0
2014/03/10 12:25:25.285 kid1| ufs/UFSStoreState.cc(308) writeCompleted: dirno 0, fileno 00000000, len 1000
2014/03/10 12:25:25.286 kid1| store_swapout.cc(153) doPages: storeSwapOut: swap_buf_len = 4096
2014/03/10 12:25:25.286 kid1| store_swapout.cc(157) doPages: storeSwapOut: swapping out 4096 bytes from 32768
2014/03/10 12:25:25.288 kid1| ufs/UFSStoreState.cc(197) write: UFSStoreState::write: dirn 0, fileno 00000000
2014/03/10 12:25:25.289 kid1| ufs/UFSStoreState.cc(504) queueWrite: 0xb9434a78 UFSStoreState::queueWrite: queueing write of size 4096
2014/03/10 12:25:25.289 kid1| ufs/UFSStoreState.cc(219) doWrite: 0xb9434a78 UFSStoreState::doWrite
2014/03/10 12:25:25.290 kid1| ufs/UFSStoreState.cc(254) doWrite: 0xb9434a78 calling theFile->write(4096)
2014/03/10 12:25:25.291 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(253) write: DiskThreadsDiskFile::write: FD 16
2014/03/10 12:25:25.292 kid1| disk.cc(233) diskHandleWrite: diskHandleWrite: FD 16
2014/03/10 12:25:25.293 kid1| disk.cc(243) diskHandleWrite: diskHandleWrite: FD 16 writing 4096 bytes at -1
2014/03/10 12:25:25.294 kid1| disk.cc(254) diskHandleWrite: diskHandleWrite: FD 16 len = 4096
2014/03/10 12:25:25.295 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(361) writeDone: DiskThreadsDiskFile::writeDone: FD 16, len 4096, err=0
2014/03/10 12:25:25.296 kid1| ufs/UFSStoreState.cc(308) writeCompleted: dirno 0, fileno 00000000, len 1000
2014/03/10 12:25:25.297 kid1| store_swapout.cc(153) doPages: storeSwapOut: swap_buf_len = 4096
2014/03/10 12:25:25.297 kid1| store_swapout.cc(157) doPages: storeSwapOut: swapping out 4096 bytes from 36864
2014/03/10 12:25:25.298 kid1| ufs/UFSStoreState.cc(197) write: UFSStoreState::write: dirn 0, fileno 00000000
2014/03/10 12:25:25.299 kid1| ufs/UFSStoreState.cc(504) queueWrite: 0xb9434a78 UFSStoreState::queueWrite: queueing write of size 4096
2014/03/10 12:25:25.299 kid1| ufs/UFSStoreState.cc(219) doWrite: 0xb9434a78 UFSStoreState::doWrite
2014/03/10 12:25:25.300 kid1| ufs/UFSStoreState.cc(254) doWrite: 0xb9434a78 calling theFile->write(4096)
2014/03/10 12:25:25.301 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(253) write: DiskThreadsDiskFile::write: FD 16
2014/03/10 12:25:25.301 kid1| disk.cc(233) diskHandleWrite: diskHandleWrite: FD 16
2014/03/10 12:25:25.301 kid1| disk.cc(243) diskHandleWrite: diskHandleWrite: FD 16 writing 4096 bytes at -1
2014/03/10 12:25:25.302 kid1| disk.cc(254) diskHandleWrite: diskHandleWrite: FD 16 len = 4096
2014/03/10 12:25:25.302 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(361) writeDone: DiskThreadsDiskFile::writeDone: FD 16, len 4096, err=0
2014/03/10 12:25:25.303 kid1| ufs/UFSStoreState.cc(308) writeCompleted: dirno 0, fileno 00000000, len 1000
2014/03/10 12:25:25.303 kid1| store_swapout.cc(153) doPages: storeSwapOut: swap_buf_len = 4096
2014/03/10 12:25:25.303 kid1| store_swapout.cc(157) doPages: storeSwapOut: swapping out 4096 bytes from 40960
2014/03/10 12:25:25.304 kid1| ufs/UFSStoreState.cc(197) write: UFSStoreState::write: dirn 0, fileno 00000000
2014/03/10 12:25:25.304 kid1| ufs/UFSStoreState.cc(504) queueWrite: 0xb9434a78 UFSStoreState::queueWrite: queueing write of size 4096
2014/03/10 12:25:25.304 kid1| ufs/UFSStoreState.cc(219) doWrite: 0xb9434a78 UFSStoreState::doWrite
2014/03/10 12:25:25.305 kid1| ufs/UFSStoreState.cc(254) doWrite: 0xb9434a78 calling theFile->write(4096)
2014/03/10 12:25:25.305 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(253) write: DiskThreadsDiskFile::write: FD 16
2014/03/10 12:25:25.306 kid1| disk.cc(233) diskHandleWrite: diskHandleWrite: FD 16
2014/03/10 12:25:25.306 kid1| disk.cc(243) diskHandleWrite: diskHandleWrite: FD 16 writing 4096 bytes at -1
2014/03/10 12:25:25.307 kid1| disk.cc(254) diskHandleWrite: diskHandleWrite: FD 16 len = 4096
2014/03/10 12:25:25.307 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(361) writeDone: DiskThreadsDiskFile::writeDone: FD 16, len 4096, err=0
2014/03/10 12:25:25.307 kid1| ufs/UFSStoreState.cc(308) writeCompleted: dirno 0, fileno 00000000, len 1000
2014/03/10 12:25:25.308 kid1| store_client.cc(776) invokeHandlers: InvokeHandlers: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.308 kid1| store_client.cc(782) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0
2014/03/10 12:25:25.309 kid1| http.cc(1076) persistentConnStatus: local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 eof=0
2014/03/10 12:25:25.309 kid1| comm.cc(773) commSetConnTimeout: local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 timeout 900
2014/03/10 12:25:25.310 kid1| comm.cc(1967) delayRead: Adding deferred read on local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.311 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 (0, 0)
2014/03/10 12:25:25.312 kid1| HttpReply.cc(562) receivedBodyTooLarge: 20480 >? -1
2014/03/10 12:25:25.312 kid1| clientStream.cc(207) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0xb941e008 from node 0xb941e0e0
2014/03/10 12:25:25.313 kid1| store_client.cc(237) copy: store_client::copy: 53804C3A926E06BC3760A15E5F9E6E0D, from 25099, for length 4096, cb 1, cbdata 0xb941cfa0
2014/03/10 12:25:25.313 kid1| comm.cc(2066) kickARead: Kicking deferred read on local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.313 kid1| comm.cc(1967) delayRead: Adding deferred read on local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.313 kid1| store_client.cc(332) storeClientCopy2: storeClientCopy2: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.314 kid1| store_client.cc(465) scheduleMemRead: store_client::doCopy: Copying normal from memory
2014/03/10 12:25:25.314 kid1| clientStream.cc(185) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0xb941ce3c from node 0xb941bda8
2014/03/10 12:25:25.314 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=5
2014/03/10 12:25:25.315 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 (0, 0)
2014/03/10 12:25:25.315 kid1| HttpReply.cc(562) receivedBodyTooLarge: 24576 >? -1
2014/03/10 12:25:25.316 kid1| clientStream.cc(207) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0xb941e008 from node 0xb941e0e0
2014/03/10 12:25:25.316 kid1| store_client.cc(237) copy: store_client::copy: 53804C3A926E06BC3760A15E5F9E6E0D, from 29195, for length 4096, cb 1, cbdata 0xb941cfa0
2014/03/10 12:25:25.317 kid1| comm.cc(2066) kickARead: Kicking deferred read on local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.317 kid1| comm.cc(1967) delayRead: Adding deferred read on local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.317 kid1| store_client.cc(332) storeClientCopy2: storeClientCopy2: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.318 kid1| store_client.cc(465) scheduleMemRead: store_client::doCopy: Copying normal from memory
2014/03/10 12:25:25.318 kid1| clientStream.cc(185) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0xb941ce3c from node 0xb941bda8
2014/03/10 12:25:25.319 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=5
2014/03/10 12:25:25.319 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 (0, 0)
2014/03/10 12:25:25.319 kid1| HttpReply.cc(562) receivedBodyTooLarge: 28672 >? -1
2014/03/10 12:25:25.320 kid1| clientStream.cc(207) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0xb941e008 from node 0xb941e0e0
2014/03/10 12:25:25.320 kid1| store_client.cc(237) copy: store_client::copy: 53804C3A926E06BC3760A15E5F9E6E0D, from 33291, for length 4096, cb 1, cbdata 0xb941cfa0
2014/03/10 12:25:25.320 kid1| comm.cc(2066) kickARead: Kicking deferred read on local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.321 kid1| store_client.cc(332) storeClientCopy2: storeClientCopy2: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.321 kid1| store_client.cc(465) scheduleMemRead: store_client::doCopy: Copying normal from memory
2014/03/10 12:25:25.321 kid1| clientStream.cc(185) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0xb941ce3c from node 0xb941bda8
2014/03/10 12:25:25.322 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=5
2014/03/10 12:25:25.323 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 (0, 0)
2014/03/10 12:25:25.323 kid1| comm.cc(145) commHandleRead: comm_read_try: FD 12, size 16383, retval 2897, errno 0
2014/03/10 12:25:25.324 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 (0, 0)
2014/03/10 12:25:25.324 kid1| HttpReply.cc(562) receivedBodyTooLarge: 32768 >? -1
2014/03/10 12:25:25.325 kid1| clientStream.cc(207) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0xb941e008 from node 0xb941e0e0
2014/03/10 12:25:25.325 kid1| store_client.cc(237) copy: store_client::copy: 53804C3A926E06BC3760A15E5F9E6E0D, from 37387, for length 4096, cb 1, cbdata 0xb941cfa0
2014/03/10 12:25:25.325 kid1| store_client.cc(332) storeClientCopy2: storeClientCopy2: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.325 kid1| store_client.cc(465) scheduleMemRead: store_client::doCopy: Copying normal from memory
2014/03/10 12:25:25.326 kid1| clientStream.cc(185) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0xb941ce3c from node 0xb941bda8
2014/03/10 12:25:25.326 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=5
2014/03/10 12:25:25.326 kid1| store_swapout.cc(153) doPages: storeSwapOut: swap_buf_len = 4096
2014/03/10 12:25:25.327 kid1| store_swapout.cc(157) doPages: storeSwapOut: swapping out 4096 bytes from 45056
2014/03/10 12:25:25.327 kid1| ufs/UFSStoreState.cc(197) write: UFSStoreState::write: dirn 0, fileno 00000000
2014/03/10 12:25:25.328 kid1| ufs/UFSStoreState.cc(504) queueWrite: 0xb9434a78 UFSStoreState::queueWrite: queueing write of size 4096
2014/03/10 12:25:25.328 kid1| ufs/UFSStoreState.cc(219) doWrite: 0xb9434a78 UFSStoreState::doWrite
2014/03/10 12:25:25.329 kid1| ufs/UFSStoreState.cc(254) doWrite: 0xb9434a78 calling theFile->write(4096)
2014/03/10 12:25:25.329 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(253) write: DiskThreadsDiskFile::write: FD 16
2014/03/10 12:25:25.329 kid1| disk.cc(233) diskHandleWrite: diskHandleWrite: FD 16
2014/03/10 12:25:25.329 kid1| disk.cc(243) diskHandleWrite: diskHandleWrite: FD 16 writing 4096 bytes at -1
2014/03/10 12:25:25.330 kid1| disk.cc(254) diskHandleWrite: diskHandleWrite: FD 16 len = 4096
2014/03/10 12:25:25.331 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(361) writeDone: DiskThreadsDiskFile::writeDone: FD 16, len 4096, err=0
2014/03/10 12:25:25.331 kid1| ufs/UFSStoreState.cc(308) writeCompleted: dirno 0, fileno 00000000, len 1000
2014/03/10 12:25:25.331 kid1| store_client.cc(776) invokeHandlers: InvokeHandlers: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.332 kid1| store_client.cc(782) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0
2014/03/10 12:25:25.332 kid1| http.cc(1076) persistentConnStatus: local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 eof=0
2014/03/10 12:25:25.332 kid1| comm.cc(799) commUnsetConnTimeout: Remove timeout for local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1
2014/03/10 12:25:25.332 kid1| comm.cc(773) commSetConnTimeout: local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 timeout -1
2014/03/10 12:25:25.333 kid1| forward.cc(426) unregister: http://www.moovie.cc/images/movies/17031/poster.jpg
2014/03/10 12:25:25.333 kid1| pconn.cc(414) push: new IdleConnList for {141.101.118.23:80/www.moovie.cc}
2014/03/10 12:25:25.333 kid1| comm.cc(773) commSetConnTimeout: local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 timeout 60
2014/03/10 12:25:25.333 kid1| pconn.cc(426) push: pushed local=192.168.50.200:52462 remote=141.101.118.23:80 FD 12 flags=1 for 141.101.118.23:80/www.moovie.cc
2014/03/10 12:25:25.334 kid1| forward.cc(451) complete: http://www.moovie.cc/images/movies/17031/poster.jpg
        status 200
2014/03/10 12:25:25.334 kid1| forward.cc(1214) reforward: http://www.moovie.cc/images/movies/17031/poster.jpg?
2014/03/10 12:25:25.334 kid1| forward.cc(1217) reforward: No, ENTRY_FWD_HDR_WAIT isn't set
2014/03/10 12:25:25.334 kid1| forward.cc(475) complete: server (FD closed) not re-forwarding status 200
2014/03/10 12:25:25.335 kid1| store.cc(1068) complete: storeComplete: '53804C3A926E06BC3760A15E5F9E6E0D'
2014/03/10 12:25:25.335 kid1| store.cc(1369) validLength: storeEntryValidLength: Checking '53804C3A926E06BC3760A15E5F9E6E0D'
2014/03/10 12:25:25.335 kid1| store_swapout.cc(153) doPages: storeSwapOut: swap_buf_len = 911
2014/03/10 12:25:25.335 kid1| store_swapout.cc(157) doPages: storeSwapOut: swapping out 911 bytes from 49152
2014/03/10 12:25:25.335 kid1| ufs/UFSStoreState.cc(197) write: UFSStoreState::write: dirn 0, fileno 00000000
2014/03/10 12:25:25.336 kid1| ufs/UFSStoreState.cc(504) queueWrite: 0xb9434a78 UFSStoreState::queueWrite: queueing write of size 911
2014/03/10 12:25:25.336 kid1| ufs/UFSStoreState.cc(219) doWrite: 0xb9434a78 UFSStoreState::doWrite
2014/03/10 12:25:25.336 kid1| ufs/UFSStoreState.cc(254) doWrite: 0xb9434a78 calling theFile->write(911)
2014/03/10 12:25:25.336 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(253) write: DiskThreadsDiskFile::write: FD 16
2014/03/10 12:25:25.337 kid1| disk.cc(233) diskHandleWrite: diskHandleWrite: FD 16
2014/03/10 12:25:25.337 kid1| disk.cc(243) diskHandleWrite: diskHandleWrite: FD 16 writing 911 bytes at -1
2014/03/10 12:25:25.337 kid1| disk.cc(254) diskHandleWrite: diskHandleWrite: FD 16 len = 911
2014/03/10 12:25:25.337 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(361) writeDone: DiskThreadsDiskFile::writeDone: FD 16, len 911, err=0
2014/03/10 12:25:25.338 kid1| ufs/UFSStoreState.cc(308) writeCompleted: dirno 0, fileno 00000000, len 38F
2014/03/10 12:25:25.338 kid1| store_swapout.cc(292) swapOutFileClose: storeSwapOutFileClose: 53804C3A926E06BC3760A15E5F9E6E0D how=0
2014/03/10 12:25:25.338 kid1| store_swapout.cc(293) swapOutFileClose: storeSwapOutFileClose: sio = 0xb9434a78
2014/03/10 12:25:25.339 kid1| store_io.cc(68) storeClose: storeClose: calling sio->close(0)
2014/03/10 12:25:25.339 kid1| ufs/UFSStoreState.cc(156) close: UFSStoreState::close: dirno 0, fileno 00000000
2014/03/10 12:25:25.339 kid1| ufs/UFSStoreState.cc(487) tryClosing: 0xb9434a78 tryClosing() closing = 0 flags.try_closing = 0 ioInProgress = 0
2014/03/10 12:25:25.339 kid1| DiskIO/DiskThreads/DiskThreadsDiskFile.cc(230) close: DiskThreadsDiskFile::close: 0xb9434a10 closing for 0xb9434aac
2014/03/10 12:25:25.340 kid1| fd.cc(116) fd_close: fd_close FD 16 /var/spool/squid/00/00/00000000
2014/03/10 12:25:25.340 kid1| ufs/UFSStoreState.cc(131) closeCompleted: UFSStoreState::closeCompleted: dirno 0, fileno 00000000 status 0
2014/03/10 12:25:25.341 kid1| ufs/UFSStoreState.cc(332) doCloseCallback: storeUfsIOCallback: errflag=0
2014/03/10 12:25:25.341 kid1| ufs/UFSStoreState.cc(387) freePending: UFSStoreState::freePending: freed pending reads
2014/03/10 12:25:25.341 kid1| ufs/UFSStoreState.cc(397) freePending: UFSStoreState::freePending: freed pending writes
2014/03/10 12:25:25.342 kid1| store_swapout.cc(335) storeSwapOutFileClosed: storeSwapOutFileClosed: SwapOut complete: 'http://www.moovie.cc/images/movies/17031/poster.jpg' to 0, 00000000
2014/03/10 12:25:25.342 kid1| store_dir.cc(334) storeDirSwapLog: storeDirSwapLog: SWAP_LOG_ADD 53804C3A926E06BC3760A15E5F9E6E0D 0 00000000
2014/03/10 12:25:25.342 kid1| disk.cc(233) diskHandleWrite: diskHandleWrite: FD 10
2014/03/10 12:25:25.343 kid1| disk.cc(243) diskHandleWrite: diskHandleWrite: FD 10 writing 68 bytes at -1
2014/03/10 12:25:25.343 kid1| disk.cc(254) diskHandleWrite: diskHandleWrite: FD 10 len = 68
2014/03/10 12:25:25.344 kid1| store_swapout.cc(355) storeSwapOutFileClosed: storeSwapOutFileClosed: store_swapout.cc:355
2014/03/10 12:25:25.344 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=4
2014/03/10 12:25:25.345 kid1| StoreIOState.cc(62) ~StoreIOState: StoreIOState::~StoreIOState: 0xb9434a78
2014/03/10 12:25:25.345 kid1| store_client.cc(776) invokeHandlers: InvokeHandlers: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.345 kid1| store_client.cc(782) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0
2014/03/10 12:25:25.345 kid1| store_client.cc(801) storePendingNClients: storePendingNClients: returning 1
2014/03/10 12:25:25.346 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=3
2014/03/10 12:25:25.346 kid1| forward.cc(248) ~FwdState: FwdState destructor starting
2014/03/10 12:25:25.346 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=2
2014/03/10 12:25:25.346 kid1| AsyncCall.cc(48) cancel: will not call fwdConnectDoneWrapper [call429] because FwdState destructed
2014/03/10 12:25:25.347 kid1| forward.cc(278) ~FwdState: FwdState destructor done
2014/03/10 12:25:25.347 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 (0, 0)
2014/03/10 12:25:25.347 kid1| HttpReply.cc(562) receivedBodyTooLarge: 36864 >? -1
2014/03/10 12:25:25.348 kid1| clientStream.cc(207) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0xb941e008 from node 0xb941e0e0
2014/03/10 12:25:25.348 kid1| store_client.cc(237) copy: store_client::copy: 53804C3A926E06BC3760A15E5F9E6E0D, from 41483, for length 4096, cb 1, cbdata 0xb941cfa0
2014/03/10 12:25:25.348 kid1| store_client.cc(332) storeClientCopy2: storeClientCopy2: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.349 kid1| store_client.cc(465) scheduleMemRead: store_client::doCopy: Copying normal from memory
2014/03/10 12:25:25.349 kid1| clientStream.cc(185) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0xb941ce3c from node 0xb941bda8
2014/03/10 12:25:25.350 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=2
2014/03/10 12:25:25.351 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 (0, 0)
2014/03/10 12:25:25.351 kid1| HttpReply.cc(562) receivedBodyTooLarge: 40960 >? -1
2014/03/10 12:25:25.351 kid1| clientStream.cc(207) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0xb941e008 from node 0xb941e0e0
2014/03/10 12:25:25.351 kid1| store_client.cc(237) copy: store_client::copy: 53804C3A926E06BC3760A15E5F9E6E0D, from 45579, for length 4096, cb 1, cbdata 0xb941cfa0
2014/03/10 12:25:25.352 kid1| store_client.cc(332) storeClientCopy2: storeClientCopy2: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.352 kid1| store_client.cc(465) scheduleMemRead: store_client::doCopy: Copying normal from memory
2014/03/10 12:25:25.352 kid1| clientStream.cc(185) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0xb941ce3c from node 0xb941bda8
2014/03/10 12:25:25.353 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=2
2014/03/10 12:25:25.354 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 (0, 0)
2014/03/10 12:25:25.354 kid1| HttpReply.cc(562) receivedBodyTooLarge: 45056 >? -1
2014/03/10 12:25:25.354 kid1| clientStream.cc(207) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0xb941e008 from node 0xb941e0e0
2014/03/10 12:25:25.355 kid1| store_client.cc(237) copy: store_client::copy: 53804C3A926E06BC3760A15E5F9E6E0D, from 49675, for length 4096, cb 1, cbdata 0xb941cfa0
2014/03/10 12:25:25.355 kid1| store_client.cc(332) storeClientCopy2: storeClientCopy2: 53804C3A926E06BC3760A15E5F9E6E0D
2014/03/10 12:25:25.355 kid1| store_client.cc(465) scheduleMemRead: store_client::doCopy: Copying normal from memory
2014/03/10 12:25:25.356 kid1| clientStream.cc(185) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0xb941ce3c from node 0xb941bda8
2014/03/10 12:25:25.356 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=2
2014/03/10 12:25:25.357 kid1| IoCallback.cc(108) finish: called for local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 (0, 0)
2014/03/10 12:25:25.357 kid1| client_side_reply.cc(1082) storeOKTransferDone: storeOKTransferDone  out.offset=49540 objectLen()=50063 headers_sz=523
2014/03/10 12:25:25.358 kid1| client_side.cc(1543) keepaliveNextRequest: ConnnStateData(local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1), Context(local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1)
2014/03/10 12:25:25.358 kid1| clientStream.cc(225) clientStreamDetach: clientStreamDetach: Detaching node 0xb941e0e0
2014/03/10 12:25:25.358 kid1| clientStream.cc(310) clientStreamFree: Freeing clientStreamNode 0xb941e0e0
2014/03/10 12:25:25.359 kid1| client_side_request.cc(291) ~ClientHttpRequest: httpRequestFree: http://www.moovie.cc/images/movies/17031/poster.jpg
2014/03/10 12:25:25.360 kid1| ModDaemon.cc(196) logfile_mod_daemon_append: logfile_mod_daemon_append: daemon:/var/log/squid/access.log: appending 1 bytes
2014/03/10 12:25:25.360 kid1| ModDaemon.cc(200) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 0 of 32768 bytes before append
2014/03/10 12:25:25.360 kid1| ModDaemon.cc(196) logfile_mod_daemon_append: logfile_mod_daemon_append: daemon:/var/log/squid/access.log: appending 152 bytes
2014/03/10 12:25:25.361 kid1| ModDaemon.cc(200) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 1 of 32768 bytes before append
2014/03/10 12:25:25.361 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=1
2014/03/10 12:25:25.361 kid1| clientStream.cc(270) clientStreamAbort: clientStreamAbort: Aborting stream with tail 0xb941bda8
2014/03/10 12:25:25.361 kid1| clientStream.cc(225) clientStreamDetach: clientStreamDetach: Detaching node 0xb941bda8
2014/03/10 12:25:25.361 kid1| clientStream.cc(246) clientStreamDetach: clientStreamDetach: Calling 1 with cbdata 0xb941e008
2014/03/10 12:25:25.362 kid1| clientStream.cc(310) clientStreamFree: Freeing clientStreamNode 0xb941bda8
2014/03/10 12:25:25.362 kid1| store_client.cc(704) storeUnregister: storeUnregister: called for '53804C3A926E06BC3760A15E5F9E6E0D'
2014/03/10 12:25:25.362 kid1| store_client.cc(801) storePendingNClients: storePendingNClients: returning 0
2014/03/10 12:25:25.362 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=1
2014/03/10 12:25:25.363 kid1| store.cc(570) unlock: StoreEntry::unlock: key '53804C3A926E06BC3760A15E5F9E6E0D' count=0
2014/03/10 12:25:25.363 kid1| store_client.cc(801) storePendingNClients: storePendingNClients: returning 0
2014/03/10 12:25:25.363 kid1| ufs/UFSSwapDir.cc(497) dereference: dereferencing 0xb9425460 0/0
2014/03/10 12:25:25.363 kid1| heap/store_heap_replacement.cc(91) HeapKeyGen_StoreEntry_LFUDA: HeapKeyGen_StoreEntry_LFUDA: 53804C3A926E06BC3760A15E5F9E6E0D refcnt=1 lastref=1394450725 heap_age=1.00 tie=0.00 -> 2.00
2014/03/10 12:25:25.363 kid1| heap/store_heap_replacement.cc(94) HeapKeyGen_StoreEntry_LFUDA: HeapKeyGen_StoreEntry_LFUDA: url=http://www.moovie.cc/images/movies/17031/poster.jpg
2014/03/10 12:25:25.364 kid1| heap/store_heap_replacement.cc(129) HeapKeyGen_StoreEntry_GDSF: HeapKeyGen_StoreEntry_GDSF: 53804C3A926E06BC3760A15E5F9E6E0D size=50234.00 refcnt=1 lastref=1394450725 heap_age=1.00 tie=0.00 -> 1.00
2014/03/10 12:25:25.364 kid1| heap/store_heap_replacement.cc(132) HeapKeyGen_StoreEntry_GDSF: HeapKeyGen_StoreEntry_GDSF: url=http://www.moovie.cc/images/movies/17031/poster.jpg
2014/03/10 12:25:25.364 kid1| client_side.cc(1613) keepaliveNextRequest: local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1: calling conn->readNextRequest()
2014/03/10 12:25:25.364 kid1| comm.cc(773) commSetConnTimeout: local=192.168.50.200:3128 remote=192.168.50.200:53191 FD 11 flags=1 timeout 120
2014/03/10 12:25:25.975 kid1| ufs/UFSSwapDir.cc(456) maintain: f=1.00, max_scan=500, max_remove=80
2014/03/10 12:25:25.975 kid1| ufs/UFSSwapDir.cc(480) maintain: /var/spool/squid removed 0/80 f=1.0000 max_scan=500
2014/03/10 12:25:25.976 kid1| ModDaemon.cc(196) logfile_mod_daemon_append: logfile_mod_daemon_append: daemon:/var/log/squid/access.log: appending 2 bytes
2014/03/10 12:25:25.977 kid1| ModDaemon.cc(200) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 153 of 32768 bytes before append
2014/03/10 12:25:25.978 kid1| ModDaemon.cc(131) logfileHandleWrite: logfileHandleWrite: daemon:/var/log/squid/access.log: write returned 155
2014/03/10 12:25:26.976 kid1| ufs/UFSSwapDir.cc(456) maintain: f=1.00, max_scan=500, max_remove=80
2014/03/10 12:25:26.977 kid1| ufs/UFSSwapDir.cc(480) maintain: /var/spool/squid removed 0/80 f=1.0000 max_scan=500
2014/03/10 12:25:27.979 kid1| ufs/UFSSwapDir.cc(456) maintain: f=1.00, max_scan=500, max_remove=80
2014/03/10 12:25:27.980 kid1| ufs/UFSSwapDir.cc(480) maintain: /var/spool/squid removed 0/80 f=1.0000 max_scan=500
2014/03/10 12:25:28.981 kid1| ufs/UFSSwapDir.cc(456) maintain: f=1.00, max_scan=500, max_remove=80
2014/03/10 12:25:28.981 kid1| ufs/UFSSwapDir.cc(480) maintain: /var/spool/squid removed 0/80 f=1.0000 max_scan=500
