squid ssl bump and Adobe Connect

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

squid ssl bump and Adobe Connect

Vieri
Hi,


I'm reposting this message because my previous email was too big.


I'm unable to connect to Adobe Connect through Squid TPROXY.

The URL is:

https://emeacmsd.acms.com/common/help/en/support/meeting_test.htm

# grep -v ^# squid.test.conf | grep -v ^$
http_access allow localhost manager
http_access deny manager
http_port 3227
http_port 3228 tproxy
https_port 3229 tproxy ssl-bump generate-host-certificates=on dynamic_cert_mem_cache_size=16MB cert=/etc/ssl/squid/proxyserver.pem
acl localnet src 10.0.0.0/8     # 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 interceptedhttp myportname 3228
acl interceptedhttps myportname 3229
http_access deny interceptedhttp !localnet
http_access deny interceptedhttps !localnet
sslcrtd_program /usr/libexec/squid/ssl_crtd -s /var/lib/squid/ssl_db_test -M 16MB
sslcrtd_children 10
reply_header_access Alternate-Protocol deny all
ssl_bump stare all
ssl_bump bump all
cache_dir diskd /var/cache/squid.test 100 16 256
http_access allow localnet
http_access allow localhost
http_access deny all
coredump_dir /var/cache/squid
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
pid_filename /run/squid.test.pid
access_log daemon:/var/log/squid/access.test.log squid
cache_log /var/log/squid/cache.test.log
debug_options rotate=1 ALL,5

# cat /var/log/squid/access.test.log

1496665078.340    223 10.215.145.187 TAG_NONE/200 0 CONNECT 216.58.201.142:443 - ORIGINAL_DST/216.58.201.142 -
1496665079.387   1003 10.215.145.187 TCP_MISS/200 4623 POST https://safebrowsing.google.com/safebrowsing/downloads? - ORIGINAL_DST/216.58.201.142 application/vnd.google.safebrowsing-update
1496665080.000    541 10.215.145.187 TAG_NONE/200 0 CONNECT 216.58.211.238:443 - ORIGINAL_DST/216.58.211.238 -
1496665080.129     85 10.215.145.187 TCP_MISS/200 550 GET https://safebrowsing-cache.google.com/safebrowsing/rd/ChVnb29nLWJhZGJpbnVybC1zaGF2YXI4AEACSgwIABCD9QcYg_UHIAE - ORIGINAL_DST/216.58.211.238 application/vnd.google.safebrowsing-chunk
1496665080.241    107 10.215.145.187 TCP_MISS/200 3069 GET https://safebrowsing-cache.google.com/safebrowsing/rd/ChNnb29nLW1hbHdhcmUtc2hhdmFyOABAAkoMCAEQy4YQGMuGECABSgwIARC3hhAYt4YQIAFKDAgBEKOFEBijhRAgAUoMCAEQ2IMQGNiDECABSgwIARCEghAYhIIQIAFKDAgBEOv5Dxjr-Q8gAUoMCAEQ9ugPGPboDyABSgwIARDg6A8Y4OgPIAFKDAgBEI3cDxiN3A8gAUoMCAEQitsPGIrbDyABSgwIARD42g8Y-NoPIAFKDAgBEITaDxiF2g8gAUoMCAEQ9NYPGPTWDyABSgwIARCc1Q8YnNUPIAFKDAgBELHLDxixyw8gAUoMCAEQmMoPGJjKDyABSgwIARDLyQ8Yy8kPIAFKDAgBEN7EDxjexA8gAUoMCAEQyb4PGMm-DyABSgwIARCkug8YpLoPIAFKDAgBEIG5DxiBuQ8gAUoMCAEQ-bgPGPm4DyABSgwIARC1uA8YtbgPIAFKDAgBEIq3DxiKtw8gAUoMCAEQobYPGKG2DyABSgwIARCDtg8Yg7YPIAFKDAgBEJa1DxiWtQ8gAUoMCAEQ07QPGNO0DyABSgwIARDGsw8YxrMPIAFKDAgBENuyDxjbsg8gAUoMCAEQmrIPGJqyDyABSgwIARD5sQ8Y-bEPIAFKDAgBEOuxDxjrsQ8gAUoQCAAQltUPGJ3VDyABKgIBBg - ORIGINAL_DST/216.58.211.238 application/vnd.google.safebrowsing-chunk
1496665080.711    466 10.215.145.187 TCP_MISS/200 186018 GET https://safebrowsing-cache.google.com/safebrowsing/rd/ChNnb29nLW1hbHdhcmUtc2hhdmFyOABAAkoMCAAQvqgQGL6oECABSiQIABCC2Q8YnNsPIAEqFsUBxgHkAegB9gH3AfgB-QH7Af0BgwI - ORIGINAL_DST/216.58.211.238 application/vnd.google.safebrowsing-chunk
1496665081.067    355 10.215.145.187 TCP_MISS/200 185194 GET https://safebrowsing-cache.google.com/safebrowsing/rd/ChNnb29nLW1hbHdhcmUtc2hhdmFyOABAAkp_CAAQntUPGIHZDyABKnEICQoLDBIkLzxCUFJeX2BhZmhqbG5ydnx9mwGqAbEBtAG4AbsBwAHBAcIB6AHuAfAB9gH5AY4CwwLJAs0C3gLhAuIC5ALmAusC7QLuAvAC8QLyAv4C_wKEA4gDigOLA5IDmQOaA5sDpQOoA6kDqwOtAw - ORIGINAL_DST/216.58.211.238 application/vnd.google.safebrowsing-chunk
1496665081.263    193 10.215.145.187 TCP_MISS/200 36504 GET https://safebrowsing-cache.google.com/safebrowsing/rd/ChFnb29nLXBoaXNoLXNoYXZhcjgAQAJKDAgBEMrlExjK5RMgAUoMCAEQueMTGLnjEyABSgwIARCR4xMYkuMTIAFKDAgBEOHiExji4hMgAUoMCAEQz-ITGNLiEyABSgwIARDL4hMYzeITIAFKDAgBEP_hExiD4hMgAUoMCAEQ9-ETGP3hEyABSgwIARDk4RMY9OETIAFKDAgBEM7hExji4RMgAUoMCAEQit4TGIreEyABSgwIARDZ2hMY2doTIAFKDAgBELLZExiy2RMgAUoMCAEQ1NgTGNTYEyABSgwIARCy1RMYuNUTIAFKDAgBEMLUExjE1BMgAUoMCAEQjdQTGI3UEyABSgwIARC-0RMYvtETIAFKDAgBELzRExi80RMgAUoMCAEQstETGLPREyABSgwIARCo0RMYqNETIAFKDAgBEOjQExjo0BMgAUoMCAEQ5NATGOTQEyABSgwIARCd0BMYntATIAFKDAgBEObPExjmzxMgAUoMCAEQ288TGNvPEyABSgwIARDGzxMY0M8TIAFKDAgBELvPExjDzxMgAUoMCAEQqM8TGKjPEyABSgwIARCVzxMYlc8TIAFKDAgBEJHPExiRzxMgAUoMCAEQ684TGO7OEyABSgwIARDazhMY584TIAFKDAgBEM_OExjTzhMgAUoMCAEQns4TGJ7OEyABSgwIARDYzRMY2M0TIAFKDAgBELzNExi8zRMgAUoMCAEQ8MwTGPDMEyABSgwIARDtzBMY7cwTIAFKDAgBEOjMExjrzBMgAUoMCAEQ4cwTGOTMEyABSgwIARDfzBMY38wTIAFKDAgBENfMExjYzBMgAUoMCAEQ08wTGNPMEyABSgwIARDPzBMYz8wTIAFKDAgBEM3MExjNzBMgAUoMCAEQv8wTGL_MEyABSgwIARC9zBMYvcwTIAFKDAgBELvMExi7zBMgAUoMCAEQuMwTGLjMEyABSgwIARCyzBMYsswTIAFKDAgBEK3MExiuzBMgAUoMCAEQpswTGKbMEyABSgwIARCWzBMYlswTIAFKDAgBEIrMExiKzBMgAUoMCAEQ_8sTGP_LEyABSgwIARD6yxMY-ssTIAFKDAgBEPfLExj4yxMgAUoMCAEQ88sTGPPLEyABSgwIARDryxMY68sTIAFKDAgBEObLExjnyxMgAUoMCAEQ2csTGNnLEyABSgwIARDPyxMYz8sTIAFKDAgBEL3LExi9yxMgAUoMCAEQu8sTGLvLEyABSgwIARC2yxMYt8sTIAFKDAgBEKLLExiiyxMgAUoMCAEQoMsTGKDLEyABSgwIARCdyxMYncsTIAFKDAgBEJnLExiZyxMgAUoMCAEQjMsTGI3LEyABSgwIARCByxMYiMsTIAFKDAgBEPvKExj-yhMgAUoMCAEQ6soTGPnKEyABSgwIARDnyhMY58oTIAFKDAgBEOLKExjiyhMgAUoMCAEQ1soTGODKEyABSgwIARDOyhMYzsoTIAFKDAgBEMfKExjHyhMgAUoMCAEQxcoTGMXKEyABSgwIARC9yhMYvcoTIAFKDAgBELrKExi6yhMgAUoMCAEQsMoTGLHKEyABSgwIARCsyhMYrMoTIAFKDAgBEKrKExiqyhMgAUoMCAEQosoTGKLKEyABSgwIARCLyhMYi8oTIAFKDAgBEIDKExiAyhMgAUoMCAEQ-8kTGPzJEyABSgwIARD3yRMY-MkTIAFKDAgBEO3JExjyyRMgAUoMCAEQ6ckTGOnJEyABSgwIARDjyRMY48kTIAFKDAgBEN7JExjfyRMgAUoMCAEQ18kTGNjJEyABSgwIARDUyRMY1MkTIAFKDAgBENHJExjRyRMgAUoMCAEQzckTGM3JEyABSgwIARDGyRMYyMkTIAFKDAgBEMLJExjCyRMgAUoMCAEQvskTGL7JEyAB - ORIGINAL_DST/216.58.211.238 application/vnd.google.safebrowsing-chunk
1496665081.389    123 10.215.145.187 TCP_MISS/200 10706 GET https://safebrowsing-cache.google.com/safebrowsing/rd/ChFnb29nLXBoaXNoLXNoYXZhcjgAQAJKDAgBELnJExi5yRMgAUoMCAEQt8kTGLfJEyABSgwIARCzyRMYs8kTIAFKDAgBELHJExixyRMgAUoMCAEQr8kTGK_JEyABSgwIARCnyRMYp8kTIAFKDAgBEKTJExikyRMgAUoMCAEQmskTGKHJEyABSgwIARCYyRMYmMkTIAFKDAgBEJHJExiSyRMgAUoMCAEQjskTGI7JEyABSgwIARCGyRMYi8kTIAFKDAgBEITJExiEyRMgAUoMCAEQgskTGILJEyABSgwIARCAyRMYgMkTIAFKDAgBEOvIExjryBMgAUoMCAEQ5cgTGObIEyABSgwIARDgyBMY4MgTIAFKDAgBENHIExjRyBMgAUoMCAEQzsgTGM_IEyAB - ORIGINAL_DST/216.58.211.238 application/vnd.google.safebrowsing-chunk
1496665081.812    419 10.215.145.187 TCP_MISS/200 189122 GET https://safebrowsing-cache.google.com/safebrowsing/rd/ChFnb29nLXBoaXNoLXNoYXZhcjgAQAJKDAgAEIKqHRiCqh0gAUoMCAAQ1JsdGJ2dHSAB - ORIGINAL_DST/216.58.211.238 application/vnd.google.safebrowsing-chunk
1496665082.104    290 10.215.145.187 TCP_MISS/200 192024 GET https://safebrowsing-cache.google.com/safebrowsing/rd/ChFnb29nLXBoaXNoLXNoYXZhcjgAQAJKEAgAEJyaHRjTmx0gASoCrwE - ORIGINAL_DST/216.58.211.238 application/vnd.google.safebrowsing-chunk
1496665082.406    298 10.215.145.187 TCP_MISS/200 190496 GET https://safebrowsing-cache.google.com/safebrowsing/rd/ChFnb29nLXBoaXNoLXNoYXZhcjgAQAJKDAgAEM-YHRibmh0gAQ - ORIGINAL_DST/216.58.211.238 application/vnd.google.safebrowsing-chunk
1496665082.678    263 10.215.145.187 TCP_MISS/200 191042 GET https://safebrowsing-cache.google.com/safebrowsing/rd/ChFnb29nLXBoaXNoLXNoYXZhcjgAQAJKDAgAEN6WHRjOmB0gAQ - ORIGINAL_DST/216.58.211.238 application/vnd.google.safebrowsing-chunk
1496665085.543    124 10.215.145.187 TCP_MISS/200 7481 GET https://emeacmsd.acms.com/common/help/en/support/css/globalnav.css - ORIGINAL_DST/54.247.125.57 text/html
1496665085.717    292 10.215.145.187 TAG_NONE/200 0 CONNECT 46.137.190.100:443 - ORIGINAL_DST/46.137.190.100 -
1496665086.800    751 10.215.145.187 TCP_MISS/200 493387 GET https://emeacmsd.acms.com/common/intro/test.swf - ORIGINAL_DST/54.247.125.57 application/x-shockwave-flash
1496665087.217    114 10.215.145.187 TCP_MISS/200 1433 GET https://emeacmsd.acms.com/common/AddInInfo.xml - ORIGINAL_DST/54.247.125.57 application/xml
1496665087.404    113 10.215.145.187 TCP_MISS/200 407 POST https://emeacmsd.acms.com/messagebroker/amf - ORIGINAL_DST/54.247.125.57 application/x-amf
1496665088.098    472 10.215.145.187 TAG_NONE/200 0 CONNECT 46.51.187.18:443 - ORIGINAL_DST/46.51.187.18 -
1496665088.143      6 10.215.145.187 TAG_NONE/400 4428 NONE error:invalid-request - HIER_NONE/- text/html
1496665177.661    209 10.215.145.187 TCP_MISS/200 324 POST https://emeacmsd.acms.com/messagebroker/amf - ORIGINAL_DST/54.247.125.57 application/x-amf

