Envoy hanging with frequent hangup signals

Title: Envoy hangs with frequent hangup signals

Description: My team is currently working on deploying Envoy as an edge proxy. We're managing Envoy through Nomad which is handling the lifecycle of the container running through docker. We've noticed that intermittently, Envoy will 'freeze' and stop accepting requests. I think I've traced this back to something with the hot-restarter where if it receives SIGHUPs too frequently, it'll get stuck and the old Envoy process will eventually turn into a zombie, without anything transitioning to the new fork that just spawned.

Repro steps:

Using Envoy 1.11.0 in Docker 18.03.1-ce and Ubuntu 16.04.5

I was able to reproduce the issue by sending frequent SIGHUPs to my container. e.g.

while true; sleep 2; do docker kill --signal="SIGHUP" 52dfc; done

We are passing the following to the command line

/usr/local/bin/envoy -c /local/envoy.yaml --restart-epoch 0 --parent-shutdown-time-s 180 --drain-time-s 120 --cpuset-threads --log-level INFO

Our entrypoint is the python hot-restarter.

Logs: strace output attached to the hot-restarter towards the crash

...
--- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=0, si_uid=0} ---
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
write(1, "got SIGHUP", 10)              = 10
write(1, "\n", 1)                       = 1
write(1, "forking and execing new child pr"..., 49) = 49
write(1, "\n", 1)                       = 1
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f2154e4b9d0) = 193
write(1, "forked new child process with PI"..., 37) = 37
write(1, "\n", 1)                       = 1
select(0, NULL, NULL, NULL, {60, 0})    = ? ERESTARTNOHAND (To be restarted if no handler)
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=155, si_uid=0, si_status=0, si_utime=7, si_stime=3} ---
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
write(1, "got SIGCHLD", 11)             = 11
write(1, "\n", 1)                       = 1
wait4(155, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG, NULL) = 155
write(1, "PID=155 exited with code=0", 26) = 26
write(1, "\n", 1)                       = 1
wait4(174, 0x7ffe08efa8bc, WNOHANG, NULL) = 0
wait4(193, 0x7ffe08efa8bc, WNOHANG, NULL) = 0
select(0, NULL, NULL, NULL, {60, 0})    = ? ERESTARTNOHAND (To be restarted if no handler)
--- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=0, si_uid=0} ---
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
write(1, "got SIGHUP", 10)              = 10
write(1, "\n", 1)                       = 1
write(1, "forking and execing new child pr"..., 49) = 49
write(1, "\n", 1)                       = 1
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f2154e4b9d0) = 212
write(1, "forked new child process with PI"..., 37) = 37
write(1, "\n", 1)                       = 1
select(0, NULL, NULL, NULL, {60, 0})    = ? ERESTARTNOHAND (To be restarted if no handler)
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=174, si_uid=0, si_status=0, si_utime=3, si_stime=1} ---
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
write(1, "got SIGCHLD", 11)             = 11
write(1, "\n", 1)                       = 1
wait4(174, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG, NULL) = 174
write(1, "PID=174 exited with code=0", 26) = 26
write(1, "\n", 1)                       = 1
wait4(193, 0x7ffe08efa8bc, WNOHANG, NULL) = 0
wait4(212, 0x7ffe08efa8bc, WNOHANG, NULL) = 0
select(0, NULL, NULL, NULL, {60, 0})    = ? ERESTARTNOHAND (To be restarted if no handler)
--- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=0, si_uid=0} ---
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
write(1, "got SIGHUP", 10)              = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
--- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=0, si_uid=0} ---
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
write(1, "got SIGHUP", 10)              = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
--- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=0, si_uid=0} ---
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
write(1, "got SIGHUP", 10)              = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
--- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=0, si_uid=0} ---
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
write(1, "got SIGHUP", 10)              = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
--- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=0, si_uid=0} ---
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
write(1, "got SIGHUP", 10)              = ? ERESTARTSYS (To be restarted if SA_RESTART is set)

Snippet of the last bits of logs before it died

[2019-08-08 01:05:22.822][212][debug][http] [source/common/http/conn_manager_impl.cc:600] [C6][S18271715739972951314] request headers complete (end_stream=true):
':authority', '1.2.3.4:443'
':path', '/ready'
':method', 'GET'
'user-agent', 'Consul Health Check'
'accept', 'text/plain, text/*, */*'
'accept-encoding', 'gzip'
'x-forwarded-proto', 'https'
'x-request-id', '12345'
'x-envoy-expected-rq-timeout-ms', '15000'
'content-length', '0'

