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_...@somewhere.com mail_from custom-sq...@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
_______________________________________________ squid-users mailing list squid-users@lists.squid-cache.org http://lists.squid-cache.org/listinfo/squid-users