Note the "error:invalid-request" message.

# cat /var/log/squid/cache.test.log (part of it)

---------
HTTP/1.1 200 OK
Accept-Ranges: bytes
Cache-Control: max-age=3600
Content-Type: application/x-shockwave-flash
Date: Mon, 05 Jun 2017 12:18:05 GMT
Last-Modified: Wed, 16 Sep 2015 16:36:14 GMT
Server: Apache-Coyote/1.1
Set-Cookie: BreezeCCookie=FDYC-UW78-J9K9-SZ93-YUQP-F4B4-ZRNY-UVXE; Path=/; Secure; HttpOnly
X-Breeze-Cache: appserv/common/intro/test.swf
X-Breeze-Public-Map: /common/,appserv/common/
Content-Length: 492826
X-Cache: MISS from inf-fw1
X-Cache-Lookup: MISS from inf-fw1:3227
Via: 1.1 inf-fw1 (squid/3.5.14)
Connection: keep-alive


----------
2017/06/05 14:18:06.175 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall clientWriteComplete constructed, this=0x80e081e8 [call2315]
2017/06/05 14:18:06.175 kid1| 5,5| Write.cc(35) Write: local=54.247.125.57:443 remote=10.215.145.187 FD 13 flags=17: sz 561: asynCall 0x80e081e8*1
2017/06/05 14:18:06.175 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=2, handler=1, client_data=0x808b43a0, timeout=0
2017/06/05 14:18:06.175 kid1| 11,5| http.cc(1399) processReplyBody: adaptationAccessCheckPending=0
2017/06/05 14:18:06.175 kid1| 20,5| store.cc(834) write: storeWrite: writing 8192 bytes for 'B04729E56EF0FD97349B176C475C4F1B'
2017/06/05 14:18:06.175 kid1| 20,3| store_swapout.cc(376) mayStartSwapOut: already allowed
2017/06/05 14:18:06.175 kid1| 20,5| store_swapout.cc(47) storeSwapOutStart: storeSwapOutStart: Begin SwapOut 'https://emeacmsd.acms.com/common/intro/test.swf' to dirno -1, fileno FFFFFFFF
2017/06/05 14:18:06.175 kid1| 73,3| HttpRequest.cc(689) storeId: sent back canonicalUrl:https://emeacmsd.acms.com/common/intro/test.swf
2017/06/05 14:18:06.175 kid1| 20,3| store_swapmeta.cc(54) storeSwapMetaBuild: storeSwapMetaBuild URL: https://emeacmsd.acms.com/common/intro/test.swf
2017/06/05 14:18:06.175 kid1| 20,2| store_io.cc(42) storeCreate: storeCreate: Selected dir 0 for e:=w1p2DV/0x80d8d2e8*4
2017/06/05 14:18:06.175 kid1| 79,3| ufs/UFSStrategy.cc(100) create: fileno 0000002D
2017/06/05 14:18:06.175 kid1| 79,3| DiskIO/DiskDaemon/DiskdFile.cc(40) DiskdFile: DiskdFile::DiskdFile: /var/cache/squid.test/00/00/0000002D
2017/06/05 14:18:06.175 kid1| 79,3| DiskIO/DiskDaemon/DiskdFile.cc(86) create: DiskdFile::create: 0x80e08bf0 creating for 0x80e0585c
2017/06/05 14:18:06.175 kid1| 47,4| ufs/UFSSwapDir.cc(1206) replacementAdd: added node 0x80d8d2e8 to dir 0
2017/06/05 14:18:06.175 kid1| 20,3| store.cc(484) lock: storeSwapOutStart locked key B04729E56EF0FD97349B176C475C4F1B e:=w1p2DV/0x80d8d2e8*5
2017/06/05 14:18:06.175 kid1| 79,3| ufs/UFSStoreState.cc(161) write: UFSStoreState::write: dirn 0, fileno 0000002D
2017/06/05 14:18:06.175 kid1| 79,3| ufs/UFSStoreState.cc(469) queueWrite: 0x80e05828 UFSStoreState::queueWrite: queueing write of size 125
2017/06/05 14:18:06.175 kid1| 79,3| ufs/UFSStoreState.cc(184) doWrite: 0x80e05828 UFSStoreState::doWrite
2017/06/05 14:18:06.175 kid1| 79,3| ufs/UFSStoreState.cc(219) doWrite: 0x80e05828 calling theFile->write(125)
2017/06/05 14:18:06.175 kid1| 79,3| DiskIO/DiskDaemon/DiskdFile.cc(278) write: DiskdFile::write: this 0x80e08bf0, buf 0x80e05480, off 0, len 125
2017/06/05 14:18:06.175 kid1| 20,3| store_swapout.cc(132) doPages: storeSwapOut: swap_buf_len = 4096
2017/06/05 14:18:06.175 kid1| 20,3| store_swapout.cc(136) doPages: storeSwapOut: swapping out 4096 bytes from 0
2017/06/05 14:18:06.175 kid1| 79,3| ufs/UFSStoreState.cc(161) write: UFSStoreState::write: dirn 0, fileno 0000002D
2017/06/05 14:18:06.175 kid1| 79,3| ufs/UFSStoreState.cc(469) queueWrite: 0x80e05828 UFSStoreState::queueWrite: queueing write of size 4096
2017/06/05 14:18:06.175 kid1| 79,3| ufs/UFSStoreState.cc(184) doWrite: 0x80e05828 UFSStoreState::doWrite
2017/06/05 14:18:06.175 kid1| 79,3| ufs/UFSStoreState.cc(219) doWrite: 0x80e05828 calling theFile->write(4096)
2017/06/05 14:18:06.175 kid1| 79,3| DiskIO/DiskDaemon/DiskdFile.cc(278) write: DiskdFile::write: this 0x80e08bf0, buf 0x80daa56c, off -1, len 4096
2017/06/05 14:18:06.175 kid1| 20,3| store_swapout.cc(132) doPages: storeSwapOut: swap_buf_len = 4096
2017/06/05 14:18:06.175 kid1| 20,3| store_swapout.cc(136) doPages: storeSwapOut: swapping out 4096 bytes from 4096
2017/06/05 14:18:06.175 kid1| 79,3| ufs/UFSStoreState.cc(161) write: UFSStoreState::write: dirn 0, fileno 0000002D
2017/06/05 14:18:06.175 kid1| 79,3| ufs/UFSStoreState.cc(469) queueWrite: 0x80e05828 UFSStoreState::queueWrite: queueing write of size 4096
2017/06/05 14:18:06.176 kid1| 79,3| ufs/UFSStoreState.cc(184) doWrite: 0x80e05828 UFSStoreState::doWrite
2017/06/05 14:18:06.176 kid1| 79,3| ufs/UFSStoreState.cc(219) doWrite: 0x80e05828 calling theFile->write(4096)
2017/06/05 14:18:06.176 kid1| 79,3| DiskIO/DiskDaemon/DiskdFile.cc(278) write: DiskdFile::write: this 0x80e08bf0, buf 0x80da954c, off -1, len 4096
2017/06/05 14:18:06.176 kid1| 90,3| store_client.cc(732) invokeHandlers: InvokeHandlers: B04729E56EF0FD97349B176C475C4F1B
2017/06/05 14:18:06.176 kid1| 90,3| store_client.cc(738) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0
2017/06/05 14:18:06.176 kid1| 11,3| http.cc(1054) persistentConnStatus: local=10.215.145.187:60291 remote=54.247.125.57:443 FD 15 flags=25 eof=0
2017/06/05 14:18:06.176 kid1| 11,5| http.cc(1074) persistentConnStatus: persistentConnStatus: content_length=492826
2017/06/05 14:18:06.176 kid1| 11,5| http.cc(1078) persistentConnStatus: persistentConnStatus: clen=492826
2017/06/05 14:18:06.176 kid1| 11,5| http.cc(1091) persistentConnStatus: persistentConnStatus: body_bytes_read=8192 content_length=492826
2017/06/05 14:18:06.176 kid1| 11,5| http.cc(1428) processReplyBody: processReplyBody: INCOMPLETE_MSG from local=10.215.145.187:60291 remote=54.247.125.57:443 FD 15 flags=25

Any ideas?

Vieri
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: squid ssl bump and Adobe Connect

Alex Rousskov
On 06/05/2017 06:49 AM, Vieri wrote:

> 1496665088.143      6 10.215.145.187 TAG_NONE/400 4428 NONE error:invalid-request - HIER_NONE/- text/html

> Any ideas?

I recommend finding the place in the debugging cache.log where Squid
generates the above error response and then going backwards to find the
cause. Please note that this error may not be the reason you cannot
connect to Adobe Connect, but if it is the only red flag, it is worth
investigating.

Logging the source port of the client connection to access.log can help
you narrow down your search.

In general, copy-pasting debugging cache.logs here is rarely useful
_unless_ you isolate the problematic lines first. If you cannot isolate
those lines, post a link to a compressed full log. In fact, posting such
a link is a good idea even if you copy-paste (what you think are) the
relevant lines here.


HTH,

Alex.
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: squid ssl bump and Adobe Connect

Vieri
________________________________
From: Alex Rousskov <[hidden email]>
>

>> 1496665088.143      6 10.215.145.187 TAG_NONE/400 4428 NONE error:invalid-request - HIER_NONE/-

>> text/html>
> I recommend finding the place in the debugging cache.log where Squid