[2019-08-08 01:05:22.822][212][debug][http] [source/common/http/conn_manager_impl.cc:1092] [C6][S18271715739972951314] request end stream
[2019-08-08 01:05:22.822][212][debug][admin] [source/server/http/admin.cc:1178] [C6][S18271715739972951314] request complete: path: /ready
[2019-08-08 01:05:22.822][212][debug][http] [source/common/http/conn_manager_impl.cc:1359] [C6][S18271715739972951314] encoding headers via codec (end_stream=false):
':status', '200'
'content-type', 'text/plain; charset=UTF-8'
'cache-control', 'no-cache, max-age=0'
'x-content-type-options', 'nosniff'
'date', 'Thu, 08 Aug 2019 01:05:22 GMT'
'server', 'envoy'

[2019-08-08 01:05:22.822][212][trace][connection] [source/common/network/connection_impl.cc:392] [C6] writing 209 bytes, end_stream false
[2019-08-08 01:05:22.822][212][trace][http] [source/common/http/conn_manager_impl.cc:1497] [C6][S18271715739972951314] encoding data via codec (size=5 end_stream=true)
[2019-08-08 01:05:22.822][212][trace][connection] [source/common/network/connection_impl.cc:392] [C6] writing 15 bytes, end_stream false
[2019-08-08 01:05:22.822][212][trace][main] [source/common/event/dispatcher_impl.cc:158] item added to deferred deletion list (size=1)
[2019-08-08 01:05:22.822][212][trace][http] [source/common/http/conn_manager_impl.cc:857] [C6][S18271715739972951314] decode headers called: filter=0x3346000 status=1
[2019-08-08 01:05:22.822][212][trace][http] [source/common/http/http1/codec_impl.cc:387] [C6] parsed 272 bytes
[2019-08-08 01:05:22.822][212][trace][connection] [source/common/network/connection_impl.cc:456] [C6] socket event: 2
[2019-08-08 01:05:22.822][212][trace][connection] [source/common/network/connection_impl.cc:541] [C6] write ready
[2019-08-08 01:05:22.822][212][trace][connection] [source/common/network/raw_buffer_socket.cc:66] [C6] write returns: 224
[2019-08-08 01:05:22.822][228][trace][connection] [source/common/network/connection_impl.cc:456] [C5] socket event: 3
[2019-08-08 01:05:22.822][228][trace][connection] [source/common/network/connection_impl.cc:541] [C5] write ready
[2019-08-08 01:05:22.822][228][trace][connection] [source/common/network/connection_impl.cc:494] [C5] read ready
[2019-08-08 01:05:22.822][228][trace][connection] [source/common/network/raw_buffer_socket.cc:23] [C5] read returns: 224
[2019-08-08 01:05:22.822][228][trace][connection] [source/common/network/raw_buffer_socket.cc:37] [C5] read error: Resource temporarily unavailable
[2019-08-08 01:05:22.822][228][trace][http] [source/common/http/http1/codec_impl.cc:366] [C5] parsing 224 bytes
[2019-08-08 01:05:22.822][228][trace][http] [source/common/http/http1/codec_impl.cc:479] [C5] message begin
[2019-08-08 01:05:22.822][228][trace][http] [source/common/http/http1/codec_impl.cc:334] [C5] completed header: key=content-type value=text/plain; charset=UTF-8
[2019-08-08 01:05:22.822][228][trace][http] [source/common/http/http1/codec_impl.cc:334] [C5] completed header: key=cache-control value=no-cache, max-age=0
[2019-08-08 01:05:22.822][228][trace][http] [source/common/http/http1/codec_impl.cc:334] [C5] completed header: key=x-content-type-options value=nosniff
[2019-08-08 01:05:22.822][228][trace][http] [source/common/http/http1/codec_impl.cc:334] [C5] completed header: key=date value=Thu, 08 Aug 2019 01:05:22 GMT
[2019-08-08 01:05:22.822][228][trace][http] [source/common/http/http1/codec_impl.cc:334] [C5] completed header: key=server value=envoy
[2019-08-08 01:05:22.822][228][trace][http] [source/common/http/http1/codec_impl.cc:445] [C5] headers complete
[2019-08-08 01:05:22.822][228][trace][http] [source/common/http/http1/codec_impl.cc:334] [C5] completed header: key=transfer-encoding value=chunked
[2019-08-08 01:05:22.822][228][debug][router] [source/common/router/router.cc:994] [C4][S14432783368273822899] upstream headers complete: end_stream=false
[2019-08-08 01:05:22.822][228][trace][http] [source/common/http/conn_manager_impl.cc:1254] [C4][S14432783368273822899] encode headers called: filter=0x33337c0 status=0
[2019-08-08 01:05:22.822][228][debug][http] [source/common/http/conn_manager_impl.cc:1297] [C4][S14432783368273822899] closing connection due to connection close header
[2019-08-08 01:05:22.823][228][debug][http] [source/common/http/conn_manager_impl.cc:1359] [C4][S14432783368273822899] encoding headers via codec (end_stream=false):
':status', '200'
'content-type', 'text/plain; charset=UTF-8'
'cache-control', 'no-cache, max-age=0'
'x-content-type-options', 'nosniff'
'date', 'Thu, 08 Aug 2019 01:05:22 GMT'
'server', 'envoy'
'x-envoy-upstream-service-time', '4'
'connection', 'close'

