Consensys / quorum

A permissioned implementation of Ethereum supporting data privacy
https://www.goquorum.com/
GNU Lesser General Public License v3.0
4.69k stars 1.3k forks source link

Kubernetes GoQuorum Geth Unclean Shutdown due to Non Graceful Termination #1419

Closed frankie-lim-partior closed 2 years ago

frankie-lim-partior commented 2 years ago

System information

Geth version: v22.4.1 OS & Version: Linux, Docker, Kubernetes, GKE quorumengineering/quorum:22.4.1

Expected behaviour

When GoQuorum container terminate/exit in Kubernetes, GoQuorum Geth process should shutdown gracefully and show logs something similar to below.

Got interrupt, shutting down...
DEBUG[05-19|12:26:09.503] RPC server shutting down 
INFO [05-19|12:26:09.504] HTTP server stopped                      endpoint=[::]:22000
DEBUG[05-19|12:26:09.504] RPC server shutting down 
INFO [05-19|12:26:09.504] IPC endpoint closed                      url=/home/achraf/projects/protocol/quorum-examples/test-out/geth.ipc
DEBUG[05-19|12:26:09.504] RPC server shutting down 
INFO [05-19|12:26:09.504] Stopping all plugins                     count=0
INFO [05-19|12:26:09.504] All plugins stopped                      errors=[]
INFO [05-19|12:26:09.504] extension service: stopping 
INFO [05-19|12:26:09.504] extension service: stopped 
INFO [05-19|12:26:09.504] Ethereum protocol stopped 

Actual behaviour

When GoQuorum container terminate/exit in Kubernetes, GoQuorum Geth process did not shutdown gracefully as it did not receive the SIGTERM or SIGINT to shutdown gracefully. As a result, once Kubernetes reached terminationGracePeriod expiry, Kubernetes will kill geth process / container forcefully resulting in ‘Unclean shutdown detected’ in GoQuorum log.

WARN [05-19|02:53:47.587] Unclean shutdown detected booted=2022-05-18T05:46:33+0000 age=21h7m14s
WARN [05-19|02:53:47.587] Unclean shutdown detected booted=2022-05-18T08:40:38+0000 age=18h13m9s
WARN [05-19|02:53:47.587] Unclean shutdown detected booted=2022-05-18T09:31:21+0000 age=17h22m26s
WARN [05-19|02:53:47.587] Unclean shutdown detected booted=2022-05-18T10:03:18+0000 age=16h50m29s
WARN [05-19|02:53:47.587] Unclean shutdown detected booted=2022-05-18T10:37:50+0000 age=16h15m57s
WARN [05-19|02:53:47.587] Unclean shutdown detected booted=2022-05-18T11:17:21+0000 age=15h36m26s
WARN [05-19|02:53:47.587] Unclean shutdown detected booted=2022-05-19T00:04:13+0000 age=2h49m34s
WARN [05-19|02:53:47.587] Unclean shutdown detected booted=2022-05-19T02:26:14+0000 age=27m33s

Steps to reproduce the behaviour

  1. use quorumengineering/quorum:22.4.1 docker image for GoQuorum in K8S template
  2. deploy k8s statefulset for GoQuorum , and start geth using sh -cx
      containers:
      - name: quorum
         image: quorumengineering/quorum:22.4.1
         command: [ "sh" ] 
         args:
         - "-cx"
         - "
               ....
              /usr/local/bin/geth \
              --datadir $QUORUM_DATA_DIR \
              ...
  3. Wait until geth started completely and minting blocks
  4. Stop the K8s pod (Kubectl delete pod, set statefulset replica to 0 or helm uninstall)
  5. Trail the log of the Quorum pod to look for the shutting down sequence. Shutting down sequence not found as it did not receive graceful termination signal SIGTERM or SIGINT
  6. Start the container again. In the log, you will see an 'Unclean shutdown detected' message added to the log.

Possible Root cause

https://pracucci.com/graceful-shutdown-of-kubernetes-pods.html The container shell form runs the command with /bin/sh -cx /usr/local/bin/geth .. , so the process that will get the SIGTERM is actually /bin/sh and not its child geth. The shell shipped by default with Alpine Linux (used in the Quorum docker image) does not pass signals to children (in this case geth). As such, when the container / pod is terminated, geth did not receive the graceful termination signal, and by the end of the terminationGracePeriod, K8s will forcefully kill geth resulting in an unclean shutdown.

Suggestion

Bash shell will be able to pass termination signal to child process. Suggest to include bash shell in the Quorum Docker docker image, so that we can start geth in container using bash rather than sh.

Alternative

We have tested using k8s lifecycle preStop hook and try to insert kill, however, it does not seems to be able to execute the preStop hook to kill geth.

kill $(pgrep -f /usr/local/bin/geth -n)
kill -INT $(pgrep -f '/usr/local/bin/geth' -n)

Executing the kill command direction in a pod exec do work, and the geth shutdown gracefully.

Backtrace

antonydenyer commented 2 years ago

You're right the SIGTERM isn't passed through to child process's. But this is more of a problem with the way you're calling geth. You should be able to call:

exec /usr/local/bin/geth \
              --datadir $QUORUM_DATA_DIR  ...

and it should pass the signal along. You can take a look at

https://github.com/ConsenSys/quorum-dev-quickstart/blob/master/files/goquorum/config/goquorum/docker-entrypoint.sh#L65

for inspiration (previously this was suffering from the same problem)

The other thing to be cautious of is piping after the command as this may have an impact on which process has pid 1

Whilst using bash might mitigate the problem, the correct solution is to ensure that geth is running on pid 1.

antonydenyer commented 2 years ago

Closing as no response. Feel free to re-open.

frankie-lim-partior commented 2 years ago

Thanks @antonydenyer. Apology for the late reply, was on leave. will test this.

frankie-lim-partior commented 2 years ago

@antonydenyer I have tried out your suggestion, to run the geth using exec.

exec /usr/local/bin/geth \
              --datadir $QUORUM_DATA_DIR  ...

I have then confirmed the within the pod, geth is running with PID 1.

image

However, when I try to kubectl delete the pod, where k8s send SIGTERM to the pod, it still didnt trigger geth to shutdown gracefully. I can still see unlcean shutdown in the logs.

Anything else you can think of that could solve this?

antonydenyer commented 2 years ago

if the pod is under heavy load you might need to increase the terminationGracePeriodSeconds. What do you get in the logs after you call delete? You should be getting something like "Got interrupt, shutting down..."

frankie-lim-partior commented 2 years ago

@antonydenyer thanks. I am now able to pass the SIGTERM and have the pod shutdown gracefully as suggested. Thanks for the solution.