Hi,
Am 24.9.2013 16:25, schrieb Amos Jeffries:
...Perhase a "debug_options ALL,1 11,6 78,6" trace would be more
informative.
To get an usefull example in the logfiles I requestet
http://www.uni-leipzig.de, I found the following in cache.log:
...
2013/09/25 09:08:47.988| persistentConnStatus: FD 17 eof=0
2013/09/25 09:08:47.988| persistentConnStatus: content_length=4
2013/09/25 09:08:47.988| persistentConnStatus: clen=4
2013/09/25 09:08:47.988| persistentConnStatus: body_bytes_read=4
content_length=4
2013/09/25 09:08:47.988| processReplyBody: COMPLETE_PERSISTENT_MSG
2013/09/25 09:08:47.988| Server.cc(169) serverComplete: serverComplete
0x7fa5b432dc48
2013/09/25 09:08:47.988| Server.cc(194) serverComplete2:
serverComplete2 0x7fa5b432dc48
2013/09/25 09:08:47.988| Server.cc(234) completeForwarding: completing
forwarding for 0x7fa5b4019728*2
2013/09/25 09:08:47.988| Server.cc(225) quitIfAllDone: transaction done
2013/09/25 09:08:47.988| Server.cc(556) cleanAdaptation: cleaning ICAP;
ACL: 0
2013/09/25 09:08:47.988| http.cc(163) ~HttpStateData: HttpStateData
0x7fa5b432dc48 destroyed; FD -1
2013/09/25 09:08:47.988| leaving HttpStateData::readReply(FD 17,
data=0x7fa5b432dc48, size=131, buf=0x7fa5b4332680)
2013/09/25 09:08:48.929| idnsALookup: buf is 36 bytes for
www.uni-leipzig.de, id = 0x44dd
2013/09/25 09:08:48.929| httpStart: "GET http://www.uni-leipzig.de/";
2013/09/25 09:08:48.929| http.cc(83) HttpStateData: HttpStateData
0x7fa5b432dc48 created
2013/09/25 09:08:48.929| httpSendRequest: FD 24, request
0x7fa5b4024410, this 0x7fa5b432dc48.
2013/09/25 09:08:48.929| The AsyncCall HttpStateData::httpTimeout
constructed, this=0x7fa5ce592ac0 [call4888553]
2013/09/25 09:08:48.929| The AsyncCall HttpStateData::readReply
constructed, this=0x7fa5ce758e50 [call4888554]
2013/09/25 09:08:48.929| The AsyncCall HttpStateData::sendComplete
constructed, this=0x7fa5ce591430 [call4888555]
2013/09/25 09:08:48.929| httpBuildRequestHeader: Host:
www.uni-leipzig.de
2013/09/25 09:08:48.929| httpBuildRequestHeader: User-Agent:
Mozilla/5.0 (Windows NT 5.1; rv:24.0) Gecko/20100101 Firefox/24.0
2013/09/25 09:08:48.929| httpBuildRequestHeader: Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
2013/09/25 09:08:48.929| httpBuildRequestHeader: Accept-Language:
de-de,de;q=0.8,en-us;q=0.5,en;q=0.3
2013/09/25 09:08:48.929| httpBuildRequestHeader: Accept-Encoding: gzip,
deflate
2013/09/25 09:08:48.929| httpBuildRequestHeader: DNT: 1
2013/09/25 09:08:48.929| httpBuildRequestHeader: Connection: keep-alive
2013/09/25 09:08:48.930| httpSendRequest: FD 24:
GET http://www.uni-leipzig.de/ HTTP/1.1
Host: www.uni-leipzig.de
User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:24.0) Gecko/20100101
Firefox/24.0
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: de-de,de;q=0.8,en-us;q=0.5,en;q=0.3
Accept-Encoding: gzip, deflate
DNT: 1
Via: 1.1 lav-desproxy.lav.lsa-net.de (squid/3.1.12)
X-Forwarded-For: 11.40.11.223
Cache-Control: max-age=259200
2013/09/25 09:08:48.930| comm.cc(165) will call
HttpStateData::sendComplete(FD 24, data=0x7fa5b432dc48) [call4888555]
2013/09/25 09:08:48.930| entering HttpStateData::sendComplete(FD 24,
data=0x7fa5b432dc48)
2013/09/25 09:08:48.930| AsyncCall.cc(32) make: make call
HttpStateData::sendComplete [call4888555]
2013/09/25 09:08:48.930| HttpStateData status in: [ job298503]
2013/09/25 09:08:48.930| httpSendComplete: FD 24: size 430: errflag 0.
2013/09/25 09:08:48.930| The AsyncCall HttpStateData::httpTimeout
constructed, this=0x7fa5ce75b5b0 [call4888556]
2013/09/25 09:08:48.930| HttpStateData status out: [ job298503]
2013/09/25 09:08:48.930| leaving HttpStateData::sendComplete(FD 24,
data=0x7fa5b432dc48)
2013/09/25 09:08:48.958| idnsRead: starting with FD 12
2013/09/25 09:08:48.958| idnsRead: FD 12: received 94 bytes from
11.136.15.1:53
2013/09/25 09:08:48.958| idnsGrokReply: ID 0x44dd, 0 answers
2013/09/25 09:08:48.958| idnsGrokReply: www.uni-leipzig.de has no AAAA
records. Looking up A record instead.
2013/09/25 09:08:48.998| idnsRead: starting with FD 12
2013/09/25 09:08:48.998| idnsRead: FD 12: received 94 bytes from
11.136.15.1:53
2013/09/25 09:08:48.998| idnsGrokReply: ID 0x3243, 0 answers
2013/09/25 09:08:48.998| dns_internal.cc(1143) idnsGrokReply: Sending 0
DNS results to caller.
2013/09/25 09:08:49.261| comm.cc(165) will call
HttpStateData::readReply(FD 24, data=0x7fa5b432dc48, size=435,
buf=0x7fa5b4332680) [call4888554]
2013/09/25 09:08:49.261| entering HttpStateData::readReply(FD 24,
data=0x7fa5b432dc48, size=435, buf=0x7fa5b4332680)
2013/09/25 09:08:49.261| AsyncCall.cc(32) make: make call
HttpStateData::readReply [call4888554]
2013/09/25 09:08:49.261| HttpStateData status in: [ job298503]
2013/09/25 09:08:49.261| httpReadReply: FD 24: len 435.
2013/09/25 09:08:49.261| ctx: enter level 0:
'http://www.uni-leipzig.de/'
2013/09/25 09:08:49.262| processReplyHeader: key
'882E49B7988A3984505D9280607E717C'
2013/09/25 09:08:49.262| Server.cc(136) setVirginReply: 0x7fa5b432dc48
setting virgin reply to 0x7fa5ce7567e0
2013/09/25 09:08:49.262| ctx: exit level 0
2013/09/25 09:08:49.262| Server.cc(819) adaptOrFinalizeReply:
adaptationAccessCheckPending=0
2013/09/25 09:08:49.262| Server.cc(153) setFinalReply: 0x7fa5b432dc48
setting final reply to 0x7fa5ce7567e0
2013/09/25 09:08:49.262| ctx: enter level 0:
'http://www.uni-leipzig.de/'
2013/09/25 09:08:49.262| haveParsedReplyHeaders: HTTP CODE: 302
2013/09/25 09:08:49.262| httpMakeVaryMark:
accept-encoding="gzip,%20deflate"
2013/09/25 09:08:49.262| ctx: exit level 0
2013/09/25 09:08:49.262| http.cc(1309) processReplyBody:
adaptationAccessCheckPending=0
2013/09/25 09:08:49.262| persistentConnStatus: FD 24 eof=0
2013/09/25 09:08:49.262| persistentConnStatus: content_length=212
2013/09/25 09:08:49.262| persistentConnStatus: clen=212
2013/09/25 09:08:49.262| persistentConnStatus: body_bytes_read=212
content_length=212
2013/09/25 09:08:49.262| processReplyBody: COMPLETE_NONPERSISTENT_MSG
2013/09/25 09:08:49.262| Server.cc(169) serverComplete: serverComplete
0x7fa5b432dc48
2013/09/25 09:08:49.262| http.cc(1476) closeServer: closing HTTP server
FD 24 this 0x7fa5b432dc48
2013/09/25 09:08:49.262| Server.cc(194) serverComplete2:
serverComplete2 0x7fa5b432dc48
2013/09/25 09:08:49.262| Server.cc(234) completeForwarding: completing
forwarding for 0x7fa5b4019728*2
2013/09/25 09:08:49.262| Server.cc(225) quitIfAllDone: transaction done
2013/09/25 09:08:49.262| Server.cc(556) cleanAdaptation: cleaning ICAP;
ACL: 0
2013/09/25 09:08:49.262| http.cc(163) ~HttpStateData: HttpStateData
0x7fa5b432dc48 destroyed; FD -1
2013/09/25 09:08:49.262| leaving HttpStateData::readReply(FD 24,
data=0x7fa5b432dc48, size=435, buf=0x7fa5b4332680)
2013/09/25 09:08:49.423| idnsALookup: buf is 39 bytes for
www.zv.uni-leipzig.de, id = 0xbc2b
2013/09/25 09:08:49.423| httpStart: "GET http://www.zv.uni-leipzig.de/";
2013/09/25 09:08:49.423| http.cc(83) HttpStateData: HttpStateData
0x7fa5b432dc48 created
2013/09/25 09:08:49.423| httpSendRequest: FD 24, request
0x7fa5b4024410, this 0x7fa5b432dc48.
2013/09/25 09:08:49.423| The AsyncCall HttpStateData::httpTimeout
constructed, this=0x7fa5ce760b50 [call4888572]
2013/09/25 09:08:49.423| The AsyncCall HttpStateData::readReply
constructed, this=0x7fa5ce761fb0 [call4888573]
2013/09/25 09:08:49.423| The AsyncCall HttpStateData::sendComplete
constructed, this=0x7fa5ce7631e0 [call4888574]
2013/09/25 09:08:49.423| httpBuildRequestHeader: Host:
www.zv.uni-leipzig.de
2013/09/25 09:08:49.424| httpBuildRequestHeader: User-Agent:
Mozilla/5.0 (Windows NT 5.1; rv:24.0) Gecko/20100101 Firefox/24.0
2013/09/25 09:08:49.424| httpBuildRequestHeader: Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
2013/09/25 09:08:49.424| httpBuildRequestHeader: Accept-Language:
de-de,de;q=0.8,en-us;q=0.5,en;q=0.3
2013/09/25 09:08:49.424| httpBuildRequestHeader: Accept-Encoding: gzip,
deflate
2013/09/25 09:08:49.424| httpBuildRequestHeader: DNT: 1
2013/09/25 09:08:49.424| httpBuildRequestHeader: Connection: keep-alive
2013/09/25 09:08:49.424| httpSendRequest: FD 24:
GET http://www.zv.uni-leipzig.de/ HTTP/1.1
Host: www.zv.uni-leipzig.de
User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:24.0) Gecko/20100101
Firefox/24.0
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: de-de,de;q=0.8,en-us;q=0.5,en;q=0.3
Accept-Encoding: gzip, deflate
DNT: 1
Via: 1.1 lav-desproxy.lav.lsa-net.de (squid/3.1.12)
X-Forwarded-For: 11.40.11.223
Cache-Control: max-age=259200
...
In the the wireshark trace file I found, that squid get my http
request, starts a dns query for www.uni-leipzig.de but forwards my
request to the parent proxy before the (useless) answer from the
nameserve returns. This is the first time I see the requests/queries in
this order.
If you can upgrade to a Squid-3.3 version ...
I guess, this is not possible now.
Kind regards
Thomas