[2019-08-08 01:05:22.823][228][trace][connection] [source/common/network/connection_impl.cc:392] [C4] writing 262 bytes, end_stream false
[2019-08-08 01:05:22.823][228][trace][http] [source/common/http/conn_manager_impl.cc:1484] [C4][S14432783368273822899] encode data called: filter=0x33337c0 status=0
[2019-08-08 01:05:22.823][228][trace][http] [source/common/http/conn_manager_impl.cc:1497] [C4][S14432783368273822899] encoding data via codec (size=5 end_stream=false)
[2019-08-08 01:05:22.823][228][trace][connection] [source/common/network/connection_impl.cc:392] [C4] writing 10 bytes, end_stream false
[2019-08-08 01:05:22.823][228][trace][http] [source/common/http/http1/codec_impl.cc:466] [C5] message complete
[2019-08-08 01:05:22.823][228][trace][http] [source/common/http/http1/codec_impl.cc:740] [C5] message complete
[2019-08-08 01:05:22.823][228][debug][client] [source/common/http/codec_client.cc:95] [C5] response complete
[2019-08-08 01:05:22.823][228][trace][main] [source/common/event/dispatcher_impl.cc:158] item added to deferred deletion list (size=1)
[2019-08-08 01:05:22.823][228][trace][http] [source/common/http/conn_manager_impl.cc:1484] [C4][S14432783368273822899] encode data called: filter=0x33337c0 status=0
[2019-08-08 01:05:22.823][228][trace][http] [source/common/http/conn_manager_impl.cc:1497] [C4][S14432783368273822899] encoding data via codec (size=0 end_stream=true)
[2019-08-08 01:05:22.823][228][trace][connection] [source/common/network/connection_impl.cc:392] [C4] writing 5 bytes, end_stream false
[2019-08-08 01:05:22.823][228][trace][main] [source/common/event/dispatcher_impl.cc:158] item added to deferred deletion list (size=2)
[2019-08-08 01:05:22.823][228][debug][connection] [source/common/network/connection_impl.cc:101] [C4] closing data_to_write=277 type=2
[2019-08-08 01:05:22.823][228][debug][connection] [source/common/network/connection_impl.cc:651] [C4] setting delayed close timer with timeout 1000 ms
[2019-08-08 01:05:22.823][228][debug][pool] [source/common/http/http1/conn_pool.cc:198] [C5] response complete
[2019-08-08 01:05:22.823][228][debug][pool] [source/common/http/http1/conn_pool.cc:236] [C5] moving to ready
[2019-08-08 01:05:22.823][228][trace][http] [source/common/http/http1/codec_impl.cc:387] [C5] parsed 224 bytes
[2019-08-08 01:05:22.823][228][trace][main] [source/common/event/dispatcher_impl.cc:76] clearing deferred deletion list (size=2)
[2019-08-08 01:05:22.823][228][trace][connection] [source/common/network/connection_impl.cc:456] [C4] socket event: 2
[2019-08-08 01:05:22.823][228][trace][connection] [source/common/network/connection_impl.cc:541] [C4] write ready
[2019-08-08 01:05:22.823][228][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:234] [C4] ssl write returns: 277
[2019-08-08 01:05:22.823][228][debug][connection] [source/common/network/connection_impl.cc:580] [C4] write flush complete
[2019-08-08 01:05:22.822][212][trace][main] [source/common/event/dispatcher_impl.cc:76] clearing deferred deletion list (size=1)
[2019-08-08 01:05:22.826][228][trace][connection] [source/common/network/connection_impl.cc:456] [C4] socket event: 6
[2019-08-08 01:05:22.826][228][debug][connection] [source/common/network/connection_impl.cc:477] [C4] remote early close
[2019-08-08 01:05:22.826][228][debug][connection] [source/common/network/connection_impl.cc:188] [C4] closing socket: 0
[2019-08-08 01:05:22.826][228][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:270] [C4] SSL shutdown: rc=0
[2019-08-08 01:05:22.826][228][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:201] [C4]
[2019-08-08 01:05:22.826][228][debug][main] [source/server/connection_handler_impl.cc:80] [C4] adding to cleanup list
[2019-08-08 01:05:22.826][228][trace][main] [source/common/event/dispatcher_impl.cc:158] item added to deferred deletion list (size=1)
[2019-08-08 01:05:22.826][228][trace][main] [source/common/event/dispatcher_impl.cc:76] clearing deferred deletion list (size=1)
[2019-08-08 01:05:22.900][228][trace][connection] [source/common/network/connection_impl.cc:456] [C0] socket event: 3
[2019-08-08 01:05:22.900][228][trace][connection] [source/common/network/connection_impl.cc:541] [C0] write ready
[2019-08-08 01:05:22.900][228][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:168] [C0] handshake error: 2
[2019-08-08 01:05:22.900][228][trace][connection] [source/common/network/connection_impl.cc:494] [C0] read ready
[2019-08-08 01:05:22.900][228][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:168] [C0] handshake error: 2
[2019-08-08 01:05:23.101][228][trace][connection] [source/common/network/connection_impl.cc:456] [C0] socket event: 3
[2019-08-08 01:05:23.101][228][trace][connection] [source/common/network/connection_impl.cc:541] [C0] write ready
[2019-08-08 01:05:23.101][228][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:157] [C0] handshake complete
[2019-08-08 01:05:23.101][228][trace][connection] [source/common/network/connection_impl.cc:494] [C0] read ready
[2019-08-08 01:05:23.101][228][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:73] [C0] ssl read returns: -1
[2019-08-08 01:05:23.101][228][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:148] [C0] ssl read 0 bytes into 0 slices
[2019-08-08 01:05:23.139][228][debug][main] [source/server/connection_handler_impl.cc:280] [C7] new connection
[2019-08-08 01:05:23.139][228][trace][connection] [source/common/network/connection_impl.cc:456] [C7] socket event: 3
[2019-08-08 01:05:23.139][228][trace][connection] [source/common/network/connection_impl.cc:541] [C7] write ready
[2019-08-08 01:05:23.139][228][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:168] [C7] handshake error: 5
[2019-08-08 01:05:23.139][228][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:201] [C7]
[2019-08-08 01:05:23.139][228][debug][connection] [source/common/network/connection_impl.cc:188] [C7] closing socket: 0
[2019-08-08 01:05:23.139][228][debug][main] [source/server/connection_handler_impl.cc:80] [C7] adding to cleanup list
[2019-08-08 01:05:23.139][228][trace][main] [source/common/event/dispatcher_impl.cc:158] item added to deferred deletion list (size=1)
[2019-08-08 01:05:23.139][228][trace][main] [source/common/event/dispatcher_impl.cc:76] clearing deferred deletion list (size=1)
[2019-08-08 01:05:23.263][228][trace][connection] [source/common/network/connection_impl.cc:456] [C0] socket event: 3
[2019-08-08 01:05:23.263][228][trace][connection] [source/common/network/connection_impl.cc:541] [C0] write ready
[2019-08-08 01:05:23.263][228][trace][connection] [source/common/network/connection_impl.cc:494] [C0] read ready
[2019-08-08 01:05:23.263][228][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:73] [C0] ssl read returns: 133
[2019-08-08 01:05:23.263][228][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:73] [C0] ssl read returns: -1
[2019-08-08 01:05:23.263][228][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:148] [C0] ssl read 133 bytes into 1 slices
[2019-08-08 01:05:23.263][228][trace][http] [source/common/http/http1/codec_impl.cc:366] [C0] parsing 133 bytes
[2019-08-08 01:05:23.263][228][trace][http] [source/common/http/http1/codec_impl.cc:479] [C0] message begin
[2019-08-08 01:05:23.263][228][debug][http] [source/common/http/conn_manager_impl.cc:246] [C0] new stream
[2019-08-08 01:05:23.264][228][trace][http] [source/common/http/http1/codec_impl.cc:334] [C0] completed header: key=Host value=10.96.7.233:443
[2019-08-08 01:05:23.264][228][trace][http] [source/common/http/http1/codec_impl.cc:334] [C0] completed header: key=Connection value=close
[2019-08-08 01:05:23.264][228][trace][http] [source/common/http/http1/codec_impl.cc:334] [C0] completed header: key=User-Agent value=ELB-HealthChecker/2.0
[2019-08-08 01:05:23.264][228][trace][http] [source/common/http/http1/codec_impl.cc:334] [C0] completed header: key=Accept value=*/*
[2019-08-08 01:05:23.264][228][trace][http] [source/common/http/http1/codec_impl.cc:445] [C0] headers complete
[2019-08-08 01:05:23.264][228][trace][http] [source/common/http/http1/codec_impl.cc:334] [C0] completed header: key=Accept-Encoding value=*