> generates the above error response and then going backwards to find the
> cause.

OK Alex, got it.
In the meantime, I searched for the events around the time this happened.
BTW as a side question I'd like to know if I can change the timestamp in cache.log so it can print the unixtime as in access.log.

In any case, here's the relevant part:

[Mon Jun  5 14:18:08 2017].143      6 10.215.145.187 TAG_NONE/400 4428 NONE error:invalid-request - HIER_NONE/- text/html

cache.log within 14:18:08:

2017/06/05 14:18:08 kid1| hold write on SSL connection on FD 30
2017/06/05 14:18:08.000 kid1| 28,3| Checklist.cc(70) preCheck: 0x80d21df8 checking slow rules
2017/06/05 14:18:08.000 kid1| 28,5| Acl.cc(138) matches: checking (ssl_bump rules)
2017/06/05 14:18:08.000 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'ALLOWED/4 is  banned
2017/06/05 14:18:08.000 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'ALLOWED/5is not banned
2017/06/05 14:18:08.000 kid1| 28,5| Acl.cc(138) matches: checking (ssl_bump rule)
2017/06/05 14:18:08.000 kid1| 28,5| Acl.cc(138) matches: checking all
2017/06/05 14:18:08.000 kid1| 28,3| Ip.cc(539) match: aclIpMatchIp: '10.215.145.187' found
2017/06/05 14:18:08.000 kid1| 28,3| Acl.cc(158) matches: checked: all = 1
2017/06/05 14:18:08.000 kid1| 28,3| Acl.cc(158) matches: checked: (ssl_bump rule) = 1
2017/06/05 14:18:08.000 kid1| 28,3| Acl.cc(158) matches: checked: (ssl_bump rules) = 1
2017/06/05 14:18:08.000 kid1| 28,3| Checklist.cc(63) markFinished: 0x80d21df8 answer ALLOWED for match
2017/06/05 14:18:08.000 kid1| 28,3| Checklist.cc(163) checkCallback: ACLChecklist::checkCallback: 0x80d21df8 answer=ALLOWED
2017/06/05 14:18:08.000 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x80d21df8
2017/06/05 14:18:08.000 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x80d21df8
2017/06/05 14:18:08.000 kid1| 83,5| PeerConnector.cc(418) checkForPeekAndSpliceMatched: Will check for peek and splice on FD 30
2017/06/05 14:18:08.000 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 30, type=2, handler=1, client_data=0x80d36e50, timeout=0
2017/06/05 14:18:08.000 kid1| 83,5| PeerConnector.cc(436) checkForPeekAndSpliceMatched: Retry the fwdNegotiateSSL on FD 30
2017/06/05 14:18:08.000 kid1| 83,5| bio.cc(95) write: FD 30 wrote 150 <= 150
2017/06/05 14:18:08.000 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80e60900 11(0, 0)
2017/06/05 14:18:08.000 kid1| 83,5| bio.cc(118) read: FD 30 read -1 <= 5
2017/06/05 14:18:08.000 kid1| 83,5| bio.cc(123) read: error: 11 ignored: 1
2017/06/05 14:18:08.000 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25 timeout 59
2017/06/05 14:18:08.000 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 30, type=1, handler=1, client_data=0x80d36e50, timeout=0
2017/06/05 14:18:08.000 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 30, type=2, handler=0, client_data=0, timeout=0
2017/06/05 14:18:08.096 kid1| 83,5| bio.cc(118) read: FD 30 read 5 <= 5
2017/06/05 14:18:08.096 kid1| 83,5| bio.cc(118) read: FD 30 read 1 <= 1
2017/06/05 14:18:08.096 kid1| 83,5| bio.cc(118) read: FD 30 read 5 <= 5
2017/06/05 14:18:08.096 kid1| 83,5| bio.cc(118) read: FD 30 read 64 <= 64
2017/06/05 14:18:08.096 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80e60900 7(0, 0x80e6f868)
2017/06/05 14:18:08.096 kid1| 83,5| PeerConnector.cc(307) serverCertificateVerified: HTTPS server CN: *.acms.com bumped: local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25
2017/06/05 14:18:08.096 kid1| 5,5| comm.cc(1038) comm_remove_close_handler: comm_remove_close_handler: FD 30, AsyncCall=0x80e60820*2
2017/06/05 14:18:08.096 kid1| 9,5| AsyncCall.cc(56) cancel: will not call Ssl::PeerConnector::commCloseHandler [call2554] because comm_remove_close_handler
2017/06/05 14:18:08.096 kid1| 17,4| AsyncCall.cc(93) ScheduleCall: PeerConnector.cc(742) will call FwdState::ConnectedToPeer(0x80d4b730, local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25, 0/0) [call2552]
2017/06/05 14:18:08.096 kid1| 93,5| AsyncJob.cc(137) callEnd: Ssl::PeerConnector::negotiateSsl() ends job [ FD 30 job59]
2017/06/05 14:18:08.096 kid1| 83,5| PeerConnector.cc(58) ~PeerConnector: Peer connector 0x80d36e50 gone
2017/06/05 14:18:08.096 kid1| 93,5| AsyncJob.cc(40) ~AsyncJob: AsyncJob destructed, this=0x80d36e74 type=Ssl::PeerConnector [job59]
2017/06/05 14:18:08.096 kid1| 17,4| AsyncCallQueue.cc(55) fireNext: entering FwdState::ConnectedToPeer(0x80d4b730, local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25, 0/0)
2017/06/05 14:18:08.096 kid1| 17,4| AsyncCall.cc(38) make: make call FwdState::ConnectedToPeer [call2552]
2017/06/05 14:18:08.096 kid1| 17,3| FwdState.cc(905) dispatch: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: Fetching CONNECT 46.51.187.18:443
2017/06/05 14:18:08.096 kid1| 14,4| ipcache.cc(501) ipcache_nbgethostbyname: ipcache_nbgethostbyname: Name '46.51.187.18'.
2017/06/05 14:18:08.096 kid1| 14,4| ipcache.cc(810) ipcacheCheckNumeric: ipcacheCheckNumeric: HIT_BYPASS for '46.51.187.18' == 46.51.187.18
2017/06/05 14:18:08.096 kid1| 14,4| ipcache.cc(514) ipcache_nbgethostbyname: ipcache_nbgethostbyname: BYPASS for '46.51.187.18' (already numeric)
2017/06/05 14:18:08.096 kid1| 14,5| net_db.cc(365) networkFromInaddr: networkFromInaddr : Masked IPv4 Address to 46.51.187.18/24.
2017/06/05 14:18:08.096 kid1| 14,5| net_db.cc(369) networkFromInaddr: networkFromInaddr : Masked IPv4 Address to 46.51.187.18/24.
2017/06/05 14:18:08.096 kid1| 14,5| net_db.cc(365) networkFromInaddr: networkFromInaddr : Masked IPv4 Address to 46.51.187.18/24.
2017/06/05 14:18:08.096 kid1| 14,5| net_db.cc(369) networkFromInaddr: networkFromInaddr : Masked IPv4 Address to 46.51.187.18/24.
2017/06/05 14:18:08.097 kid1| 38,3| net_db.cc(325) netdbSendPing: netdbSendPing: pinging 46.51.187.18
2017/06/05 14:18:08.097 kid1| 37,4| IcmpSquid.cc(181) DomainPing: '46.51.187.18' (46.51.187.18)
2017/06/05 14:18:08.097 kid1| 37,2| IcmpSquid.cc(90) SendEcho: to 46.51.187.18, opcode 3, len 12
2017/06/05 14:18:08.097| 42,2| IcmpPinger.cc(198) Recv:  Pass 46.51.187.18 off to ICMPv4 module.
2017/06/05 14:18:08.097| 42,5| Icmp4.cc(135) SendEcho: Send ICMP packet to 46.51.187.18.
2017/06/05 14:18:08.097| 42,2| Icmp.cc(95) Log: pingerLog: 1496665088.097213 46.51.187.18                                  32
2017/06/05 14:18:08.097 kid1| 17,4| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::ConnStateData::httpsPeeked constructed, this=0x80e60728 [call2561]
2017/06/05 14:18:08.097 kid1| 17,4| AsyncCall.cc(93) ScheduleCall: FwdState.cc(952) will call ConnStateData::ConnStateData::httpsPeeked(local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25) [call2561]
2017/06/05 14:18:08.097 kid1| 17,3| FwdState.cc(446) unregister: 46.51.187.18:443
2017/06/05 14:18:08.097 kid1| 5,5| comm.cc(1011) comm_remove_close_handler: comm_remove_close_handler: FD 30, handler=1, data=0x80d4b730
2017/06/05 14:18:08.097 kid1| 5,4| AsyncCall.cc(56) cancel: will not call SomeCloseHandler [call2551] because comm_remove_close_handler
2017/06/05 14:18:08.097 kid1| 17,3| FwdState.cc(471) complete: 46.51.187.18:443
2017/06/05 14:18:08.097 kid1| 17,3| FwdState.cc(1043) reforward: 46.51.187.18:443?
2017/06/05 14:18:08.097 kid1| 17,3| FwdState.cc(1058) reforward: No alternative forwarding paths left
2017/06/05 14:18:08.097 kid1| 17,3| FwdState.cc(495) complete: server (FD closed) not re-forwarding status 0
2017/06/05 14:18:08.097 kid1| 20,3| store.cc(1053) complete: storeComplete: '52E847A2F8AF07D9783AAE4A91F2E9E6'
2017/06/05 14:18:08.097 kid1| 20,3| store.cc(1342) validLength: storeEntryValidLength: Checking '52E847A2F8AF07D9783AAE4A91F2E9E6'
2017/06/05 14:18:08.097 kid1| 20,5| store.cc(1344) validLength: storeEntryValidLength:     object_len = 0
2017/06/05 14:18:08.097 kid1| 20,5| store.cc(1345) validLength: storeEntryValidLength:         hdr_sz = 0
2017/06/05 14:18:08.097 kid1| 20,5| store.cc(1346) validLength: storeEntryValidLength: content_length = -1
2017/06/05 14:18:08.097 kid1| 20,5| store.cc(1349) validLength: storeEntryValidLength: Unspecified content length: 52E847A2F8AF07D9783AAE4A91F2E9E6
2017/06/05 14:18:08.097 kid1| 20,3| store.cc(985) checkCachable: StoreEntry::checkCachable: NO: private key
2017/06/05 14:18:08.097 kid1| 20,3| store.cc(500) setReleaseFlag: StoreEntry::setReleaseFlag: '52E847A2F8AF07D9783AAE4A91F2E9E6'
2017/06/05 14:18:08.097 kid1| 20,3| store_swapout.cc(381) mayStartSwapOut: not cachable
2017/06/05 14:18:08.097 kid1| 20,2| store.cc(954) checkCachable: StoreEntry::checkCachable: NO: not cachable
2017/06/05 14:18:08.097 kid1| 90,3| store_client.cc(732) invokeHandlers: InvokeHandlers: 52E847A2F8AF07D9783AAE4A91F2E9E6
2017/06/05 14:18:08.097 kid1| 90,3| store_client.cc(738) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0
2017/06/05 14:18:08.097 kid1| 46,5| access_log.cc(289) stopPeerClock: First connection started: 1496665087.724223, current total response time value: -1
2017/06/05 14:18:08.097 kid1| 90,3| store_client.cc(758) storePendingNClients: storePendingNClients: returning 1
2017/06/05 14:18:08.097 kid1| 17,3| FwdState.cc(265) ~FwdState: FwdState destructor starting
2017/06/05 14:18:08.097 kid1| 20,3| store.cc(522) unlock: FwdState unlocking key 52E847A2F8AF07D9783AAE4A91F2E9E6 e:=sp2XDIV/0x80e0a448*2
2017/06/05 14:18:08.097 kid1| 17,3| AsyncCall.cc(56) cancel: will not call fwdConnectDoneWrapper [call2544] because FwdState destructed
2017/06/05 14:18:08.097 kid1| 17,3| FwdState.cc(292) ~FwdState: FwdState destructor done
2017/06/05 14:18:08.098 kid1| 17,4| AsyncCallQueue.cc(57) fireNext: leaving FwdState::ConnectedToPeer(0, local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25, 0/0)
2017/06/05 14:18:08.098 kid1| 17,4| AsyncCallQueue.cc(55) fireNext: entering ConnStateData::ConnStateData::httpsPeeked(local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25)
2017/06/05 14:18:08.098 kid1| 17,4| AsyncCall.cc(38) make: make call ConnStateData::ConnStateData::httpsPeeked [call2561]
2017/06/05 14:18:08.098 kid1| 17,4| AsyncJob.cc(123) callStart: Http::Server status in: [ job56]
2017/06/05 14:18:08.098 kid1| 33,3| client_side.cc(5106) unpinConnection:
2017/06/05 14:18:08.098 kid1| 33,3| client_side.cc(4938) pinNewConnection: local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25
2017/06/05 14:18:08.098 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::clientPinnedConnectionClosed constructed, this=0x80e84ea0 [call2562]
2017/06/05 14:18:08.098 kid1| 5,5| comm.cc(993) comm_add_close_handler: comm_add_close_handler: FD 30, AsyncCall=0x80e84ea0*1
2017/06/05 14:18:08.098 kid1| 33,3| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::clientPinnedConnectionRead constructed, this=0x80e84790 [call2563]
2017/06/05 14:18:08.098 kid1| 5,5| Read.cc(58) comm_read_base: comm_read, queueing read for local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25; asynCall 0x80e84790*1
2017/06/05 14:18:08.098 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 30, type=1, handler=1, client_data=0x808b490c, timeout=0
2017/06/05 14:18:08.098 kid1| 33,5| client_side.cc(4409) httpsPeeked: bumped HTTPS server: 46.51.187.18
2017/06/05 14:18:08.098 kid1| 87,3| clientStream.cc(202) clientStreamDetach: clientStreamDetach: Detaching node 0x80d39c38
2017/06/05 14:18:08.098 kid1| 87,3| clientStream.cc(287) clientStreamFree: Freeing clientStreamNode 0x80d39c38
2017/06/05 14:18:08.098 kid1| 87,3| clientStream.cc(223) clientStreamDetach: clientStreamDetach: Calling 1 with cbdata 0x80d39bc8
2017/06/05 14:18:08.098 kid1| 87,3| clientStream.cc(202) clientStreamDetach: clientStreamDetach: Detaching node 0x80d39be8
2017/06/05 14:18:08.098 kid1| 87,3| clientStream.cc(287) clientStreamFree: Freeing clientStreamNode 0x80d39be8
2017/06/05 14:18:08.098 kid1| 33,3| client_side_request.cc(246) ~ClientHttpRequest: httpRequestFree: 46.51.187.18:443
2017/06/05 14:18:08.098 kid1| 33,5| client_side.cc(576) logRequest: logging half-baked transaction: 46.51.187.18:443
2017/06/05 14:18:08.098 kid1| 28,3| Checklist.cc(70) preCheck: 0xbf839e8c checking fast ACLs
2017/06/05 14:18:08.098 kid1| 28,5| Acl.cc(138) matches: checking access_log daemon:/var/log/squid/access.test.log
2017/06/05 14:18:08.098 kid1| 28,5| Acl.cc(138) matches: checking (access_log daemon:/var/log/squid/access.test.log line)
2017/06/05 14:18:08.098 kid1| 28,3| Acl.cc(158) matches: checked: (access_log daemon:/var/log/squid/access.test.log line) = 1
2017/06/05 14:18:08.098 kid1| 28,3| Acl.cc(158) matches: checked: access_log daemon:/var/log/squid/access.test.log = 1
2017/06/05 14:18:08.098 kid1| 28,3| Checklist.cc(63) markFinished: 0xbf839e8c answer ALLOWED for match
2017/06/05 14:18:08.098 kid1| 50,5| ModDaemon.cc(65) logfileNewBuffer: logfileNewBuffer: daemon:/var/log/squid/access.test.log: new buffer
2017/06/05 14:18:08.098 kid1| 50,3| ModDaemon.cc(172) logfile_mod_daemon_append: logfile_mod_daemon_append: daemon:/var/log/squid/access.test.log: appending 1 bytes
2017/06/05 14:18:08.098 kid1| 50,3| ModDaemon.cc(176) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 0 of 32768 bytes before append
2017/06/05 14:18:08.098 kid1| 50,3| ModDaemon.cc(172) logfile_mod_daemon_append: logfile_mod_daemon_append: daemon:/var/log/squid/access.test.log: appending 107 bytes
2017/06/05 14:18:08.098 kid1| 50,3| ModDaemon.cc(176) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 1 of 32768 bytes before append
2017/06/05 14:18:08.098 kid1| 50,3| ModDaemon.cc(172) logfile_mod_daemon_append: logfile_mod_daemon_append: daemon:/var/log/squid/access.test.log: appending 2 bytes
2017/06/05 14:18:08.098 kid1| 50,3| ModDaemon.cc(176) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 108 of 32768 bytes before append
2017/06/05 14:18:08.098 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 21, type=2, handler=1, client_data=0x808fb030, timeout=0
2017/06/05 14:18:08.098 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xbf839e8c
2017/06/05 14:18:08.098 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0xbf839e8c
2017/06/05 14:18:08.098 kid1| 93,5| AsyncCall.cc(26) AsyncCall: The AsyncCall Initiate::noteInitiatorAborted constructed, this=0x80e84cb0 [call2564]
2017/06/05 14:18:08.098 kid1| 93,5| AsyncCall.cc(93) ScheduleCall: Initiator.cc(40) will call Initiate::noteInitiatorAborted() [call2564]
2017/06/05 14:18:08.098 kid1| 93,5| AsyncJob.cc(40) ~AsyncJob: AsyncJob destructed, this=0x80d37708 type=ClientHttpRequest [job57]
2017/06/05 14:18:08.098 kid1| 28,3| Checklist.cc(70) preCheck: 0xbf83a14c checking fast ACLs
2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking sslproxy_cert_sign signUntrusted
2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking (sslproxy_cert_sign signUntrusted line)
2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking ssl::certUntrusted
2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: ssl::certUntrusted = 0
2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: (sslproxy_cert_sign signUntrusted line) = 0
2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: sslproxy_cert_sign signUntrusted = 0
2017/06/05 14:18:08.099 kid1| 28,3| Checklist.cc(63) markFinished: 0xbf83a14c answer DENIED for ACLs failed to match
2017/06/05 14:18:08.099 kid1| 28,3| Checklist.cc(70) preCheck: 0xbf83a14c checking fast ACLs
2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking sslproxy_cert_sign signSelf
2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking (sslproxy_cert_sign signSelf line)
2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking ssl::certSelfSigned
2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: ssl::certSelfSigned = 0
2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: (sslproxy_cert_sign signSelf line) = 0
2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: sslproxy_cert_sign signSelf = 0
2017/06/05 14:18:08.099 kid1| 28,3| Checklist.cc(63) markFinished: 0xbf83a14c answer DENIED for ACLs failed to match
2017/06/05 14:18:08.099 kid1| 28,3| Checklist.cc(70) preCheck: 0xbf83a14c checking fast ACLs
2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking sslproxy_cert_sign signTrusted
2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking (sslproxy_cert_sign signTrusted line)
2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking all
2017/06/05 14:18:08.099 kid1| 28,3| Ip.cc(539) match: aclIpMatchIp: '10.215.145.187' found
2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: all = 1
2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: (sslproxy_cert_sign signTrusted line) = 1
2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: sslproxy_cert_sign signTrusted = 1
2017/06/05 14:18:08.099 kid1| 28,3| Checklist.cc(63) markFinished: 0xbf83a14c answer ALLOWED for match
2017/06/05 14:18:08.099 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xbf83a14c
2017/06/05 14:18:08.099 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0xbf83a14c
2017/06/05 14:18:08.099 kid1| 33,5| client_side.cc(4135) getSslContextStart: Generating SSL certificate for *.acms.com using ssl_crtd.
2017/06/05 14:18:08.099 kid1| 33,5| client_side.cc(4139) getSslContextStart: SSL crtd request: new_certificate 5112 host=*.acms.com
2017/06/05 14:18:08.099 kid1| 84,5| helper.cc(1167) GetFirstAvailable: GetFirstAvailable: Running servers 5
2017/06/05 14:18:08.099 kid1| 5,5| AsyncCall.cc(26) AsyncCall: The AsyncCall helperDispatchWriteDone constructed, this=0x80e6f6b8 [call2565]
2017/06/05 14:18:08.100 kid1| 5,5| Write.cc(35) Write: local=[::] remote=[::] FD 10 flags=1: sz 5134: asynCall 0x80e6f6b8*1
2017/06/05 14:18:08.100 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 10, type=2, handler=1, client_data=0x808b42a4, timeout=0
2017/06/05 14:18:08.100 kid1| 84,5| helper.cc(1309) helperDispatch: helperDispatch: Request sent to ssl_crtd #Hlpr1, 5134 bytes
2017/06/05 14:18:08.100 kid1| 17,4| AsyncJob.cc(152) callEnd: Http::Server status out: [ job56]
2017/06/05 14:18:08.100 kid1| 17,4| AsyncCallQueue.cc(57) fireNext: leaving ConnStateData::ConnStateData::httpsPeeked(local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25)
2017/06/05 14:18:08.100 kid1| 93,5| AsyncCallQueue.cc(55) fireNext: entering Initiate::noteInitiatorAborted()
2017/06/05 14:18:08.100 kid1| 93,5| AsyncCall.cc(38) make: make call Initiate::noteInitiatorAborted [call2564]
2017/06/05 14:18:08.100 kid1| 93,5| AsyncCall.cc(56) cancel: will not call Initiate::noteInitiatorAborted [call2564] because job gone
2017/06/05 14:18:08.100 kid1| 93,5| AsyncCall.cc(48) make: will not call Initiate::noteInitiatorAborted [call2564] because of job gone
2017/06/05 14:18:08.100 kid1| 93,5| AsyncCallQueue.cc(57) fireNext: leaving Initiate::noteInitiatorAborted()
2017/06/05 14:18:08.100 kid1| 50,3| ModDaemon.cc(108) logfileHandleWrite: daemon:/var/log/squid/access.test.log: write returned 110
2017/06/05 14:18:08.100 kid1| 5,5| Write.cc(66) HandleWrite: local=[::] remote=[::] FD 10 flags=1: off 0, sz 5134.
2017/06/05 14:18:08.100 kid1| 5,5| Write.cc(108) HandleWrite: write() returns 5134
2017/06/05 14:18:08.100 kid1| 5,3| IoCallback.cc(116) finish: called for local=[::] remote=[::] FD 10 flags=1 (0, 0)
2017/06/05 14:18:08.100 kid1| 5,5| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call helperDispatchWriteDone(local=[::] remote=[::] FD 10 flags=1, data=0x808d9390, size=5134, buf=0x80dd0608) [call2565]
2017/06/05 14:18:08.100 kid1| 5,5| AsyncCallQueue.cc(55) fireNext: entering helperDispatchWriteDone(local=[::] remote=[::] FD 10 flags=1, data=0x808d9390, size=5134, buf=0x80dd0608)
2017/06/05 14:18:08.100 kid1| 5,5| AsyncCall.cc(38) make: make call helperDispatchWriteDone [call2565]
2017/06/05 14:18:08.100 kid1| 5,5| AsyncCallQueue.cc(57) fireNext: leaving helperDispatchWriteDone(local=[::] remote=[::] FD 10 flags=1, data=0x808d9390, size=5134, buf=0x80dd0608)
2017/06/05 14:18:08.100 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 21, type=2, handler=0, client_data=0, timeout=0
2017/06/05 14:18:08.100 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 10, type=2, handler=0, client_data=0, timeout=0
2017/06/05 14:18:08.106 kid1| 5,3| Read.cc(144) HandleRead: FD 10, size 8191, retval 3161, errno 0
2017/06/05 14:18:08.106 kid1| 5,3| IoCallback.cc(116) finish: called for local=[::] remote=[::] FD 10 flags=1 (0, 0)
2017/06/05 14:18:08.106 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call helperHandleRead(local=[::] remote=[::] FD 10 flags=1, data=0x808d9390, size=3161, buf=0x80d904b8) [call2299]
2017/06/05 14:18:08.106 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering helperHandleRead(local=[::] remote=[::] FD 10 flags=1, data=0x808d9390, size=3161, buf=0x80d904b8)
2017/06/05 14:18:08.106 kid1| 5,4| AsyncCall.cc(38) make: make call helperHandleRead [call2299]
2017/06/05 14:18:08.106 kid1| 84,5| helper.cc(866) helperHandleRead: helperHandleRead: 3161 bytes from ssl_crtd #Hlpr1
2017/06/05 14:18:08.106 kid1| 84,3| helper.cc(892) helperHandleRead: helperHandleRead: end of reply found
2017/06/05 14:18:08.106 kid1| 84,3| Reply.cc(29) parse: Parsing helper buffer
2017/06/05 14:18:08.106 kid1| 84,3| Reply.cc(48) parse: Buff length is larger than 2
2017/06/05 14:18:08.106 kid1| 84,3| Reply.cc(52) parse: helper Result = OK
2017/06/05 14:18:08.106 kid1| 33,5| client_side.cc(3992) sslCrtdHandleReply: Certificate for 46.51.187.18 was successfully recieved from ssl_crtd
2017/06/05 14:18:08.106 kid1| 33,5| client_side.cc(4394) doPeekAndSpliceStep: PeekAndSplice mode, proceed with client negotiation. Currrent state:SSLv2/v3 read client hello A
2017/06/05 14:18:08.106 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=2, handler=1, client_data=0x80e07e00, timeout=0
2017/06/05 14:18:08.106 kid1| 84,5| helper.cc(1167) GetFirstAvailable: GetFirstAvailable: Running servers 5
2017/06/05 14:18:08.106 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall helperHandleRead constructed, this=0x80e84cb0 [call2566]
2017/06/05 14:18:08.106 kid1| 5,5| Read.cc(58) comm_read_base: comm_read, queueing read for local=[::] remote=[::] FD 10 flags=1; asynCall 0x80e84cb0*1
2017/06/05 14:18:08.107 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 10, type=1, handler=1, client_data=0x808b427c, timeout=0
2017/06/05 14:18:08.107 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving helperHandleRead(local=[::] remote=[::] FD 10 flags=1, data=0x808d9390, size=3161, buf=0x80d904b8)
2017/06/05 14:18:08.107 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80e07048 6(0, 0x80e14ad0)
2017/06/05 14:18:08.107 kid1| 83,5| bio.cc(95) write: FD 29 wrote 1135 <= 1135
2017/06/05 14:18:08.107 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80e07048 11(0, 0)
2017/06/05 14:18:08.107 kid1| 83,5| bio.cc(118) read: FD 29 read -1 <= 5
2017/06/05 14:18:08.107 kid1| 83,5| bio.cc(123) read: error: 11 ignored: 1
2017/06/05 14:18:08.107 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=1, handler=1, client_data=0x80e07e00, timeout=0
2017/06/05 14:18:08.107 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=2, handler=0, client_data=0, timeout=0
2017/06/05 14:18:08.109 kid1| 83,5| bio.cc(118) read: FD 29 read 5 <= 5
2017/06/05 14:18:08.109 kid1| 83,5| bio.cc(118) read: FD 29 read 262 <= 262
2017/06/05 14:18:08.128 kid1| 83,5| bio.cc(118) read: FD 29 read 5 <= 5
2017/06/05 14:18:08.128 kid1| 83,5| bio.cc(118) read: FD 29 read 1 <= 1
2017/06/05 14:18:08.128 kid1| 83,5| bio.cc(118) read: FD 29 read 5 <= 5
2017/06/05 14:18:08.128 kid1| 83,5| bio.cc(118) read: FD 29 read 48 <= 48
2017/06/05 14:18:08.129 kid1| 83,5| bio.cc(95) write: FD 29 wrote 59 <= 59
2017/06/05 14:18:08.129 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80e07048 11(0, 0)
2017/06/05 14:18:08.129 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80e07048 7(0, 0x80e14ad0)
2017/06/05 14:18:08.129 kid1| 83,5| support.cc(2097) store_session_cb: Request to store SSL Session
2017/06/05 14:18:08.129 kid1| 54,5| MemMap.cc(45) openForWriting: trying to open slot for key 9E7C52DD3CBFFBD0304B94480415CC7C for writing in map [ssl_session_cache]
2017/06/05 14:18:08.129 kid1| 54,5| MemMap.cc(81) openForWritingAt: opened slot at 41 for writing in map [ssl_session_cache]
2017/06/05 14:18:08.129 kid1| 54,5| MemMap.cc(94) closeForWriting: closing slot at 41 for writing and openning for reading in map [ssl_session_cache]
2017/06/05 14:18:08.129 kid1| 83,5| support.cc(2119) store_session_cb: wrote an ssl session entry of size 157 at pos 41
2017/06/05 14:18:08.129 kid1| 83,2| client_side.cc(3796) clientNegotiateSSL: clientNegotiateSSL: New session 0x80e80e30 on FD 29 (10.215.145.187:54815)
2017/06/05 14:18:08.129 kid1| 83,3| client_side.cc(3800) clientNegotiateSSL: clientNegotiateSSL: FD 29 negotiated cipher AES128-SHA
2017/06/05 14:18:08.129 kid1| 83,5| client_side.cc(3816) clientNegotiateSSL: clientNegotiateSSL: FD 29 has no certificate.
2017/06/05 14:18:08.129 kid1| 33,4| client_side.cc(231) readSomeData: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: reading request...
2017/06/05 14:18:08.129 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::clientReadRequest constructed, this=0x80e80578 [call2567]
2017/06/05 14:18:08.129 kid1| 5,5| Read.cc(58) comm_read_base: comm_read, queueing read for local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17; asynCall 0x80e80578*1
2017/06/05 14:18:08.129 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=1, handler=1, client_data=0x808b48b8, timeout=0
2017/06/05 14:18:08.135 kid1| 5,3| IoCallback.cc(116) finish: called for local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 (0, 0)
2017/06/05 14:18:08.135 kid1| 33,5| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call ConnStateData::clientReadRequest(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80e07e00) [call2567]
2017/06/05 14:18:08.135 kid1| 33,5| AsyncCallQueue.cc(55) fireNext: entering ConnStateData::clientReadRequest(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80e07e00)
2017/06/05 14:18:08.135 kid1| 33,5| AsyncCall.cc(38) make: make call ConnStateData::clientReadRequest [call2567]
2017/06/05 14:18:08.135 kid1| 33,5| AsyncJob.cc(123) callStart: Http::Server status in: [ job56]
2017/06/05 14:18:08.136 kid1| 33,5| client_side.cc(3251) clientReadRequest: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17
2017/06/05 14:18:08.136 kid1| 83,5| bio.cc(118) read: FD 29 read 5 <= 5
2017/06/05 14:18:08.136 kid1| 83,5| bio.cc(118) read: FD 29 read 1568 <= 1568
2017/06/05 14:18:08.136 kid1| 83,2| support.cc(1364) ssl_read_method: SSL FD 29 is pending
2017/06/05 14:18:08.136 kid1| 5,3| Read.cc(91) ReadNow: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, size 66, retval 66, errno 0
2017/06/05 14:18:08.136 kid1| 33,5| client_side.cc(3200) clientParseRequests: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: attempting to parse
2017/06/05 14:18:08.136 kid1| 74,5| HttpParser.cc(37) reset: Request buffer is
2017/06/05 14:18:08.136 kid1| 74,5| HttpParser.cc(47) parseRequestFirstLine: parsing possible request:
2017/06/05 14:18:08.136 kid1| 74,5| HttpParser.cc(257) HttpParserParseReqLine: Parser: retval -1: from 0->4: method 0->-1; url -1->-1; version -1->-1 (0/0)
2017/06/05 14:18:08.136 kid1| 93,5| AsyncJob.cc(34) AsyncJob: AsyncJob constructed, this=0x80d227d0 type=ClientHttpRequest [job60]
2017/06/05 14:18:08.136 kid1| 87,3| clientStream.cc(144) clientStreamInsertHead: clientStreamInsertHead: Inserted node 0x80d39c38 with data 0x80d38b44 after head
2017/06/05 14:18:08.136 kid1| 33,5| client_side.cc(3221) clientParseRequests: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: done parsing a request
2017/06/05 14:18:08.136 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall clientLifetimeTimeout constructed, this=0x80e14ad0 [call2568]
2017/06/05 14:18:08.136 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 timeout 86400
2017/06/05 14:18:08.136 kid1| 33,2| client_side.cc(2584) clientProcessRequest: clientProcessRequest: Invalid Request
2017/06/05 14:18:08.136 kid1| 33,4| client_side.cc(2455) quitAfterError: Will close after error: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17
2017/06/05 14:18:08.136 kid1| 20,3| store.cc(779) storeCreatePureEntry: storeCreateEntry: 'error:invalid-request'
2017/06/05 14:18:08.136 kid1| 20,5| store.cc(371) StoreEntry: StoreEntry constructed, this=0x80e05f48
2017/06/05 14:18:08.136 kid1| 20,3| MemObject.cc(97) MemObject: new MemObject 0x80e71638
2017/06/05 14:18:08.136 kid1| 20,3| store.cc(500) setReleaseFlag: StoreEntry::setReleaseFlag: '[null_store_key]'
2017/06/05 14:18:08.136 kid1| 20,3| store_key_md5.cc(89) storeKeyPrivate: storeKeyPrivate: NONE error:invalid-request
2017/06/05 14:18:08.136 kid1| 20,3| store.cc(448) hashInsert: StoreEntry::hashInsert: Inserting Entry e:=XI/0x80e05f48*0 key '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.136 kid1| 20,3| store.cc(484) lock: storeCreateEntry locked key 908891323D546174B25B4E7FDFB415C7 e:=XIV/0x80e05f48*1
2017/06/05 14:18:08.137 kid1| 4,4| errorpage.cc(603) errorAppendEntry: Creating an error page for entry 0x80e05f48 with errorstate 0x80e80440 page id 20
2017/06/05 14:18:08.137 kid1| 4,2| errorpage.cc(1262) BuildContent: No existing error page language negotiated for ERR_INVALID_REQ. Using default error file.
2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%l --> '/*
2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%; --> '%;'
2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%c --> 'ERR_INVALID_REQ'
2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%R --> ''
2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%w --> 'root'
2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%W --> '?subject=CacheErrorInfo%20-%20ERR_INVALID_REQ&body=CacheHost%3A%20inf-fw1%0D%0AErrPage%3A%20ERR_INVALID_REQ%0D%0AErr%3A%20%5Bnone%5D%0D%0ATimeStamp%3A%20Mon,%2005%20Jun%202017%2012%3A18%3A08%20GMT%0D%0A%0D%0AClientIP%3A%2010.215.145.187%0D%0A%0D%0AHTTP%20Request%3A%0D%0A%0D%0A%0D%0A'
2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%w --> 'root'
2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%M --> '[unknown method]'
2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%u --> 'error:invalid-request'
2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%P --> '[unknown protocol]'
2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%T --> 'Mon, 05 Jun 2017 12:18:08 GMT'
2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%h --> 'inf-fw1'
2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%s --> 'squid/3.5.14'
2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%c --> 'ERR_INVALID_REQ'
2017/06/05 14:18:08.137 kid1| 20,3| store.cc(484) lock: StoreEntry::storeErrorResponse locked key 908891323D546174B25B4E7FDFB415C7 e:=XIV/0x80e05f48*2
2017/06/05 14:18:08.137 kid1| 20,3| store.cc(1867) replaceHttpReply: StoreEntry::replaceHttpReply: error:invalid-request
2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 26 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 6 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 12 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 12 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 3 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 4 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 29 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 12 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 23 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 14 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 4 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 13 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 17 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 4 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 15 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 16 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 4062 bytes for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,2| store.cc(954) checkCachable: StoreEntry::checkCachable: NO: not cachable
2017/06/05 14:18:08.138 kid1| 20,3| store_swapout.cc(381) mayStartSwapOut: not cachable
2017/06/05 14:18:08.138 kid1| 20,2| store.cc(954) checkCachable: StoreEntry::checkCachable: NO: not cachable
2017/06/05 14:18:08.138 kid1| 90,3| store_client.cc(732) invokeHandlers: InvokeHandlers: 908891323D546174B25B4E7FDFB415C7
2017/06/05 14:18:08.138 kid1| 90,3| store_client.cc(738) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0
2017/06/05 14:18:08.138 kid1| 20,3| store.cc(1053) complete: storeComplete: '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,3| store.cc(1342) validLength: storeEntryValidLength: Checking '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(1344) validLength: storeEntryValidLength:     object_len = 4308
2017/06/05 14:18:08.138 kid1| 20,5| store.cc(1345) validLength: storeEntryValidLength:         hdr_sz = 246
2017/06/05 14:18:08.139 kid1| 20,5| store.cc(1346) validLength: storeEntryValidLength: content_length = 4062
2017/06/05 14:18:08.139 kid1| 20,3| store_swapout.cc(356) mayStartSwapOut:  already rejected
2017/06/05 14:18:08.139 kid1| 20,2| store.cc(954) checkCachable: StoreEntry::checkCachable: NO: not cachable
2017/06/05 14:18:08.139 kid1| 90,3| store_client.cc(732) invokeHandlers: InvokeHandlers: 908891323D546174B25B4E7FDFB415C7
2017/06/05 14:18:08.139 kid1| 90,3| store_client.cc(738) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0
2017/06/05 14:18:08.139 kid1| 20,3| store.cc(522) unlock: StoreEntry::storeErrorResponse unlocking key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*2
2017/06/05 14:18:08.139 kid1| 33,5| client_side.cc(1709) pullData: 0 written 0 into local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17
2017/06/05 14:18:08.139 kid1| 33,5| client_side.cc(1665) getNextRangeOffset: range: 0; http offset 0; reply 0
2017/06/05 14:18:08.139 kid1| 87,3| clientStream.cc(184) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0x80d39bc8 from node 0x80d39c38
2017/06/05 14:18:08.139 kid1| 90,3| store_client.cc(200) copy: store_client::copy: 908891323D546174B25B4E7FDFB415C7, from 0, for length 4096, cb 1, cbdata 0x80d38b60
2017/06/05 14:18:08.139 kid1| 20,3| store.cc(484) lock: store_client::copy locked key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*2
2017/06/05 14:18:08.139 kid1| 90,3| store_client.cc(297) storeClientCopy2: storeClientCopy2: 908891323D546174B25B4E7FDFB415C7
2017/06/05 14:18:08.139 kid1| 33,5| store_client.cc(329) doCopy: store_client::doCopy: co: 0, hi: 4308
2017/06/05 14:18:08.139 kid1| 90,3| store_client.cc(433) scheduleMemRead: store_client::doCopy: Copying normal from memory
2017/06/05 14:18:08.139 kid1| 88,5| client_side_reply.cc(2154) sendMoreData: clientReplyContext::sendMoreData: error:invalid-request, 4096 bytes (4096 new bytes)
2017/06/05 14:18:08.139 kid1| 88,5| client_side_reply.cc(2158) sendMoreData: clientReplyContext::sendMoreData:local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 'error:invalid-request' out.offset=0
2017/06/05 14:18:08.139 kid1| 88,2| client_side_reply.cc(2001) processReplyAccessResult: The reply for NONE error:invalid-request is ALLOWED, because it matched all
2017/06/05 14:18:08.139 kid1| 20,3| store.cc(484) lock: ClientHttpRequest::loggingEntry locked key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*3
2017/06/05 14:18:08.139 kid1| 88,3| client_side_reply.cc(2039) processReplyAccessResult: clientReplyContext::sendMoreData: Appending 3850 bytes after 246 bytes of headers
2017/06/05 14:18:08.139 kid1| 87,3| clientStream.cc(162) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0x80d38b44 from node 0x80d39be8
2017/06/05 14:18:08.139 kid1| 11,2| client_side.cc(1391) sendStartOfMessage: HTTP Client local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17
2017/06/05 14:18:08.139 kid1| 11,2| client_side.cc(1392) sendStartOfMessage: HTTP Client REPLY:
2017/06/05 14:18:08.139 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall clientWriteComplete constructed, this=0x80e73b48 [call2569]
2017/06/05 14:18:08.139 kid1| 5,5| Write.cc(35) Write: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: sz 4216: asynCall 0x80e73b48*1
2017/06/05 14:18:08.139 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=2, handler=1, client_data=0x808b48e0, timeout=0
2017/06/05 14:18:08.139 kid1| 20,3| store.cc(522) unlock: store_client::copy unlocking key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*3
2017/06/05 14:18:08.139 kid1| 33,5| client_side.cc(2422) consumeInput: in.buf has 0 unused bytes
2017/06/05 14:18:08.139 kid1| 33,5| AsyncJob.cc(152) callEnd: Http::Server status out: [ job56]
2017/06/05 14:18:08.139 kid1| 33,5| AsyncCallQueue.cc(57) fireNext: leaving ConnStateData::clientReadRequest(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80e07e00)
2017/06/05 14:18:08.140 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=1, handler=0, client_data=0, timeout=0
2017/06/05 14:18:08.140 kid1| 5,5| Write.cc(66) HandleWrite: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: off 0, sz 4216.
2017/06/05 14:18:08.140 kid1| 83,5| bio.cc(95) write: FD 29 wrote 4282 <= 4282
2017/06/05 14:18:08.140 kid1| 5,5| Write.cc(108) HandleWrite: write() returns 4216
2017/06/05 14:18:08.140 kid1| 5,3| IoCallback.cc(116) finish: called for local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 (0, 0)
2017/06/05 14:18:08.140 kid1| 33,5| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call clientWriteComplete(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80d37b00) [call2569]
2017/06/05 14:18:08.140 kid1| 33,5| AsyncCallQueue.cc(55) fireNext: entering clientWriteComplete(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80d37b00)
2017/06/05 14:18:08.140 kid1| 33,5| AsyncCall.cc(38) make: make call clientWriteComplete [call2569]
2017/06/05 14:18:08.140 kid1| 33,5| client_side.cc(1845) writeComplete: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, sz 4216, err 0, off 4216, len 4308
2017/06/05 14:18:08.140 kid1| 58,3| HttpReply.cc(520) receivedBodyTooLarge: -246 >? -1
2017/06/05 14:18:08.140 kid1| 33,5| client_side.cc(1709) pullData: 0x80e07350 written 4216 into local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17
2017/06/05 14:18:08.140 kid1| 33,5| client_side.cc(1665) getNextRangeOffset: range: 0; http offset 3850; reply 0x80e07350
2017/06/05 14:18:08.140 kid1| 87,3| clientStream.cc(184) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0x80d39bc8 from node 0x80d39c38
2017/06/05 14:18:08.140 kid1| 90,3| store_client.cc(200) copy: store_client::copy: 908891323D546174B25B4E7FDFB415C7, from 4096, for length 4096, cb 1, cbdata 0x80d38b60
2017/06/05 14:18:08.140 kid1| 20,3| store.cc(484) lock: store_client::copy locked key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*3
2017/06/05 14:18:08.140 kid1| 90,3| store_client.cc(297) storeClientCopy2: storeClientCopy2: 908891323D546174B25B4E7FDFB415C7
2017/06/05 14:18:08.140 kid1| 33,5| store_client.cc(329) doCopy: store_client::doCopy: co: 4096, hi: 4308
2017/06/05 14:18:08.140 kid1| 90,3| store_client.cc(433) scheduleMemRead: store_client::doCopy: Copying normal from memory
2017/06/05 14:18:08.140 kid1| 88,5| client_side_reply.cc(2154) sendMoreData: clientReplyContext::sendMoreData: error:invalid-request, 4308 bytes (212 new bytes)
2017/06/05 14:18:08.140 kid1| 88,5| client_side_reply.cc(2158) sendMoreData: clientReplyContext::sendMoreData:local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 'error:invalid-request' out.offset=3850
2017/06/05 14:18:08.140 kid1| 87,3| clientStream.cc(162) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0x80d38b44 from node 0x80d39be8
2017/06/05 14:18:08.140 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall clientWriteBodyComplete constructed, this=0x80e80578 [call2570]
2017/06/05 14:18:08.140 kid1| 5,5| Write.cc(35) Write: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: sz 212: asynCall 0x80e80578*1
2017/06/05 14:18:08.140 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=2, handler=1, client_data=0x808b48e0, timeout=0
2017/06/05 14:18:08.140 kid1| 20,3| store.cc(522) unlock: store_client::copy unlocking key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*3
2017/06/05 14:18:08.140 kid1| 33,5| AsyncCallQueue.cc(57) fireNext: leaving clientWriteComplete(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80d37b00)
2017/06/05 14:18:08.140 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=1, handler=0, client_data=0, timeout=0
2017/06/05 14:18:08.140 kid1| 5,5| Write.cc(66) HandleWrite: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: off 0, sz 212.
2017/06/05 14:18:08.140 kid1| 83,5| bio.cc(95) write: FD 29 wrote 282 <= 282
2017/06/05 14:18:08.140 kid1| 5,5| Write.cc(108) HandleWrite: write() returns 212
2017/06/05 14:18:08.140 kid1| 5,3| IoCallback.cc(116) finish: called for local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 (0, 0)
2017/06/05 14:18:08.140 kid1| 33,5| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call clientWriteBodyComplete(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80d37b00, size=212, buf=0x80d37b10) [call2570]
2017/06/05 14:18:08.140 kid1| 33,5| AsyncCallQueue.cc(55) fireNext: entering clientWriteBodyComplete(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80d37b00, size=212, buf=0x80d37b10)
2017/06/05 14:18:08.141 kid1| 33,5| AsyncCall.cc(38) make: make call clientWriteBodyComplete [call2570]
2017/06/05 14:18:08.141 kid1| 33,5| client_side.cc(1845) writeComplete: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, sz 212, err 0, off 4428, len 4308
2017/06/05 14:18:08.141 kid1| 88,3| client_side_reply.cc(1098) storeOKTransferDone: storeOKTransferDone  out.offset=4062 objectLen()=4308 headers_sz=246
2017/06/05 14:18:08.141 kid1| 88,5| client_side_reply.cc(1210) replyStatus: clientReplyStatus: transfer is DONE: 10
2017/06/05 14:18:08.141 kid1| 88,5| client_side_reply.cc(1236) replyStatus: clientReplyStatus: stream complete; keepalive=0
2017/06/05 14:18:08.141 kid1| 33,5| client_side.cc(1866) writeComplete: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 Stream complete, keepalive is 0
2017/06/05 14:18:08.141 kid1| 33,4| client_side.cc(1819) stopSending: sending error (local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17): STREAM_COMPLETE NOKEEPALIVE; old receiving error: none
2017/06/05 14:18:08.141 kid1| 5,3| comm.cc(868) _comm_close: comm_close: start closing FD 29
2017/06/05 14:18:08.141 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall commStartSslClose constructed, this=0x80e73b48 [call2571]
2017/06/05 14:18:08.141 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: comm.cc(902) will call commStartSslClose(FD 29) [call2571]
2017/06/05 14:18:08.141 kid1| 5,3| comm.cc(540) commUnsetFdTimeout: Remove timeout for FD 29
2017/06/05 14:18:08.141 kid1| 5,5| comm.cc(721) commCallCloseHandlers: commCallCloseHandlers: FD 29
2017/06/05 14:18:08.141 kid1| 5,5| comm.cc(729) commCallCloseHandlers: commCallCloseHandlers: ch->handler=0x80dfaaf8*1
2017/06/05 14:18:08.141 kid1| 33,5| AsyncCall.cc(93) ScheduleCall: comm.cc(730) will call ConnStateData::connStateClosed(FD -1, data=0x80e07e00) [call2541]
2017/06/05 14:18:08.141 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall comm_close_complete constructed, this=0x80e14ad0 [call2572]
2017/06/05 14:18:08.141 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: comm.cc(941) will call comm_close_complete(FD 29) [call2572]
2017/06/05 14:18:08.141 kid1| 33,5| AsyncCallQueue.cc(57) fireNext: leaving clientWriteBodyComplete(local=46.51.187.18:443 remote=10.215.145.187 flags=17, data=0x80d37b00, size=212, buf=0x80d37b10)
2017/06/05 14:18:08.141 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering commStartSslClose(FD 29)
2017/06/05 14:18:08.141 kid1| 5,4| AsyncCall.cc(38) make: make call commStartSslClose [call2571]
2017/06/05 14:18:08.141 kid1| 83,5| bio.cc(95) write: FD 29 wrote 37 <= 37
2017/06/05 14:18:08.141 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving commStartSslClose(FD 29)
2017/06/05 14:18:08.141 kid1| 33,5| AsyncCallQueue.cc(55) fireNext: entering ConnStateData::connStateClosed(FD -1, data=0x80e07e00)
2017/06/05 14:18:08.141 kid1| 33,5| AsyncCall.cc(38) make: make call ConnStateData::connStateClosed [call2541]
2017/06/05 14:18:08.141 kid1| 33,5| AsyncJob.cc(123) callStart: Http::Server status in: [ job56]
2017/06/05 14:18:08.141 kid1| 93,4| AsyncJob.cc(55) deleteThis: Http::Server will NOT delete in-call job, reason: ConnStateData::connStateClosed
2017/06/05 14:18:08.142 kid1| 93,5| AsyncJob.cc(137) callEnd: ConnStateData::connStateClosed(FD -1, data=0x80e07e00) ends job [Stopped, reason:ConnStateData::connStateClosed job56]
2017/06/05 14:18:08.142 kid1| 33,2| client_side.cc(815) swanSong: local=46.51.187.18:443 remote=10.215.145.187 flags=17
2017/06/05 14:18:08.142 kid1| 87,3| clientStream.cc(202) clientStreamDetach: clientStreamDetach: Detaching node 0x80d39c38
2017/06/05 14:18:08.142 kid1| 87,3| clientStream.cc(287) clientStreamFree: Freeing clientStreamNode 0x80d39c38
2017/06/05 14:18:08.142 kid1| 87,3| clientStream.cc(223) clientStreamDetach: clientStreamDetach: Calling 1 with cbdata 0x80d39bc8
2017/06/05 14:18:08.142 kid1| 87,3| clientStream.cc(202) clientStreamDetach: clientStreamDetach: Detaching node 0x80d39be8
2017/06/05 14:18:08.142 kid1| 87,3| clientStream.cc(287) clientStreamFree: Freeing clientStreamNode 0x80d39be8
2017/06/05 14:18:08.142 kid1| 90,3| store_client.cc(664) storeUnregister: storeUnregister: called for '908891323D546174B25B4E7FDFB415C7'
2017/06/05 14:18:08.142 kid1| 20,3| store_swapout.cc(356) mayStartSwapOut:  already rejected
2017/06/05 14:18:08.142 kid1| 20,2| store.cc(954) checkCachable: StoreEntry::checkCachable: NO: not cachable
2017/06/05 14:18:08.142 kid1| 20,3| store.cc(484) lock: storeUnregister locked key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*3
2017/06/05 14:18:08.142 kid1| 90,3| store_client.cc(758) storePendingNClients: storePendingNClients: returning 0
2017/06/05 14:18:08.142 kid1| 20,3| store.cc(522) unlock: storeUnregister unlocking key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*3
2017/06/05 14:18:08.142 kid1| 20,3| store.cc(522) unlock: clientReplyContext::removeStoreReference unlocking key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*2
2017/06/05 14:18:08.142 kid1| 33,3| client_side_request.cc(246) ~ClientHttpRequest: httpRequestFree: error:invalid-request
2017/06/05 14:18:08.142 kid1| 28,3| Checklist.cc(70) preCheck: 0xbf839f2c checking fast ACLs
2017/06/05 14:18:08.143 kid1| 28,5| Acl.cc(138) matches: checking access_log daemon:/var/log/squid/access.test.log
2017/06/05 14:18:08.143 kid1| 28,5| Acl.cc(138) matches: checking (access_log daemon:/var/log/squid/access.test.log line)
2017/06/05 14:18:08.143 kid1| 28,3| Acl.cc(158) matches: checked: (access_log daemon:/var/log/squid/access.test.log line) = 1
2017/06/05 14:18:08.143 kid1| 28,3| Acl.cc(158) matches: checked: access_log daemon:/var/log/squid/access.test.log = 1
2017/06/05 14:18:08.143 kid1| 28,3| Checklist.cc(63) markFinished: 0xbf839f2c answer ALLOWED for match
2017/06/05 14:18:08.143 kid1| 50,5| ModDaemon.cc(65) logfileNewBuffer: logfileNewBuffer: daemon:/var/log/squid/access.test.log: new buffer
2017/06/05 14:18:08.143 kid1| 50,3| ModDaemon.cc(172) logfile_mod_daemon_append: logfile_mod_daemon_append: daemon:/var/log/squid/access.test.log: appending 1 bytes
2017/06/05 14:18:08.143 kid1| 50,3| ModDaemon.cc(176) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 0 of 32768 bytes before append
2017/06/05 14:18:08.143 kid1| 50,3| ModDaemon.cc(172) logfile_mod_daemon_append: logfile_mod_daemon_append: daemon:/var/log/squid/access.test.log: appending 106 bytes
2017/06/05 14:18:08.143 kid1| 50,3| ModDaemon.cc(176) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 1 of 32768 bytes before append
2017/06/05 14:18:08.143 kid1| 50,3| ModDaemon.cc(172) logfile_mod_daemon_append: logfile_mod_daemon_append: daemon:/var/log/squid/access.test.log: appending 2 bytes
2017/06/05 14:18:08.143 kid1| 50,3| ModDaemon.cc(176) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 107 of 32768 bytes before append
2017/06/05 14:18:08.143 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 21, type=2, handler=1, client_data=0x808fb030, timeout=0
2017/06/05 14:18:08.143 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xbf839f2c
2017/06/05 14:18:08.143 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0xbf839f2c
2017/06/05 14:18:08.143 kid1| 20,3| store.cc(522) unlock: ClientHttpRequest::loggingEntry unlocking key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*1
2017/06/05 14:18:08.143 kid1| 90,3| store_client.cc(758) storePendingNClients: storePendingNClients: returning 0
2017/06/05 14:18:08.143 kid1| 20,3| store.cc(1244) release: releasing e:=sXINV/0x80e05f48*0 908891323D546174B25B4E7FDFB415C7
2017/06/05 14:18:08.143 kid1| 20,3| store.cc(403) destroyMemObject: destroyMemObject 0x80e71638
2017/06/05 14:18:08.143 kid1| 20,3| MemObject.cc(110) ~MemObject: del MemObject 0x80e71638
2017/06/05 14:18:08.144 kid1| 20,3| store.cc(421) destroyStoreEntry: destroyStoreEntry: destroying 0x80e05f4c
2017/06/05 14:18:08.144 kid1| 20,3| store.cc(403) destroyMemObject: destroyMemObject 0
2017/06/05 14:18:08.144 kid1| 20,5| store.cc(376) ~StoreEntry: StoreEntry destructed, this=0x80e05f48
2017/06/05 14:18:08.144 kid1| 93,5| AsyncCall.cc(26) AsyncCall: The AsyncCall Initiate::noteInitiatorAborted constructed, this=0x80e717d0 [call2573]
2017/06/05 14:18:08.144 kid1| 93,5| AsyncCall.cc(93) ScheduleCall: Initiator.cc(40) will call Initiate::noteInitiatorAborted() [call2573]
2017/06/05 14:18:08.144 kid1| 93,5| AsyncJob.cc(40) ~AsyncJob: AsyncJob destructed, this=0x80d227d0 type=ClientHttpRequest [job60]
2017/06/05 14:18:08.144 kid1| 33,3| client_side.cc(5106) unpinConnection: local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25
2017/06/05 14:18:08.144 kid1| 5,5| comm.cc(1038) comm_remove_close_handler: comm_remove_close_handler: FD 30, AsyncCall=0x80e84ea0*2
2017/06/05 14:18:08.144 kid1| 33,5| AsyncCall.cc(56) cancel: will not call ConnStateData::clientPinnedConnectionClosed [call2562] because comm_remove_close_handler
2017/06/05 14:18:08.144 kid1| 33,3| AsyncCall.cc(56) cancel: will not call ConnStateData::clientPinnedConnectionRead [call2563] because comm_read_cancel
2017/06/05 14:18:08.144 kid1| 33,3| AsyncCall.cc(56) cancel: will not call ConnStateData::clientPinnedConnectionRead [call2563] also because comm_read_cancel
2017/06/05 14:18:08.144 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 30, type=1, handler=0, client_data=0, timeout=0
2017/06/05 14:18:08.144 kid1| 5,3| comm.cc(868) _comm_close: comm_close: start closing FD 30
2017/06/05 14:18:08.144 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall commStartSslClose constructed, this=0x80e73a38 [call2574]
2017/06/05 14:18:08.144 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: comm.cc(902) will call commStartSslClose(FD 30) [call2574]
2017/06/05 14:18:08.144 kid1| 5,3| comm.cc(540) commUnsetFdTimeout: Remove timeout for FD 30
2017/06/05 14:18:08.144 kid1| 5,5| comm.cc(721) commCallCloseHandlers: commCallCloseHandlers: FD 30
2017/06/05 14:18:08.144 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall comm_close_complete constructed, this=0x80e84ea0 [call2575]
2017/06/05 14:18:08.144 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: comm.cc(941) will call comm_close_complete(FD 30) [call2575]
2017/06/05 14:18:08.144 kid1| 33,3| client_side.cc(846) ~ConnStateData: local=46.51.187.18:443 remote=10.215.145.187 flags=17
2017/06/05 14:18:08.144 kid1| 33,4| ServerBump.cc(44) ~ServerBump: destroying
2017/06/05 14:18:08.144 kid1| 33,4| ServerBump.cc(46) ~ServerBump: e:=sp2XDIV/0x80e0a448*1
2017/06/05 14:18:08.144 kid1| 90,3| store_client.cc(664) storeUnregister: storeUnregister: called for '52E847A2F8AF07D9783AAE4A91F2E9E6'
2017/06/05 14:18:08.144 kid1| 20,3| store_swapout.cc(356) mayStartSwapOut:  already rejected
2017/06/05 14:18:08.144 kid1| 20,2| store.cc(954) checkCachable: StoreEntry::checkCachable: NO: not cachable
2017/06/05 14:18:08.144 kid1| 20,3| store.cc(484) lock: storeUnregister locked key 52E847A2F8AF07D9783AAE4A91F2E9E6 e:=sp2XDIV/0x80e0a448*2
2017/06/05 14:18:08.144 kid1| 90,3| store_client.cc(758) storePendingNClients: storePendingNClients: returning 0
2017/06/05 14:18:08.144 kid1| 20,3| store.cc(522) unlock: storeUnregister unlocking key 52E847A2F8AF07D9783AAE4A91F2E9E6 e:=sp2XDIV/0x80e0a448*2
2017/06/05 14:18:08.145 kid1| 20,3| store.cc(522) unlock: Ssl::ServerBump unlocking key 52E847A2F8AF07D9783AAE4A91F2E9E6 e:=sp2XDIV/0x80e0a448*1
2017/06/05 14:18:08.145 kid1| 90,3| store_client.cc(758) storePendingNClients: storePendingNClients: returning 0
2017/06/05 14:18:08.145 kid1| 20,3| store.cc(1244) release: releasing e:=sp2XDIV/0x80e0a448*0 52E847A2F8AF07D9783AAE4A91F2E9E6
2017/06/05 14:18:08.145 kid1| 20,3| store.cc(403) destroyMemObject: destroyMemObject 0x80e09f08
2017/06/05 14:18:08.145 kid1| 20,3| MemObject.cc(110) ~MemObject: del MemObject 0x80e09f08
2017/06/05 14:18:08.145 kid1| 20,3| store.cc(421) destroyStoreEntry: destroyStoreEntry: destroying 0x80e0a44c
2017/06/05 14:18:08.145 kid1| 20,3| store.cc(403) destroyMemObject: destroyMemObject 0
2017/06/05 14:18:08.145 kid1| 20,5| store.cc(376) ~StoreEntry: StoreEntry destructed, this=0x80e0a448
2017/06/05 14:18:08.145 kid1| 93,5| AsyncJob.cc(40) ~AsyncJob: AsyncJob destructed, this=0x80e07f24 type=Http::Server [job56]
2017/06/05 14:18:08.145 kid1| 33,5| AsyncCallQueue.cc(57) fireNext: leaving ConnStateData::connStateClosed(FD -1, data=0x80e07e00)
2017/06/05 14:18:08.145 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering comm_close_complete(FD 29)
2017/06/05 14:18:08.145 kid1| 5,4| AsyncCall.cc(38) make: make call comm_close_complete [call2572]
2017/06/05 14:18:08.145 kid1| 51,3| fd.cc(93) fd_close: fd_close FD 29 Reading next request
2017/06/05 14:18:08.145 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=1, handler=0, client_data=0, timeout=0
2017/06/05 14:18:08.145 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=2, handler=0, client_data=0, timeout=0
2017/06/05 14:18:08.145 kid1| 5,5| AcceptLimiter.cc(55) kick: size=0
2017/06/05 14:18:08.145 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving comm_close_complete(FD 29)
2017/06/05 14:18:08.145 kid1| 93,5| AsyncCallQueue.cc(55) fireNext: entering Initiate::noteInitiatorAborted()
2017/06/05 14:18:08.145 kid1| 93,5| AsyncCall.cc(38) make: make call Initiate::noteInitiatorAborted [call2573]
2017/06/05 14:18:08.145 kid1| 93,5| AsyncCall.cc(56) cancel: will not call Initiate::noteInitiatorAborted [call2573] because job gone
2017/06/05 14:18:08.145 kid1| 93,5| AsyncCall.cc(48) make: will not call Initiate::noteInitiatorAborted [call2573] because of job gone
2017/06/05 14:18:08.145 kid1| 93,5| AsyncCallQueue.cc(57) fireNext: leaving Initiate::noteInitiatorAborted()
2017/06/05 14:18:08.145 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering commStartSslClose(FD 30)
2017/06/05 14:18:08.145 kid1| 5,4| AsyncCall.cc(38) make: make call commStartSslClose [call2574]
2017/06/05 14:18:08.146 kid1| 83,5| bio.cc(95) write: FD 30 wrote 53 <= 53
2017/06/05 14:18:08.146 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving commStartSslClose(FD 30)
2017/06/05 14:18:08.146 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering comm_close_complete(FD 30)
2017/06/05 14:18:08.146 kid1| 5,4| AsyncCall.cc(38) make: make call comm_close_complete [call2575]
2017/06/05 14:18:08.146 kid1| 51,3| fd.cc(93) fd_close: fd_close FD 30 [unknown] pinned connection for 10.215.145.187 (29)
2017/06/05 14:18:08.146 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 30, type=1, handler=0, client_data=0, timeout=0
2017/06/05 14:18:08.146 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 30, type=2, handler=0, client_data=0, timeout=0
2017/06/05 14:18:08.146 kid1| 5,5| AcceptLimiter.cc(55) kick: size=0
2017/06/05 14:18:08.146 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving comm_close_complete(FD 30)
2017/06/05 14:18:08.146 kid1| 50,3| ModDaemon.cc(108) logfileHandleWrite: daemon:/var/log/squid/access.test.log: write returned 109
2017/06/05 14:18:08.146 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 21, type=2, handler=0, client_data=0, timeout=0
2017/06/05 14:18:08.786 kid1| 41,5| AsyncCall.cc(26) AsyncCall: The AsyncCall MaintainSwapSpace constructed, this=0x80d3d960 [call2576]
2017/06/05 14:18:08.786 kid1| 41,5| AsyncCall.cc(93) ScheduleCall: event.cc(237) will call MaintainSwapSpace() [call2576]
2017/06/05 14:18:08.786 kid1| 41,5| AsyncCallQueue.cc(55) fireNext: entering MaintainSwapSpace()
2017/06/05 14:18:08.786 kid1| 41,5| AsyncCall.cc(38) make: make call MaintainSwapSpace [call2576]
2017/06/05 14:18:08.786 kid1| 47,5| ufs/UFSSwapDir.cc(447) maintain: space still available in /var/cache/squid.test
2017/06/05 14:18:08.786 kid1| 41,5| AsyncCallQueue.cc(57) fireNext: leaving MaintainSwapSpace()
2017/06/05 14:18:08.786 kid1| 41,5| AsyncCall.cc(26) AsyncCall: The AsyncCall logfileFlush constructed, this=0x80d3d960 [call2577]
2017/06/05 14:18:08.786 kid1| 41,5| AsyncCall.cc(93) ScheduleCall: event.cc(237) will call logfileFlush(0x808fb030*?) [call2577]
2017/06/05 14:18:08.787 kid1| 41,5| AsyncCallQueue.cc(55) fireNext: entering logfileFlush(0x808fb030*?)
2017/06/05 14:18:08.787 kid1| 41,5| AsyncCall.cc(38) make: make call logfileFlush [call2577]
2017/06/05 14:18:08.787 kid1| 41,5| AsyncCallQueue.cc(57) fireNext: leaving logfileFlush(0x808fb030*?)

