目的
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
でググると同様の記事が見つかります。
apiVersion: extensions/v1beta1
kind: Deployment
...
preStop:
exec:
command: ["/usr/sbin/nginx","-s","quit"]
...
一見正しくSIGQUIT
が送信されgraceful shutdown
されそうです。
理由は簡単。
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
を送信するように変更
FROM nginx
STOPSIGNAL SIGQUIT
検証
ではここから本当に修正されるか確認していきます。
検証ではnginxの代わりに、lua
を使用するためOpenRestyを使用しています。
検証で使用した設定はこちらにアップロードしています。
再現編
- レスポンスに10秒かかる
GET /sleep
の設定が含まれたnginxをデプロイ - curlでリクエストしつつ……
- (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
が出力されます。
解決編
- nginxのDockerfileに
STOPSIGNAL SIGQUIT
を追加しbuild - Dockerhub(or DockerPrivateRegistry) へpublish
- K8Sのマニフェストから
preStop
の部分を削除してデプロイ - curlでリクエストしつつ……
- (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の進化は早いので定期的にドキュメントを見ていかないと。