nginx
gcp
kubernetes
gclb

新説 nginxのGracefulShutdown on Kubernetes

目的

GoogleCloudLoadBalancer(以後GCLB)のリクエストログに以下の内容が出力されていました。

resource.type: "http_load_balancer"
severity: "WARNING"
httpRequest.status: 502
jsonPayload.statusDetails: "backend_connection_closed_before_data_sent_to_client"

Kubernetes(以後K8S)で動作しているnginx(Pod)を再起動するタイミングで発生しているため対応していきます。

再起動するタイミング以外に上記エラーログが出力される場合は、以下の記事が参考になります。

環境

  • Kubernetes: v1.8.6(Docker v17.3)
  • nginx: v1.11.x

原因

エラーメッセージの内容から、nginxにリクエストされた通信がレスポンスされていないことがわかります。
よくある原因としてgraceful shutdownが実施されていないケースが考えられます。

と言うことでgraceful shutdownの処理を見直していきます。

設定はK8S公式docに記載されている以下の設定を使ってgraceful shutdownを実現していました。
kubernetes nginx graceful shutdownでググると同様の記事が見つかります。

deployment.yaml
apiVersion: extensions/v1beta1
kind: Deployment
...
      preStop:
        exec:
          command: ["/usr/sbin/nginx","-s","quit"]
...

一見正しくSIGQUITが送信されgraceful shutdownされそうです。

が、この設定ではダメでした。
image.png

理由は簡単。
nginx -s quitはnginxの終了を待ちません。そのため直後にK8SからSIGTERMが送信されます。

nginxのエラーログレベルをnoticeに変更すると挙動が確認できます。

2018/01/25 13:46:18 [notice] 1#1: using the "epoll" event method
2018/01/25 13:46:18 [notice] 1#1: openresty/1.13.6.1
2018/01/25 13:46:18 [notice] 1#1: built by gcc 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.5)
2018/01/25 13:46:18 [notice] 1#1: OS: Linux 4.4.86+
2018/01/25 13:46:18 [notice] 1#1: getrlimit(RLIMIT_NOFILE): 1048576:1048576
2018/01/25 13:46:18 [notice] 1#1: start worker processes
2018/01/25 13:46:18 [notice] 1#1: start worker process 7

# まずSIGQUIT受けgraceful shutdownを開始します。
2018/01/25 13:46:55 [notice] 1#1: signal 3 (SIGQUIT) received from 8, shutting down
2018/01/25 13:46:55 [notice] 7#7: gracefully shutting down

# SIGQUIT受けgraceful shutdownしている最中にSIGTERMが送信されている
2018/01/25 13:46:55 [notice] 1#1: signal 15 (SIGTERM) received, exiting <= っええ!!
2018/01/25 13:46:55 [notice] 7#7: exiting

# あぼーん
2018/01/25 13:46:55 [alert] 7#7: *1 open socket #3 left in connection 2
2018/01/25 13:46:55 [alert] 7#7: aborting

2018/01/25 13:46:55 [notice] 7#7: exit
2018/01/25 13:46:55 [notice] 1#1: signal 17 (SIGCHLD) received from 7
2018/01/25 13:46:55 [notice] 1#1: worker process 7 exited with code 0
2018/01/25 13:46:55 [notice] 1#1: exit

対応方法

対応も簡単。

  • K8Sのマニフェストに設定しているpreStop部分を削除
  • DockerfileのSTOPSIGNALinstructionsでコンテナ終了時にSIGQUITを送信するように変更
Dockerfile
FROM nginx
STOPSIGNAL SIGQUIT

検証

ではここから本当に修正されるか確認していきます。
検証ではnginxの代わりに、luaを使用するためOpenRestyを使用しています。
検証で使用した設定はこちらにアップロードしています。

再現編

  1. レスポンスに10秒かかるGET /sleepの設定が含まれたnginxをデプロイ
  2. curlでリクエストしつつ……
  3. (with 2) nginxのコンテナを再起動

するとGCLBからHTTP/1.1 502 Bad Gatewayがレスポンスされます。

