Re: Large cookie causing squid 3.2 to stop processing? from Guy Helmer on 2012-03-22 (squid-dev)

From: Guy Helmer <guy.helmer_at_palisadesystems.com>
Date: Thu, 22 Mar 2012 12:01:19 -0500

On Mar 20, 2012, at 1:19 PM, Alex Rousskov wrote:

> On 03/20/2012 12:05 PM, Guy Helmer wrote:
>> On Mar 20, 2012, at 12:01 PM, Alex Rousskov wrote:
>>
>>> On 03/20/2012 07:10 AM, Guy Helmer wrote:
>>>
>>>> I have a user that fairly consistently triggers a lack of response from squid (in intercept mode) when using Facebook. In my first steps in tracking this down this problem, I found that squid stops responding after receiving a request with a huge cookie (some data modified to try preserve privacy, but the length of the data remains correct) extracted as text using Wireshark. Is this sufficient to determine what could be happening, or will it be necessary to get a debugging log?
>>>
>>> Is this similar to bug 3467?
>>> http://bugs.squid-cache.org/show_bug.cgi?id=3467
>
>
>> Hmm, I have not found any "WARNING" messages in cache.log. I was not
>> using any debug_options setting at the time.
>
>> The reassembled request from 3 TCP segments was a total of 3237
>> bytes, so I would expect it Squid to be able to fully read it without
>> problems.
>
>
> I recommend opening a new bug report then. 3KB is by no means "huge",
> will not trigger Squid warnings, and should be handled normally. To make
> progress, we would probably need ALL,5+ debugging log or a way to
> reproduce this.
>
>
>> I will work to get a debugging log to help diagnose the situation.
>

Further analysis seems to indicate this is really a host header forgery problem possibly resulting from a transient error in looking up www.facebook.com. I've pasted the result of "perl trace-job.pl job6413 cache-hang.log" below, with some editing to try to keep any session/authentication information private. I'm wondering why the client seems to hang when this happens...

2012/03/20 19:20:56.487 kid1| AsyncJob constructed, this=0x4a0dcb74 type=ConnStateData [job6413]

2012/03/20 19:20:56.531 kid1| entering ConnStateData::clientReadRequest(local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33, data=0x4a0dca90, size=2920, buf=0x49f58000)
2012/03/20 19:20:56.531 kid1| ConnStateData status in: [ job6413]
2012/03/20 19:20:56.531 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.531 kid1| client_side.cc(2906) clientReadRequest: local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33 size 2920
2012/03/20 19:20:56.531 kid1| client_side.cc(2845) clientParseRequests: local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33: attempting to parse
2012/03/20 19:20:56.531 kid1| HttpParser.cc(28) reset: Request buffer is GET /ajax/emu/end.php?eid=...&en=fad_strmsgobjectclick&ed=%22http%3A%5C%2F%5C%2Fwww.facebook.com%5C%2Fbarackobama%22&a=0&sig=102857 HTTP/1.1
Accept: text/html, application/xhtml+xml, */*
Referer: http://www.facebook.com/
Accept-Language: en-US
User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
Accept-Encoding: gzip, deflate
Host: www.facebook.com
Connection: Keep-Alive
Cookie: datr=...
2012/03/20 19:20:56.531 kid1| HttpParser.cc(38) parseRequestFirstLine: parsing possible request: GET /ajax/emu/end.php?eid=...&en=fad_strmsgobjectclick&ed=%22http%3A%5C%2F%5C%2Fwww.facebook.com%5C%2Fbarackobama%22&a=0&sig=102857 HTTP/1.1
Accept: text/html, application/xhtml+xml, */*
Referer: http://www.facebook.com/
Accept-Language: en-US
User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
Accept-Encoding: gzip, deflate
Host: www.facebook.com
Connection: Keep-Alive
Cookie: datr=...
2012/03/20 19:20:56.531 kid1| Parser: retval 1: from 0->1341: method 0->2; url 4->1330; version 1332->1339 (1/1)
2012/03/20 19:20:56.531 kid1| Incomplete request, waiting for end of headers
2012/03/20 19:20:56.531 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.531 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.531 kid1| client_side.cc(259) readSomeData: local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33: reading request...
2012/03/20 19:20:56.531 kid1| cbdataLock: 0x4a0dca90=7
2012/03/20 19:20:56.531 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.531 kid1| cbdataLock: 0x4a0dca90=8
2012/03/20 19:20:56.531 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.531 kid1| cbdataLock: 0x4a0dca90=9
2012/03/20 19:20:56.531 kid1| cbdataLock: 0x4a0dca90=10
2012/03/20 19:20:56.531 kid1| cbdataUnlock: 0x4a0dca90=9
2012/03/20 19:20:56.531 kid1| The AsyncCall ConnStateData::clientReadRequest constructed, this=0x48965b80 [call41658]
2012/03/20 19:20:56.531 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.531 kid1| cbdataLock: 0x4a0dca90=10
2012/03/20 19:20:56.532 kid1| cbdataLock: 0x4a0dca90=11
2012/03/20 19:20:56.532 kid1| cbdataUnlock: 0x4a0dca90=10
2012/03/20 19:20:56.532 kid1| cbdataUnlock: 0x4a0dca90=9
2012/03/20 19:20:56.532 kid1| cbdataUnlock: 0x4a0dca90=8
2012/03/20 19:20:56.532 kid1| comm_read, queueing read for local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33; asynCall 0x48965b80*1
2012/03/20 19:20:56.532 kid1| ModPoll.cc(150) SetSelect: FD 12, type=1, handler=1, client_data=0x49600394, timeout=0
2012/03/20 19:20:56.532 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.532 kid1| ConnStateData status out: [ job6413]
2012/03/20 19:20:56.532 kid1| leaving ConnStateData::clientReadRequest(local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33, data=0x4a0dca90, size=2920, buf=0x49f58000)

