[squid-users] Squid Proxy SSL Bump can not retrieve SSL session back to the client?

Mon Dec 9 17:56:50 UTC 2019

Hi Alex,

this time I tried, a little different, this is the log from got the server
certs to colose the
SSL with error, and at the end, it is also saying security_file_certgen
crashes rapidly!!!

below the output of log
thanks.
- George

geyBC5spVGniTZ9g4/4EALHmrmP0d4vcbw0FJugljU7jWmdiUQEpoZZCovZY+lyX
IGRmShEZ6Enq77nr6xgMpW080lJojSBBE0bG7tJj8sUeU03xVyHJZJ4cNX7VD/Dn
g0KNg0PA4UvJLMoKal8UqHzxNXjZZ778O7mOOyvdHfkHgUsFdp9a25/nzduUFQ4R
8faCm0U26P8C
-----END CERTIFICATE-----

2019/12/09 09:39:32.243 kid1| 83,5| helper.cc(136) Submit: request from
0x256a4a8 as crtGenRq12500/1
2019/12/09 09:39:32.243 kid1| 84,5| helper.cc(1247) GetFirstAvailable:
GetFirstAvailable: Running servers 5
2019/12/09 09:39:32.243 kid1| 5,5| AsyncCall.cc(26) AsyncCall: The AsyncCall
helperDispatchWriteDone constructed, this=0x2557fe0 [call2906]
2019/12/09 09:39:32.243 kid1| 5,5| Write.cc(35) Write: local=[::]
remote=[::] FD 10 flags=1: sz 5266: asynCall 0x2557fe0*1
2019/12/09 09:39:32.243 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 10,
type=2, handler=1, client_data=0x2091e30, timeout=0
2019/12/09 09:39:32.243 kid1| 84,5| helper.cc(1379) helperDispatch:
helperDispatch: Request sent to
/usr/local/squid/libexec/security_file_certgen -s
/usr/local/squid/var/logs/ssl_db -M 4MB #Hlpr1, 5266 bytes
2019/12/09 09:39:32.243 kid1| 17,4| AsyncJob.cc(154) callEnd: Http1::Server
status out: [ job203]
2019/12/09 09:39:32.243 kid1| 17,4| AsyncCallQueue.cc(57) fireNext: leaving
ConnStateData::ConnStateData::httpsPeeked(local=192.168.1.35:46896
remote=X.Y.82.162:443 FD 15 flags=1, request=0x20fb630*3)
2019/12/09 09:39:32.243 kid1| 93,5| AsyncCallQueue.cc(55) fireNext: entering
Initiate::noteInitiatorAborted()
2019/12/09 09:39:32.243 kid1| 93,5| AsyncCall.cc(38) make: make call
Initiate::noteInitiatorAborted [call2905]
2019/12/09 09:39:32.243 kid1| 93,5| AsyncCall.cc(56) cancel: will not call
Initiate::noteInitiatorAborted [call2905] because job gone
2019/12/09 09:39:32.243 kid1| 93,5| AsyncCall.cc(48) make: will not call
Initiate::noteInitiatorAborted [call2905] because of job gone
2019/12/09 09:39:32.243 kid1| 93,5| AsyncCallQueue.cc(57) fireNext: leaving
Initiate::noteInitiatorAborted()
2019/12/09 09:39:32.243 kid1| 50,3| ModDaemon.cc(110) logfileHandleWrite:
daemon:/usr/local/squid/var/logs/access.log: write returned 106
2019/12/09 09:39:32.243 kid1| 5,5| Write.cc(66) HandleWrite: local=[::]
remote=[::] FD 10 flags=1: off 0, sz 5266.
2019/12/09 09:39:32.243 kid1| 5,5| Write.cc(108) HandleWrite: write()
returns 5266
2019/12/09 09:39:32.243 kid1| 5,3| IoCallback.cc(116) finish: called for
local=[::] remote=[::] FD 10 flags=1 (0, 0)
2019/12/09 09:39:32.243 kid1| 5,5| AsyncCall.cc(93) ScheduleCall:
IoCallback.cc(135) will call helperDispatchWriteDone(local=[::] remote=[::]
FD 10 flags=1, data=0x20b4b18, size=5266, buf=0x20ea960) [call2906]
2019/12/09 09:39:32.243 kid1| 5,5| AsyncCallQueue.cc(55) fireNext: entering
helperDispatchWriteDone(local=[::] remote=[::] FD 10 flags=1,
data=0x20b4b18, size=5266, buf=0x20ea960)
2019/12/09 09:39:32.243 kid1| 5,5| AsyncCall.cc(38) make: make call
helperDispatchWriteDone [call2906]
2019/12/09 09:39:32.243 kid1| 5,5| AsyncCallQueue.cc(57) fireNext: leaving
helperDispatchWriteDone(local=[::] remote=[::] FD 10 flags=1,
data=0x20b4b18, size=5266, buf=0x20ea960)
2019/12/09 09:39:32.243 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 20,
type=2, handler=0, client_data=0, timeout=0
2019/12/09 09:39:32.243 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 10,
type=2, handler=0, client_data=0, timeout=0
2019/12/09 09:39:32.244 kid1| 5,3| Read.cc(145) HandleRead: FD 10, size
32767, retval 3401, errno 0
2019/12/09 09:39:32.244 kid1| 5,3| IoCallback.cc(116) finish: called for
local=[::] remote=[::] FD 10 flags=1 (0, 0)
2019/12/09 09:39:32.244 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
IoCallback.cc(135) will call helperHandleRead(local=[::] remote=[::] FD 10
flags=1, data=0x20b4b18, size=3401, buf=0x20b4d40) [call2841]
2019/12/09 09:39:32.244 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering
helperHandleRead(local=[::] remote=[::] FD 10 flags=1, data=0x20b4b18,
size=3401, buf=0x20b4d40)
2019/12/09 09:39:32.244 kid1| 5,4| AsyncCall.cc(38) make: make call
helperHandleRead [call2841]
2019/12/09 09:39:32.244 kid1| 84,5| helper.cc(963) helperHandleRead:
helperHandleRead: 3401 bytes from
/usr/local/squid/libexec/security_file_certgen -s
/usr/local/squid/var/logs/ssl_db -M 4MB #Hlpr1
2019/12/09 09:39:32.244 kid1| 84,3| helper.cc(991) helperHandleRead:
helperHandleRead: end of reply found
2019/12/09 09:39:32.244 kid1| 84,3| Reply.cc(41) finalize: Parsing helper
buffer
2019/12/09 09:39:32.244 kid1| 84,3| Reply.cc(59) finalize: Buff length is
larger than 2
2019/12/09 09:39:32.244 kid1| 84,3| Reply.cc(63) finalize: helper Result =
OK
2019/12/09 09:39:32.244 kid1| 83,5| helper.cc(158) HandleGeneratorReply: to
0x256a4a8 in crtGenRq12500/1
2019/12/09 09:39:32.244 kid1| 33,5| client_side.cc(2870) sslCrtdHandleReply:
Certificate for X.Y.82.162 was successfully recieved from ssl_crtd
2019/12/09 09:39:32.245 kid1| 33,5| client_side.cc(3358)
doPeekAndSpliceStep: PeekAndSplice mode, proceed with client negotiation.
Currrent state:SSLv2/v3 read client hello A
2019/12/09 09:39:32.245 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 13,
type=2, handler=1, client_data=0x256a4a8, timeout=0
2019/12/09 09:39:32.245 kid1| 84,5| helper.cc(1247) GetFirstAvailable:
GetFirstAvailable: Running servers 5
2019/12/09 09:39:32.245 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall
helperHandleRead constructed, this=0x258f150 [call2907]
2019/12/09 09:39:32.245 kid1| 5,5| Read.cc(57) comm_read_base: comm_read,
queueing read for local=[::] remote=[::] FD 10 flags=1; asynCall 0x258f150*1
2019/12/09 09:39:32.245 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 10,
type=1, handler=1, client_data=0x2091df8, timeout=0
2019/12/09 09:39:32.245 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving
helperHandleRead(local=[::] remote=[::] FD 10 flags=1, data=0x20b4b18,
size=3401, buf=0x20b4d40)
2019/12/09 09:39:32.245 kid1| 83,5| bio.cc(612) squid_bio_ctrl: 0x20d61f0
6(0, 0x2592b20)
2019/12/09 09:39:32.245 kid1| 83,5| bio.cc(113) write: FD 13 wrote 7 <= 7
2019/12/09 09:39:32.245 kid1| 83,5| bio.cc(612) squid_bio_ctrl: 0x20d61f0
11(0, 0)
2019/12/09 09:39:32.245 kid1| *Error negotiating SSL connection on FD 13:
error:00000001:lib(0):func(0):reason(1) (1/-1)*
2019/12/09 09:39:32.245 kid1| 5,3| comm.cc(859) _comm_close: comm_close:
start closing FD 13
2019/12/09 09:39:32.245 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall
commStartTlsClose constructed, this=0x25983a0 [call2908]
2019/12/09 09:39:32.245 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(892) will call commStartTlsClose(FD 13) [call2908]
2019/12/09 09:39:32.245 kid1| 5,3| comm.cc(546) commUnsetFdTimeout: Remove
timeout for FD 13
2019/12/09 09:39:32.245 kid1| 5,5| comm.cc(727) commCallCloseHandlers:
commCallCloseHandlers: FD 13
2019/12/09 09:39:32.245 kid1| 5,5| comm.cc(735) commCallCloseHandlers:
commCallCloseHandlers: ch->handler=0x256df80*1
2019/12/09 09:39:32.245 kid1| 33,5| AsyncCall.cc(93) ScheduleCall:
comm.cc(736) will call ConnStateData::connStateClosed(FD -1, data=0x256a4a8)
[call2864]
2019/12/09 09:39:32.245 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall
comm_close_complete constructed, this=0x256d600 [call2909]
2019/12/09 09:39:32.245 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(930) will call comm_close_complete(FD 13) [call2909]
2019/12/09 09:39:32.245 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering
commStartTlsClose(FD 13)
2019/12/09 09:39:32.245 kid1| 5,4| AsyncCall.cc(38) make: make call
commStartTlsClose [call2908]
2019/12/09 09:39:32.245 kid1| 83,5| Session.cc(202) SessionSendGoodbye:
session=0x259dbd0
2019/12/09 09:39:32.245 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving
commStartTlsClose(FD 13)
2019/12/09 09:39:32.245 kid1| 33,5| AsyncCallQueue.cc(55) fireNext: entering
ConnStateData::connStateClosed(FD -1, data=0x256a4a8)
2019/12/09 09:39:32.246 kid1| 33,5| AsyncCall.cc(38) make: make call
ConnStateData::connStateClosed [call2864]
2019/12/09 09:39:32.246 kid1| 33,5| AsyncJob.cc(123) callStart:
Http1::Server status in: [ job203]
2019/12/09 09:39:32.246 kid1| 93,4| AsyncJob.cc(55) deleteThis:
Http1::Server will NOT delete in-call job, reason:
ConnStateData::connStateClosed
2019/12/09 09:39:32.246 kid1| 93,5| AsyncJob.cc(139) callEnd:
ConnStateData::connStateClosed(FD -1, data=0x256a4a8) ends job [Stopped,
reason:ConnStateData::connStateClosed job203]
2019/12/09 09:39:32.246 kid1| 33,2| client_side.cc(582) swanSong:
local=X.Y.82.162:443 remote=192.168.1.25:53556 flags=33
2019/12/09 09:39:32.246 kid1| 33,3| client_side.cc(4118) unpinConnection:
local=192.168.1.35:46896 remote=X.Y.82.162:443 FD 15 flags=1
2019/12/09 09:39:32.246 kid1| 5,5| comm.cc(1030) comm_remove_close_handler:
comm_remove_close_handler: FD 15, AsyncCall=0x25b4d10*2
2019/12/09 09:39:32.246 kid1| 33,5| AsyncCall.cc(56) cancel: will not call
ConnStateData::clientPinnedConnectionClosed [call2903] because
comm_remove_close_handler
2019/12/09 09:39:32.246 kid1| 33,3| AsyncCall.cc(56) cancel: will not call
ConnStateData::clientPinnedConnectionRead [call2904] because
comm_read_cancel
2019/12/09 09:39:32.246 kid1| 33,3| AsyncCall.cc(56) cancel: will not call
ConnStateData::clientPinnedConnectionRead [call2904] also because
comm_read_cancel
2019/12/09 09:39:32.246 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 15,
type=1, handler=0, client_data=0, timeout=0
2019/12/09 09:39:32.246 kid1| 5,3| comm.cc(859) _comm_close: comm_close:
start closing FD 15
2019/12/09 09:39:32.246 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall
commStartTlsClose constructed, this=0x25983a0 [call2910]
2019/12/09 09:39:32.246 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(892) will call commStartTlsClose(FD 15) [call2910]
2019/12/09 09:39:32.246 kid1| 5,3| comm.cc(546) commUnsetFdTimeout: Remove
timeout for FD 15
2019/12/09 09:39:32.246 kid1| 5,5| comm.cc(727) commCallCloseHandlers:
commCallCloseHandlers: FD 15
2019/12/09 09:39:32.246 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall
comm_close_complete constructed, this=0x2598420 [call2911]
2019/12/09 09:39:32.246 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(930) will call comm_close_complete(FD 15) [call2911]
2019/12/09 09:39:32.246 kid1| 33,3| client_side.cc(612) ~ConnStateData:
local=X.Y.82.162:443 remote=192.168.1.25:53556 flags=33
2019/12/09 09:39:32.246 kid1| 33,4| ServerBump.cc(46) ~ServerBump:
destroying
2019/12/09 09:39:32.246 kid1| 33,4| ServerBump.cc(48) ~ServerBump:
e:=sp2XIV/0x25617e0*1
2019/12/09 09:39:32.246 kid1| 90,3| store_client.cc(651) storeUnregister:
storeUnregister: called for '41000000000000000E11000001000000'
2019/12/09 09:39:32.246 kid1| 20,3| store_swapout.cc(347) mayStartSwapOut: 
already rejected
2019/12/09 09:39:32.246 kid1| 20,2| store.cc(986) checkCachable:
StoreEntry::checkCachable: NO: not cachable
2019/12/09 09:39:32.246 kid1| 20,3| store.cc(444) lock: storeUnregister
locked key 41000000000000000E11000001000000 e:=sp2XIV/0x25617e0*2
2019/12/09 09:39:32.246 kid1| 90,3| store_client.cc(764)
CheckQuickAbortIsReasonable: entry=e:=sp2XIV/0x25617e0*2
2019/12/09 09:39:32.246 kid1| 90,3| store_client.cc(755)
storePendingNClients: storePendingNClients: returning 0
2019/12/09 09:39:32.246 kid1| 90,3| store_client.cc(777)
CheckQuickAbortIsReasonable: quick-abort? NO store_status != STORE_PENDING
2019/12/09 09:39:32.246 kid1| 20,3| store.cc(469) unlock: storeUnregister
unlocking key 41000000000000000E11000001000000 e:=sp2XIV/0x25617e0*2
2019/12/09 09:39:32.246 kid1| 20,3| store.cc(469) unlock: Ssl::ServerBump
unlocking key 41000000000000000E11000001000000 e:=sp2XIV/0x25617e0*1
2019/12/09 09:39:32.246 kid1| 20,5| store.cc(485) doAbandon:
e:=sp2XIV/0x25617e0*0 via Ssl::ServerBump
2019/12/09 09:39:32.246 kid1| 90,3| store_client.cc(755)
storePendingNClients: storePendingNClients: returning 0
2019/12/09 09:39:32.246 kid1| 20,3| store.cc(1216) release: 0
e:=sp2XIV/0x25617e0*0 41000000000000000E11000001000000
2019/12/09 09:39:32.246 kid1| 20,3| store.cc(379) destroyMemObject:
0x256a240 in e:=sp2XIV/0x25617e0*0
2019/12/09 09:39:32.246 kid1| 20,3| MemObject.cc(110) ~MemObject: MemObject
destructed, this=0x256a240
2019/12/09 09:39:32.246 kid1| 20,3| store.cc(397) destroyStoreEntry:
destroyStoreEntry: destroying 0x25617e8
2019/12/09 09:39:32.246 kid1| 20,3| store.cc(379) destroyMemObject: 0 in
e:=sp2XIV/0x25617e0*0
2019/12/09 09:39:32.246 kid1| 20,5| store.cc(352) ~StoreEntry: StoreEntry
destructed, this=0x25617e0
2019/12/09 09:39:32.246 kid1| 93,5| AsyncJob.cc(40) ~AsyncJob: AsyncJob
destructed, this=0x256a788 type=Http1::Server [job203]
2019/12/09 09:39:32.246 kid1| 93,6| AsyncJob.cc(149) callEnd:
ConnStateData::connStateClosed(FD -1, data=0x256a4a8) ended 0x256a788
2019/12/09 09:39:32.246 kid1| 33,5| AsyncCallQueue.cc(57) fireNext: leaving
ConnStateData::connStateClosed(FD -1, data=0x256a4a8)
2019/12/09 09:39:32.246 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering
comm_close_complete(FD 13)
2019/12/09 09:39:32.246 kid1| 5,4| AsyncCall.cc(38) make: make call
comm_close_complete [call2909]
2019/12/09 09:39:32.246 kid1| 83,5| Session.cc(100) operator(): SSL_free
session=0x259dbd0
2019/12/09 09:39:32.246 kid1| 83,5| bio.cc(612) squid_bio_ctrl: 0x20d61f0
7(0, 0x2592b20)
2019/12/09 09:39:32.246 kid1| 83,5| ../../src/security/PeerOptions.h(112)
operator(): SSL_CTX destruct, this=0x25a0570
2019/12/09 09:39:32.246 kid1| 51,3| fd.cc(94) fd_close: fd_close FD 13
client https start
2019/12/09 09:39:32.246 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 13,
type=3, handler=0, client_data=0, timeout=0
2019/12/09 09:39:32.247 kid1| 5,5| AcceptLimiter.cc(47) kick: size=0
2019/12/09 09:39:32.247 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving
comm_close_complete(FD 13)
2019/12/09 09:39:32.247 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering
commStartTlsClose(FD 15)
2019/12/09 09:39:32.247 kid1| 5,4| AsyncCall.cc(38) make: make call
commStartTlsClose [call2910]
2019/12/09 09:39:32.247 kid1| 83,5| Session.cc(202) SessionSendGoodbye:
session=0x257cb00
2019/12/09 09:39:32.247 kid1| 83,5| bio.cc(113) write: FD 15 wrote 31 <= 31
2019/12/09 09:39:32.247 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving
commStartTlsClose(FD 15)
2019/12/09 09:39:32.247 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering
comm_close_complete(FD 15)
2019/12/09 09:39:32.247 kid1| 5,4| AsyncCall.cc(38) make: make call
comm_close_complete [call2911]
2019/12/09 09:39:32.247 kid1| 83,5| Session.cc(100) operator(): SSL_free
session=0x257cb00
2019/12/09 09:39:32.247 kid1| 51,3| fd.cc(94) fd_close: fd_close FD 15
X.Y.82.162 pinned connection for 192.168.1.25:53556 (13)
2019/12/09 09:39:32.247 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 15,
type=3, handler=0, client_data=0, timeout=0
2019/12/09 09:39:32.247 kid1| 5,5| AcceptLimiter.cc(47) kick: size=0
2019/12/09 09:39:32.247 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving
comm_close_complete(FD 15)
2019/12/09 09:39:32.800 kid1| 41,5| AsyncCall.cc(26) AsyncCall: The
AsyncCall ipcache_purgelru constructed, this=0x255e980 [call2912]
2019/12/09 09:39:32.800 kid1| 41,5| AsyncCall.cc(93) ScheduleCall:
event.cc(241) will call ipcache_purgelru() [call2912]
2019/12/09 09:39:32.800 kid1| 41,5| AsyncCallQueue.cc(55) fireNext: entering
ipcache_purgelru()
2019/12/09 09:39:32.800 kid1| 41,5| AsyncCall.cc(38) make: make call
ipcache_purgelru [call2912]
2019/12/09 09:39:32.800 kid1| 41,5| AsyncCallQueue.cc(57) fireNext: leaving
ipcache_purgelru()
2019/12/09 09:39:33.096 kid1| 41,5| AsyncCall.cc(26) AsyncCall: The
AsyncCall logfileFlush constructed, this=0x255e980 [call2913]
2019/12/09 09:39:33.097 kid1| 41,5| AsyncCall.cc(93) ScheduleCall:
event.cc(241) will call logfileFlush(0x20f1eb8*?) [call2913]
2019/12/09 09:39:33.097 kid1| 41,5| AsyncCallQueue.cc(55) fireNext: entering
logfileFlush(0x20f1eb8*?)
2019/12/09 09:39:33.097 kid1| 41,5| AsyncCall.cc(38) make: make call
logfileFlush [call2913]
2019/12/09 09:39:33.097 kid1| 41,5| AsyncCallQueue.cc(57) fireNext: leaving
logfileFlush(0x20f1eb8*?)
2019/12/09 09:39:33.171 kid1| 41,5| AsyncCall.cc(26) AsyncCall: The
AsyncCall MaintainSwapSpace constructed, this=0x255e980 [call2914]
2019/12/09 09:39:33.171 kid1| 41,5| AsyncCall.cc(93) ScheduleCall:
event.cc(241) will call MaintainSwapSpace() [call2914]
2019/12/09 09:39:33.171 kid1| 41,5| AsyncCallQueue.cc(55) fireNext: entering
MaintainSwapSpace()
2019/12/09 09:39:33.171 kid1| 41,5| AsyncCall.cc(38) make: make call
MaintainSwapSpace [call2914]
2019/12/09 09:39:33.171 kid1| 47,5| ufs/UFSSwapDir.cc(445) maintain: space
still available in /usr/local/squid/var/cache/squid
2019/12/09 09:39:33.171 kid1| 41,5| AsyncCallQueue.cc(57) fireNext: leaving
MaintainSwapSpace()
^C2019/12/09 09:39:33.337| 1,2| main.cc(1788) masterShutdownStart: received
shutdown command
2019/12/09 09:39:33.337 kid1| 5,3| Read.cc(145) HandleRead: FD 14, size
32767, retval 0, errno 0
2019/12/09 09:39:33.337 kid1| 5,3| IoCallback.cc(116) finish: called for
local=[::] remote=[::] FD 14 flags=1 (0, 0)
2019/12/09 09:39:33.337 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
IoCallback.cc(135) will call helperHandleRead(local=[::] remote=[::] FD 14
flags=1, data=0x20c5848, size=0, buf=0x20c5b50) [call9]
2019/12/09 09:39:33.337 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 14,
type=2, handler=0, client_data=0, timeout=0
2019/12/09 09:39:33.337 kid1| 5,3| Read.cc(145) HandleRead: FD 18, size
32767, retval 0, errno 0
2019/12/09 09:39:33.337 kid1| 5,3| IoCallback.cc(116) finish: called for
local=[::] remote=[::] FD 18 flags=1 (0, 0)
2019/12/09 09:39:33.337 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
IoCallback.cc(135) will call helperHandleRead(local=[::] remote=[::] FD 18
flags=1, data=0x20d6288, size=0, buf=0x20d6590) [call15]
2019/12/09 09:39:33.337 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 18,
type=2, handler=0, client_data=0, timeout=0
2019/12/09 09:39:33.337 kid1| 5,3| Read.cc(145) HandleRead: FD 16, size
32767, retval 0, errno 0
2019/12/09 09:39:33.337 kid1| 5,3| IoCallback.cc(116) finish: called for
local=[::] remote=[::] FD 16 flags=1 (0, 0)
2019/12/09 09:39:33.337 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
IoCallback.cc(135) will call helperHandleRead(local=[::] remote=[::] FD 16
flags=1, data=0x20cdd68, size=0, buf=0x20ce070) [call12]
2019/12/09 09:39:33.338 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 16,
type=2, handler=0, client_data=0, timeout=0
2019/12/09 09:39:33.338 kid1| 5,3| Read.cc(145) HandleRead: FD 12, size
32767, retval 0, errno 0
2019/12/09 09:39:33.338 kid1| 5,3| IoCallback.cc(116) finish: called for
local=[::] remote=[::] FD 12 flags=1 (0, 0)
2019/12/09 09:39:33.338 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
IoCallback.cc(135) will call helperHandleRead(local=[::] remote=[::] FD 12
flags=1, data=0x20bd328, size=0, buf=0x20bd630) [call6]
2019/12/09 09:39:33.338 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 12,
type=2, handler=0, client_data=0, timeout=0
2019/12/09 09:39:33.338 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering
helperHandleRead(local=[::] remote=[::] FD 14 flags=1, data=0x20c5848,
size=0, buf=0x20c5b50)
2019/12/09 09:39:33.338 kid1| 5,4| AsyncCall.cc(38) make: make call
helperHandleRead [call9]
2019/12/09 09:39:33.338 kid1| 84,5| helper.cc(963) helperHandleRead:
helperHandleRead: 0 bytes from
/usr/local/squid/libexec/security_file_certgen -s
/usr/local/squid/var/logs/ssl_db -M 4MB #Hlpr3
2019/12/09 09:39:33.338 kid1| 5,3| comm.cc(859) _comm_close: comm_close:
start closing FD 14
2019/12/09 09:39:33.338 kid1| 5,3| comm.cc(546) commUnsetFdTimeout: Remove
timeout for FD 14
2019/12/09 09:39:33.338 kid1| 5,5| comm.cc(727) commCallCloseHandlers:
commCallCloseHandlers: FD 14
2019/12/09 09:39:33.338 kid1| 5,5| comm.cc(735) commCallCloseHandlers:
commCallCloseHandlers: ch->handler=0x20cdb60*1
2019/12/09 09:39:33.338 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(736) will call helperServerFree(0x20c5848/0x20c5848) [call8]
2019/12/09 09:39:33.338 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall
comm_close_complete constructed, this=0x2598420 [call2915]
2019/12/09 09:39:33.338 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(930) will call comm_close_complete(FD 14) [call2915]
2019/12/09 09:39:33.338 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving
helperHandleRead(local=[::] remote=[::] flags=1, data=0x20c5848, size=0,
buf=0x20c5b50)
2019/12/09 09:39:33.338 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering
helperHandleRead(local=[::] remote=[::] FD 18 flags=1, data=0x20d6288,
size=0, buf=0x20d6590)
2019/12/09 09:39:33.338 kid1| 5,4| AsyncCall.cc(38) make: make call
helperHandleRead [call15]
2019/12/09 09:39:33.338 kid1| 84,5| helper.cc(963) helperHandleRead:
helperHandleRead: 0 bytes from
/usr/local/squid/libexec/security_file_certgen -s
/usr/local/squid/var/logs/ssl_db -M 4MB #Hlpr5
2019/12/09 09:39:33.338 kid1| 5,3| comm.cc(859) _comm_close: comm_close:
start closing FD 18
2019/12/09 09:39:33.338 kid1| 5,3| comm.cc(546) commUnsetFdTimeout: Remove
timeout for FD 18
2019/12/09 09:39:33.338 kid1| 5,5| comm.cc(727) commCallCloseHandlers:
commCallCloseHandlers: FD 18
2019/12/09 09:39:33.338 kid1| 5,5| comm.cc(735) commCallCloseHandlers:
commCallCloseHandlers: ch->handler=0x20de5a0*1
2019/12/09 09:39:33.338 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(736) will call helperServerFree(0x20d6288/0x20d6288) [call14]
2019/12/09 09:39:33.338 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall
comm_close_complete constructed, this=0x25b1b30 [call2916]
2019/12/09 09:39:33.338 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(930) will call comm_close_complete(FD 18) [call2916]
2019/12/09 09:39:33.338 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving
helperHandleRead(local=[::] remote=[::] flags=1, data=0x20d6288, size=0,
buf=0x20d6590)
2019/12/09 09:39:33.338 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering
helperHandleRead(local=[::] remote=[::] FD 16 flags=1, data=0x20cdd68,
size=0, buf=0x20ce070)
2019/12/09 09:39:33.338 kid1| 5,4| AsyncCall.cc(38) make: make call
helperHandleRead [call12]
2019/12/09 09:39:33.338 kid1| 84,5| helper.cc(963) helperHandleRead:
helperHandleRead: 0 bytes from
/usr/local/squid/libexec/security_file_certgen -s
/usr/local/squid/var/logs/ssl_db -M 4MB #Hlpr4
2019/12/09 09:39:33.338 kid1| 5,3| comm.cc(859) _comm_close: comm_close:
start closing FD 16
2019/12/09 09:39:33.338 kid1| 5,3| comm.cc(546) commUnsetFdTimeout: Remove
timeout for FD 16
2019/12/09 09:39:33.338 kid1| 5,5| comm.cc(727) commCallCloseHandlers:
commCallCloseHandlers: FD 16
2019/12/09 09:39:33.338 kid1| 5,5| comm.cc(735) commCallCloseHandlers:
commCallCloseHandlers: ch->handler=0x20d6080*1
2019/12/09 09:39:33.339 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(736) will call helperServerFree(0x20cdd68/0x20cdd68) [call11]
2019/12/09 09:39:33.339 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall
comm_close_complete constructed, this=0x2564110 [call2917]
2019/12/09 09:39:33.339 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(930) will call comm_close_complete(FD 16) [call2917]
2019/12/09 09:39:33.339 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving
helperHandleRead(local=[::] remote=[::] flags=1, data=0x20cdd68, size=0,
buf=0x20ce070)
2019/12/09 09:39:33.339 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering
helperHandleRead(local=[::] remote=[::] FD 12 flags=1, data=0x20bd328,
size=0, buf=0x20bd630)
2019/12/09 09:39:33.339 kid1| 5,4| AsyncCall.cc(38) make: make call
helperHandleRead [call6]
2019/12/09 09:39:33.339 kid1| 84,5| helper.cc(963) helperHandleRead:
helperHandleRead: 0 bytes from
/usr/local/squid/libexec/security_file_certgen -s
/usr/local/squid/var/logs/ssl_db -M 4MB #Hlpr2
2019/12/09 09:39:33.339 kid1| 5,3| comm.cc(859) _comm_close: comm_close:
start closing FD 12
2019/12/09 09:39:33.339 kid1| 5,3| comm.cc(546) commUnsetFdTimeout: Remove
timeout for FD 12
2019/12/09 09:39:33.339 kid1| 5,5| comm.cc(727) commCallCloseHandlers:
commCallCloseHandlers: FD 12
2019/12/09 09:39:33.339 kid1| 5,5| comm.cc(735) commCallCloseHandlers:
commCallCloseHandlers: ch->handler=0x20c5640*1
2019/12/09 09:39:33.339 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(736) will call helperServerFree(0x20bd328/0x20bd328) [call5]
2019/12/09 09:39:33.339 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall
comm_close_complete constructed, this=0x25b3490 [call2918]
2019/12/09 09:39:33.339 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(930) will call comm_close_complete(FD 12) [call2918]
2019/12/09 09:39:33.339 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving
helperHandleRead(local=[::] remote=[::] flags=1, data=0x20bd328, size=0,
buf=0x20bd630)
2019/12/09 09:39:33.339 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering
helperServerFree(0x20c5848/0x20c5848)
2019/12/09 09:39:33.339 kid1| 5,4| AsyncCall.cc(38) make: make call
helperServerFree [call8]
2019/12/09 09:39:33.339 kid1| WARNING:
/usr/local/squid/libexec/security_file_certgen -s
/usr/local/squid/var/logs/ssl_db -M 4MB #Hlpr3 exited
2019/12/09 09:39:33.339 kid1| Too few
/usr/local/squid/libexec/security_file_certgen -s
/usr/local/squid/var/logs/ssl_db -M 4MB processes are running (need 1/32)
2019/12/09 09:39:33.339 kid1| Starting new helpers
2019/12/09 09:39:33.339 kid1| helperOpenServers: Starting 1/32
'security_file_certgen' processes
2019/12/09 09:39:33.339 kid1| 51,3| fd.cc(198) fd_open: fd_open() FD 13 IPC
UNIX STREAM Parent
2019/12/09 09:39:33.339 kid1| 51,3| fd.cc(198) fd_open: fd_open() FD 15 IPC
UNIX STREAM Parent
2019/12/09 09:39:33.339 kid1| 54,3| ipc.cc(204) ipcCreate: ipcCreate: prfd
FD 13
2019/12/09 09:39:33.339 kid1| 54,3| ipc.cc(205) ipcCreate: ipcCreate: pwfd
FD 13
2019/12/09 09:39:33.339 kid1| 54,3| ipc.cc(206) ipcCreate: ipcCreate: crfd
FD 15
2019/12/09 09:39:33.339 kid1| 54,3| ipc.cc(207) ipcCreate: ipcCreate: cwfd
FD 15
2019/12/09 09:39:33.340 kid1| 5,3| comm.cc(859) _comm_close: comm_close:
start closing FD 15
2019/12/09 09:39:33.340 kid1| 5,3| comm.cc(546) commUnsetFdTimeout: Remove
timeout for FD 15
2019/12/09 09:39:33.340 kid1| 5,5| comm.cc(727) commCallCloseHandlers:
commCallCloseHandlers: FD 15
2019/12/09 09:39:33.340 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall
comm_close_complete constructed, this=0x256a970 [call2919]
2019/12/09 09:39:33.340 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(930) will call comm_close_complete(FD 15) [call2919]
2019/12/09 09:39:33.340 kid1| 21,3| tools.cc(506) leave_suid: leave_suid:
PID 4394 called
2019/12/09 09:39:33.340 kid1| 21,3| tools.cc(606) no_suid: no_suid: PID 4394
giving up root privileges forever
2019/12/09 09:39:33.340 kid1| 5,3| comm.cc(546) commUnsetFdTimeout: Remove
timeout for FD 13
2019/12/09 09:39:33.340 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall
helperServerFree constructed, this=0x255e980 [call2920]
2019/12/09 09:39:33.340 kid1| 5,5| comm.cc(985) comm_add_close_handler:
comm_add_close_handler: FD 13, AsyncCall=0x255e980*1
2019/12/09 09:39:33.340 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall
helperHandleRead constructed, this=0x254d4c0 [call2921]
2019/12/09 09:39:33.340 kid1| 5,5| Read.cc(57) comm_read_base: comm_read,
queueing read for local=[::] remote=[::] FD 13 flags=1; asynCall 0x254d4c0*1
2019/12/09 09:39:33.340 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 13,
type=1, handler=1, client_data=0x2091f60, timeout=0
2019/12/09 09:39:33.340 kid1| 84,5| helper.cc(1247) GetFirstAvailable:
GetFirstAvailable: Running servers 5
2019/12/09 09:39:33.340 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving
helperServerFree(0x20c5848/0x20c5848)
2019/12/09 09:39:33.340 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering
comm_close_complete(FD 14)
2019/12/09 09:39:33.340 kid1| 5,4| AsyncCall.cc(38) make: make call
comm_close_complete [call2915]
2019/12/09 09:39:33.340 kid1| 51,3| fd.cc(94) fd_close: fd_close FD 14
security_file_certgen #3
2019/12/09 09:39:33.340 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 14,
type=3, handler=0, client_data=0, timeout=0
2019/12/09 09:39:33.341 kid1| 5,5| AcceptLimiter.cc(47) kick: size=0
2019/12/09 09:39:33.341 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving
comm_close_complete(FD 14)
2019/12/09 09:39:33.341 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering
helperServerFree(0x20d6288/0x20d6288)
2019/12/09 09:39:33.341 kid1| 5,4| AsyncCall.cc(38) make: make call
helperServerFree [call14]
2019/12/09 09:39:33.341 kid1| WARNING:
/usr/local/squid/libexec/security_file_certgen -s
/usr/local/squid/var/logs/ssl_db -M 4MB #Hlpr5 exited
2019/12/09 09:39:33.341 kid1| Too few
/usr/local/squid/libexec/security_file_certgen -s
/usr/local/squid/var/logs/ssl_db -M 4MB processes are running (need 1/32)
2019/12/09 09:39:33.341 kid1| Closing HTTP(S) port [::]:3128
2019/12/09 09:39:33.341 kid1| 5,3| comm.cc(859) _comm_close: comm_close:
start closing FD 28
2019/12/09 09:39:33.341 kid1| 5,3| comm.cc(546) commUnsetFdTimeout: Remove
timeout for FD 28
2019/12/09 09:39:33.341 kid1| 5,5| comm.cc(727) commCallCloseHandlers:
commCallCloseHandlers: FD 28
2019/12/09 09:39:33.341 kid1| 5,5| comm.cc(735) commCallCloseHandlers:
commCallCloseHandlers: ch->handler=0x20ff240*2
2019/12/09 09:39:33.341 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(736) will call Comm::TcpAcceptor::handleClosure(FD -1,
data=0x2539878) [call29]
2019/12/09 09:39:33.341 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall
comm_close_complete constructed, this=0x2598420 [call2922]
2019/12/09 09:39:33.341 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(930) will call comm_close_complete(FD 28) [call2922]
2019/12/09 09:39:33.341 kid1| Closing HTTP(S) port [::]:3129
2019/12/09 09:39:33.341 kid1| 5,3| comm.cc(859) _comm_close: comm_close:
start closing FD 29
2019/12/09 09:39:33.341 kid1| 5,3| comm.cc(546) commUnsetFdTimeout: Remove
timeout for FD 29
2019/12/09 09:39:33.341 kid1| 5,5| comm.cc(727) commCallCloseHandlers:
commCallCloseHandlers: FD 29
2019/12/09 09:39:33.341 kid1| 5,5| comm.cc(735) commCallCloseHandlers:
commCallCloseHandlers: ch->handler=0x23dd590*2
2019/12/09 09:39:33.342 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(736) will call Comm::TcpAcceptor::handleClosure(FD -1,
data=0x2539d18) [call30]
2019/12/09 09:39:33.342 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall
comm_close_complete constructed, this=0x254cdd0 [call2923]
2019/12/09 09:39:33.342 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(930) will call comm_close_complete(FD 29) [call2923]
2019/12/09 09:39:33.342 kid1| Closing HTTP(S) port [::]:3130
2019/12/09 09:39:33.342 kid1| 5,3| comm.cc(859) _comm_close: comm_close:
start closing FD 30
2019/12/09 09:39:33.342 kid1| 5,3| comm.cc(546) commUnsetFdTimeout: Remove
timeout for FD 30
2019/12/09 09:39:33.342 kid1| 5,5| comm.cc(727) commCallCloseHandlers:
commCallCloseHandlers: FD 30
2019/12/09 09:39:33.342 kid1| 5,5| comm.cc(735) commCallCloseHandlers:
commCallCloseHandlers: ch->handler=0x23dd620*2
2019/12/09 09:39:33.342 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(736) will call Comm::TcpAcceptor::handleClosure(FD -1,
data=0x2539d88) [call31]
2019/12/09 09:39:33.342 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall
comm_close_complete constructed, this=0x2592b20 [call2924]
2019/12/09 09:39:33.342 kid1| 5,4| AsyncCall.cc(93) ScheduleCall:
comm.cc(930) will call comm_close_complete(FD 30) [call2924]
2019/12/09 09:39:33.342 kid1| 21,3| tools.cc(506) leave_suid: leave_suid:
PID 4366 called
2019/12/09 09:39:33.342 kid1| storeDirWriteCleanLogs: Starting...
2019/12/09 09:39:33.342 kid1| 6,5| fs_io.cc(65) file_open: FD 14
2019/12/09 09:39:33.342 kid1| 51,3| fd.cc(198) fd_open: fd_open() FD 14
/usr/local/squid/var/cache/squid/swap.state.clean
2019/12/09 09:39:33.343 kid1| 47,3| ufs/UFSSwapDir.cc(959) writeCleanStart:
opened /usr/local/squid/var/cache/squid/swap.state.clean, FD 14
2019/12/09 09:39:33.343 kid1| 6,5| fs_io.cc(120) file_close: file_close: FD
11 really closing
2019/12/09 09:39:33.343 kid1| 51,3| fd.cc(94) fd_close: fd_close FD 11
/usr/local/squid/var/cache/squid/swap.state
2019/12/09 09:39:33.343 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 11,
type=3, handler=0, client_data=0, timeout=0
2019/12/09 09:39:33.343 kid1| 47,3| ufs/UFSSwapDir.cc(764) closeLog: Cache
Dir #0 log closed on FD 11
2019/12/09 09:39:33.343 kid1| 21,2| fs_io.cc(510) FileRename: renaming
/usr/local/squid/var/cache/squid/swap.state.clean to
/usr/local/squid/var/cache/squid/swap.state
2019/12/09 09:39:33.344 kid1| 6,5| fs_io.cc(65) file_open: FD 11
2019/12/09 09:39:33.344 kid1| 51,3| fd.cc(198) fd_open: fd_open() FD 11
/usr/local/squid/var/cache/squid/swap.state.last-clean
2019/12/09 09:39:33.344 kid1| 6,5| fs_io.cc(120) file_close: file_close: FD
11 really closing
2019/12/09 09:39:33.344 kid1| 51,3| fd.cc(94) fd_close: fd_close FD 11
/usr/local/squid/var/cache/squid/swap.state.last-clean
2019/12/09 09:39:33.344 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 11,
type=3, handler=0, client_data=0, timeout=0
2019/12/09 09:39:33.344 kid1| 6,5| fs_io.cc(120) file_close: file_close: FD
14 really closing
2019/12/09 09:39:33.344 kid1| 51,3| fd.cc(94) fd_close: fd_close FD 14
/usr/local/squid/var/cache/squid/swap.state.clean
2019/12/09 09:39:33.344 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 14,
type=3, handler=0, client_data=0, timeout=0
2019/12/09 09:39:33.344 kid1|   Finished.  Wrote 213 entries.
2019/12/09 09:39:33.344 kid1|   Took 0.00 seconds (105445.54 entries/sec).
2019/12/09 09:39:33.344 kid1| *FATAL: The
/usr/local/squid/libexec/security_file_certgen -s
/usr/local/squid/var/logs/ssl_db -M 4MB helpers are crashing too rapidly,
need help!*

--
Sent from: http://squid-web-proxy-cache.1019090.n4.nabble.com/Squid-Users-f1019091.html