curl -v 35.xxx.xxx.xxx/sleep
*   Trying 35.xxx.xxx.xxx...
* TCP_NODELAY set
* Connected to 35.xxx.xxx.xxx (35.xxx.xxx.xxx) port 80 (#0)
> GET /sleep HTTP/1.1
> Host: 35.xxx.xxx.xxx
> User-Agent: curl/7.54.0
> Accept: */*
>

< HTTP/1.1 502 Bad Gateway
< Content-Type: text/html; charset=UTF-8
< Referrer-Policy: no-referrer
< Content-Length: 332
< Date: Fri, 26 Jan 2018 08:46:14 GMT
<

<html><head>
<meta http-equiv="content-type" content="text/html;charset=utf-8">
<title>502 Server Error</title>
</head>
<body text=#000000 bgcolor=#ffffff>
<h1>Error: Server Error</h1>
<h2>The server encountered a temporary error and could not complete your request.<p>Please try again in 30 seconds.</h2>
<h2></h2>
</body></html>
* Connection #0 to host 35.xxx.xxx.xxx left intact

GCLBのログにはbackend_connection_closed_before_data_sent_to_clientが出力されます。

解決編

  1. nginxのDockerfileにSTOPSIGNAL SIGQUITを追加しbuild
  2. Dockerhub(or DockerPrivateRegistry) へpublish
  3. K8SのマニフェストからpreStopの部分を削除してデプロイ
  4. curlでリクエストしつつ……
  5. (with 4) nginxのコンテナを再起動

意図したとおり、curlのリクエストは10秒後にレスポンスされます。

curl -v 35.xxx.xxx.xxx/sleep
*   Trying 35.xxx.xxx.xxx...
* TCP_NODELAY set
* Connected to 35.xxx.xxx.xxx (35.xxx.xxx.xxx) port 80 (#0)
> GET /sleep HTTP/1.1
> Host: 35.xxx.xxx.xxx
> User-Agent: curl/7.54.0
> Accept: */*

# ここで10秒待つ!!!!!!

>
< HTTP/1.1 200 OK
< Server: openresty/1.13.6.1
< Date: Thu, 25 Jan 2018 13:58:41 GMT
< Content-Type: text/plain
< Transfer-Encoding: chunked
< Connection: keep-alive
<

# きたーーーー
Hello!!
* Connection #0 to host 35.xxx.xxx.xxx left intact

nginxのログ内容から、graceful shutdownが正常に実行されていることが確認できます。

2018/01/25 13:57:14 [notice] 1#1: using the "epoll" event method
2018/01/25 13:57:14 [notice] 1#1: openresty/1.13.6.1
2018/01/25 13:57:14 [notice] 1#1: built by gcc 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.5)
2018/01/25 13:57:14 [notice] 1#1: OS: Linux 4.4.86+
2018/01/25 13:57:14 [notice] 1#1: getrlimit(RLIMIT_NOFILE): 1048576:1048576
2018/01/25 13:57:14 [notice] 1#1: start worker processes
2018/01/25 13:57:14 [notice] 1#1: start worker process 11

# SIGQUITが送信される
2018/01/25 13:58:31 [notice] 1#1: signal 3 (SIGQUIT) received, shutting down
2018/01/25 13:58:31 [notice] 11#11: gracefully shutting down

# レスポンスが終了するまで待つ
2018/01/25 13:58:41 [notice] 11#11: exiting
10.0.2.1 - - [25/Jan/2018:13:58:41 +0000] "GET /sleep HTTP/1.1" 200 18 "-" "curl/7.54.0"
2018/01/25 13:58:41 [notice] 11#11: exit
2018/01/25 13:58:41 [notice] 1#1: signal 17 (SIGCHLD) received from 11
2018/01/25 13:58:41 [notice] 1#1: worker process 11 exited with code 0
2018/01/25 13:58:41 [notice] 1#1: exit

まとめ

  • TERM以外のSIGNALを送信したい場合、Dockerfile instructionsのSTOPSIGNALで変更

最後に

Issue #30051を見るとK8SのSTOPSIGNAL 対応は、2016年8月(v1.4以降)以降に実施されているようです。
そのため、それ以前の記事ではWorkaroundな対応として、preStopを使った方法を記載してたのかも。
ただ途中でlifetimeの挙動が変更されたため、当時は正常にgraceful shutdownしていた可能性もあります。

K8Sの進化は早いので定期的にドキュメントを見ていかないと。

備考