2012/03/20 19:20:56.544 kid1| entering ConnStateData::clientReadRequest(local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33, data=0x4a0dca90, size=1175, buf=0x49f58b68)
2012/03/20 19:20:56.544 kid1| ConnStateData status in: [ job6413]
2012/03/20 19:20:56.544 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.544 kid1| client_side.cc(2906) clientReadRequest: local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33 size 1175
2012/03/20 19:20:56.544 kid1| client_side.cc(2845) clientParseRequests: local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33: attempting to parse
2012/03/20 19:20:56.544 kid1| HttpParser.cc(28) reset: Request buffer is GET /ajax/emu/end.php?eid=...&ed=%22http%3A%5C%2F%5C%2Fwww.facebook.com%5C%2Fbarackobama%22&a=0&sig=102857 HTTP/1.1
Accept: text/html, application/xhtml+xml, */*
Referer: http://www.facebook.com/
Accept-Language: en-US
User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
Accept-Encoding: gzip, deflate
Host: www.facebook.com
Connection: Keep-Alive
Cookie: datr=...
2012/03/20 19:20:56.544 kid1| HttpParser.cc(38) parseRequestFirstLine: parsing possible request: GET /ajax/emu/end.php?eid=...&ed=%22http%3A%5C%2F%5C%2Fwww.facebook.com%5C%2Fbarackobama%22&a=0&sig=102857 HTTP/1.1
Accept: text/html, application/xhtml+xml, */*
Referer: http://www.facebook.com/
Accept-Language: en-US
User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
Accept-Encoding: gzip, deflate
Host: www.facebook.com
Connection: Keep-Alive
Cookie: datr=...
2012/03/20 19:20:56.544 kid1| Parser: retval 1: from 0->1341: method 0->2; url 4->1330; version 1332->1339 (1/1)
2012/03/20 19:20:56.544 kid1| Incomplete request, waiting for end of headers
2012/03/20 19:20:56.544 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.544 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.544 kid1| client_side.cc(259) readSomeData: local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33: reading request...
2012/03/20 19:20:56.544 kid1| growing request buffer: notYetUsed=4095 size=8192
2012/03/20 19:20:56.544 kid1| cbdataLock: 0x4a0dca90=7
2012/03/20 19:20:56.544 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.544 kid1| cbdataLock: 0x4a0dca90=8
2012/03/20 19:20:56.544 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.544 kid1| cbdataLock: 0x4a0dca90=9
2012/03/20 19:20:56.544 kid1| cbdataLock: 0x4a0dca90=10
2012/03/20 19:20:56.544 kid1| cbdataUnlock: 0x4a0dca90=9
2012/03/20 19:20:56.544 kid1| The AsyncCall ConnStateData::clientReadRequest constructed, this=0x48965c40 [call41671]
2012/03/20 19:20:56.544 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.544 kid1| cbdataLock: 0x4a0dca90=10
2012/03/20 19:20:56.544 kid1| cbdataLock: 0x4a0dca90=11
2012/03/20 19:20:56.544 kid1| cbdataUnlock: 0x4a0dca90=10
2012/03/20 19:20:56.544 kid1| cbdataUnlock: 0x4a0dca90=9
2012/03/20 19:20:56.544 kid1| cbdataUnlock: 0x4a0dca90=8
2012/03/20 19:20:56.544 kid1| comm_read, queueing read for local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33; asynCall 0x48965c40*1
2012/03/20 19:20:56.544 kid1| ModPoll.cc(150) SetSelect: FD 12, type=1, handler=1, client_data=0x49600394, timeout=0
2012/03/20 19:20:56.544 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.544 kid1| ConnStateData status out: [ job6413]
2012/03/20 19:20:56.544 kid1| leaving ConnStateData::clientReadRequest(local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33, data=0x4a0dca90, size=1175, buf=0x49f58b68)

