Re: TProxy not faking source address.

[rihad <rihad@xxxxxxx>]

Amos Jeffries wrote:
> rihad wrote:
> > Looks like I'm the only one trying to use TProxy? Somebody else, please?
> > To summarize: Squid does NOT spoof client's IP address when initiating 
> > connections on its own. Just as if there weren't a thing named "TProxy".
>
> We have had a fair few trying it with complete success when its the only 
> thing used. This kind of thing seems to crop up with WCCP, for you and 
> one other.
I don't use WCCP.

> I'm not sure yet what the problem seems to be. Can you check your 
> cache.log for messages about "Stopping full transparency", the rest of 
> the message says why. I've updated the wiki troubleshooting section to 
> list the messages that appear when tproxy is turned off automatically 
> and what needs to be done to fix it.
No such errors at all. Some relevant lines:
2009/05/17 14:09:05| Accepting  spoofing HTTP connections at 
0.0.0.0:3129, FD 15.

(Note the extra space after "Accepting ")

After squid starts it finally logs this line, as it does normally:
	
	storeLateRelease: released 0 objects

and no more error lines were logged for a few hours and testing 
attempts, until I finally stop Squid:
	
	Preparing for shutdown after 5 requests

again, as normal.

> If you can't see any of those please can you set:
>   debug_options ALL,1 89,6
>
> to see whats going on?
I put that line in my config and did squid -k debug. Then I did this on 
the client:
telnet 192.168.0.1 80
GET / HTTP/1.0

(bunch of ouput)
Connection closed by remote host.

Whatever squid spat to cache.log is below. I've grepped it for the words 
"tproxy" or "transparent":

$ fgrep -i -e tproxy -e transparent /tmp/captured.log
2009/05/17 14:52:58.470| TRANSPARENT REWRITE: 'http://192.168.0.1:80/'
Via: 1.0 tproxy (squid/3.1.0.7)

(tproxy is a hostname in this case).

I don't know what else to look for.

> I know the squid->client link should be 100% spoofed.
You mean the old transparent (interception) proxying, where Squid 
pretends to be the server? Of course it works, and has worked long ago.



Here comes the 1 second worth part of the logfile when I hit enter and 
telnet sent the request down the line. Excuse me its length.
N.B.: you can see traces of another Squid 2.7.STABLE3 on my desktop 
(192.168.0.1) intercepting connections from the local network, which is 
irrelevant to the problem.

