新説 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)を再起動するタイミングで発生しているため対応していきます。

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

- [Tuning NGINX behind Google Cloud Platform HTTP(S) Load Balancer](https://blog.percy.io/tuning-nginx-behind-google-cloud-platform-http-s-load-balancer-305982ddb340)

## 環境
- Kubernetes: v1.8.6(Docker v17.3)
- nginx: v1.11.x

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

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

設定は[K8S公式doc](https://kubernetes.io/docs/tasks/configure-pod-container/attach-handler-lifecycle-event/)に記載されている以下の設定を使って`graceful shutdown`を実現していました。
`kubernetes nginx graceful shutdown`でググると同様の記事が見つかります。

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

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

が、この設定ではダメでした。
![image.png](https://qiita-image-store.s3.amazonaws.com/0/62029/b588c265-918d-42d7-b0b9-cf9d884d1e29.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の`STOPSIGNAL`instructionsでコンテナ終了時に`SIGQUIT`を送信するように変更

```dockerfile:Dockerfile
FROM nginx
STOPSIGNAL SIGQUIT
```

## 検証
ではここから本当に修正されるか確認していきます。
検証ではnginxの代わりに、`lua`を使用するためOpenRestyを使用しています。
検証で使用した設定は[こちら](https://gist.github.com/watawuwu/5b47c17fabb015773766b8840380140f)にアップロードしています。

### 再現編
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](https://github.com/kubernetes/kubernetes/issues/30051#issue-169290787)を見るとK8Sの`STOPSIGNAL` 対応は、2016年8月(v1.4以降)以降に実施されているようです。
そのため、それ以前の記事ではWorkaroundな対応として、`preStop`を使った方法を記載してたのかも。
ただ途中でlifetimeの挙動が変更されたため、当時は正常に`graceful shutdown`していた可能性もあります。

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

# 備考
- [検証で使用した設定](https://gist.github.com/watawuwu/5b47c17fabb015773766b8840380140f)
- [Kubernetes: 詳解 Pods の終了](https://qiita.com/superbrothers/items/3ac78daba3560ea406b2)