I tried to make something out of the log before the generation of ERR_INVALID_REQ, but I'm a bit lost here.

Thanks,

Vieri
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: squid ssl bump and Adobe Connect

Amos Jeffries
Administrator
On 06/06/17 18:08, Vieri wrote:

> ________________________________
> From: Alex Rousskov <[hidden email]>
>>> 1496665088.143      6 10.215.145.187 TAG_NONE/400 4428 NONE error:invalid-request - HIER_NONE/-
>>> text/html>
>> I recommend finding the place in the debugging cache.log where Squid
>> generates the above error response and then going backwards to find the
>> cause.
> OK Alex, got it.
> In the meantime, I searched for the events around the time this happened.
> BTW as a side question I'd like to know if I can change the timestamp in cache.log so it can print the unixtime as in access.log.
>
> In any case, here's the relevant part:
>
> [Mon Jun  5 14:18:08 2017].143      6 10.215.145.187 TAG_NONE/400 4428 NONE error:invalid-request - HIER_NONE/- text/html
>
> cache.log within 14:18:08:

<snip>

> 2017/06/05 14:18:08.129 kid1| 83,2| client_side.cc(3796) clientNegotiateSSL: clientNegotiateSSL: New session 0x80e80e30 on FD 29 (10.215.145.187:54815)
> 2017/06/05 14:18:08.129 kid1| 83,3| client_side.cc(3800) clientNegotiateSSL: clientNegotiateSSL: FD 29 negotiated cipher AES128-SHA
> 2017/06/05 14:18:08.129 kid1| 83,5| client_side.cc(3816) clientNegotiateSSL: clientNegotiateSSL: FD 29 has no certificate.
> 2017/06/05 14:18:08.129 kid1| 33,4| client_side.cc(231) readSomeData: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: reading request...
> 2017/06/05 14:18:08.129 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::clientReadRequest constructed, this=0x80e80578 [call2567]
> 2017/06/05 14:18:08.129 kid1| 5,5| Read.cc(58) comm_read_base: comm_read, queueing read for local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17; asynCall 0x80e80578*1
> 2017/06/05 14:18:08.129 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=1, handler=1, client_data=0x808b48b8, timeout=0
> 2017/06/05 14:18:08.135 kid1| 5,3| IoCallback.cc(116) finish: called for local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 (0, 0)
> 2017/06/05 14:18:08.135 kid1| 33,5| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call ConnStateData::clientReadRequest(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80e07e00) [call2567]
> 2017/06/05 14:18:08.135 kid1| 33,5| AsyncCallQueue.cc(55) fireNext: entering ConnStateData::clientReadRequest(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80e07e00)
> 2017/06/05 14:18:08.135 kid1| 33,5| AsyncCall.cc(38) make: make call ConnStateData::clientReadRequest [call2567]
> 2017/06/05 14:18:08.135 kid1| 33,5| AsyncJob.cc(123) callStart: Http::Server status in: [ job56]
> 2017/06/05 14:18:08.136 kid1| 33,5| client_side.cc(3251) clientReadRequest: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17
> 2017/06/05 14:18:08.136 kid1| 83,5| bio.cc(118) read: FD 29 read 5 <= 5
> 2017/06/05 14:18:08.136 kid1| 83,5| bio.cc(118) read: FD 29 read 1568 <= 1568
> 2017/06/05 14:18:08.136 kid1| 83,2| support.cc(1364) ssl_read_method: SSL FD 29 is pending

FD 29 went through SSL-Bump processing and was bump'ed. An HTTPS request
message is now expected to arrive.

> 2017/06/05 14:18:08.136 kid1| 5,3| Read.cc(91) ReadNow: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, size 66, retval 66, errno 0
> 2017/06/05 14:18:08.136 kid1| 33,5| client_side.cc(3200) clientParseRequests: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: attempting to parse

... 66 bytes arrive ...

> 2017/06/05 14:18:08.136 kid1| 74,5| HttpParser.cc(37) reset: Request buffer is
> 2017/06/05 14:18:08.136 kid1| 74,5| HttpParser.cc(47) parseRequestFirstLine: parsing possible request:
> 2017/06/05 14:18:08.136 kid1| 74,5| HttpParser.cc(257) HttpParserParseReqLine: Parser: retval -1: from 0->4: method 0->-1; url -1->-1; version -1->-1 (0/0)

The first 4 bytes were ones which cannot exist at the start if any HTTP
message - so the protocol being bumped on port 443 was not HTTPS.

Squid then proceeds to generate and send the invalid-request error
response to this non-HTTPS over port 443.


Amos
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Loading...