gate第二弾 〜流れるログが見たい〜
こちらはピクシブ株式会社Advent Calendar 12/14分の記事です。
インフラチームの @catatsuy です．
以前の記事で gate を紹介しました．
gateを使って手軽に認証を導入する - pixiv inside
今回の記事は gate 第二弾です．
以前にも紹介しましたがピクシブ社内ではデプロイツールとして edvakf/pploy を採用しています． しかし pploy ではデプロイ時に実行されるログをブラウザからリアルタイムに見られるようになっていましたが，実際のインフラ構成では以下のように pploy のレスポンスはプロキシされていきます．
pploy --> gate --> Nginx --> User
このように pploy からユーザーに辿り着くまでに Nginx と gate の 2 つのプロキシサーバーを通る必要があります．その際にどこかでログがバッファリングされていてログがストリーミングされないという問題が発生しました．
なんとしてもログをストリーミングにして流れるところが見たい，その気持ちで @edvakf さんを中心に今回色々調べました．
今回の記事の前半は以下の記事と重複している部分もあるので是非参考にしてください．
PlayでOSコマンドの出力をリアルタイムに返したい - Qiita
行バッファリングではなくフルバッファリングになる
pploy ではコマンドを exec していますが，libc の実装では出力先がターミナルでない場合は行バッファリングではなく4096バイトのフルバッファリングになるという問題がありました．
shell - Turn off buffering in pipe - Unix & Linux Stack Exchange
これを解消するにはいくつか方法があるようですが，script コマンドで実行するようにすることにしました．script コマンドは Mac(BSD) と Linux でコマンドの使い方が異なるので pploy では OS 毎に実行されるコマンドを変えています．
script コマンドを使って command というコマンドを実行する場合は以下の様に実行できます．
# Linux
script -c command -q /dev/null
# BSD
script -q /dev/null command
こうすることでコマンドの実行結果は行バッファリングされるだけになります．これで pploy 単体ではログがストリーミングされるようになりました．
Transfer-Encoding: chunked
当初は HTTP1.1 で定義された Transfer-Encoding: chunked を使用してログをストリーミングにしようとしていました．
pploy + Nginx の構成ではログがストリーミングされたので gate 側でバッファリングされていないか調査をしました．そこで net/http/httputil の ReverseProxy では FlushInterval を指定ができ，そこで指定をしなければバッファリングは Go 側に完全に任されてしまっていつバッファリングを解放してくれるかわからないことがわかりました．そこで以下のプルリクのようにバッファリングを解放するタイミングを指定するパッチを当てました．
これにより Nginx と gate を通る検証環境ではうまく動きましたが，実環境に反映したところストリーミングされませんでした．当初は実環境で動かない原因を究明することができず，Transfer-Encoding: chunked を使う方法を一旦断念しました．
WebSocket
gate は WebSocket に対応しているので、 WebSocket を使って pploy のログを流すように変更しました．
しかし Nginx はそのままでは WebSocket をプロキシしてくれません．なので以下の記事を参考に設定しました．
NGINX as a WebSockets Proxy - NGINX
実際に行った設定は以下の様な設定です．
map $http_upgrade $connection_upgrade {
default upgrade;
'' close;
}
server {
listen 443 ssl;
server_name gate.example.com;
# sslの設定
include include-confs/ssl.conf;
location / {
satisfy any;
# officeのIP
allow ***.***.***.***;
deny all;
auth_basic "Please enter user / password";
auth_basic_user_file htpasswd;
proxy_read_timeout 300;
proxy_connect_timeout 300;
proxy_set_header Upgrade $http_upgrade;
proxy_set_header Connection "Upgrade";
proxy_http_version 1.1;
proxy_pass http://127.0.0.1:9999;
}
error_log /var/log/nginx/gate.example.com_error.log error;
access_log /var/log/nginx/gate.example.com_access.log;
}
これで Nginx は WebSocket を通してくれます．これで終わり…と思いきや，今度は gate 側に問題が見つかりました．gate では WebSocket の実装にバグがあり，ソケットのファイルディスクリプタを close してくれないのでデプロイが終了してログが止まってもコネクションが切れないという問題がありました．通常はあまり WebSocket の接続を切ることはないので問題になりませんが、 pploy ではこれが問題になるため、原因を突き止めて gate に以下のプルリクのような変更を加えて対応しました．
Fix bug where WebSocket's close wasn't sent to client by edvakf · Pull Request #14 · typester/gate
これによりデプロイのログがストリーミングされるようになり，デプロイ時のログを気持ちよく流すことに成功しました．
Transfer-Encoding: chunked 再び
WebSocket でログを流すことには成功しましたが，今回の用途では一方的にログを流したいだけなので WebSocket の双方向性は必要ありません．そこでなぜ chunked で成功しなかったのかもう一度調べることにしました．
本番環境と検証環境の差異は HTTPS 通信であるかないかの違いしか見当たらなかったので検証環境でオレオレ証明書を作成して検証してみました．
Apache/SSL自己証明書の作成とmod sslの設定 - maruko2 Note.
そして HTTPS で通信させたところ実環境で確認されたログがストリーミングされない現象を再現することができました．そこで下のページを参考に proxy_buffering off; の設定を Nginx に追加しました．
node.js - nginx 1.4.4 + https + chunk encoding - Stack Overflow
これで HTTPS 通信を使っていてもログがストリーミングされるようになりました．SSL で Transfer-Encoding: chunked をきちんとプロキシする Nginx の設定は以下のようになります．
server {
listen 443 ssl;
server_name gate.example.com;
# sslの設定
include include-confs/ssl.conf;
location / {
satisfy any;
# officeのIP
allow ***.***.***.***;
deny all;
auth_basic "Please enter user / password";
auth_basic_user_file htpasswd;
proxy_http_version 1.1;
proxy_buffering off;
proxy_pass http://127.0.0.1:9999;
}
error_log /var/log/nginx/gate.example.com_error.log error;
access_log /var/log/nginx/gate.example.com_access.log;
}
これで edvakf/testploy をデプロイしてみるとこのようにログがストリーミングされます．
まとめ
デプロイ時のログをストリーミングしたい！という強い思いでやっと pploy で gate と Nginx を通してもうまくログをストリーミングさせることができました．今回は 2 つのプロキシサーバーを通さなければならない上に HTTPS 通信をする必要があるという特殊な環境でしたが，参考になれば幸いです．
明日は @consomme72 さんが Android の話をしてくれると思うのでご期待ください！！
