たごもりすメモ

コードとかその他の話とか。

Nginx 1.13 の http_mirror_module を試す

みなさんにも、さまざまな過去の経緯からくる微妙挙動を満載した外部ユーザ向けの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で適当に書く。環境変数で設定をいじれるようにしとく。

# app.rb
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
- -> /b

content 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投入するの、最近は心理的にどうなんすかね。

*1:とやって思い出せるので、こういうのを書いてくれる人は本当にすばらしい

*2:ロードバランス等はそこより上流で適当に行われている

*3:自分の例では off にしたら何も検証できなくなるので、しない

*4:http_mirror_moduleのコードを読んだ限り、この区別に使えそうな変数は特に増えてはいない様子だった

*5:超短くてわかりやすい!

*6:他の用途における internal redirect などを含めればもっと?