2012/03/20 19:20:56.548 kid1| entering ConnStateData::clientReadRequest(local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33, data=0x4a0dca90, size=1239, buf=0x4990dfff)
2012/03/20 19:20:56.548 kid1| ConnStateData status in: [ job6413]
2012/03/20 19:20:56.548 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.548 kid1| client_side.cc(2906) clientReadRequest: local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33 size 1239
2012/03/20 19:20:56.548 kid1| client_side.cc(2845) clientParseRequests: local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33: attempting to parse
2012/03/20 19:20:56.548 kid1| HttpParser.cc(28) reset: Request buffer is GET /ajax/emu/end.php?eid=...&ed=%22http%3A%5C%2F%5C%2Fwww.facebook.com%5C%2Fbarackobama%22&a=0&sig=102857 HTTP/1.1
Accept: text/html, application/xhtml+xml, */*
Referer: http://www.facebook.com/
Accept-Language: en-US
User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
Accept-Encoding: gzip, deflate
Host: www.facebook.com
Connection: Keep-Alive
Cookie: datr=...

2012/03/20 19:20:56.548 kid1| HttpParser.cc(38) parseRequestFirstLine: parsing possible request: GET /ajax/emu/end.php?eid=...&ed=%22http%3A%5C%2F%5C%2Fwww.facebook.com%5C%2Fbarackobama%22&a=0&sig=102857 HTTP/1.1
Accept: text/html, application/xhtml+xml, */*
Referer: http://www.facebook.com/
Accept-Language: en-US
User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
Accept-Encoding: gzip, deflate
Host: www.facebook.com
Connection: Keep-Alive
Cookie: datr=...