> 2009/05/17 14:52:58.207| comm_read_try: FD 11, size 4095, retval 16, errno 0
> 2009/05/17 14:52:58.207| commio_finish_callback: called for FD 11 (0, 0)
> 2009/05/17 14:52:58.207| comm.cc(163) will call ConnStateData::clientReadRequest(FD 11, data=0x9c2df40, size=16, buf=0xb7b66008) [call211]
> 2009/05/17 14:52:58.207| entering ConnStateData::clientReadRequest(FD 11, data=0x9c2df40, size=16, buf=0xb7b66008)
> 2009/05/17 14:52:58.207| AsyncCall.cc(32) make: make call ConnStateData::clientReadRequest [call211]
> 2009/05/17 14:52:58.208| ConnStateData status in: [ job5]
> 2009/05/17 14:52:58.208| client_side.cc(2533) clientReadRequest: clientReadRequest FD 11 size 16
> 2009/05/17 14:52:58.208| clientParseRequest: FD 11: attempting to parse
> 2009/05/17 14:52:58.208| httpParseInit: Request buffer is GET / HTTP/1.0
>
> 2009/05/17 14:52:58.208| httpParserParseReqLine: parsing GET / HTTP/1.0
>
> 2009/05/17 14:52:58.208| Parser: retval 1: from 0->15: method 0->2; url 4->4; version 6->14 (1/0)
> 2009/05/17 14:52:58.208| Incomplete request, waiting for end of headers
> 2009/05/17 14:52:58.208| clientReadSomeData: FD 11: reading request...
> 2009/05/17 14:52:58.208| The AsyncCall ConnStateData::clientReadRequest constructed, this=0x9ae1ef0 [call220]
> 2009/05/17 14:52:58.208| comm_read, queueing read for FD 11; asynCall 0x9ae1ef0*1
> 2009/05/17 14:52:58.208| ConnStateData status out: [ job5]
> 2009/05/17 14:52:58.208| leaving ConnStateData::clientReadRequest(FD 11, data=0x9c2df40, size=16, buf=0xb7b66008)
> 2009/05/17 14:52:58.469| comm_read_try: FD 11, size 4079, retval 2, errno 0
> 2009/05/17 14:52:58.470| commio_finish_callback: called for FD 11 (0, 0)
> 2009/05/17 14:52:58.470| comm.cc(163) will call ConnStateData::clientReadRequest(FD 11, data=0x9c2df40, size=2, buf=0xb7b66018) [call220]
> 2009/05/17 14:52:58.470| entering ConnStateData::clientReadRequest(FD 11, data=0x9c2df40, size=2, buf=0xb7b66018)
> 2009/05/17 14:52:58.470| AsyncCall.cc(32) make: make call ConnStateData::clientReadRequest [call220]
> 2009/05/17 14:52:58.470| ConnStateData status in: [ job5]
> 2009/05/17 14:52:58.470| client_side.cc(2533) clientReadRequest: clientReadRequest FD 11 size 2
> 2009/05/17 14:52:58.470| clientParseRequest: FD 11: attempting to parse
> 2009/05/17 14:52:58.470| httpParseInit: Request buffer is GET / HTTP/1.0
>
>
> 2009/05/17 14:52:58.470| httpParserParseReqLine: parsing GET / HTTP/1.0
>
>
> 2009/05/17 14:52:58.470| Parser: retval 1: from 0->15: method 0->2; url 4->4; version 6->14 (1/0)
> 2009/05/17 14:52:58.470| parseHttpRequest: req_hdr = {
> }
> 2009/05/17 14:52:58.470| parseHttpRequest: end = {
> }
> 2009/05/17 14:52:58.470| parseHttpRequest: prefix_sz = 18, req_line_sz = 16
> 2009/05/17 14:52:58.470| clientStreamInsertHead: Inserted node 0x9c3d540 with data 0xb7b04054 after head
> 2009/05/17 14:52:58.470| parseHttpRequest: Request Header is
>
>
> 2009/05/17 14:52:58.470| mime_get_header: looking for 'Host'
> 2009/05/17 14:52:58.470| TRANSPARENT REWRITE: 'http://192.168.0.1:80/'
> 2009/05/17 14:52:58.470| parseHttpRequest: Complete request received
> 2009/05/17 14:52:58.470| clientParseRequest: FD 11: parsed a request
> 2009/05/17 14:52:58.470| comm.cc(1153) commSetTimeout: FD 11 timeout 86400
> 2009/05/17 14:52:58.471| The AsyncCall SomeTimeoutHandler constructed, this=0x9ae1f48 [call221]
> 2009/05/17 14:52:58.471| comm.cc(1164) commSetTimeout: FD 11 timeout 86400
> 2009/05/17 14:52:58.471| urlParse: Split URL 'http://192.168.0.1:80/' into proto='http', host='192.168.0.1', port='80', path='/'
> 2009/05/17 14:52:58.471| init-ing hdr: 0x9c04144 owner: 2
> 2009/05/17 14:52:58.471| HttpRequest::SetHost() given IP: 192.168.0.1
> 2009/05/17 14:52:58.471| parsing hdr: (0x9c04144)
>
> 2009/05/17 14:52:58.471| clientSetKeepaliveFlag: http_ver = 1.0
> 2009/05/17 14:52:58.471| clientSetKeepaliveFlag: method = GET
> 2009/05/17 14:52:58.471| client_side_request.cc(129) ClientRequestContext: 0x9c415b0 ClientRequestContext constructed
> 2009/05/17 14:52:58.471| client_side_request.cc(1238) doCallouts: Doing calloutContext->clientAccessCheck()
> 2009/05/17 14:52:58.471| ACLChecklist::preCheck: 0x9c45670 checking 'http_access allow manager localhost'
> 2009/05/17 14:52:58.471| ACLList::matches: checking manager
> 2009/05/17 14:52:58.471| ACL::checklistMatches: checking 'manager'
> 2009/05/17 14:52:58.471| ACL::ChecklistMatches: result for 'manager' is 0
> 2009/05/17 14:52:58.471| ACLList::matches: result is false
> 2009/05/17 14:52:58.471| aclmatchAclList: 0x9c45670 returning false (AND list entry failed to match)
> 2009/05/17 14:52:58.471| aclmatchAclList: async=0 nodeMatched=0 async_in_progress=0 lastACLResult() = 0 finished() = 0
> 2009/05/17 14:52:58.471| ACLChecklist::preCheck: 0x9c45670 checking 'http_access deny manager'
> 2009/05/17 14:52:58.471| ACLList::matches: checking manager
> 2009/05/17 14:52:58.471| ACL::checklistMatches: checking 'manager'
> 2009/05/17 14:52:58.471| ACL::ChecklistMatches: result for 'manager' is 0
> 2009/05/17 14:52:58.472| ACLList::matches: result is false
> 2009/05/17 14:52:58.472| aclmatchAclList: 0x9c45670 returning false (AND list entry failed to match)
> 2009/05/17 14:52:58.472| aclmatchAclList: async=0 nodeMatched=0 async_in_progress=0 lastACLResult() = 0 finished() = 0
> 2009/05/17 14:52:58.472| ACLChecklist::preCheck: 0x9c45670 checking 'http_access deny !Safe_ports'
> 2009/05/17 14:52:58.472| ACLList::matches: checking !Safe_ports
> 2009/05/17 14:52:58.472| ACL::checklistMatches: checking 'Safe_ports'
> 2009/05/17 14:52:58.472| ACL::ChecklistMatches: result for 'Safe_ports' is 1
> 2009/05/17 14:52:58.472| ACLList::matches: result is false
> 2009/05/17 14:52:58.472| aclmatchAclList: 0x9c45670 returning false (AND list entry failed to match)
> 2009/05/17 14:52:58.472| aclmatchAclList: async=0 nodeMatched=0 async_in_progress=0 lastACLResult() = 0 finished() = 0
> 2009/05/17 14:52:58.472| ACLChecklist::preCheck: 0x9c45670 checking 'http_access deny CONNECT !SSL_ports'
> 2009/05/17 14:52:58.472| ACLList::matches: checking CONNECT
> 2009/05/17 14:52:58.472| ACL::checklistMatches: checking 'CONNECT'
> 2009/05/17 14:52:58.472| ACL::ChecklistMatches: result for 'CONNECT' is 0
> 2009/05/17 14:52:58.472| ACLList::matches: result is false
> 2009/05/17 14:52:58.472| aclmatchAclList: 0x9c45670 returning false (AND list entry failed to match)
> 2009/05/17 14:52:58.472| aclmatchAclList: async=0 nodeMatched=0 async_in_progress=0 lastACLResult() = 0 finished() = 0
> 2009/05/17 14:52:58.472| ACLChecklist::preCheck: 0x9c45670 checking 'http_access allow localnet'
> 2009/05/17 14:52:58.472| ACLList::matches: checking localnet
> 2009/05/17 14:52:58.472| ACL::checklistMatches: checking 'localnet'
> 2009/05/17 14:52:58.472| aclIpMatchIp: '192.168.1.2:4155' found
> 2009/05/17 14:52:58.472| ACL::ChecklistMatches: result for 'localnet' is 1
> 2009/05/17 14:52:58.472| ACLList::matches: result is true
> 2009/05/17 14:52:58.472| aclmatchAclList: 0x9c45670 returning true (AND list satisfied)
> 2009/05/17 14:52:58.472| ACLChecklist::markFinished: 0x9c45670 checklist processing finished
> 2009/05/17 14:52:58.472| ACLChecklist::check: 0x9c45670 match found, calling back with 1
> 2009/05/17 14:52:58.473| ACLFilledChecklist::checkCallback: 0x9c45670 answer=1
> 2009/05/17 14:52:58.473| ACLChecklist::checkCallback: 0x9c45670 answer=1
> 2009/05/17 14:52:58.473| The request GET http://192.168.0.1:80/ is ALLOWED, because it matched 'localnet'
> 2009/05/17 14:52:58.473| client_side_request.cc(1267) doCallouts: Doing clientInterpretRequestHeaders()
> 2009/05/17 14:52:58.473| clientInterpretRequestHeaders: REQ_NOCACHE = NOT SET
> 2009/05/17 14:52:58.473| clientInterpretRequestHeaders: REQ_CACHABLE = SET
> 2009/05/17 14:52:58.473| clientInterpretRequestHeaders: REQ_HIERARCHICAL = SET
> 2009/05/17 14:52:58.473| FilledChecklist.cc(162) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xbffe39ec
> 2009/05/17 14:52:58.473| ACLChecklist::~ACLChecklist: destroyed 0xbffe39ec
> 2009/05/17 14:52:58.473| client_side_request.cc(120) ~ClientRequestContext: 0x9c415b0 ClientRequestContext destructed
> 2009/05/17 14:52:58.473| client_side_request.cc(1302) doCallouts: calling processRequest()
> 2009/05/17 14:52:58.473| clientProcessRequest: GET 'http://192.168.0.1/'
> 2009/05/17 14:52:58.473| ClientHttpRequest::httpStart: NONE for 'http://192.168.0.1/'
> 2009/05/17 14:52:58.473| clientStreamRead: Calling 1 with cbdata 0xb7ae207c from node 0x9c3d540
> 2009/05/17 14:52:58.473| storeGet: looking up D0FA8C28006D4CB87F077DFA08FC7BE0
> 2009/05/17 14:52:58.473| clientProcessRequest2: StoreEntry is NULL -  MISS
> 2009/05/17 14:52:58.473| clientProcessMiss: 'GET http://192.168.0.1/'
> 2009/05/17 14:52:58.473| storeCreateEntry: 'http://192.168.0.1/'
> 2009/05/17 14:52:58.473| store.cc(360) StoreEntry: new StoreEntry 0xb7bea740
> 2009/05/17 14:52:58.473| MemObject.cc(76) MemObject: new MemObject 0x9bf8b30
> 2009/05/17 14:52:58.473| init-ing hdr: 0x9bfbebc owner: 3
> 2009/05/17 14:52:58.473| storeKeyPrivate: GET http://192.168.0.1/
> 2009/05/17 14:52:58.473| StoreEntry::hashInsert: Inserting Entry 0xb7bea740 key 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.473| store_client::copy: C0695605EF48788B2CC89D6EE31B3048, from 0, for length 4096, cb 1, cbdata 0xb7ae1018
> 2009/05/17 14:52:58.474| storeClientCopy2: C0695605EF48788B2CC89D6EE31B3048
> 2009/05/17 14:52:58.474| store_client::doCopy: co: 0, hi: 0
> 2009/05/17 14:52:58.474| store_client::doCopy: Waiting for more
> 2009/05/17 14:52:58.474| aclCheckFast: list: 0x99b2a20
> 2009/05/17 14:52:58.474| ACLChecklist::preCheck: 0xbffe3800 checking 'miss_access allow all'
> 2009/05/17 14:52:58.474| ACLList::matches: checking all
> 2009/05/17 14:52:58.474| ACL::checklistMatches: checking 'all'
> 2009/05/17 14:52:58.474| aclIpMatchIp: '192.168.1.2:4155' found
> 2009/05/17 14:52:58.474| ACL::ChecklistMatches: result for 'all' is 1
> 2009/05/17 14:52:58.474| ACLList::matches: result is true
> 2009/05/17 14:52:58.474| aclmatchAclList: 0xbffe3800 returning true (AND list satisfied)
> 2009/05/17 14:52:58.474| ACLChecklist::markFinished: 0xbffe3800 checklist processing finished
> 2009/05/17 14:52:58.474| FilledChecklist.cc(162) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xbffe3800
> 2009/05/17 14:52:58.474| ACLChecklist::~ACLChecklist: destroyed 0xbffe3800
> 2009/05/17 14:52:58.474| FwdState::start() 'http://192.168.0.1/'
> 2009/05/17 14:52:58.474| StoreEntry::lock: key 'C0695605EF48788B2CC89D6EE31B3048' count=2
> 2009/05/17 14:52:58.474| peerSelect: http://192.168.0.1/
> 2009/05/17 14:52:58.474| StoreEntry::lock: key 'C0695605EF48788B2CC89D6EE31B3048' count=3
> 2009/05/17 14:52:58.474| peerSelectFoo: 'GET 192.168.0.1'
> 2009/05/17 14:52:58.474| peerSelectFoo: direct = DIRECT_MAYBE
> 2009/05/17 14:52:58.474| peerSelectIcpPing: http://192.168.0.1/
> 2009/05/17 14:52:58.474| neighborsCount: 0
> 2009/05/17 14:52:58.474| peerSelectIcpPing: counted 0 neighbors
> 2009/05/17 14:52:58.474| peerGetSomeParent: GET 192.168.0.1
> 2009/05/17 14:52:58.474| getDefaultParent: returning NULL
> 2009/05/17 14:52:58.474| neighbors.cc(322) getRoundRobinParent: returning NULL
> 2009/05/17 14:52:58.474| getWeightedRoundRobinParent: returning NULL
> 2009/05/17 14:52:58.474| getFirstUpParent: returning NULL
> 2009/05/17 14:52:58.475| getAnyParent: returning NULL
> 2009/05/17 14:52:58.475| peerAddFwdServer: adding DIRECT DIRECT
> 2009/05/17 14:52:58.475| peerSelectCallback: http://192.168.0.1/
> 2009/05/17 14:52:58.475| fwdStartComplete: http://192.168.0.1/
> 2009/05/17 14:52:58.475| fwdConnectStart: http://192.168.0.1/
> 2009/05/17 14:52:58.475| PconnPool::key(192.168.0.1,80,
> 2009/05/17 14:52:58.475| PconnPool::pop: lookup for key {192.168.0.1:80} failed.
> 2009/05/17 14:52:58.475| FilledChecklist.cc(162) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xbffe3544
> 2009/05/17 14:52:58.475| ACLChecklist::~ACLChecklist: destroyed 0xbffe3544
> 2009/05/17 14:52:58.475| fwdConnectStart: got outgoing addr [::], tos 0
> 2009/05/17 14:52:58.475| comm_openex: Attempt open socket for: [::]
> 2009/05/17 14:52:58.475| comm_openex: Opened socket FD 13 : family=10, type=1, protocol=6
> 2009/05/17 14:52:58.475| comm_open: FD 13 is a new socket
> 2009/05/17 14:52:58.475| fd_open() FD 13 http://192.168.0.1/
> 2009/05/17 14:52:58.475| fwdConnectStart: got TCP FD 13
> 2009/05/17 14:52:58.475| comm_add_close_handler: FD 13, handler=1, data=0x9c4d8e8
> 2009/05/17 14:52:58.475| The AsyncCall SomeCloseHandler constructed, this=0x9ae1fa0 [call222]
> 2009/05/17 14:52:58.476| comm_add_close_handler: FD 13, AsyncCall=0x9ae1fa0*1
> 2009/05/17 14:52:58.476| comm.cc(1153) commSetTimeout: FD 13 timeout 60
> 2009/05/17 14:52:58.476| The AsyncCall SomeTimeoutHandler constructed, this=0x9c61e10 [call223]
> 2009/05/17 14:52:58.476| comm.cc(1164) commSetTimeout: FD 13 timeout 60
> 2009/05/17 14:52:58.476| commConnectStart: FD 13, data 0x9c4d8e8, 192.168.0.1:80
> 2009/05/17 14:52:58.476| The AsyncCall SomeCommConnectHandler constructed, this=0x9c61e50 [call224]
> 2009/05/17 14:52:58.476| commConnectStart: FD 13, cb 0x9c61e50*1, 192.168.0.1:80
> 2009/05/17 14:52:58.476| comm_add_close_handler: FD 13, handler=1, data=0x9c59d40
> 2009/05/17 14:52:58.476| The AsyncCall SomeCloseHandler constructed, this=0x9c61dc8 [call225]
> 2009/05/17 14:52:58.476| comm_add_close_handler: FD 13, AsyncCall=0x9c61dc8*1
> 2009/05/17 14:52:58.476| ipcache_nbgethostbyname: Name '192.168.0.1'.
> 2009/05/17 14:52:58.476| ipcacheCheckNumeric: HIT_BYPASS for '192.168.0.1' == 192.168.0.1
> 2009/05/17 14:52:58.476| ipcache_nbgethostbyname: BYPASS for '192.168.0.1' (already numeric)
> 2009/05/17 14:52:58.476| comm.cc(1078) connect: to 192.168.0.1:80
> 2009/05/17 14:52:58.477| comm_connect_addr: sock=13, addrinfo(  flags=4, family=10, socktype=1, protocol=6, &addr=0x9c61e90, addrlen=28 )
> 2009/05/17 14:52:58.477| comm.cc(1083) connect: FD 13: COMM_INPROGRESS
> 2009/05/17 14:52:58.478| StoreEntry::unlock: key 'C0695605EF48788B2CC89D6EE31B3048' count=2
> 2009/05/17 14:52:58.478| FilledChecklist.cc(162) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x9c45670
> 2009/05/17 14:52:58.478| ACLChecklist::~ACLChecklist: destroyed 0x9c45670
> 2009/05/17 14:52:58.478| client_side.cc(2146) connNoteUseOfBuffer: conn->in.notYetUsed = 0
> 2009/05/17 14:52:58.478| clientReadSomeData: FD 11: reading request...
> 2009/05/17 14:52:58.478| The AsyncCall ConnStateData::clientReadRequest constructed, this=0x9ae49b0 [call226]
> 2009/05/17 14:52:58.478| comm_read, queueing read for FD 11; asynCall 0x9ae49b0*1
> 2009/05/17 14:52:58.478| ConnStateData status out: [ job5]
> 2009/05/17 14:52:58.478| leaving ConnStateData::clientReadRequest(FD 11, data=0x9c2df40, size=2, buf=0xb7b66018)
> 2009/05/17 14:52:58.478| comm.cc(1078) connect: to 192.168.0.1:80
> 2009/05/17 14:52:58.478| comm.cc(1088) connect: FD 13: COMM_OK - connected
> 2009/05/17 14:52:58.478| commConnectCallback: FD 13
> 2009/05/17 14:52:58.478| comm_remove_close_handler: FD 13, handler=1, data=0x9c59d40
> 2009/05/17 14:52:58.478| comm.cc(1153) commSetTimeout: FD 13 timeout -1
> 2009/05/17 14:52:58.478| comm.cc(1164) commSetTimeout: FD 13 timeout -1
> 2009/05/17 14:52:58.478| comm.cc(898) will call SomeCommConnectHandler(FD 13, data=0x9c4d8e8) [call224]
> 2009/05/17 14:52:58.479| commConnectFree: FD 13
> 2009/05/17 14:52:58.479| entering SomeCommConnectHandler(FD 13, data=0x9c4d8e8)
> 2009/05/17 14:52:58.479| AsyncCall.cc(32) make: make call SomeCommConnectHandler [call224]
> 2009/05/17 14:52:58.479| fwdConnectDone: FD 13: 'http://192.168.0.1/'
> 2009/05/17 14:52:58.479| fwdDispatch: FD 11: Fetching 'GET http://192.168.0.1/'
> 2009/05/17 14:52:58.479| httpStart: "GET http://192.168.0.1/";
> 2009/05/17 14:52:58.479| AsyncJob of type HttpStateData constructed, this=0x9c5ddac [async6]
> 2009/05/17 14:52:58.479| StoreEntry::lock: key 'C0695605EF48788B2CC89D6EE31B3048' count=3
> 2009/05/17 14:52:58.479| http.cc(81) HttpStateData: HttpStateData 0x9c5dd48 created
> 2009/05/17 14:52:58.479| The AsyncCall httpStateData::httpStateConnClosed constructed, this=0x9ae1ef0 [call227]
> 2009/05/17 14:52:58.479| comm_add_close_handler: FD 13, AsyncCall=0x9ae1ef0*1
> 2009/05/17 14:52:58.479| httpSendRequest: FD 13, request 0x9c04138, this 0x9c5dd48.
> 2009/05/17 14:52:58.479| The AsyncCall HttpStateData::httpTimeout constructed, this=0x9ae4a08 [call228]
> 2009/05/17 14:52:58.479| comm.cc(1164) commSetTimeout: FD 13 timeout 86400
> 2009/05/17 14:52:58.479| The AsyncCall HttpStateData::readReply constructed, this=0x9c62c70 [call229]
> 2009/05/17 14:52:58.479| comm_read, queueing read for FD 13; asynCall 0x9c62c70*1
> 2009/05/17 14:52:58.479| The AsyncCall HttpStateData::SendComplete constructed, this=0x9c62cc8 [call230]
> 2009/05/17 14:52:58.479| init-ing hdr: 0xbffe3dc8 owner: 2
> 2009/05/17 14:52:58.479| getMaxAge: 'http://192.168.0.1/'
> 2009/05/17 14:52:58.479| packing hdr: (0xbffe3dc8)
> 2009/05/17 14:52:58.479| cleaning hdr: 0xbffe3dc8 owner: 2
> 2009/05/17 14:52:58.479| cleaning hdr: 0xbffe3dc8 owner: 2
> 2009/05/17 14:52:58.479| httpSendRequest: FD 13:
> GET / HTTP/1.0
> Via: 1.0 tproxy (squid/3.1.0.7)
> X-Forwarded-For: 192.168.1.2
> Host: 192.168.0.1
> Cache-Control: max-age=259200
> Connection: keep-alive
>
>
> 2009/05/17 14:52:58.479| comm_write: FD 13: sz 155: asynCall 0x9c62cc8*1
> 2009/05/17 14:52:58.479| leaving SomeCommConnectHandler(FD 13, data=0x9c4d8e8)
> 2009/05/17 14:52:58.480| commHandleWrite: FD 13: off 0, sz 155.
> 2009/05/17 14:52:58.481| commHandleWrite: write() returns 155
> 2009/05/17 14:52:58.481| commio_finish_callback: called for FD 13 (0, 0)
> 2009/05/17 14:52:58.481| comm.cc(163) will call HttpStateData::SendComplete(FD 13, data=0x9c5dd48) [call230]
> 2009/05/17 14:52:58.481| entering HttpStateData::SendComplete(FD 13, data=0x9c5dd48)
> 2009/05/17 14:52:58.481| AsyncCall.cc(32) make: make call HttpStateData::SendComplete [call230]
> 2009/05/17 14:52:58.482| HttpStateData status in: [ job6]
> 2009/05/17 14:52:58.482| httpSendComplete: FD 13: size 155: errflag 0.
> 2009/05/17 14:52:58.482| The AsyncCall HttpStateData::httpTimeout constructed, this=0x9c61e10 [call231]
> 2009/05/17 14:52:58.482| comm.cc(1164) commSetTimeout: FD 13 timeout 900
> 2009/05/17 14:52:58.482| HttpStateData status out: [ job6]
> 2009/05/17 14:52:58.482| leaving HttpStateData::SendComplete(FD 13, data=0x9c5dd48)
> 2009/05/17 14:52:58.494| comm_read_try: FD 13, size 4094, retval 330, errno 0
> 2009/05/17 14:52:58.495| commio_finish_callback: called for FD 13 (0, 0)
> 2009/05/17 14:52:58.495| comm.cc(163) will call HttpStateData::readReply(FD 13, data=0x9c5dd48, size=330, buf=0xb7b67008) [call229]
> 2009/05/17 14:52:58.495| entering HttpStateData::readReply(FD 13, data=0x9c5dd48, size=330, buf=0xb7b67008)
> 2009/05/17 14:52:58.495| AsyncCall.cc(32) make: make call HttpStateData::readReply [call229]
> 2009/05/17 14:52:58.495| HttpStateData status in: [ job6]
> 2009/05/17 14:52:58.495| httpReadReply: FD 13: len 330.
> 2009/05/17 14:52:58.495| ctx: enter level  0: 'http://192.168.0.1/'
> 2009/05/17 14:52:58.495| processReplyHeader: key 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.495| init-ing hdr: 0x9bfce94 owner: 3
> 2009/05/17 14:52:58.495| parsing hdr: (0x9bfce94)
> Server: webfs/1.21
> Accept-Ranges: bytes
> Content-Type: text/plain
> Content-Length: 28
> Date: Sun, 17 May 2009 09:52:58 GMT
> X-Cache: MISS from rihad.localnet
> X-Cache-Lookup: MISS from rihad.localnet:3128
> Via: 1.1 rihad.localnet:3128 (squid/2.7.STABLE3)
> Connection: close
>
> 2009/05/17 14:52:58.495| 0x9bfce94: joined for id 9: close
> 2009/05/17 14:52:58.495| Server.cc(134) setVirginReply: 0x9c5dd48 setting virgin reply to 0x9bfce88
> 2009/05/17 14:52:58.495| ctx: exit level  0
> 2009/05/17 14:52:58.495| Server.cc(151) setFinalReply: 0x9c5dd48 setting final reply to 0x9bfce88
> 2009/05/17 14:52:58.495| StoreEntry::replaceHttpReply: http://192.168.0.1/
> 2009/05/17 14:52:58.495| cleaning hdr: 0x9bfbebc owner: 3
> 2009/05/17 14:52:58.496| cleaning hdr: 0x9bfbebc owner: 3
> 2009/05/17 14:52:58.496| storeWrite: writing 24 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.496| memWrite: offset -302 len 24
> 2009/05/17 14:52:58.496| mem_hdr::write: [0,24) object end 0
> 2009/05/17 14:52:58.496| packing hdr: (0x9bfce94)
> 2009/05/17 14:52:58.496| storeWrite: writing 6 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.496| memWrite: offset -278 len 6
> 2009/05/17 14:52:58.496| mem_hdr::write: [24,30) object end 24
> 2009/05/17 14:52:58.496| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.496| memWrite: offset -272 len 2
> 2009/05/17 14:52:58.496| mem_hdr::write: [30,32) object end 30
> 2009/05/17 14:52:58.496| storeWrite: writing 10 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.496| memWrite: offset -270 len 10
> 2009/05/17 14:52:58.496| mem_hdr::write: [32,42) object end 32
> 2009/05/17 14:52:58.496| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.496| memWrite: offset -260 len 2
> 2009/05/17 14:52:58.496| mem_hdr::write: [42,44) object end 42
> 2009/05/17 14:52:58.496| storeWrite: writing 13 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.496| memWrite: offset -258 len 13
> 2009/05/17 14:52:58.496| mem_hdr::write: [44,57) object end 44
> 2009/05/17 14:52:58.496| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.496| memWrite: offset -245 len 2
> 2009/05/17 14:52:58.496| mem_hdr::write: [57,59) object end 57
> 2009/05/17 14:52:58.497| storeWrite: writing 5 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.497| memWrite: offset -243 len 5
> 2009/05/17 14:52:58.497| mem_hdr::write: [59,64) object end 59
> 2009/05/17 14:52:58.497| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.497| memWrite: offset -238 len 2
> 2009/05/17 14:52:58.497| mem_hdr::write: [64,66) object end 64
> 2009/05/17 14:52:58.497| storeWrite: writing 12 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.497| memWrite: offset -236 len 12
> 2009/05/17 14:52:58.497| mem_hdr::write: [66,78) object end 66
> 2009/05/17 14:52:58.497| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.497| memWrite: offset -224 len 2
> 2009/05/17 14:52:58.497| mem_hdr::write: [78,80) object end 78
> 2009/05/17 14:52:58.497| storeWrite: writing 10 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.497| memWrite: offset -222 len 10
> 2009/05/17 14:52:58.497| mem_hdr::write: [80,90) object end 80
> 2009/05/17 14:52:58.497| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.497| memWrite: offset -212 len 2
> 2009/05/17 14:52:58.497| mem_hdr::write: [90,92) object end 90
> 2009/05/17 14:52:58.497| storeWrite: writing 14 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.497| memWrite: offset -210 len 14
> 2009/05/17 14:52:58.497| mem_hdr::write: [92,106) object end 92
> 2009/05/17 14:52:58.497| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.497| memWrite: offset -196 len 2
> 2009/05/17 14:52:58.497| mem_hdr::write: [106,108) object end 106
> 2009/05/17 14:52:58.497| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.497| memWrite: offset -194 len 2
> 2009/05/17 14:52:58.497| mem_hdr::write: [108,110) object end 108
> 2009/05/17 14:52:58.498| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.498| memWrite: offset -192 len 2
> 2009/05/17 14:52:58.498| mem_hdr::write: [110,112) object end 110
> 2009/05/17 14:52:58.498| storeWrite: writing 4 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.498| memWrite: offset -190 len 4
> 2009/05/17 14:52:58.498| mem_hdr::write: [112,116) object end 112
> 2009/05/17 14:52:58.498| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.498| memWrite: offset -186 len 2
> 2009/05/17 14:52:58.498| mem_hdr::write: [116,118) object end 116
> 2009/05/17 14:52:58.498| storeWrite: writing 29 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.498| memWrite: offset -184 len 29
> 2009/05/17 14:52:58.498| mem_hdr::write: [118,147) object end 118
> 2009/05/17 14:52:58.498| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.498| memWrite: offset -155 len 2
> 2009/05/17 14:52:58.498| mem_hdr::write: [147,149) object end 147
> 2009/05/17 14:52:58.498| storeWrite: writing 7 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.498| memWrite: offset -153 len 7
> 2009/05/17 14:52:58.498| mem_hdr::write: [149,156) object end 149
> 2009/05/17 14:52:58.498| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.498| memWrite: offset -146 len 2
> 2009/05/17 14:52:58.498| mem_hdr::write: [156,158) object end 156
> 2009/05/17 14:52:58.498| storeWrite: writing 24 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.498| memWrite: offset -144 len 24
> 2009/05/17 14:52:58.498| mem_hdr::write: [158,182) object end 158
> 2009/05/17 14:52:58.498| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.498| memWrite: offset -120 len 2
> 2009/05/17 14:52:58.499| mem_hdr::write: [182,184) object end 182
> 2009/05/17 14:52:58.499| storeWrite: writing 14 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.499| memWrite: offset -118 len 14
> 2009/05/17 14:52:58.499| mem_hdr::write: [184,198) object end 184
> 2009/05/17 14:52:58.499| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.499| memWrite: offset -104 len 2
> 2009/05/17 14:52:58.499| mem_hdr::write: [198,200) object end 198
> 2009/05/17 14:52:58.499| storeWrite: writing 29 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.499| memWrite: offset -102 len 29
> 2009/05/17 14:52:58.499| mem_hdr::write: [200,229) object end 200
> 2009/05/17 14:52:58.499| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.499| memWrite: offset -73 len 2
> 2009/05/17 14:52:58.499| mem_hdr::write: [229,231) object end 229
> 2009/05/17 14:52:58.499| storeWrite: writing 3 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.499| memWrite: offset -71 len 3
> 2009/05/17 14:52:58.499| mem_hdr::write: [231,234) object end 231
> 2009/05/17 14:52:58.499| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.499| memWrite: offset -68 len 2
> 2009/05/17 14:52:58.499| mem_hdr::write: [234,236) object end 234
> 2009/05/17 14:52:58.499| storeWrite: writing 43 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.499| memWrite: offset -66 len 43
> 2009/05/17 14:52:58.499| mem_hdr::write: [236,279) object end 236
> 2009/05/17 14:52:58.499| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.499| memWrite: offset -23 len 2
> 2009/05/17 14:52:58.500| mem_hdr::write: [279,281) object end 279
> 2009/05/17 14:52:58.500| storeWrite: writing 10 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.500| memWrite: offset -21 len 10
> 2009/05/17 14:52:58.500| mem_hdr::write: [281,291) object end 281
> 2009/05/17 14:52:58.500| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.500| memWrite: offset -11 len 2
> 2009/05/17 14:52:58.500| mem_hdr::write: [291,293) object end 291
> 2009/05/17 14:52:58.500| storeWrite: writing 5 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.500| memWrite: offset -9 len 5
> 2009/05/17 14:52:58.500| mem_hdr::write: [293,298) object end 293
> 2009/05/17 14:52:58.500| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.500| memWrite: offset -4 len 2
> 2009/05/17 14:52:58.500| mem_hdr::write: [298,300) object end 298
> 2009/05/17 14:52:58.500| storeWrite: writing 2 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.500| memWrite: offset -2 len 2
> 2009/05/17 14:52:58.500| mem_hdr::write: [300,302) object end 300
> 2009/05/17 14:52:58.500| storeSwapOut: http://192.168.0.1/
> 2009/05/17 14:52:58.500| storeSwapOut: store_status = STORE_PENDING
> 2009/05/17 14:52:58.500| store_swapout.cc(190) swapOut: storeSwapOut: mem->inmem_lo = 0
> 2009/05/17 14:52:58.500| store_swapout.cc(191) swapOut: storeSwapOut: mem->endOffset() = 302
> 2009/05/17 14:52:58.500| store_swapout.cc(192) swapOut: storeSwapOut: swapout.queue_offset = 0
> 2009/05/17 14:52:58.500| store_swapout.cc(203) swapOut: storeSwapOut: lowest_offset = 0
> 2009/05/17 14:52:58.500| MemObject::isContiguous: Returning true
> 2009/05/17 14:52:58.500| storeSwapOut: swapout_size = 302
> 2009/05/17 14:52:58.500| InvokeHandlers: C0695605EF48788B2CC89D6EE31B3048
> 2009/05/17 14:52:58.500| StoreEntry::InvokeHandlers: checking client #0
> 2009/05/17 14:52:58.500| storeClientCopy2: returning because ENTRY_FWD_HDR_WAIT set
> 2009/05/17 14:52:58.501| ctx: enter level  0: 'http://192.168.0.1/'
> 2009/05/17 14:52:58.501| haveParsedReplyHeaders: HTTP CODE: 404
> 2009/05/17 14:52:58.501| storeGet: looking up D0FA8C28006D4CB87F077DFA08FC7BE0
> 2009/05/17 14:52:58.501| storeGet: looking up DF109D2A3EBC8EE8699197FC193FAF83
> 2009/05/17 14:52:58.501| StoreEntry::expireNow: 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.501| StoreEntry::setReleaseFlag: 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.501| ctx: exit level  0
> 2009/05/17 14:52:58.501| storeWrite: writing 28 bytes for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.501| memWrite: offset 0 len 28
> 2009/05/17 14:52:58.501| mem_hdr::write: [302,330) object end 302
> 2009/05/17 14:52:58.501| storeSwapOut: http://192.168.0.1/
> 2009/05/17 14:52:58.501| storeSwapOut: store_status = STORE_PENDING
> 2009/05/17 14:52:58.501| store_swapout.cc(190) swapOut: storeSwapOut: mem->inmem_lo = 0
> 2009/05/17 14:52:58.501| store_swapout.cc(191) swapOut: storeSwapOut: mem->endOffset() = 330
> 2009/05/17 14:52:58.501| store_swapout.cc(192) swapOut: storeSwapOut: swapout.queue_offset = 0
> 2009/05/17 14:52:58.501| store_swapout.cc(203) swapOut: storeSwapOut: lowest_offset = 0
> 2009/05/17 14:52:58.501| InvokeHandlers: C0695605EF48788B2CC89D6EE31B3048
> 2009/05/17 14:52:58.501| StoreEntry::InvokeHandlers: checking client #0
> 2009/05/17 14:52:58.501| storeClientCopy2: C0695605EF48788B2CC89D6EE31B3048
> 2009/05/17 14:52:58.501| store_client::doCopy: co: 0, hi: 330
> 2009/05/17 14:52:58.501| store_client::doCopy: Copying normal from memory
> 2009/05/17 14:52:58.501| memCopy: [0,4096)
> 2009/05/17 14:52:58.501| clientReplyContext::sendMoreData: http://192.168.0.1/, 330 bytes (330 new bytes)
> 2009/05/17 14:52:58.501| clientReplyContext::sendMoreData: FD 11 'http://192.168.0.1/' out.offset=0
> 2009/05/17 14:52:58.502| init-ing hdr: 0x9bfbebc owner: 3
> 2009/05/17 14:52:58.502| appending hdr: 0x9bfbebc += 0x9bfce94
> 2009/05/17 14:52:58.502| 0x9bfbebc: joined for id 9: close
> 2009/05/17 14:52:58.502| 0x9bfbebc: joined for id 9: 0xbffe3938
> 2009/05/17 14:52:58.502| clientBuildReplyHeader: Error, don't keep-alive
> 2009/05/17 14:52:58.502| 0x9bfbebc: joined for id 54: 0xbffe39d4
> 2009/05/17 14:52:58.502| FilledChecklist.cc(162) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xbffe3a9c
> 2009/05/17 14:52:58.502| ACLChecklist::~ACLChecklist: destroyed 0xbffe3a9c
> 2009/05/17 14:52:58.502| HttpReply.cc(516) expectedBodyTooLarge: bodySizeMax=-1
> 2009/05/17 14:52:58.502| The reply for GET http://192.168.0.1/ is ALLOWED, because it matched 'all'
> 2009/05/17 14:52:58.502| StoreEntry::lock: key 'C0695605EF48788B2CC89D6EE31B3048' count=4
> 2009/05/17 14:52:58.502| clientReplyContext::sendMoreData: Appending 28 bytes after 302 bytes of headers
> 2009/05/17 14:52:58.502| clientStreamCallback: Calling 1 with cbdata 0xb7b04054 from node 0x9c3d4f8
> 2009/05/17 14:52:58.502| packing hdr: (0x9bfbebc)
> 2009/05/17 14:52:58.502| client_side.cc(1228) sendStartOfMessage: sendStartOfMessage schedules clientWriteComplete
> 2009/05/17 14:52:58.502| The AsyncCall clientWriteComplete constructed, this=0x9ae4a50 [call232]
> 2009/05/17 14:52:58.502| comm_write: FD 11: sz 391: asynCall 0x9ae4a50*1
> 2009/05/17 14:52:58.502| persistentConnStatus: FD 13 eof=0
> 2009/05/17 14:52:58.502| persistentConnStatus: content_length=28
> 2009/05/17 14:52:58.502| persistentConnStatus: flags.headers_parsed=1
> 2009/05/17 14:52:58.503| persistentConnStatus: clen=28
> 2009/05/17 14:52:58.503| persistentConnStatus: body_bytes_read=28 content_length=28
> 2009/05/17 14:52:58.503| 0x9bfce94: joined for id 9: close
> 2009/05/17 14:52:58.503| processReplyBody: COMPLETE_NONPERSISTENT_MSG
> 2009/05/17 14:52:58.503| Server.cc(167) serverComplete: serverComplete 0x9c5dd48
> 2009/05/17 14:52:58.503| http.cc(1387) closeServer: closing HTTP server FD 13 this 0x9c5dd48
> 2009/05/17 14:52:58.503| forward.cc(296) unregister: http://192.168.0.1/
> 2009/05/17 14:52:58.503| comm_remove_close_handler: FD 13, handler=1, data=0x9c4d8e8
> 2009/05/17 14:52:58.503| comm_remove_close_handler: FD 13, AsyncCall=0x9ae1ef0*2
> 2009/05/17 14:52:58.503| comm_close: start closing FD 13
> 2009/05/17 14:52:58.503| The AsyncCall comm_close_start constructed, this=0x9c62d20 [call233]
> 2009/05/17 14:52:58.503| comm.cc(1568) will call comm_close_start(FD 13) [call233]
> 2009/05/17 14:52:58.503| comm.cc(1153) commSetTimeout: FD 13 timeout -1
> 2009/05/17 14:52:58.503| comm.cc(1164) commSetTimeout: FD 13 timeout -1
> 2009/05/17 14:52:58.503| commCallCloseHandlers: FD 13
> 2009/05/17 14:52:58.503| The AsyncCall comm_close_complete constructed, this=0x9c61e10 [call234]
> 2009/05/17 14:52:58.503| comm.cc(1600) will call comm_close_complete(FD 13) [call234]
> 2009/05/17 14:52:58.503| Server.cc(188) serverComplete2: serverComplete2 0x9c5dd48
> 2009/05/17 14:52:58.503| Server.cc(228) completeForwarding: completing forwarding for 0x9c4d8e8*2
> 2009/05/17 14:52:58.503| forward.cc(314) complete: http://192.168.0.1/
> 	status 404
> 2009/05/17 14:52:58.503| fwdReforward: http://192.168.0.1/?
> 2009/05/17 14:52:58.503| fwdReforward: No, ENTRY_FWD_HDR_WAIT isn't set
> 2009/05/17 14:52:58.503| fwdComplete: server FD -1 not re-forwarding status 404
> 2009/05/17 14:52:58.503| storeComplete: 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.503| storeEntryValidLength: Checking 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.503| storeEntryValidLength:     object_len = 330
> 2009/05/17 14:52:58.503| storeEntryValidLength:         hdr_sz = 302
> 2009/05/17 14:52:58.504| storeEntryValidLength: content_length = 28
> 2009/05/17 14:52:58.504| storeSwapOut: http://192.168.0.1/
> 2009/05/17 14:52:58.504| storeSwapOut: store_status = STORE_OK
> 2009/05/17 14:52:58.504| store_swapout.cc(190) swapOut: storeSwapOut: mem->inmem_lo = 0
> 2009/05/17 14:52:58.504| store_swapout.cc(191) swapOut: storeSwapOut: mem->endOffset() = 330
> 2009/05/17 14:52:58.504| store_swapout.cc(192) swapOut: storeSwapOut: swapout.queue_offset = 0
> 2009/05/17 14:52:58.504| store_swapout.cc(203) swapOut: storeSwapOut: lowest_offset = 0
> 2009/05/17 14:52:58.504| InvokeHandlers: C0695605EF48788B2CC89D6EE31B3048
> 2009/05/17 14:52:58.504| StoreEntry::InvokeHandlers: checking client #0
> 2009/05/17 14:52:58.504| storePendingNClients: returning 1
> 2009/05/17 14:52:58.504| Server.cc(219) quitIfAllDone: transaction done
> 2009/05/17 14:52:58.504| HttpStateData will NOT delete in-call job, reason: ServerStateData::quitIfAllDone
> 2009/05/17 14:52:58.504| HttpStateData::readReply(FD 13, data=0x9c5dd48, size=330, buf=0xb7b67008) ends job [Stopped, reason:ServerStateData::quitIfAllDone job6]
> 2009/05/17 14:52:58.504| http.cc(157) ~HttpStateData: HttpStateData 0x9c5dd48 destroyed; FD -1
> 2009/05/17 14:52:58.504| StoreEntry::unlock: key 'C0695605EF48788B2CC89D6EE31B3048' count=3
> 2009/05/17 14:52:58.504| forward.cc(159) ~FwdState: FwdState destructor starting
> 2009/05/17 14:52:58.504| StoreEntry::unlock: key 'C0695605EF48788B2CC89D6EE31B3048' count=2
> 2009/05/17 14:52:58.504| forward.cc(186) ~FwdState: FwdState destructor done
> 2009/05/17 14:52:58.504| AsyncJob.cc(140) callEnd: HttpStateData::readReply(FD 13, data=0x9c5dd48, size=330, buf=0xb7b67008) ended 0x9c5ddac
> 2009/05/17 14:52:58.504| leaving HttpStateData::readReply(FD 13, data=0x9c5dd48, size=330, buf=0xb7b67008)
> 2009/05/17 14:52:58.504| entering comm_close_start(FD 13)
> 2009/05/17 14:52:58.504| AsyncCall.cc(32) make: make call comm_close_start [call233]
> 2009/05/17 14:52:58.504| leaving comm_close_start(FD 13)
> 2009/05/17 14:52:58.504| entering comm_close_complete(FD 13)
> 2009/05/17 14:52:58.504| AsyncCall.cc(32) make: make call comm_close_complete [call234]
> 2009/05/17 14:52:58.504| fd_close FD 13 http://192.168.0.1/
> 2009/05/17 14:52:58.505| leaving comm_close_complete(FD 13)
> 2009/05/17 14:52:58.505| commHandleWrite: FD 11: off 0, sz 391.
> 2009/05/17 14:52:58.506| commHandleWrite: write() returns 391
> 2009/05/17 14:52:58.506| commio_finish_callback: called for FD 11 (0, 0)
> 2009/05/17 14:52:58.506| comm.cc(163) will call clientWriteComplete(FD 11, data=0xb7b03018) [call232]
> 2009/05/17 14:52:58.506| entering clientWriteComplete(FD 11, data=0xb7b03018)
> 2009/05/17 14:52:58.506| AsyncCall.cc(32) make: make call clientWriteComplete [call232]
> 2009/05/17 14:52:58.506| clientWriteComplete: FD 11, sz 391, err 0, off 391, len 0xb7bea740
> 2009/05/17 14:52:58.506| client_side_reply.cc(1007) storeOKTransferDone: storeOKTransferDone  out.offset=28 objectLen()=330 headers_sz=302
> 2009/05/17 14:52:58.506| clientReplyStatus: transfer is DONE
> 2009/05/17 14:52:58.506| clientReplyStatus: stream was not expected to complete!
> 2009/05/17 14:52:58.506| client_side.cc(1611) initiateClose: initiateClose: closing for STREAM_UNPLANNED_COMPLETE
> 2009/05/17 14:52:58.506| comm_close: start closing FD 11
> 2009/05/17 14:52:58.507| The AsyncCall comm_close_start constructed, this=0x9ae1fa0 [call235]
> 2009/05/17 14:52:58.507| comm.cc(1568) will call comm_close_start(FD 11) [call235]
> 2009/05/17 14:52:58.507| comm.cc(1153) commSetTimeout: FD 11 timeout -1
> 2009/05/17 14:52:58.507| comm.cc(1164) commSetTimeout: FD 11 timeout -1
> 2009/05/17 14:52:58.507| commio_finish_callback: called for FD 11 (-10, 0)
> 2009/05/17 14:52:58.507| comm.cc(163) will call ConnStateData::clientReadRequest(FD 11, flag=-10, data=0x9c2df40, size=0, buf=0xb7b66008) [call226]
> 2009/05/17 14:52:58.507| commCallCloseHandlers: FD 11
> 2009/05/17 14:52:58.507| commCallCloseHandlers: ch->handler=0x9bb93a8*1
> 2009/05/17 14:52:58.507| comm.cc(1418) will call ConnStateData::connStateClosed(FD 11, data=0x9c2df40) [call209]
> 2009/05/17 14:52:58.507| The AsyncCall comm_close_complete constructed, this=0x9c61dc8 [call236]
> 2009/05/17 14:52:58.507| comm.cc(1600) will call comm_close_complete(FD 11) [call236]
> 2009/05/17 14:52:58.507| leaving clientWriteComplete(FD 11, data=0xb7b03018)
> 2009/05/17 14:52:58.507| entering comm_close_start(FD 11)
> 2009/05/17 14:52:58.507| AsyncCall.cc(32) make: make call comm_close_start [call235]
> 2009/05/17 14:52:58.507| leaving comm_close_start(FD 11)
> 2009/05/17 14:52:58.507| entering ConnStateData::clientReadRequest(FD 11, flag=-10, data=0x9c2df40, size=0, buf=0xb7b66008)
> 2009/05/17 14:52:58.507| AsyncCall.cc(32) make: make call ConnStateData::clientReadRequest [call226]
> 2009/05/17 14:52:58.507| ConnStateData status in: [ job5]
> 2009/05/17 14:52:58.507| client_side.cc(2533) clientReadRequest: clientReadRequest FD 11 size 0
> 2009/05/17 14:52:58.507| client_side.cc(2542) clientReadRequest:  FD 11 closing Bailout.
> 2009/05/17 14:52:58.507| ConnStateData status out: [ job5]
> 2009/05/17 14:52:58.507| leaving ConnStateData::clientReadRequest(FD 11, flag=-10, data=0x9c2df40, size=0, buf=0xb7b66008)
> 2009/05/17 14:52:58.507| entering ConnStateData::connStateClosed(FD 11, data=0x9c2df40)
> 2009/05/17 14:52:58.507| AsyncCall.cc(32) make: make call ConnStateData::connStateClosed [call209]
> 2009/05/17 14:52:58.508| ConnStateData status in: [ job5]
> 2009/05/17 14:52:58.508| ConnStateData will NOT delete in-call job, reason: ConnStateData::connStateClosed
> 2009/05/17 14:52:58.508| ConnStateData::connStateClosed(FD 11, data=0x9c2df40) ends job [Stopped, reason:ConnStateData::connStateClosed job5]
> 2009/05/17 14:52:58.508| ConnStateData::swanSong: FD 11
> 2009/05/17 14:52:58.508| clientStreamDetach: Detaching node 0x9c3d540
> 2009/05/17 14:52:58.508| Freeing clientStreamNode 0x9c3d540
> 2009/05/17 14:52:58.508| clientStreamDetach: Calling 1 with cbdata 0xb7ae207c
> 2009/05/17 14:52:58.508| clientStreamDetach: Detaching node 0x9c3d4f8
> 2009/05/17 14:52:58.508| Freeing clientStreamNode 0x9c3d4f8
> 2009/05/17 14:52:58.508| storeUnregister: called for 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.508| storeSwapOut: http://192.168.0.1/
> 2009/05/17 14:52:58.508| storeSwapOut: store_status = STORE_OK
> 2009/05/17 14:52:58.508| store_swapout.cc(190) swapOut: storeSwapOut: mem->inmem_lo = 0
> 2009/05/17 14:52:58.508| store_swapout.cc(191) swapOut: storeSwapOut: mem->endOffset() = 330
> 2009/05/17 14:52:58.508| store_swapout.cc(192) swapOut: storeSwapOut: swapout.queue_offset = 0
> 2009/05/17 14:52:58.508| store_swapout.cc(203) swapOut: storeSwapOut: lowest_offset = 331
> 2009/05/17 14:52:58.508| storePendingNClients: returning 0
> 2009/05/17 14:52:58.508| StoreEntry::unlock: key 'C0695605EF48788B2CC89D6EE31B3048' count=1
> 2009/05/17 14:52:58.508| httpRequestFree: http://192.168.0.1/
> 2009/05/17 14:52:58.508| FilledChecklist.cc(162) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x9c45670
> 2009/05/17 14:52:58.508| ACLChecklist::~ACLChecklist: destroyed 0x9c45670
> 2009/05/17 14:52:58.508| cleaning hdr: 0x9bfbebc owner: 3
> 2009/05/17 14:52:58.508| cleaning hdr: 0x9bfbebc owner: 3
> 2009/05/17 14:52:58.508| StoreEntry::unlock: key 'C0695605EF48788B2CC89D6EE31B3048' count=0
> 2009/05/17 14:52:58.508| storePendingNClients: returning 0
> 2009/05/17 14:52:58.509| storeRelease: Releasing: 'C0695605EF48788B2CC89D6EE31B3048'
> 2009/05/17 14:52:58.511| store.cc(382) destroyStoreEntry: destroyStoreEntry: destroying 0xb7bea744
> 2009/05/17 14:52:58.511| store.cc(372) destroyMemObject: destroyMemObject 0x9bf8b30
> 2009/05/17 14:52:58.511| MemObject.cc(97) ~MemObject: del MemObject 0x9bf8b30
> 2009/05/17 14:52:58.511| ctx: enter level  0: 'http://192.168.0.1/'
> 2009/05/17 14:52:58.511| cleaning hdr: 0x9bfce94 owner: 3
> 2009/05/17 14:52:58.511| cleaning hdr: 0x9bfce94 owner: 3
> 2009/05/17 14:52:58.511| ctx: exit level  0
> 2009/05/17 14:52:58.511| cleaning hdr: 0x9c04144 owner: 2
> 2009/05/17 14:52:58.511| cleaning hdr: 0x9c04144 owner: 2
> 2009/05/17 14:52:58.511| ConnStateData::~ConnStateData: FD -1
> 2009/05/17 14:52:58.511| AsyncJob.cc(140) callEnd: ConnStateData::connStateClosed(FD 11, data=0x9c2df40) ended 0x9c2e020
> 2009/05/17 14:52:58.511| leaving ConnStateData::connStateClosed(FD 11, data=0x9c2df40)
> 2009/05/17 14:52:58.511| entering comm_close_complete(FD 11)
> 2009/05/17 14:52:58.511| AsyncCall.cc(32) make: make call comm_close_complete [call236]
> 2009/05/17 14:52:58.511| fd_close FD 11 Reading next request
> 2009/05/17 14:52:58.519| leaving comm_close_complete(FD 11)
> 2009/05/17 14:52:58.877| event.cc(251) checkEvents: checkEvents
> 2009/05/17 14:52:58.878| The AsyncCall MaintainSwapSpace constructed, this=0x9c59b68 [call237]
> 2009/05/17 14:52:58.878| event.cc(260) will call MaintainSwapSpace() [call237]
> 2009/05/17 14:52:58.879| entering MaintainSwapSpace()