Re: [squid-users] TProxy not faking source address.

Sun, 17 May 2009 03:14:37 -0700 

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()
























					Reply via email to