[squid-users] Squid cannot parse Content-Length header value and closes connection before sending body?
Masha Lifshin
mlifshin at phantomdesign.com
Mon May 1 22:12:05 UTC 2017
Dear squid-users mailing list,
Thank you for reading this message and for all your hard work on this great
project.
I have inherited a Squid 3.5.2 install, with ecap, icap, and custom respmod
and reqmod icap services. I am upgrading to Squid 4, adding ssl-bump, and
upgrading c-icap to 0.5.2.
When I run squid without icap (by editing it out of squid.conf), things
work fine and my custom client can load http and https pages. However, for
http, when I turn on icap, squid shuts down the connection early, without
returning the body of the response. It seems it cannot read the content
length header and that messes up both squid and icap. Or is there some
disconnect about the 206 code from icap?
Does anyone know what I can do to further debug or fix this issue?
Debugging info below, (sanitized so you'll see dummy names like
'custom-info'). Let me know if there is anything else I can add.
Thank you again,
-Masha
------------------------------
------------------------------
squid.conf
------------------------------
------------------------------
acl localnet src 10.0.0.0/8 # RFC1918 possible internal network
acl localnet src 172.16.0.0/12 # RFC1918 possible internal network
acl localnet src 192.168.0.0/16 # RFC1918 possible internal network
acl localnet src fc00::/7 # RFC 4193 local private network range
acl localnet src fe80::/10 # RFC 4291 link-local (directly plugged)
machines
acl SSL_ports port 443
acl Safe_ports port 80 # http
acl Safe_ports port 81 # http
acl Safe_ports port 800 # http
acl Safe_ports port 8000 # http
acl Safe_ports port 8080 # http
acl Safe_ports port 21 # ftp
acl Safe_ports port 443 # https
acl Safe_ports port 70 # gopher
acl Safe_ports port 210 # wais
acl Safe_ports port 1025-65535 # unregistered ports
acl Safe_ports port 280 # http-mgmt
acl Safe_ports port 488 # gss-http
acl Safe_ports port 591 # filemaker
acl Safe_ports port 777 # multiling http
acl SSL method CONNECT
acl CONNECT method CONNECT
http_access allow manager to_localhost
http_access deny manager
http_access deny !Safe_ports
http_access deny to_localhost
icp_access deny all
htcp_access deny all
http_port 172.30.0.67:80 <http://172.30.0.67/> ssl-bump
cert=/some/path/etc/ca.pem generate-host-certificates=on
dynamic_cert_mem_cache_size=4MB
http_port 172.30.0.67:443 ssl-bump cert=/some/path/etc/ca.pem
generate-host-certificates=on dynamic_cert_mem_cache_size=4MB
acl step1 at_step SslBump1
ssl_bump peek step1
ssl_bump bump all
sslproxy_cert_error allow all
logformat custom %>a %[ui %{custom-info}>h [%tl] "%rm %ru HTTP/%rv" %>Hs
%<st
access_log stdio:/some/path/var/log/access.log custom
cache_store_log stdio:/some/path/var/log/store.log custom
log_mime_hdrs on
pid_filename /some/path/var/run/custom-squid.pid
coredump_dir /some/path/var/cache
refresh_pattern ^ftp: 1440 20% 10080
refresh_pattern ^gopher: 1440 0% 1440
refresh_pattern -i (/cgi-bin/|\?) 0 0% 0
refresh_pattern . 0 20% 4320
request_header_access Proxy-Authenticate deny all
request_header_access Proxy-Authentication-Info deny all
request_header_access Proxy-Authorization deny all
request_header_access Proxy-Connection deny all
request_header_access Proxy-support deny all
request_header_access custom-client-version deny all
request_header_access custom-watermark deny all
request_header_access custom-info deny all
request_header_access more-custom-info deny all
request_header_access Via deny all
request_header_access X-Cache deny all
request_header_access X-Cache-Lookup deny all
request_header_access X-Forwarded-For deny all
reply_header_access X-XSS-Protection deny all
request_header_access Other allow all
cache_mgr cache_mgr at somewhere.com
mail_from custom-squid at somewhere.com
icap_enable on
icap_preview_enable on
icap_preview_size 1024
icap_default_options_ttl 60
icap_persistent_connections on
icap_send_client_ip on
icap_send_client_username on
icap_client_username_header X-Client-Username
icap_client_username_encode off
ecap_enable on
loadable_modules /some/path/modules/libcustom_ecap.so
ecap_service custom_validate_req reqmod_precache ecap://
somewhere.com/ecap/services/validate routing=on bypass=off
ecap_service custom_validate_resp respmod_precache ecap://
somewhere.com/ecap/services/validate routing=on bypass=off
icap_service custom_req reqmod_precache routing=on icap://
127.0.0.1:1344/custom_req
icap_service custom_resp respmod_precache routing=on icap://
127.0.0.1:1344/custom_resp
forwarded_for delete
adaptation_service_set custom_req_set custom_validate_req custom_req
adaptation_service_set custom_resp_set custom_validate_resp custom_resp
adaptation_access custom_req_set allow all
adaptation_access custom_resp_set allow all
icap_service_failure_limit -1
debug_options ALL,3 44,0 23,0 40,0 73,0 93,3
------------------------------
------------------------------
Abridged cache.log
------------------------------
------------------------------
2017/04/28 08:11:46.958 kid1| 11,2| client_side.cc(1330) parseHttpRequest:
HTTP Client local=172.30.0.67:80 <http://172.30.0.67/> remote=
75.147.129.242:55706 FD 11 flags=1
2017/04/28 08:11:46.958 kid1| 11,2| client_side.cc(1334) parseHttpRequest:
HTTP Client REQUEST:
---------
GET http://example.com/ HTTP/1.1
Host: example.com
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Proxy-Connection: keep-alive
Accept-Language: en-us
custom-info: <snip>
Accept-Encoding: gzip, deflate
another-custom-info: true
more-custom-info: example.com
custom-client-version: iOS-1.0
User-Agent: Mozilla/5.0 (iPhone; CPU iPhone OS 10_3 like Mac OS X)
AppleWebKit/603.1.30 (KHTML, like Gecko) Mobile/14E269 (140606214001632)
Upgrade-Insecure-Requests: 1
Connection: keep-alive
----------
2017/04/28 08:11:46.958 kid1| 33,3| client_side.cc(1366) parseHttpRequest:
complete request received. prefix_sz = 546, request-line-size=34,
mime-header-size=512, mime header block:
Host: example.com
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Proxy-Connection: keep-alive
Accept-Language: en-us
custom-info: <snip>
Accept-Encoding: gzip, deflate
another-custom-info: true
more-custom-info: example.com
custom-client-version: iOS-1.0
User-Agent: Mozilla/5.0 (iPhone; CPU iPhone OS 10_3 like Mac OS X)
AppleWebKit/603.1.30 (KHTML, like Gecko) Mobile/14E269 (140606214001632)
Upgrade-Insecure-Requests: 1
Connection: keep-alive
----------
2017/04/28 08:11:46.958 kid1| 87,3| clientStream.cc(140)
clientStreamInsertHead: clientStreamInsertHead: Inserted node 0x230b5f8
with data 0x2309e58 after head
2017/04/28 08:11:46.958 kid1| 5,3| comm.cc(559) commSetConnTimeout: local=
172.30.0.67:80 <http://172.30.0.67/> remote=75.147.129.242:55706 FD 11
flags=1 timeout 86400
2017/04/28 08:11:46.958 kid1| 33,3| Pipeline.cc(24) add: Pipeline 0x23032c0
add request 1 0x2308df0*4
2017/04/28 08:11:46.958 kid1| 14,3| Address.cc(389) lookupHostIP: Given
Non-IP 'example.com': Name or service not known
2017/04/28 08:11:46.958 kid1| 33,3| client_side.cc(646)
clientSetKeepaliveFlag: http_ver = HTTP/1.1
2017/04/28 08:11:46.958 kid1| 33,3| client_side.cc(647)
clientSetKeepaliveFlag: method = GET
2017/04/28 08:11:46.958 kid1| 85,3| client_side_request.cc(142)
ClientRequestContext: ClientRequestContext constructed, this=0x1e94968
2017/04/28 08:11:46.958 kid1| 83,3| client_side_request.cc(1693)
doCallouts: Doing calloutContext->hostHeaderVerify()
2017/04/28 08:11:46.958 kid1| 85,3| client_side_request.cc(654)
hostHeaderVerify: validate host=example.com, port=0, portStr=NULL
2017/04/28 08:11:46.958 kid1| 85,3| client_side_request.cc(668)
hostHeaderVerify: validate skipped.
2017/04/28 08:11:46.958 kid1| 83,3| client_side_request.cc(1700)
doCallouts: Doing calloutContext->clientAccessCheck()
2017/04/28 08:11:46.958 kid1| 28,3| Checklist.cc(70) preCheck: 0x2310918
checking slow rules
<snip>
2017/04/28 08:11:47.294 kid1| 50,3| comm.cc(350) comm_openex: comm_openex:
Attempt open socket for: 0.0.0.0
2017/04/28 08:11:47.294 kid1| 50,3| comm.cc(393) comm_openex: comm_openex:
Opened socket local=0.0.0.0 remote=[::] FD 15 flags=1 : family=2, type=1,
protocol=6
2017/04/28 08:11:47.294 kid1| 51,3| fd.cc(199) fd_open: fd_open() FD 15
example.com
2017/04/28 08:11:47.294 kid1| 5,3| ConnOpener.cc(289) createFd:
local=0.0.0.0 remote=93.184.216.34:80 <http://93.184.216.34/> flags=1 will
timeout in 60
2017/04/28 08:11:47.295 kid1| 17,3| AsyncCall.cc(93) ScheduleCall:
ConnOpener.cc(137) will call fwdConnectDoneWrapper(local=172.30.0.67:18160
remote=93.184.216.34:80 <http://93.184.216.34/> FD 15 flags=1,
data=0x231bfb8) [call127]
2017/04/28 08:11:47.295 kid1| 17,3| AsyncCallQueue.cc(55) fireNext:
entering fwdConnectDoneWrapper(local=172.30.0.67:18160 remote=
93.184.216.34:80 <http://93.184.216.34/> FD 15 flags=1, data=0x231bfb8)
2017/04/28 08:11:47.295 kid1| 17,3| AsyncCall.cc(38) make: make call
fwdConnectDoneWrapper [call127]
2017/04/28 08:11:47.295 kid1| 17,3| FwdState.cc(681) connectDone: local=
172.30.0.67:18160 remote=93.184.216.34:80 <http://93.184.216.34/> FD 15
flags=1: 'http://example.com/'
2017/04/28 08:11:47.295 kid1| 17,3| FwdState.cc(929) dispatch: local=
172.30.0.67:80 <http://172.30.0.67/> remote=75.147.129.242:55706 FD 11
flags=1: Fetching GET http://example.com/
2017/04/28 08:11:47.295 kid1| 11,3| http.cc(2330) httpStart: GET
http://example.com/
2017/04/28 08:11:47.295 kid1| 20,3| store.cc(457) lock: Client locked key
3400000000000000132A000001000000 e:=p2DIWV/0x231f010*3
2017/04/28 08:11:47.295 kid1| 17,3| AsyncCallQueue.cc(57) fireNext: leaving
fwdConnectDoneWrapper(local=172.30.0.67:18160 remote=93.184.216.34:80
<http://93.184.216.34/> FD 15 flags=1, data=0x231bfb8)
2017/04/28 08:11:47.295 kid1| 5,3| comm.cc(559) commSetConnTimeout: local=
172.30.0.67:18160 remote=93.184.216.34:80 <http://93.184.216.34/> FD 15
flags=1 timeout 86400
2017/04/28 08:11:47.295 kid1| 22,3| refresh.cc(646) getMaxAge: getMaxAge: '
http://example.com/'
2017/04/28 08:11:47.295 kid1| 28,3| Checklist.cc(70) preCheck:
0x7ffdcaef6840 checking fast rules
2017/04/28 08:11:47.295 kid1| 28,3| Ip.cc(540) match: aclIpMatchIp: '
75.147.129.242:55706' found
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked: all = 1
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked:
http_header_access custom-info#1 = 1
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked:
http_header_access custom-info = 1
2017/04/28 08:11:47.295 kid1| 28,3| Checklist.cc(63) markFinished:
0x7ffdcaef6840 answer DENIED for match
2017/04/28 08:11:47.295 kid1| 28,3| Checklist.cc(70) preCheck:
0x7ffdcaef6840 checking fast rules
2017/04/28 08:11:47.295 kid1| 28,3| Ip.cc(540) match: aclIpMatchIp: '
75.147.129.242:55706' found
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked: all = 1
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked:
http_header_access Other#1 = 1
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked:
http_header_access Other = 1
2017/04/28 08:11:47.295 kid1| 28,3| Checklist.cc(63) markFinished:
0x7ffdcaef6840 answer ALLOWED for match
2017/04/28 08:11:47.295 kid1| 28,3| Checklist.cc(70) preCheck:
0x7ffdcaef6840 checking fast rules
2017/04/28 08:11:47.295 kid1| 28,3| Ip.cc(540) match: aclIpMatchIp: '
75.147.129.242:55706' found
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked: all = 1
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked:
http_header_access more-custom-info#1 = 1
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked:
http_header_access more-custom-info = 1
2017/04/28 08:11:47.295 kid1| 28,3| Checklist.cc(63) markFinished:
0x7ffdcaef6840 answer DENIED for match
2017/04/28 08:11:47.295 kid1| 28,3| Checklist.cc(70) preCheck:
0x7ffdcaef6840 checking fast rules
2017/04/28 08:11:47.295 kid1| 28,3| Ip.cc(540) match: aclIpMatchIp: '
75.147.129.242:55706' found
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked: all = 1
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked:
http_header_access custom-client-version#1 = 1
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked:
http_header_access custom-client-version = 1
2017/04/28 08:11:47.295 kid1| 28,3| Checklist.cc(63) markFinished:
0x7ffdcaef6840 answer DENIED for match
2017/04/28 08:11:47.295 kid1| 28,3| Checklist.cc(70) preCheck:
0x7ffdcaef6840 checking fast rules
2017/04/28 08:11:47.295 kid1| 28,3| Ip.cc(540) match: aclIpMatchIp: '
75.147.129.242:55706' found
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked: all = 1
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked:
http_header_access Other#1 = 1
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked:
http_header_access Other = 1
2017/04/28 08:11:47.295 kid1| 28,3| Checklist.cc(63) markFinished:
0x7ffdcaef6840 answer ALLOWED for match
2017/04/28 08:11:47.295 kid1| 28,3| Checklist.cc(70) preCheck:
0x7ffdcaef6840 checking fast rules
2017/04/28 08:11:47.295 kid1| 28,3| Ip.cc(540) match: aclIpMatchIp: '
75.147.129.242:55706' found
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked: all = 1
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked:
http_header_access Via#1 = 1
2017/04/28 08:11:47.295 kid1| 28,3| Acl.cc(290) matches: checked:
http_header_access Via = 1
2017/04/28 08:11:47.295 kid1| 28,3| Checklist.cc(63) markFinished:
0x7ffdcaef6840 answer DENIED for match
2017/04/28 08:11:47.295 kid1| 11,2| http.cc(2286) sendRequest: HTTP Server
local=172.30.0.67:18160 remote=93.184.216.34:80 <http://93.184.216.34/> FD
15 flags=1
2017/04/28 08:11:47.295 kid1| 11,2| http.cc(2287) sendRequest: HTTP Server
REQUEST:
---------
GET / HTTP/1.1
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: en-us
Accept-Encoding: gzip, deflate
another-custom-info: true
User-Agent: Mozilla/5.0 (iPhone; CPU iPhone OS 10_3 like Mac OS X)
AppleWebKit/603.1.30 (KHTML, like Gecko) Mobile/14E269 (140606214001632)
Upgrade-Insecure-Requests: 1
Host: example.com
Cache-Control: max-age=259200
Connection: keep-alive
----------
2017/04/28 08:11:47.295 kid1| 5,3| IoCallback.cc(116) finish: called for
local=172.30.0.67:18160 remote=93.184.216.34:80 <http://93.184.216.34/> FD
15 flags=1 (0, 0)
2017/04/28 08:11:47.295 kid1| 5,3| comm.cc(559) commSetConnTimeout: local=
172.30.0.67:18160 remote=93.184.216.34:80 <http://93.184.216.34/> FD 15
flags=1 timeout 900
2017/04/28 08:11:47.297 kid1| 5,3| IoCallback.cc(116) finish: called for
local=172.30.0.67:18160 remote=93.184.216.34:80 <http://93.184.216.34/> FD
15 flags=1 (0, 0)
2017/04/28 08:11:47.297 kid1| 5,3| Read.cc(92) ReadNow: local=
172.30.0.67:18160 remote=93.184.216.34:80 <http://93.184.216.34/> FD 15
flags=1, size 65536, retval 956, errno 0
2017/04/28 08:11:47.297 kid1| ctx: enter level 0: 'http://example.com/'
2017/04/28 08:11:47.297 kid1| 11,3| http.cc(692) processReplyHeader:
processReplyHeader: key '3400000000000000132A000001000000'
2017/04/28 08:11:47.297 kid1| 11,2| http.cc(743) processReplyHeader: HTTP
Server local=172.30.0.67:18160 remote=93.184.216.34:80
<http://93.184.216.34/> FD 15 flags=1
2017/04/28 08:11:47.297 kid1| 11,2| http.cc(747) processReplyHeader: HTTP
Server RESPONSE:
---------
HTTP/1.1 200 OK
Content-Encoding: gzip
Accept-Ranges: bytes
Cache-Control: max-age=604800
Content-Type: text/html
Date: Fri, 28 Apr 2017 08:09:01 GMT
Etag: "359670651+gzip"
Expires: Fri, 05 May 2017 08:09:01 GMT
Last-Modified: Fri, 09 Aug 2013 23:54:35 GMT
Server: ECS (iad/182A)
Vary: Accept-Encoding
X-Cache: HIT
Content-Length: 606
----------
2017/04/28 08:11:47.297 kid1| 55,2| HttpHeader.cc(1483)
httpHeaderNoteParsedEntry: cannot parse hdr field: 'Content-Length: 606'
2017/04/28 08:11:47.297 kid1| 55,2| HttpHeader.cc(1483)
httpHeaderNoteParsedEntry: cannot parse hdr field: 'Content-Length: 606'
2017/04/28 08:11:47.297 kid1| ctx: exit level 0
2017/04/28 08:11:47.297 kid1| 28,3| Checklist.cc(70) preCheck: 0x2310918
checking slow rules
2017/04/28 08:11:47.297 kid1| 28,3| Ip.cc(540) match: aclIpMatchIp: '
75.147.129.242:55706' found
2017/04/28 08:11:47.297 kid1| 28,3| Acl.cc(290) matches: checked: all = 1
2017/04/28 08:11:47.297 kid1| 28,3| Acl.cc(290) matches: checked:
adaptation_access#1 = 1
2017/04/28 08:11:47.297 kid1| 28,3| Acl.cc(290) matches: checked:
adaptation_access = 1
2017/04/28 08:11:47.298 kid1| 28,3| Checklist.cc(63) markFinished:
0x2310918 answer ALLOWED for match
2017/04/28 08:11:47.298 kid1| 28,3| Checklist.cc(163) checkCallback:
ACLChecklist::checkCallback: 0x2310918 answer=ALLOWED
2017/04/28 08:11:47.298 kid1| 93,3| AccessCheck.cc(196) callBack:
0x1e515e0*2
2017/04/28 08:11:47.298 kid1| 11,3| http.cc(1090) persistentConnStatus:
local=172.30.0.67:18160 remote=93.184.216.34:80 <http://93.184.216.34/> FD
15 flags=1 eof=0
2017/04/28 08:11:47.298 kid1| 5,3| comm.cc(585) commUnsetConnTimeout:
Remove timeout for local=172.30.0.67:18160 remote=93.184.216.34:80
<http://93.184.216.34/> FD 15 flags=1
2017/04/28 08:11:47.298 kid1| 5,3| comm.cc(559) commSetConnTimeout: local=
172.30.0.67:18160 remote=93.184.216.34:80 <http://93.184.216.34/> FD 15
flags=1 timeout -1
2017/04/28 08:11:47.298 kid1| 17,3| FwdState.cc(455) unregister:
http://example.com/
2017/04/28 08:11:47.298 kid1| 48,3| pconn.cc(425) push: new IdleConnList
for {93.184.216.34:80/example.com <http://93.184.216.34/example.com>}
2017/04/28 08:11:47.298 kid1| 5,3| comm.cc(559) commSetConnTimeout: local=
172.30.0.67:18160 remote=93.184.216.34:80 <http://93.184.216.34/> FD 15
flags=1 timeout 60
2017/04/28 08:11:47.298 kid1| 48,3| pconn.cc(437) push: pushed local=
172.30.0.67:18160 remote=93.184.216.34:80 <http://93.184.216.34/> FD 15
flags=1 for 93.184.216.34:80/example.com <http://93.184.216.34/example.com>
2017/04/28 08:11:47.298 kid1| 93,3| Iterator.cc(193) handleAdaptationError:
trying a replacement service
2017/04/28 08:11:47.298 kid1| 93,3| Xaction.cc(101) Xaction:
Adaptation::Icap::ModXact constructed, this=0x231b938 [icapxjob22]
2017/04/28 08:11:47.298 kid1| 93,3| Xaction.cc(101) Xaction:
Adaptation::Icap::OptXact constructed, this=0x231cf78 [icapxjob24]
2017/04/28 08:11:47.298 kid1| 93,3| ServiceRep.cc(140) getConnection: got
connection:
2017/04/28 08:11:47.298 kid1| 93,3| Xaction.cc(188) openConnection:
Adaptation::Icap::OptXact opens connection to 127.0.0.1:1344
2017/04/28 08:11:47.298 kid1| 93,3| AsyncCall.cc(26) AsyncCall: The
AsyncCall Adaptation::Icap::Xaction::noteCommConnected constructed,
this=0x232bd60 [call156]
2017/04/28 08:11:47.298 kid1| 50,3| comm.cc(350) comm_openex: comm_openex:
Attempt open socket for: 0.0.0.0
<snip>
2017/04/28 08:11:47.576 kid1| 93,3| AsyncCall.cc(93) ScheduleCall:
IoCallback.cc(135) will call Adaptation::Icap::Xaction::noteCommRead(local=
127.0.0.1:16810 remote=127.0.0.1:1344 FD 17 flags=1, data=0x231b938)
[call196]
2017/04/28 08:11:47.576 kid1| 93,3| AsyncCallQueue.cc(55) fireNext:
entering Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:16810
remote=127.0.0.1:1344 FD 17 flags=1, data=0x231b938)
2017/04/28 08:11:47.576 kid1| 93,3| AsyncCall.cc(38) make: make call
Adaptation::Icap::Xaction::noteCommRead [call196]
2017/04/28 08:11:47.576 kid1| 93,3| AsyncJob.cc(123) callStart:
Adaptation::Icap::ModXact status in: [FD 17r;RrBG/wP(ieof) job26]
2017/04/28 08:11:47.576 kid1| 5,3| Read.cc(92) ReadNow: local=
127.0.0.1:16810 remote=127.0.0.1:1344 FD 17 flags=1, size 65535, retval
615, errno 0
2017/04/28 08:11:47.576 kid1| 5,3| comm.cc(585) commUnsetConnTimeout:
Remove timeout for local=127.0.0.1:16810 remote=127.0.0.1:1344 FD 17 flags=1
2017/04/28 08:11:47.576 kid1| 5,3| comm.cc(559) commSetConnTimeout: local=
127.0.0.1:16810 remote=127.0.0.1:1344 FD 17 flags=1 timeout -1
2017/04/28 08:11:47.576 kid1| 93,3| Xaction.cc(486) noteCommRead: read 615
bytes
2017/04/28 08:11:47.576 kid1| 55,2| HttpHeader.cc(1483)
httpHeaderNoteParsedEntry: cannot parse hdr field: 'Content-Length: 606'
2017/04/28 08:11:47.576 kid1| 55,2| HttpHeader.cc(1483)
httpHeaderNoteParsedEntry: cannot parse hdr field: 'Content-Length: 606'
2017/04/28 08:11:47.576 kid1| 91,2| BodyPipe.cc(489) ~BodyPipeCheckout:
Warning: cannot undo BodyPipeCheckout
2017/04/28 08:11:47.576 kid1| 93,3| ../../../src/base/AsyncJobCalls.h(177)
dial: Adaptation::Icap::Xaction::noteCommRead threw exception: garbage
instead of CRLF line terminator
2017/04/28 08:11:47.576 kid1| 93,3| Xaction.cc(591) setOutcome: Warning:
reseting outcome: from ICAP_MOD to ICAP_ERR_OTHER
2017/04/28 08:11:47.576 kid1| 93,2| AsyncJob.cc(129) callException: garbage
instead of CRLF line terminator
2017/04/28 08:11:47.576 kid1| 93,3| ServiceRep.cc(155) putConnection:
RST-closing [FD 17;rp(2)6/RwP(ieof)S job26]
2017/04/28 08:11:47.576 kid1| 5,3| comm.cc(865) _comm_close: comm_close:
start closing FD 17
2017/04/28 08:11:47.576 kid1| 5,3| comm.cc(546) commUnsetFdTimeout: Remove
timeout for FD 17
2017/04/28 08:11:47.576 kid1| 93,3| Xaction.cc(112) ~Xaction:
Adaptation::Icap::ModXact destructed, this=0x231b938 [icapxjob26]
2017/04/28 08:11:47.576 kid1| 93,3| AsyncCallQueue.cc(57) fireNext: leaving
Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:16810 remote=
127.0.0.1:1344 flags=1, data=0x231b938)
2017/04/28 08:11:47.576 kid1| 51,3| fd.cc(94) fd_close: fd_close FD 17
127.0.0.1
2017/04/28 08:11:47.576 kid1| 20,3| store.cc(1853) replaceHttpReply:
StoreEntry::replaceHttpReply: http://example.com/
2017/04/28 08:11:47.576 kid1| ctx: enter level 0: 'http://example.com/'
2017/04/28 08:11:47.576 kid1| 11,3| http.cc(934) haveParsedReplyHeaders:
HTTP CODE: 200
2017/04/28 08:11:47.576 kid1| 20,3| Controller.cc(306) find:
5C9109034C1D089FB6D92F7258B2F5C3
<snip>
2017/04/28 08:11:47.576 kid1| 20,3| store_key_md5.cc(133)
storeKeyPublicByRequestMethod: updating public key by vary headers:
accept-encoding="gzip,%20deflate" for: http://example.com/
2017/04/28 08:11:47.577 kid1| 20,3| store.cc(421) hashInsert:
StoreEntry::hashInsert: Inserting Entry e:=p2DV/0x231f010*3 key
'6E5F80FC98AEE5F58F47899D580B6430'
2017/04/28 08:11:47.577 kid1| ctx: exit level 0
2017/04/28 08:11:47.577 kid1| 90,3| store_client.cc(729) invokeHandlers:
InvokeHandlers: 6E5F80FC98AEE5F58F47899D580B6430
2017/04/28 08:11:47.577 kid1| 90,3| store_client.cc(735) invokeHandlers:
StoreEntry::InvokeHandlers: checking client #0
2017/04/28 08:11:47.577 kid1| 90,3| store_client.cc(295) storeClientCopy2:
storeClientCopy2: 6E5F80FC98AEE5F58F47899D580B6430
2017/04/28 08:11:47.577 kid1| 90,3| store_client.cc(429) scheduleMemRead:
store_client::doCopy: Copying normal from memory
2017/04/28 08:11:47.577 kid1| 55,2| HttpHeader.cc(1483)
httpHeaderNoteParsedEntry: cannot parse hdr field: 'Content-Length: 606'
2017/04/28 08:11:47.577 kid1| 55,2| HttpHeader.cc(1483)
httpHeaderNoteParsedEntry: cannot parse hdr field: 'Content-Length: 606'
2017/04/28 08:11:47.577 kid1| 88,2| client_side_reply.cc(2084)
processReplyAccessResult: The reply for GET http://example.com/ is ALLOWED,
because it matched all
2017/04/28 08:11:47.577 kid1| 20,3| store.cc(457) lock:
ClientHttpRequest::loggingEntry locked key 6E5F80FC98AEE5F58F47899D580B6430
e:=p2DV/0x231f010*4
2017/04/28 08:11:47.577 kid1| 88,3| client_side_reply.cc(2122)
processReplyAccessResult: clientReplyContext::sendMoreData: Appending 0
bytes after 440 bytes of headers
2017/04/28 08:11:47.577 kid1| 87,3| clientStream.cc(158)
clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0x2309e58
from node 0x2307b28
2017/04/28 08:11:47.577 kid1| 33,3| Pipeline.cc(35) front: Pipeline
0x23032c0 front 0x2308df0*3
2017/04/28 08:11:47.577 kid1| 33,3| Pipeline.cc(35) front: Pipeline
0x23032c0 front 0x2308df0*3
2017/04/28 08:11:47.577 kid1| 11,2| Stream.cc(266) sendStartOfMessage: HTTP
Client local=172.30.0.67:80 <http://172.30.0.67/> remote=
75.147.129.242:55706 FD 11 flags=1
2017/04/28 08:11:47.577 kid1| 11,2| Stream.cc(267) sendStartOfMessage: HTTP
Client REPLY:
---------
HTTP/1.1 200 OK
Content-Encoding: gzip
Accept-Ranges: bytes
Cache-Control: max-age=604800
Content-Type: text/html
Date: Fri, 28 Apr 2017 08:09:01 GMT
ETag: "359670651+gzip"
Expires: Fri, 05 May 2017 08:09:01 GMT
Last-Modified: Fri, 09 Aug 2013 23:54:35 GMT
Server: ECS (iad/182A)
Vary: Accept-Encoding
X-Cache: HIT
Content-Length: 606
still-more-custom-info: ignore-value
X-Cache: MISS from ip-172-30-0-67.ec2.internal
X-Cache-Lookup: MISS from ip-172-30-0-67.ec2.internal:80
Via: ICAP/1.0 localhost (C-ICAP/0.5.2 Custom Response Module ), 1.1
ip-172-30-0-67.ec2.internal (squid/4.0.17)
Connection: keep-alive
----------
2017/04/28 08:11:47.577 kid1| 20,3| store.cc(1081) lengthWentBad: because
body adaptation aborted: e:=p2DV/0x231f010*4
2017/04/28 08:11:47.577 kid1| 20,3| store.cc(472) setReleaseFlag:
StoreEntry::setReleaseFlag: '6E5F80FC98AEE5F58F47899D580B6430'
2017/04/28 08:11:47.577 kid1| 20,3| store.cc(421) hashInsert:
StoreEntry::hashInsert: Inserting Entry e:=p2XDIVL/0x231f010*4 key
'3600000000000000132A000001000000'
2017/04/28 08:11:47.577 kid1| 17,3| FwdState.cc(481) complete:
http://example.com/
status 200
2017/04/28 08:11:47.577 kid1| 17,3| FwdState.cc(1067) reforward:
http://example.com/?
2017/04/28 08:11:47.577 kid1| 17,3| FwdState.cc(1070) reforward: No,
ENTRY_FWD_HDR_WAIT isn't set
2017/04/28 08:11:47.577 kid1| 17,3| FwdState.cc(505) complete: server (FD
closed) not re-forwarding status 200
2017/04/28 08:11:47.577 kid1| 20,3| store.cc(1089) complete: storeComplete:
'3600000000000000132A000001000000'
2017/04/28 08:11:47.577 kid1| 20,2| store.cc(990) checkCachable:
StoreEntry::checkCachable: NO: not cachable
2017/04/28 08:11:47.577 kid1| 90,3| store_client.cc(729) invokeHandlers:
InvokeHandlers: 3600000000000000132A000001000000
2017/04/28 08:11:47.577 kid1| 90,3| store_client.cc(735) invokeHandlers:
StoreEntry::InvokeHandlers: checking client #0
2017/04/28 08:11:47.577 kid1| 90,3| store_client.cc(755)
storePendingNClients: storePendingNClients: returning 1
2017/04/28 08:11:47.577 kid1| 20,3| store.cc(494) unlock: Client unlocking
key 3600000000000000132A000001000000 e:=sp2XDIVL/0x231f010*4
2017/04/28 08:11:47.577 kid1| 17,3| FwdState.cc(274) ~FwdState: FwdState
destructor start
2017/04/28 08:11:47.577 kid1| 20,3| store.cc(494) unlock: FwdState
unlocking key 3600000000000000132A000001000000 e:=sp2XDIVL/0x231f010*3
2017/04/28 08:11:47.577 kid1| 17,3| AsyncCall.cc(56) cancel: will not call
fwdConnectDoneWrapper [call127] because FwdState destructed
2017/04/28 08:11:47.577 kid1| 17,3| FwdState.cc(301) ~FwdState: FwdState
destructed, this=0x231bfb8
2017/04/28 08:11:47.577 kid1| 5,3| IoCallback.cc(116) finish: called for
local=172.30.0.67:80 <http://172.30.0.67/> remote=75.147.129.242:55706 FD
11 flags=1 (0, 0)
2017/04/28 08:11:47.577 kid1| 33,3| Pipeline.cc(35) front: Pipeline
0x23032c0 front 0x2308df0*2
2017/04/28 08:11:47.577 kid1| 88,3| client_side_reply.cc(1172)
storeOKTransferDone: storeOKTransferDone out.offset=0 objectLen()=440
headers_sz=440
2017/04/28 08:11:47.577 kid1| 5,3| comm.cc(865) _comm_close: comm_close:
start closing FD 11
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20170501/8fe5a98f/attachment-0001.html>
More information about the squid-users
mailing list