2012/03/20 19:20:56.548 kid1| Parser: retval 1: from 0->1341: method 0->2; url 4->1330; version 1332->1339 (1/1)
2012/03/20 19:20:56.548 kid1| parseHttpRequest: req_hdr = {Accept: text/html, application/xhtml+xml, */*
Referer: http://www.facebook.com/
Accept-Language: en-US
User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
Accept-Encoding: gzip, deflate
Host: www.facebook.com
Connection: Keep-Alive
Cookie: datr=...

}
2012/03/20 19:20:56.548 kid1| parseHttpRequest: end = {
}
2012/03/20 19:20:56.548 kid1| parseHttpRequest: prefix_sz = 5334, req_line_sz = 1342
2012/03/20 19:20:56.548 kid1| AsyncJob constructed, this=0x48969360 type=ClientHttpRequest [job6415]
2012/03/20 19:20:56.548 kid1| cbdataLock: 0x4a0dca90=7
2012/03/20 19:20:56.548 kid1| cbdataLock: 0x48968f10=1
2012/03/20 19:20:56.548 kid1| cbdataLock: 0x48960d90=1
2012/03/20 19:20:56.548 kid1| clientStreamInsertHead: Inserted node 0x48960de0 with data 0x489a7054 after head
2012/03/20 19:20:56.548 kid1| cbdataLock: 0x48960de0=1
2012/03/20 19:20:56.548 kid1| parseHttpRequest: Request Header is
Accept: text/html, application/xhtml+xml, */*
Referer: http://www.facebook.com/
Accept-Language: en-US
User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
Accept-Encoding: gzip, deflate
Host: www.facebook.com
Connection: Keep-Alive
Cookie: datr=...

2012/03/20 19:20:56.548 kid1| client_side.cc(2266) parseHttpRequest: repare absolute URL from intercept
2012/03/20 19:20:56.548 kid1| mime_get_header: looking for 'Host'
2012/03/20 19:20:56.548 kid1| mime_get_header: checking 'Host: www.facebook.com'
2012/03/20 19:20:56.548 kid1| mime_get_header: returning 'www.facebook.com'
2012/03/20 19:20:56.548 kid1| TRANSPARENT HOST REWRITE: 'http://www.facebook.com/ajax/emu/end.php?eid=...&ed=%22http%3A%5C%2F%5C%2Fwww.facebook.com%5C%2Fbarackobama%22&a=0&sig=102857'
2012/03/20 19:20:56.549 kid1| parseHttpRequest: Complete request received
2012/03/20 19:20:56.549 kid1| HTTP Client local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33
2012/03/20 19:20:56.549 kid1| HTTP Client REQUEST:
---------
GET /ajax/emu/end.php?eid=...&ed=%22http%3A%5C%2F%5C%2Fwww.facebook.com%5C%2Fbarackobama%22&a=0&sig=102857 HTTP/1.1
Accept: text/html, application/xhtml+xml, */*
Referer: http://www.facebook.com/
Accept-Language: en-US
User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
Accept-Encoding: gzip, deflate
Host: www.facebook.com
Connection: Keep-Alive
Cookie: datr=...

----------
2012/03/20 19:20:56.549 kid1| client_side.cc(2883) clientParseRequests: local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33: parsed a request
2012/03/20 19:20:56.549 kid1| cbdataLock: 0x48968f10=2
2012/03/20 19:20:56.549 kid1| cbdataLock: 0x48968f10=3
2012/03/20 19:20:56.549 kid1| The AsyncCall clientLifetimeTimeout constructed, this=0x489b9280 [call41676]
2012/03/20 19:20:56.549 kid1| cbdataLock: 0x48968f10=4
2012/03/20 19:20:56.549 kid1| cbdataUnlock: 0x48968f10=3
2012/03/20 19:20:56.549 kid1| cbdataUnlock: 0x48968f10=2
2012/03/20 19:20:56.549 kid1| comm.cc(748) commSetConnTimeout: local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33 timeout 86400
2012/03/20 19:20:56.549 kid1| cbdataUnlock: 0x4a0dca90=6
2012/03/20 19:20:56.549 kid1| cbdataUnlock: 0x4a0dca90=5
2012/03/20 19:20:56.549 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.549 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.549 kid1| urlParse: Split URL 'http://www.facebook.com/ajax/emu/end.php?eid=...&ed=%22http%3A%5C%2F%5C%2Fwww.facebook.com%5C%2Fbarackobama%22&a=0&sig=102857' into proto='http', host='www.facebook.com', port='80', path='/ajax/emu/end.php?eid=...&ed=%22http%3A%5C%2F%5C%2Fwww.facebook.com%5C%2Fbarackobama%22&a=0&sig=102857'
2012/03/20 19:20:56.549 kid1| init-ing hdr: 0x49e66010 owner: 1
2012/03/20 19:20:56.549 kid1| HttpRequest.cc(62) HttpRequest: constructed, this=0x49e66000 id=880
2012/03/20 19:20:56.549 kid1| Address.cc(409) LookupHostIP: Given Non-IP 'www.facebook.com': hostname nor servname provided, or not known
2012/03/20 19:20:56.549 kid1| parsing hdr: (0x49e66010)
Accept: text/html, application/xhtml+xml, */*
Referer: http://www.facebook.com/
Accept-Language: en-US
User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
Accept-Encoding: gzip, deflate
Host: www.facebook.com
Connection: Keep-Alive
Cookie: datr=RgBdSy5QFeNWI9U3NgwHdivwlg..; lu=TgAU5Kt0yHCCfBA0n_Ko38ZQ; gz=1; c_user=1494993878; xs=2%3Au0AYgx0rm3h6uQ%3A0%3A1332289136; x-referer=http%3A%2F%2Fwww.facebook.com%2Fprofile.php%3Fid%3D1498050002%23%2F; act=1332289255673%2F26%3A0; p=7;
2012/03/20 19:20:56.549 kid1| parsing HttpHeaderEntry: near 'Accept: text/html, application/xhtml+xml, */*'
2012/03/20 19:20:56.549 kid1| parsed HttpHeaderEntry: 'Accept: text/html, application/xhtml+xml, */*'
2012/03/20 19:20:56.549 kid1| created HttpHeaderEntry 0x49ee8860: 'Accept : text/html, application/xhtml+xml, */*
2012/03/20 19:20:56.549 kid1| HttpHeader.cc(887) addEntry: 0x49e66010 adding entry: 0 at 0
2012/03/20 19:20:56.549 kid1| parsing HttpHeaderEntry: near 'Referer: http://www.facebook.com/'
2012/03/20 19:20:56.549 kid1| parsed HttpHeaderEntry: 'Referer: http://www.facebook.com/'
2012/03/20 19:20:56.549 kid1| created HttpHeaderEntry 0x49d83320: 'Referer : http://www.facebook.com/
2012/03/20 19:20:56.549 kid1| HttpHeader.cc(887) addEntry: 0x49e66010 adding entry: 47 at 1
2012/03/20 19:20:56.549 kid1| parsing HttpHeaderEntry: near 'Accept-Language: en-US'
2012/03/20 19:20:56.549 kid1| parsed HttpHeaderEntry: 'Accept-Language: en-US'
2012/03/20 19:20:56.549 kid1| created HttpHeaderEntry 0x489e4b80: 'Accept-Language : en-US
2012/03/20 19:20:56.549 kid1| HttpHeader.cc(887) addEntry: 0x49e66010 adding entry: 3 at 2
2012/03/20 19:20:56.549 kid1| parsing HttpHeaderEntry: near 'User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)'
2012/03/20 19:20:56.549 kid1| parsed HttpHeaderEntry: 'User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)'
2012/03/20 19:20:56.549 kid1| created HttpHeaderEntry 0x489e4b40: 'User-Agent : Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
2012/03/20 19:20:56.549 kid1| HttpHeader.cc(887) addEntry: 0x49e66010 adding entry: 60 at 3
2012/03/20 19:20:56.549 kid1| parsing HttpHeaderEntry: near 'Accept-Encoding: gzip, deflate'
2012/03/20 19:20:56.549 kid1| parsed HttpHeaderEntry: 'Accept-Encoding: gzip, deflate'
2012/03/20 19:20:56.549 kid1| created HttpHeaderEntry 0x49cccba0: 'Accept-Encoding : gzip, deflate
2012/03/20 19:20:56.549 kid1| HttpHeader.cc(887) addEntry: 0x49e66010 adding entry: 2 at 4
2012/03/20 19:20:56.549 kid1| parsing HttpHeaderEntry: near 'Host: www.facebook.com'
2012/03/20 19:20:56.549 kid1| parsed HttpHeaderEntry: 'Host: www.facebook.com'
2012/03/20 19:20:56.549 kid1| created HttpHeaderEntry 0x49eec520: 'Host : www.facebook.com
2012/03/20 19:20:56.549 kid1| HttpHeader.cc(887) addEntry: 0x49e66010 adding entry: 26 at 5
2012/03/20 19:20:56.549 kid1| parsing HttpHeaderEntry: near 'Connection: Keep-Alive'
2012/03/20 19:20:56.550 kid1| parsed HttpHeaderEntry: 'Connection: Keep-Alive'
2012/03/20 19:20:56.550 kid1| created HttpHeaderEntry 0x49e74f60: 'Connection : Keep-Alive
2012/03/20 19:20:56.550 kid1| HttpHeader.cc(887) addEntry: 0x49e66010 adding entry: 9 at 6
2012/03/20 19:20:56.550 kid1| parsing HttpHeaderEntry: near 'Cookie: datr=...'
2012/03/20 19:20:56.550 kid1| parsed HttpHeaderEntry: 'Cookie: datr=...'
2012/03/20 19:20:56.550 kid1| created HttpHeaderEntry 0x49ccca80: 'Cookie : datr=...
2012/03/20 19:20:56.550 kid1| HttpHeader.cc(887) addEntry: 0x49e66010 adding entry: 19 at 7
2012/03/20 19:20:56.550 kid1| 0x49e66010 lookup for 56
2012/03/20 19:20:56.550 kid1| cbdataLock: 0x4a0dca90=6
2012/03/20 19:20:56.550 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.550 kid1| cbdataLock: 0x4a0dca90=7
2012/03/20 19:20:56.550 kid1| cbdataUnlock: 0x4a0dca90=6
2012/03/20 19:20:56.550 kid1| cbdataLock: 0x4a0dca90=7
2012/03/20 19:20:56.550 kid1| cbdataUnlock: 0x4a0dca90=6
2012/03/20 19:20:56.550 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.550 kid1| cbdataLock: 0x4a0dca90=7
2012/03/20 19:20:56.550 kid1| cbdataUnlock: 0x4a0dca90=6
2012/03/20 19:20:56.550 kid1| 0x49e66010 lookup for 56
2012/03/20 19:20:56.550 kid1| 0x49e66010 lookup for 56
2012/03/20 19:20:56.550 kid1| 0x49e66010 lookup for 23
2012/03/20 19:20:56.550 kid1| clientSetKeepaliveFlag: http_ver = 1.1
2012/03/20 19:20:56.550 kid1| clientSetKeepaliveFlag: method = GET
2012/03/20 19:20:56.550 kid1| 0x49e66010 lookup for 43
2012/03/20 19:20:56.550 kid1| 0x49e66010 lookup for 9
2012/03/20 19:20:56.550 kid1| 0x49e66010joining for id 9
2012/03/20 19:20:56.550 kid1| 0x49e66010: joined for id 9: Keep-Alive
2012/03/20 19:20:56.550 kid1| cbdataLock: 0x48968f10=3
2012/03/20 19:20:56.550 kid1| client_side_request.cc(150) ClientRequestContext: 0x48a3ead0 ClientRequestContext constructed
2012/03/20 19:20:56.550 kid1| client_side_request.cc(1529) doCallouts: Doing calloutContext->hostHeaderVerify()
2012/03/20 19:20:56.550 kid1| client_side_request.cc(639) hostHeaderVerify: validate host=www.facebook.com, port=0, portStr=NULL
2012/03/20 19:20:56.550 kid1| ipcache_nbgethostbyname: Name 'www.facebook.com'.
2012/03/20 19:20:56.550 kid1| Address.cc(409) LookupHostIP: Given Non-IP 'www.facebook.com': hostname nor servname provided, or not known
2012/03/20 19:20:56.550 kid1| ipcache_nbgethostbyname: HIT for 'www.facebook.com'
2012/03/20 19:20:56.550 kid1| cbdataLock: 0x48a3ead0=1
2012/03/20 19:20:56.550 kid1| cbdataReferenceValid: 0x48a3ead0
2012/03/20 19:20:56.550 kid1| cbdataUnlock: 0x48a3ead0=0
2012/03/20 19:20:56.550 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.550 kid1| client_side_request.cc(546) hostHeaderIpVerify: validate IP 69.171.228.40:80 non-match from Host: IP 66.220.149.11
2012/03/20 19:20:56.550 kid1| client_side_request.cc(549) hostHeaderIpVerify: FAIL: validate IP 69.171.228.40:80 possible from Host:
2012/03/20 19:20:56.550 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.550 kid1| SECURITY ALERT: Host header forgery detected on local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33 (local IP does not match any domain IP) on URL: http://www.facebook.com/ajax/emu/end.php?eid=...&en=fad_strmsgobjectclick&ed=%22http%3A%5C%2F%5C%2Fwww.facebook.com%5C%2Fbarackobama%22&a=0&sig=102857
2012/03/20 19:20:56.550 kid1| client_side.cc(2409) connNoteUseOfBuffer: conn->in.notYetUsed = 0
2012/03/20 19:20:56.550 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.550 kid1| client_side.cc(259) readSomeData: local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33: reading request...
2012/03/20 19:20:56.550 kid1| cbdataLock: 0x4a0dca90=7
2012/03/20 19:20:56.550 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.550 kid1| cbdataLock: 0x4a0dca90=8
2012/03/20 19:20:56.550 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.550 kid1| cbdataLock: 0x4a0dca90=9
2012/03/20 19:20:56.550 kid1| cbdataLock: 0x4a0dca90=10
2012/03/20 19:20:56.550 kid1| cbdataUnlock: 0x4a0dca90=9
2012/03/20 19:20:56.550 kid1| The AsyncCall ConnStateData::clientReadRequest constructed, this=0x48965760 [call41677]
2012/03/20 19:20:56.550 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.550 kid1| cbdataLock: 0x4a0dca90=10
2012/03/20 19:20:56.550 kid1| cbdataLock: 0x4a0dca90=11
2012/03/20 19:20:56.550 kid1| cbdataUnlock: 0x4a0dca90=10
2012/03/20 19:20:56.550 kid1| cbdataUnlock: 0x4a0dca90=9
2012/03/20 19:20:56.550 kid1| cbdataUnlock: 0x4a0dca90=8
2012/03/20 19:20:56.550 kid1| comm_read, queueing read for local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33; asynCall 0x48965760*1
2012/03/20 19:20:56.550 kid1| ModPoll.cc(150) SetSelect: FD 12, type=1, handler=1, client_data=0x49600394, timeout=0
2012/03/20 19:20:56.550 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:20:56.551 kid1| ConnStateData status out: [ job6413]
2012/03/20 19:20:56.551 kid1| leaving ConnStateData::clientReadRequest(local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33, data=0x4a0dca90, size=1239, buf=0x4990dfff)

2012/03/20 19:21:49.880 kid1| entering ConnStateData::clientReadRequest(local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33, errno=54, flag=-1, data=0x4a0dca90, size=0, buf=0x4990d000)
2012/03/20 19:21:49.880 kid1| ConnStateData status in: [ job6413]
2012/03/20 19:21:49.880 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.880 kid1| client_side.cc(2906) clientReadRequest: local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33 size 0
2012/03/20 19:21:49.880 kid1| connReadWasError: FD local=69.171.228.40:80 remote=192.168.1.109:49455 FD 12 flags=33: got flag -1
2012/03/20 19:21:49.880 kid1| comm_close: start closing FD 12
2012/03/20 19:21:49.880 kid1| comm.cc(735) commUnsetFdTimeout: Remove timeout for FD 12
2012/03/20 19:21:49.880 kid1| cbdataUnlock: 0x48968f10=2
2012/03/20 19:21:49.880 kid1| commCallCloseHandlers: FD 12
2012/03/20 19:21:49.880 kid1| commCallCloseHandlers: ch->handler=0x48960970*1
2012/03/20 19:21:49.880 kid1| comm.cc(939) will call ConnStateData::connStateClosed(FD -1, data=0x4a0dca90) [call41626]
2012/03/20 19:21:49.880 kid1| The AsyncCall comm_close_complete constructed, this=0x489b9280 [call42244]
2012/03/20 19:21:49.880 kid1| comm.cc(1150) will call comm_close_complete(FD 12) [call42244]
2012/03/20 19:21:49.880 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.880 kid1| ConnStateData status out: [ job6413]
2012/03/20 19:21:49.880 kid1| leaving ConnStateData::clientReadRequest(local=69.171.228.40:80 remote=192.168.1.109:49455 flags=33, errno=54, flag=-1, data=0x4a0dca90, size=0, buf=0x4990d000)

2012/03/20 19:21:49.880 kid1| entering ConnStateData::connStateClosed(FD -1, data=0x4a0dca90)
2012/03/20 19:21:49.880 kid1| ConnStateData status in: [ job6413]
2012/03/20 19:21:49.880 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.880 kid1| ConnStateData will NOT delete in-call job, reason: ConnStateData::connStateClosed
2012/03/20 19:21:49.880 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.880 kid1| ConnStateData::connStateClosed(FD -1, data=0x4a0dca90) ends job [Stopped, reason:ConnStateData::connStateClosed job6413]
2012/03/20 19:21:49.880 kid1| client_side.cc(769) swanSong: local=69.171.228.40:80 remote=192.168.1.109:49455 flags=33
2012/03/20 19:21:49.880 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.880 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.880 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.880 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.880 kid1| clientStreamDetach: Detaching node 0x48960de0
2012/03/20 19:21:49.881 kid1| cbdataLock: 0x48960d90=2
2012/03/20 19:21:49.881 kid1| cbdataUnlock: 0x48960de0=0
2012/03/20 19:21:49.881 kid1| cbdataFree: 0x48960de0
2012/03/20 19:21:49.881 kid1| cbdataFree: Freeing 0x48960de0
2012/03/20 19:21:49.881 kid1| Freeing clientStreamNode 0x48960de0
2012/03/20 19:21:49.881 kid1| clientStreamDetach: Calling 1 with cbdata 0x489f1074
2012/03/20 19:21:49.881 kid1| cbdataReferenceValid: 0x48960d90
2012/03/20 19:21:49.881 kid1| clientStreamDetach: Detaching node 0x48960d90
2012/03/20 19:21:49.881 kid1| cbdataUnlock: 0x48960d90=1
2012/03/20 19:21:49.881 kid1| cbdataFree: 0x48960d90
2012/03/20 19:21:49.881 kid1| cbdataFree: 0x48960d90 has 1 locks, not freeing
2012/03/20 19:21:49.881 kid1| cbdataUnlock: 0x48960d90=0
2012/03/20 19:21:49.881 kid1| cbdataUnlock: Freeing 0x48960d90
2012/03/20 19:21:49.881 kid1| Freeing clientStreamNode 0x48960d90
2012/03/20 19:21:49.881 kid1| cbdataUnlock: 0x48968f10=1
2012/03/20 19:21:49.881 kid1| cbdataFree: 0x489f0010
2012/03/20 19:21:49.881 kid1| cbdataFree: Freeing 0x489f0010
2012/03/20 19:21:49.881 kid1| httpRequestFree: http://www.facebook.com/ajax/emu/end.php?eid=...&ed=%22http%3A%5C%2F%5C%2Fwww.facebook.com%5C%2Fbarackobama%22&a=0&sig=102857
2012/03/20 19:21:49.881 kid1| client_side.cc(626) logRequest: logging half-baked transaction: http://www.facebook.com/ajax/emu/end.php?
2012/03/20 19:21:49.881 kid1| clientLogRequest: al.url='http://www.facebook.com/ajax/emu/end.php?'
2012/03/20 19:21:49.881 kid1| clientLogRequest: http.code='0'
2012/03/20 19:21:49.881 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.881 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.881 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.881 kid1| cbdataLock: 0x48a4d550=7
2012/03/20 19:21:49.881 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.881 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.881 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.881 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.881 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.881 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.881 kid1| cbdataLock: 0x4a0dca90=5
2012/03/20 19:21:49.881 kid1| logfileNewBuffer: daemon:/var/log/squid/access.log: new buffer
2012/03/20 19:21:49.881 kid1| logfile_mod_daemon_append: daemon:/var/log/squid/access.log: appending 1 bytes
2012/03/20 19:21:49.881 kid1| logfile_mod_daemon_append: current buffer has 0 of 32768 bytes before append
2012/03/20 19:21:49.881 kid1| logfile_mod_daemon_append: daemon:/var/log/squid/access.log: appending 117 bytes
2012/03/20 19:21:49.881 kid1| logfile_mod_daemon_append: current buffer has 1 of 32768 bytes before append
2012/03/20 19:21:49.881 kid1| logfile_mod_daemon_append: daemon:/var/log/squid/access.log: appending 2 bytes
2012/03/20 19:21:49.881 kid1| logfile_mod_daemon_append: current buffer has 118 of 32768 bytes before append
2012/03/20 19:21:49.881 kid1| ModPoll.cc(150) SetSelect: FD 6, type=2, handler=1, client_data=0x48971110, timeout=0
2012/03/20 19:21:49.881 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.881 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.881 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.881 kid1| cbdataUnlock: 0x4a0dca90=4
2012/03/20 19:21:49.881 kid1| FilledChecklist.cc(104) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x48a21610
2012/03/20 19:21:49.881 kid1| ACLChecklist::~ACLChecklist: destroyed 0x48a21610
2012/03/20 19:21:49.881 kid1| cbdataFree: 0x48a21610
2012/03/20 19:21:49.881 kid1| cbdataFree: Freeing 0x48a21610
2012/03/20 19:21:49.881 kid1| cbdataUnlock: 0x48a4d550=6
2012/03/20 19:21:49.881 kid1| cleaning hdr: 0x49e66010 owner: 1
2012/03/20 19:21:49.881 kid1| destroying entry 0x49ee8860: 'Accept: text/html, application/xhtml+xml, */*'
2012/03/20 19:21:49.881 kid1| destroying entry 0x49d83320: 'Referer: http://www.facebook.com/'
2012/03/20 19:21:49.881 kid1| destroying entry 0x489e4b80: 'Accept-Language: en-US'
2012/03/20 19:21:49.881 kid1| destroying entry 0x489e4b40: 'User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)'
2012/03/20 19:21:49.881 kid1| destroying entry 0x49cccba0: 'Accept-Encoding: gzip, deflate'
2012/03/20 19:21:49.881 kid1| destroying entry 0x49eec520: 'Host: www.facebook.com'
2012/03/20 19:21:49.881 kid1| destroying entry 0x49e74f60: 'Connection: Keep-Alive'
2012/03/20 19:21:49.881 kid1| destroying entry 0x49ccca80: 'Cookie: datr=...'
2012/03/20 19:21:49.881 kid1| HttpRequest.cc(70) ~HttpRequest: destructed, this=0x49e66000
2012/03/20 19:21:49.881 kid1| cbdataUnlock: 0x4a0dca90=3
2012/03/20 19:21:49.881 kid1| cleaning hdr: 0x49e66010 owner: 1
2012/03/20 19:21:49.881 kid1| The AsyncCall Initiate::noteInitiatorAborted constructed, this=0x489b9500 [call42245]
2012/03/20 19:21:49.881 kid1| Initiator.cc(34) will call Initiate::noteInitiatorAborted() [call42245]
2012/03/20 19:21:49.881 kid1| cbdataUnlock: 0x48968f10=0
2012/03/20 19:21:49.881 kid1| client_side_request.cc(138) ~ClientRequestContext: 0x48a3ead0 ClientRequestContext destructed
2012/03/20 19:21:49.881 kid1| cbdataFree: 0x48a3ead0
2012/03/20 19:21:49.882 kid1| cbdataFree: Freeing 0x48a3ead0
2012/03/20 19:21:49.882 kid1| cbdataUnlock: 0x4a0dca90=2
2012/03/20 19:21:49.882 kid1| AsyncJob destructed, this=0x48969360 type=ClientHttpRequest [job6415]
2012/03/20 19:21:49.882 kid1| cbdataFree: 0x48968f10
2012/03/20 19:21:49.882 kid1| cbdataFree: Freeing 0x48968f10
2012/03/20 19:21:49.882 kid1| cbdataFree: 0x489a6010
2012/03/20 19:21:49.882 kid1| cbdataFree: Freeing 0x489a6010
2012/03/20 19:21:49.882 kid1| client_side.cc(804) ~ConnStateData:
2012/03/20 19:21:49.882 kid1| cbdataReferenceValid: 0x4a0dca90
2012/03/20 19:21:49.882 kid1| cbdataUnlock: 0x48a4d550=5
2012/03/20 19:21:49.882 kid1| AsyncJob destructed, this=0x4a0dcb74 type=ConnStateData [job6413]
2012/03/20 19:21:49.882 kid1| cbdataFree: 0x4a0dca90
2012/03/20 19:21:49.882 kid1| cbdataFree: 0x4a0dca90 has 2 locks, not freeing
2012/03/20 19:21:49.882 kid1| AsyncJob.cc(140) callEnd: ConnStateData::connStateClosed(FD -1, data=0x4a0dca90) ended 0x4a0dcb74
2012/03/20 19:21:49.882 kid1| leaving ConnStateData::connStateClosed(FD -1, data=0x4a0dca90)

--------
This message has been scanned by ComplianceSafe, powered by Palisade's PacketSure.
Received on Thu Mar 22 2012 - 17:01:48 MDT

This archive was generated by hypermail 2.2.0 : Fri Mar 23 2012 - 12:00:10 MDT