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.
