[squid-users] after changed from 3.4.13 to 3.5.8 sslbump doesn't work for the site https://banking.postbank.de/

[Sebastian Kirschner]

I increased the log level and performed a GET to https://banking.postbank.de/ , what I don't get is why squid start to generate a certificate for the ssl bump ?

cache.log
2015/09/28 14:25:28.964 kid1| 33,5| client_side.cc(4135) getSslContextStart: Generating SSL certificate for banking.postbank.de using ssl_crtd.
2015/09/28 14:25:28.964 kid1| 33,5| client_side.cc(4139) getSslContextStart: SSL crtd request: new_certificate 8149 host=banking.postbank.de
Sign=signTrusted
SignHash=SHA256
-----BEGIN CERTIFICATE-----
<snip>
-----END CERTIFICATE-----

2015/09/28 14:25:28.964 kid1| 84,5| helper.cc(1167) GetFirstAvailable: GetFirstAvailable: Running servers 5
2015/09/28 14:25:28.964 kid1| 5,5| AsyncCall.cc(26) AsyncCall: The AsyncCall helperDispatchWriteDone constructed, this=0x80775fc00 [call183]
2015/09/28 14:25:28.964 kid1| 5,5| Write.cc(35) Write: local=[::] remote=[::] FD 7 flags=1: sz 8171: asynCall 0x80775fc00*1
2015/09/28 14:25:28.964 kid1| 5,5| ModPoll.cc(131) SetSelect: FD 7, type=2, handler=1, client_data=0x806800400, timeout=0
2015/09/28 14:25:28.964 kid1| 84,5| helper.cc(1309) helperDispatch: helperDispatch: Request sent to ssl_crtd #Hlpr1, 8171 bytes
2015/09/28 14:25:28.964 kid1| 17,4| AsyncJob.cc(152) callEnd: Http::Server status out: [ job6]
2015/09/28 14:25:28.964 kid1| 17,4| AsyncCallQueue.cc(57) fireNext: leaving ConnStateData::ConnStateData::httpsPeeked(local=wan.ip.adress:8985 remote=62.153.105.15:443 FD 17 flags=1)
2015/09/28 14:25:28.964 kid1| 93,5| AsyncCallQueue.cc(55) fireNext: entering Initiate::noteInitiatorAborted()
2015/09/28 14:25:28.964 kid1| 93,5| AsyncCall.cc(38) make: make call Initiate::noteInitiatorAborted [call182]
2015/09/28 14:25:28.964 kid1| 93,5| AsyncCall.cc(56) cancel: will not call Initiate::noteInitiatorAborted [call182] because job gone
2015/09/28 14:25:28.964 kid1| 93,5| AsyncCall.cc(48) make: will not call Initiate::noteInitiatorAborted [call182] because of job gone
2015/09/28 14:25:28.964 kid1| 93,5| AsyncCallQueue.cc(57) fireNext: leaving Initiate::noteInitiatorAborted()
2015/09/28 14:25:28.964 kid1| 5,5| ModPoll.cc(435) DoSelect: comm_poll: 2+0 FDs ready
2015/09/28 14:25:28.964 kid1| 5,5| Write.cc(66) HandleWrite: local=[::] remote=[::] FD 7 flags=1: off 0, sz 8171.
2015/09/28 14:25:28.964 kid1| 5,5| Write.cc(108) HandleWrite: write() returns 8171
2015/09/28 14:25:28.964 kid1| 5,3| IoCallback.cc(116) finish: called for local=[::] remote=[::] FD 7 flags=1 (0, 0)
2015/09/28 14:25:28.964 kid1| 5,5| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call helperDispatchWriteDone(local=[::] remote=[::] FD 7 flags=1, data=0x804bc2718, size=8171, buf=0x804bfb000) [call183]
2015/09/28 14:25:28.965 kid1| 5,3| IoCallback.cc(116) finish: called for local=wan.ip.adress:8985 remote=62.153.105.15:443 FD 17 flags=1 (0, 0)
2015/09/28 14:25:28.965 kid1| 33,3| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call ConnStateData::clientPinnedConnectionRead(local=wan.ip.adress:8985 remote=62.153.105.15:443 FD 17 flags=1, data=0x804b6e798) [call181]
2015/09/28 14:25:28.965 kid1| 5,5| AsyncCallQueue.cc(55) fireNext: entering helperDispatchWriteDone(local=[::] remote=[::] FD 7 flags=1, data=0x804bc2718, size=8171, buf=0x804bfb000)
2015/09/28 14:25:28.965 kid1| 5,5| AsyncCall.cc(38) make: make call helperDispatchWriteDone [call183]
2015/09/28 14:25:28.965 kid1| 5,5| AsyncCallQueue.cc(57) fireNext: leaving helperDispatchWriteDone(local=[::] remote=[::] FD 7 flags=1, data=0x804bc2718, size=8171, buf=0x804bfb000)
2015/09/28 14:25:28.965 kid1| 33,3| AsyncCallQueue.cc(55) fireNext: entering ConnStateData::clientPinnedConnectionRead(local=wan.ip.adress:8985 remote=62.153.105.15:443 FD 17 flags=1, data=0x804b6e798)
2015/09/28 14:25:28.965 kid1| 33,3| AsyncCall.cc(38) make: make call ConnStateData::clientPinnedConnectionRead [call181]
2015/09/28 14:25:28.965 kid1| 33,3| AsyncJob.cc(123) callStart: Http::Server status in: [ job6]
2015/09/28 14:25:28.965 kid1| 33,3| client_side.cc(5010) clientPinnedConnectionRead: idle pinned local=wan.ip.adress:8985 remote=62.153.105.15:443 FD 17 flags=1 read 0 with idle client
2015/09/28 14:25:28.965 kid1| 5,3| comm.cc(868) _comm_close: comm_close: start closing FD 17
2015/09/28 14:25:28.965 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall commStartSslClose constructed, this=0x80777d4e0 [call184]
2015/09/28 14:25:28.965 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: comm.cc(902) will call commStartSslClose(FD 17) [call184]
2015/09/28 14:25:28.965 kid1| 5,3| comm.cc(540) commUnsetFdTimeout: Remove timeout for FD 17
2015/09/28 14:25:28.965 kid1| 5,5| comm.cc(721) commCallCloseHandlers: commCallCloseHandlers: FD 17
2015/09/28 14:25:28.965 kid1| 5,5| comm.cc(729) commCallCloseHandlers: commCallCloseHandlers: ch->handler=0x80775b740*2
2015/09/28 14:25:28.965 kid1| 33,5| AsyncCall.cc(93) ScheduleCall: comm.cc(730) will call ConnStateData::clientPinnedConnectionClosed(local=wan.ip.adress:8985 remote=62.153.105.15:443 FD 17 flags=1, data=0x804b6e798) [call180]
2015/09/28 14:25:28.965 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall comm_close_complete constructed, this=0x80777d550 [call185]
2015/09/28 14:25:28.965 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: comm.cc(941) will call comm_close_complete(FD 17) [call185]
2015/09/28 14:25:28.965 kid1| 5,3| comm.cc(868) _comm_close: comm_close: start closing FD 11
2015/09/28 14:25:28.965 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall commStartSslClose constructed, this=0x80777d5c0 [call186]
2015/09/28 14:25:28.965 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: comm.cc(902) will call commStartSslClose(FD 11) [call186]
2015/09/28 14:25:28.965 kid1| 5,3| comm.cc(540) commUnsetFdTimeout: Remove timeout for FD 11
2015/09/28 14:25:28.965 kid1| 5,5| comm.cc(721) commCallCloseHandlers: commCallCloseHandlers: FD 11
2015/09/28 14:25:28.965 kid1| 5,5| comm.cc(729) commCallCloseHandlers: commCallCloseHandlers: ch->handler=0x807574560*1
2015/09/28 14:25:28.965 kid1| 33,5| AsyncCall.cc(93) ScheduleCall: comm.cc(730) will call ConnStateData::connStateClosed(FD -1, data=0x804b6e798) [call123]
2015/09/28 14:25:28.965 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall comm_close_complete constructed, this=0x804c0d240 [call187]
2015/09/28 14:25:28.965 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: comm.cc(941) will call comm_close_complete(FD 11) [call187]
2015/09/28 14:25:28.965 kid1| 33,3| AsyncJob.cc(152) callEnd: Http::Server status out: [ job6]
2015/09/28 14:25:28.965 kid1| 33,3| AsyncCallQueue.cc(57) fireNext: leaving ConnStateData::clientPinnedConnectionRead(local=wan.ip.adress:8985 remote=62.153.105.15:443 flags=1, data=0x804b6e798)
2015/09/28 14:25:28.965 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering commStartSslClose(FD 17)
2015/09/28 14:25:28.965 kid1| 5,4| AsyncCall.cc(38) make: make call commStartSslClose [call184]
2015/09/28 14:25:28.966 kid1| 83,5| bio.cc(95) write: FD 17 wrote 53 <= 53
2015/09/28 14:25:28.966 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving commStartSslClose(FD 17)
2015/09/28 14:25:28.966 kid1| 33,5| AsyncCallQueue.cc(55) fireNext: entering ConnStateData::clientPinnedConnectionClosed(local=wan.ip.adress:8985 remote=62.153.105.15:443 flags=1, data=0x804b6e798)
2015/09/28 14:25:28.966 kid1| 33,5| AsyncCall.cc(38) make: make call ConnStateData::clientPinnedConnectionClosed [call180]
2015/09/28 14:25:28.966 kid1| 33,5| AsyncJob.cc(123) callStart: Http::Server status in: [ job6]
2015/09/28 14:25:28.966 kid1| 33,3| client_side.cc(5060) unpinConnection: local=wan.ip.adress:8985 remote=62.153.105.15:443 flags=1
2015/09/28 14:25:28.966 kid1| 33,5| AsyncJob.cc(152) callEnd: Http::Server status out: [ job6]
2015/09/28 14:25:28.966 kid1| 33,5| AsyncCallQueue.cc(57) fireNext: leaving ConnStateData::clientPinnedConnectionClosed(local=wan.ip.adress:8985 remote=62.153.105.15:443 flags=1, data=0x804b6e798)
2015/09/28 14:25:28.966 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering comm_close_complete(FD 17)
2015/09/28 14:25:28.966 kid1| 5,4| AsyncCall.cc(38) make: make call comm_close_complete [call185]
2015/09/28 14:25:28.966 kid1| 51,3| fd.cc(93) fd_close: fd_close FD 17 [unknown] pinned connection for client.ip.adress:57125 (11)
2015/09/28 14:25:28.966 kid1| 5,5| ModPoll.cc(131) SetSelect: FD 17, type=1, handler=0, client_data=0x0, timeout=0
2015/09/28 14:25:28.966 kid1| 5,5| ModPoll.cc(131) SetSelect: FD 17, type=2, handler=0, client_data=0x0, timeout=0
2015/09/28 14:25:28.966 kid1| 5,5| AcceptLimiter.cc(55) kick: size=0
2015/09/28 14:25:28.966 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving comm_close_complete(FD 17)
2015/09/28 14:25:28.966 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering commStartSslClose(FD 11)
2015/09/28 14:25:28.966 kid1| 5,4| AsyncCall.cc(38) make: make call commStartSslClose [call186]
2015/09/28 14:25:28.966 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving commStartSslClose(FD 11)
2015/09/28 14:25:28.966 kid1| 33,5| AsyncCallQueue.cc(55) fireNext: entering ConnStateData::connStateClosed(FD -1, data=0x804b6e798)
2015/09/28 14:25:28.966 kid1| 33,5| AsyncCall.cc(38) make: make call ConnStateData::connStateClosed [call123]
2015/09/28 14:25:28.966 kid1| 33,5| AsyncJob.cc(123) callStart: Http::Server status in: [ job6]
2015/09/28 14:25:28.966 kid1| 93,4| AsyncJob.cc(55) deleteThis: Http::Server will NOT delete in-call job, reason: ConnStateData::connStateClosed
2015/09/28 14:25:28.966 kid1| 93,5| AsyncJob.cc(137) callEnd: ConnStateData::connStateClosed(FD -1, data=0x804b6e798) ends job [Stopped, reason:ConnStateData::connStateClosed job6]
2015/09/28 14:25:28.966 kid1| 33,2| client_side.cc(815) swanSong: local=62.153.105.15:443 remote=client.ip.adress:57125 flags=33
2015/09/28 14:25:28.966 kid1| 33,3| client_side.cc(5060) unpinConnection: local=wan.ip.adress:8985 remote=62.153.105.15:443 flags=1
2015/09/28 14:25:28.966 kid1| 33,3| client_side.cc(846) ~ConnStateData: local=62.153.105.15:443 remote=client.ip.adress:57125 flags=33
2015/09/28 14:25:28.966 kid1| 33,4| ServerBump.cc(44) ~ServerBump: destroying
2015/09/28 14:25:28.966 kid1| 33,4| ServerBump.cc(46) ~ServerBump: e:=sp2XDIV/0x804ba8180*1
2015/09/28 14:25:28.967 kid1| 93,5| AsyncJob.cc(40) ~AsyncJob: AsyncJob destructed, this=0x804b6e960 type=Http::Server [job6]
2015/09/28 14:25:28.967 kid1| 33,5| AsyncCallQueue.cc(57) fireNext: leaving ConnStateData::connStateClosed(FD -1, data=0x804b6e798)
2015/09/28 14:25:28.967 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering comm_close_complete(FD 11)
2015/09/28 14:25:28.967 kid1| 5,4| AsyncCall.cc(38) make: make call comm_close_complete [call187]
2015/09/28 14:25:28.968 kid1| 51,3| fd.cc(93) fd_close: fd_close FD 11 client https start
2015/09/28 14:25:28.968 kid1| 5,5| ModPoll.cc(131) SetSelect: FD 11, type=1, handler=0, client_data=0x0, timeout=0
2015/09/28 14:25:28.968 kid1| 5,5| ModPoll.cc(131) SetSelect: FD 11, type=2, handler=0, client_data=0x0, timeout=0
2015/09/28 14:25:28.968 kid1| 5,5| AcceptLimiter.cc(55) kick: size=0
2015/09/28 14:25:28.968 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving comm_close_complete(FD 11)
2015/09/28 14:25:29.030 kid1| 5,5| ModPoll.cc(435) DoSelect: comm_poll: 1+0 FDs ready
2015/09/28 14:25:29.031 kid1| 5,3| Read.cc(144) HandleRead: FD 7, size 4095, retval 4095, errno 0
2015/09/28 14:25:29.031 kid1| 5,3| IoCallback.cc(116) finish: called for local=[::] remote=[::] FD 7 flags=1 (0, 0)
2015/09/28 14:25:29.031 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call helperHandleRead(local=[::] remote=[::] FD 7 flags=1, data=0x804bc2718, size=4095, buf=0x804c0b000) [call3]
2015/09/28 14:25:29.031 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering helperHandleRead(local=[::] remote=[::] FD 7 flags=1, data=0x804bc2718, size=4095, buf=0x804c0b000)
2015/09/28 14:25:29.031 kid1| 5,4| AsyncCall.cc(38) make: make call helperHandleRead [call3]
2015/09/28 14:25:29.031 kid1| 84,5| helper.cc(866) helperHandleRead: helperHandleRead: 4095 bytes from ssl_crtd #Hlpr1
2015/09/28 14:25:29.031 kid1| 84,3| helper.cc(924) helperHandleRead: Grew read buffer to 8192
2015/09/28 14:25:29.031 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall helperHandleRead constructed, this=0x8076eb600 [call188]
2015/09/28 14:25:29.031 kid1| 5,5| Read.cc(58) comm_read_base: comm_read, queueing read for local=[::] remote=[::] FD 7 flags=1; asynCall 0x8076eb600*1
2015/09/28 14:25:29.031 kid1| 5,5| ModPoll.cc(131) SetSelect: FD 7, type=1, handler=1, client_data=0x8068003c0, timeout=0
2015/09/28 14:25:29.031 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving helperHandleRead(local=[::] remote=[::] FD 7 flags=1, data=0x804bc2718, size=4095, buf=0x804c0b000)
2015/09/28 14:25:29.031 kid1| 5,5| ModPoll.cc(435) DoSelect: comm_poll: 1+0 FDs ready
2015/09/28 14:25:29.031 kid1| 5,3| Read.cc(144) HandleRead: FD 7, size 4096, retval 1540, errno 0
2015/09/28 14:25:29.031 kid1| 5,3| IoCallback.cc(116) finish: called for local=[::] remote=[::] FD 7 flags=1 (0, 0)
2015/09/28 14:25:29.031 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call helperHandleRead(local=[::] remote=[::] FD 7 flags=1, data=0x804bc2718, size=1540, buf=0x804bfbfff) [call188]
2015/09/28 14:25:29.031 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering helperHandleRead(local=[::] remote=[::] FD 7 flags=1, data=0x804bc2718, size=1540, buf=0x804bfbfff)
2015/09/28 14:25:29.031 kid1| 5,4| AsyncCall.cc(38) make: make call helperHandleRead [call188]
2015/09/28 14:25:29.032 kid1| 84,5| helper.cc(866) helperHandleRead: helperHandleRead: 1540 bytes from ssl_crtd #Hlpr1
2015/09/28 14:25:29.032 kid1| 84,3| helper.cc(892) helperHandleRead: helperHandleRead: end of reply found
2015/09/28 14:25:29.032 kid1| 84,5| helper.cc(1167) GetFirstAvailable: GetFirstAvailable: Running servers 5
2015/09/28 14:25:29.032 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall helperHandleRead constructed, this=0x804960080 [call189]
2015/09/28 14:25:29.032 kid1| 5,5| Read.cc(58) comm_read_base: comm_read, queueing read for local=[::] remote=[::] FD 7 flags=1; asynCall 0x804960080*1
2015/09/28 14:25:29.032 kid1| 5,5| ModPoll.cc(131) SetSelect: FD 7, type=1, handler=1, client_data=0x8068003c0, timeout=0
2015/09/28 14:25:29.032 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving helperHandleRead(local=[::] remote=[::] FD 7 flags=1, data=0x804bc2718, size=1540, buf=0x804bfbfff)

Mit freundlichen Grüßen / Best Regards

Sebastian Kirschner