On 06/06/17 18:08, Vieri wrote:
________________________________
From: Alex Rousskov <[email protected]>
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
[email protected]
http://lists.squid-cache.org/listinfo/squid-users
