みなさんにも、さまざまな過去の経緯からくる微妙挙動を満載した外部ユーザ向けのHTTPサーバをリプレイスしたりするとき、実際にガツンとやっちまう前にちょっとリクエストを分岐して挙動と性能を確認したい、と思うことがあると思います。考えるだけでつらい気分になってくるやつ。でもやったほうが100倍マシなやつ。
どうしよっかなとちょっと考えたところ、少し前にこんな話があったのを思い出すはずですね*1。
asnokaze.hatenablog.com
とはいえヨッシャ使うぞといきなりぶちこむこともできないので、まずいくつか試してみることにする。
準備
前提としては以下のように、元のアプリケーションと同じにホストにリバースプロキシが立っており、そこのnginxで http_mirror_module を使う、という想定*2。ミラー先はどこか適当なアプリケーションサーバ(あるいはロードバランサ)で、元アプリとまったく同じ機能を提供する、はず、ということにする。このNginxでstatic fileを扱うなどの処理については今回は考えない(すべてのリクエストがproxyされる)。
--->[nginx (port 8080)]--->[app P (port 8081)]
|
[http_mirror_module]
|
+------------------>[app Q (port 8082)]ここでは簡単のため、全プロセスを同一ホストで起動、それぞれ port 8080, 8081, 8082 で実行する。
Nginxのdownloadページからおもむろに現在の mainline version であるところの 1.13.10 をダウンロードして適当なディレクトリに展開、あとは普通にビルドする。http_mirror_moduleはなんとデフォルトで有効。
$ ./configure --prefix=/usr/local/nginx-1.13.10
$ make
$ sudo make install
$ sudo chown -R tagomoris /usr/local/nginx-1.13.10 # 自分のユーザ名で
Nginxの設定としてはできるだけ簡単にして、最初は以下のように。proxy先の状況もちゃんとわかるよう、アクセスログには $request_time と $upstream_response_time の両方を記録しておく。
worker_processes 1;
error_log logs/error.log;
events {
worker_connections 1024;
}
http {
include mime.types;
default_type application/octet-stream;
log_format main '$remote_addr - $remote_user [$time_local] "$request" '
'$status $body_bytes_sent "$http_referer" '
'"$http_user_agent" "$http_x_forwarded_for" '
'$request_time $upstream_response_time';
access_log logs/access.log main;
sendfile on;
keepalive_timeout 65;
server {
listen 8080;
server_name localhost;
location /a {
proxy_pass http://127.0.0.1:8081/a; # P
mirror /mirror;
}
location /b {
proxy_pass http://127.0.0.1:8081/b; # P
mirror /mirror;
}
location /mirror {
internal;
proxy_pass http://127.0.0.1:8082; # Q
}
}
}なお /mirror はリクエストの複製にのみ使う internal redirect 用のlocationなので、外部からアクセスされないようinternalディレクティブを有効にしておく。
設定内容を確認してnginxを起動。
$ /usr/local/nginx-1.13.10/sbin/nginx -t
nginx: the configuration file /usr/local/nginx-1.13.10/conf/nginx.conf syntax is ok
nginx: configuration file /usr/local/nginx-1.13.10/conf/nginx.conf test is successful
$ /usr/local/nginx-1.13.10/sbin/nginx
プロキシ先のアプリケーションは以下のようなものをrubyで適当に書く。環境変数で設定をいじれるようにしとく。
require 'sinatra'
port = ENV.fetch("PORT", "8080").to_i
sleep_time = ENV.fetch("SLEEP_INTERVAL", "0").to_i
configure do
set :port, port
end
get '/a' do
p(time: Time.now, here: "a")
sleep sleep_time
"ok #{sleep_time}"
end
post '/b' do
p(time: Time.now, here: "b", body: request.body.read)
sleep sleep_time
"ok #{sleep_time}"
end
gem i sinatra してあれば ruby app.rb で起動できる。これを以下のようにふたつ起動する。
$ PORT=8081 SLEEP_INTERVAL=0 ruby app.rb # P
[2018-04-02 18:13:24] INFO WEBrick 1.4.2
[2018-04-02 18:13:24] INFO ruby 2.5.1 (2018-03-29) [x86_64-darwin17]
== Sinatra (v2.0.1) has taken the stage on 8081 for development with backup from WEBrick
[2018-04-02 18:13:24] INFO WEBrick::HTTPServer#start: pid=19491 port=8081
$ PORT=8082 SLEEP_INTERVAL=0 ruby app.rb # Q
(省略)
準備完了。
普通にmirror proxyする
まず設定は上記の設定に入っていたこの部分から。/a および /b に来たリクエストを 8081 のupstream に流すが、同時にmirrorして 8082 にも流す。
location /a {
proxy_pass http://127.0.0.1:8081/a;
mirror /mirror;
}
location /b {
proxy_pass http://127.0.0.1:8081/b;
mirror /mirror;
}
location /mirror {
internal;
proxy_pass http://127.0.0.1:8082;
}これでリクエストを流してみる。
$ curl -v http://localhost:8080/a
* Trying ::1...
* connect to ::1 port 8080 failed: Connection refused
* Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /a HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.45.0
> Accept: */*
>
< HTTP/1.1 200 OK
< Server: nginx/1.13.10
< Date: Mon, 02 Apr 2018 09:14:13 GMT
< Content-Type: text/html;charset=utf-8
< Content-Length: 4
< Connection: keep-alive
< X-Xss-Protection: 1; mode=block
< X-Content-Type-Options: nosniff
< X-Frame-Options: SAMEORIGIN
<
* Connection #0 to host localhost left intact
ok 0
当たり前だけど普通に返ってくる。アクセスログを見てみると、やっぱり普通。
127.0.0.1 - - [02/Apr/2018:18:14:13 +0900] "GET /a HTTP/1.1" 200 4 "-" "curl/7.45.0" "-" 0.011 0.009
が、このときアプリケーション側のログを見てみるとおかしい。Pの側は普通にリクエストを処理しているがQは /mirror/a というパスのリクエストを受け取ってエラーを出してる。
# P
{:time=>2018-04-02 18:14:13 +0900, :here=>"a"}
127.0.0.1 - - [02/Apr/2018:18:14:13 +0900] "GET /a HTTP/1.1" 200 4 0.0067
- -> /a
# Q
127.0.0.1 - - [02/Apr/2018:18:14:13 +0900] "GET /mirror HTTP/1.1" 404 464 0.0074
- -> /mirrorこのとき、error_log には何も出ていない。
これは /mirror 側でproxyするとき、pathをいじったのを元に戻さなかったからですね……ということで以下のように設定を変更。
location /mirror {
internal;
proxy_pass http://127.0.0.1:8082$request_uri;
}なおこれはNginxのhttp_mirror_moduleのドキュメントを見ると冒頭に例でちゃんと $request_uri が指定されていて、見落としちゃダメですよ、という心遣いを感じる。
これで nginx -s reload して curl してみると、PとQで全く同じリクエストを受け取れるようになった。
# nginx access.log
127.0.0.1 - - [02/Apr/2018:18:20:36 +0900] "GET /a HTTP/1.1" 200 4 "-" "curl/7.45.0" "-" 0.003 0.003
# P
{:time=>2018-04-02 18:20:36 +0900, :here=>"a"}
127.0.0.1 - - [02/Apr/2018:18:20:36 +0900] "GET /a HTTP/1.1" 200 4 0.0008
- -> /a
# Q
{:time=>2018-04-02 18:20:36 +0900, :here=>"a"}
127.0.0.1 - - [02/Apr/2018:18:20:36 +0900] "GET /a HTTP/1.1" 200 4 0.0010
- -> /aパスを /b にしてPOSTしてみても大丈夫。
$ curl -v -X POST --data-ascii '{"num":1}' http://localhost:8080/b
Note: Unnecessary use of -X or --request, POST is already inferred.
* Trying ::1...
* connect to ::1 port 8080 failed: Connection refused
* Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> POST /b HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.45.0
> Accept: */*
> Content-Length: 9
> Content-Type: application/x-www-form-urlencoded
>
* upload completely sent off: 9 out of 9 bytes
< HTTP/1.1 200 OK
< Server: nginx/1.13.10
< Date: Mon, 02 Apr 2018 09:25:43 GMT
< Content-Type: text/html;charset=utf-8
< Content-Length: 4
< Connection: keep-alive
< X-Xss-Protection: 1; mode=block
< X-Content-Type-Options: nosniff
< X-Frame-Options: SAMEORIGIN
<
* Connection #0 to host localhost left intact
ok 0
# access.log
127.0.0.1 - - [02/Apr/2018:18:25:43 +0900] "POST /b HTTP/1.1" 200 4 "-" "curl/7.45.0" "-" 0.003 0.003
# P
{:time=>2018-04-02 18:25:43 +0900, :here=>"b", :body=>"{\"num\":1}"}
127.0.0.1 - - [02/Apr/2018:18:25:43 +0900] "POST /b HTTP/1.1" 200 4 0.0006
- -> /b
# Q
{:time=>2018-04-02 18:25:43 +0900, :here=>"b", :body=>"{\"num\":1}"}
127.0.0.1 - - [02/Apr/2018:18:25:43 +0900] "POST /b HTTP/1.1" 200 4 0.0007
- -> /bcontent body も両方にわたってて、あれ mirror_request_body を指定しなくてもいいの? と先述のblogエントリを読んだ印象からは受ける、が、そもそも mirror_request_body は default on だった。これはちゃんと該当ディレクティブのドキュメントを読んで、性能問題について考慮した上で必要な場合は off にしましょう。*3
mirror upstream を落としてみる
方法は簡単、単にプロセスを停止させる。この場合は Q のプロセスを止める。
で、その状態でアクセスしてみる。元々のproxy先である P は生きていることに注意。
$ curl -v http://localhost:8080/a
* Trying ::1...
* connect to ::1 port 8080 failed: Connection refused
* Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /a HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.45.0
> Accept: */*
>
< HTTP/1.1 200 OK
< Server: nginx/1.13.10
< Date: Mon, 02 Apr 2018 09:36:32 GMT
< Content-Type: text/html;charset=utf-8
< Content-Length: 4
< Connection: keep-alive
< X-Xss-Protection: 1; mode=block
< X-Content-Type-Options: nosniff
< X-Frame-Options: SAMEORIGIN
<
* Connection #0 to host localhost left intact
ok 0
# access.log
127.0.0.1 - - [02/Apr/2018:18:36:32 +0900] "GET /a HTTP/1.1" 200 4 "-" "curl/7.45.0" "-" 0.003 0.002
# P
{:time=>2018-04-02 18:36:32 +0900, :here=>"a"}
127.0.0.1 - - [02/Apr/2018:18:36:32 +0900] "GET /a HTTP/1.1" 200 4 0.0006
- -> /aフツーに動いている……が、唯一、error.log に以下のようなログが出ていた。状況はわかる。
2018/04/02 18:36:32 [error] 19539#0: *19 kevent() reported that connect() failed (61: Connection refused) while connecting to upstream, client: 127.0.0.1, server: localhost, request: "GET /a HTTP/1.1", subrequest: "/mirror", upstream: "http://127.0.0.1:8082/a", host: "localhost:8080"
これをもうちょっとわかりやすくするため log_subrequest ディレクティブを有効にしてみる。これは http_core_module のディレクティブ。
access_log logs/access.log main;
log_subrequest on;
$ /usr/local/nginx-1.13.10/sbin/nginx -t
nginx: the configuration file /usr/local/nginx-1.13.10/conf/nginx.conf syntax is ok
nginx: configuration file /usr/local/nginx-1.13.10/conf/nginx.conf test is successful
$ /usr/local/nginx-1.13.10/sbin/nginx -s reloadこの状態でもう一度 curl してみると、アクセスログに、処理に失敗しているリクエストがひとつ出てくる。んー、本来のリクエストとちょっと見分けがつかないな、これ。$upstream_addr でも入れますかね。*4
127.0.0.1 - - [02/Apr/2018:18:41:15 +0900] "GET /a HTTP/1.1" 502 0 "-" "curl/7.45.0" "-" 0.000 0.001
127.0.0.1 - - [02/Apr/2018:18:41:15 +0900] "GET /a HTTP/1.1" 200 4 "-" "curl/7.45.0" "-" 0.008 0.008
mirror upstream を遅くしてみる
今度は Q のプロセスを SLEEP_INTERVAL=5 で起動してみる。同じリクエストを投げてみると、同じレスポンスが即座に返ってくる。
$ curl -v http://localhost:8080/a
* Trying ::1...
* connect to ::1 port 8080 failed: Connection refused
* Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /a HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.45.0
> Accept: */*
>
< HTTP/1.1 200 OK
< Server: nginx/1.13.10
< Date: Mon, 02 Apr 2018 09:49:07 GMT
< Content-Type: text/html;charset=utf-8
< Content-Length: 4
< Connection: keep-alive
< X-Xss-Protection: 1; mode=block
< X-Content-Type-Options: nosniff
< X-Frame-Options: SAMEORIGIN
<
* Connection #0 to host localhost left intact
ok 0
が、アクセスログの方は、なんとQの処理が終わるまで表示されない。5秒経つと2行出力された。P側を処理したリクエストは $upstream_response_time は 0.003 なのに $request_time はQ側にひっぱられて 5.015 になっている。うーん。あとQ側の $body_bytes_sent がなんかおかしい数字。261bytesってなんだ。
# access.log
127.0.0.1 - - [02/Apr/2018:18:49:12 +0900] "GET /a HTTP/1.1" 200 261 "-" "curl/7.45.0" "-" 5.015 5.015
127.0.0.1 - - [02/Apr/2018:18:49:12 +0900] "GET /a HTTP/1.1" 200 4 "-" "curl/7.45.0" "-" 5.015 0.003
なおこの挙動とログ表示は log_subrequest off; でも変わらない。というか $upstream_response_time 0.003 なのに $request_time 5.015 な行だけが表示されてかなり不気味なことになる。実際のレスポンスはクライアントに返っているとはいえ、なかなか、どうしようかなこれ、という挙動だ。
またこの場合、PとQでは返しているレスポンスボディが異なる、が、特にそのことについて何らかのログが表示されたりはしない。コードもざっと読んだ*5が、そのような処理は書かれていないので当たり前だと言える。
primary upstream を落としてみる
逆にPが死んでるときQへのリクエストはどうなんの? というのもやってみる。Qは5秒sleepを入れたまま。
$ curl -v http://localhost:8080/a
* Trying ::1...
* connect to ::1 port 8080 failed: Connection refused
* Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /a HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.45.0
> Accept: */*
>
< HTTP/1.1 502 Bad Gateway
< Server: nginx/1.13.10
< Date: Mon, 02 Apr 2018 10:00:41 GMT
< Content-Type: text/html
< Content-Length: 174
< Connection: keep-alive
<
<html>
<head><title>502 Bad Gateway</title></head>
<body bgcolor="white">
<center><h1>502 Bad Gateway</h1></center>
<hr><center>nginx/1.13.10</center>
</body>
</html>
* Connection #0 to host localhost left intact
# access.log
127.0.0.1 - - [02/Apr/2018:19:00:46 +0900] "GET /a HTTP/1.1" 200 332 "-" "curl/7.45.0" "-" 5.006 5.006
127.0.0.1 - - [02/Apr/2018:19:00:46 +0900] "GET /a HTTP/1.1" 502 174 "-" "curl/7.45.0" "-" 5.006 0.001
# Q
{:time=>2018-04-02 19:00:41 +0900, :here=>"a"}
127.0.0.1 - - [02/Apr/2018:19:00:46 +0900] "GET /a HTTP/1.1" 200 4 5.0043
- -> /aやはりレスポンスは即座に 502 Bad Gateway として返ってくる。アクセスログはQ側を5秒待ってから表示される。
Q側のターミナルには普通にリクエストが投げられてきたのが表示されている。まあ自然といえば自然な挙動ではある、けど……。
雑感
とりあえずリクエストを複製する、という目的には十分使えそう。ただしmirror upstream側がトラブルで性能低下したりしたとき、ログ出力だけとはいえ通常の処理も影響を受けるというのは気をつけておいた方がよさそう。ログ上では $request_time の数字が遅くなるというのも、知らないでトラブル時のログを見ると混乱しそう。
また当然だけど worker_connections の数字を mirror upstream 側の接続についても当然消費するだろうから、この数字をきっちりに設定している場合は修正する必要があるはず。
mirror側のリクエストについてnginx上でどうログっておくかはなかなか悩ましい気がする。何も表示させないというのもひとつの手ではあるけど、レスポンスが遅くなったりしたときに $request_time の数字が突如低下することになる。これはどう考えても混乱要因になる……が、nginxのアクセスログを直接何かに使ってなければ無視できるかも。
log_subrequest on; しておくのはこれはこれで、いきなりアクセスログの行数が倍*6になる、というのはちょっときびしいような気もする。悩ましい。
mirror_request_body on; の場合に proxy_request_buffering が無効になる。これは性能面での特性の変化と、あとはドキュメントによると proxy_next_upstream が使えなくなる、という感じかな。これは機能的に容認できないという人がいるかもしれない。
性能面はまたひとつの懸案だけど、これは手元でちょっと試すというのにほとんど意味がないので割愛。しかし実際のところ、あまり心配しなくてもいいんじゃないか、というような予感はある。根本的にイベント駆動モデルをベースにしたサーバだしね。
さて、どうしよっかなー。そういえばみなさん nginx mainline version をproduction投入するの、最近は心理的にどうなんすかね。
