Node.js の Web サーバでタイムアウトすると自動でリトライされてる
◆ タイムアウト時に再度リクエスト来たような処理される
◆ ヘッダーやボディも同じなので多重登録される
◆ 発生しない場合もあって 3 回以上リクエスト受け付けてる場合もある
◆ Node.js のサーバの setTimeout でタイムアウト短くしたら早めに発生
◆ ブラウザでは 1 回しかリクエストしてない扱い
≪追記≫
◆ レスポンスを返さないとブラウザがリトライするのが仕様 (SHOULD)
◆ 何も返さずコネクション閉じずに 408 を返す
◆ Node.js のデフォルトは単に閉じるだけ
≪追記2≫
◆ 408 にしてもリトライされる場合はある
◆ Chrome で確認したらトップフレームアクセスなら POST でもリトライしてた
◆ fetch のバックグラウンドアクセスはしてないみたい
◆ ブラウザの挙動に振り回されたくないなら 200 にして JSON レスポンスで timeout エラーを通知
≪追記3≫
◆ レスポンスなしでコネクションを切った場合にリトライする数
◆ 同じサーバへの別リクエストが成功してるとリトライを繰り返す
◆ 別リクエストを送ってないとサーバが異常と判断されるのかリトライは 0 か 1 回
◆ ヘッダーやボディも同じなので多重登録される
◆ 発生しない場合もあって 3 回以上リクエスト受け付けてる場合もある
◆ Node.js のサーバの setTimeout でタイムアウト短くしたら早めに発生
◆ ブラウザでは 1 回しかリクエストしてない扱い
≪追記≫
◆ レスポンスを返さないとブラウザがリトライするのが仕様 (SHOULD)
◆ 何も返さずコネクション閉じずに 408 を返す
◆ Node.js のデフォルトは単に閉じるだけ
≪追記2≫
◆ 408 にしてもリトライされる場合はある
◆ Chrome で確認したらトップフレームアクセスなら POST でもリトライしてた
◆ fetch のバックグラウンドアクセスはしてないみたい
◆ ブラウザの挙動に振り回されたくないなら 200 にして JSON レスポンスで timeout エラーを通知
≪追記3≫
◆ レスポンスなしでコネクションを切った場合にリトライする数
◆ 同じサーバへの別リクエストが成功してるとリトライを繰り返す
◆ 別リクエストを送ってないとサーバが異常と判断されるのかリトライは 0 か 1 回
おかしなバグ
ウェブアプリでおかしなバグが起きていましたなぜか同じデータが複数回保存されています
そんなことになるような処理は無いはずと思いつつも予想外のバグがあるのかなと思って調べてみるもそれらしいものが全然ありません
デバッガを使って調べてみると 確かに登録関数が 2 回呼び出されていました
繰り返しの処理はなくスタックを見たところ http リクエストを受け取ったところから想定どおりのスタックで再帰になってるとかもないです
Koa を使ってたので ctx に適当なデータをセット+表示をしたところ毎回空になってたので 同じリクエストで 2 回実行されてるわけでもないようです
Koa がバグで 1 回のリクエストに対して 2 回リクエスト処理を行ってるケースも考えて ctx.req.socket でも試してみましたが同じく引き継がれてませんでした
socket が異なるならブラウザが再度リクエストしてそうですが ブラウザ側を devtools で見たところリクエストは 1 回のみでした
もう少し調べてみると 2 回目はちょうど 2 分後に実行されていました
また 2 回で終わりではなく 3 回や 4 回実行されてるケースもあります
調べたところ Node.js のデフォルトタイムアウトは 2 分なのでこれが影響してそうです
Koa は関係なさそうなのでできる限りシンプルなものにしても再現しました
タイムアウトも待ってられないので 5 秒にしましたが これで 5 秒後に再度リクエストを受けたような処理をするようになりました
ただ 5 秒にしてからは 発生しないケースが増えて 発生しても最大で 2 回のリクエストにしかなっていません
const fs = require("fs")
const path = require("path")
const http = require("http")
const server = http
.createServer((req, res) => {
if(req.url === "/wait") {
console.log("wait", new Date())
}else {
res.end("ok")
}
})
server.listen(8000).on("listening", () => { console.log("start") })
server.setTimeout(1000 * 5)
global.server = server
外部ライブラリは使わず標準の http で作ったサーバです
リクエストの url を見て /wait ならレスポンスを返さずタイムアウトさせます
それ以外なら ok というレスポンスを返します
ブラウザでは / のページを開いてから fetch で /wait にアクセスします
送信方法はコンソールで下のコードを実行します
fetch("/wait", {method: "POST", body: ""})
最初に発生したのは普通にページ上の処理なので devtools の有無は関係ないはずです
それと 困るのが POST の場合なので POST で試してますが GET でも起きてます
Node.js のコンソールにはこう表示されました
wait 2019-10-10T11:17:02.783Z
wait 2019-10-10T11:17:07.796Z
ちゃんと 5 秒後に console.log が出ています
ブラウザ側の表示はリクエスト 1 回になっています
そのリクエストが 5 秒では終わらず 10 秒後にタイムアウトになってました
発生が確実ならともかく 発生しない場合があったり繰り返し回数も固定じゃないのが気になるところです
体感だと 2 回連続でやると起きない場合があって 「/」 へのリクエストを挟むと再度発生するような気がしますが 偶然の気もします
環境の問題の可能性もあったので色々環境を変えましたがはっきりとした原因はわかりませんでした
Node.js のバージョンは 12.7 だったのでアップデートして 12.10 にしましたが変わらず発生しました
また http モジュールの代わりに https にしてみましたが これも変わらず発生しました
クライアントは Chrome でも Firefox でも起きます
サーバは Node.js しか試してませんが Windows でも Linux でも起きています
ただ devtools で curl 用のリクエストスクリプトをコピーして同じリクエストを実行すると 今のところ発生してません
curl 'http://localhost:8000/wait' -X POST -H 'Sec-Fetch-Mode: cors' -H 'Referer: http://localhost:8000/' -H 'Origin: http://localhost:8000' -H 'User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.90 Safari/537.36' -H 'Content-Type: text/plain;charset=UTF-8' --compressed
curl: (52) Empty reply from server
クライアントの問題にしては Chrome と Firefox どっちでも起きてますし イマイチよくわかりません
ブラウザのみだと preflight request が思い浮かびましたが それで 2 重登録になったら普段から 2 重登録されてるはずです
それに HTTP メソッドは OPTIONS のはずで この簡易版はともかく Koa で作ったもとのサービスでは POST のみに限定してます
対処
なんにしてもタイムアウトしてるのに 同じリクエストが自動でもう一度発生なんてバグでしかないと思いますヘッダやボディも含めて全く同じリクエストが二回なんて二重登録されて厄介すぎます
サーバ的に別リクエスト扱いなので 対処方法は何かで 2 回目であることを検出しないといけません
簡単なものだと リクエストデータにタイムスタンプを追加して離れすぎてるなら無視が単純です
でもクライアントとサーバが時刻同期されてる保証もないですし 信頼性に欠けます
リクエストデータのハッシュ値を求めて変数に保存して一定時間以内にあったら無視もできます
でも本当に同じデータを 2 回作りたいケースもありえます
ちょっと面倒ですがワンタイムトークンを送るようにすれば 2 回目以降のリクエストは不正になります
ただすでにタイムアウトしてるようにレスポンスがすぐ返らないケースがあって バックグラウンドで処理してるのに一つの処理が終わらないことには次の操作ができないのは不便です
ワンタイムトークンを 10 個くらい最初から持たせておくのもありですが 管理が大変そうです
同じのを弾けばいいので 毎回送信時にランダムなデータをクライアントで作って送信して サーバではそれを一定期間保存して重複したらエラーにするのがありかもです
ハッシュ値を保存と違って毎回ランダムなので同じデータを 2 回送信してればちゃんと保存できます
でもこんなおかしな挙動のために特殊な処理をすること自体が間違ってる気がするのですよね
サーバで設定したタイムアウトのタイミングで発生することはわかってるので タイムアウトを無効とか 1 年くらいのありえない期間にしておけばそれでいい気もします
タイムアウトがレア?
こんな問題ある挙動だと誰かが報告してすぐ直ってそうな気はするのですが サーバとクライアントで最新や少し前のバージョンの組み合わせで起きてるのですよねやっぱりタイムアウト自体がレアであまりテストしないのでしょうか
自分でもタイムアウトするような長いリクエストは普通無いよねと思ってるのですが サーバ側の処理の都合上長くなりました
とりあえず ID だけ返してあとからその ID で問い合わせてもらうのがコネクション数を減らせて良い方法だと思いますけど 作るのが面倒なのですよね
対してリクエスト数がない上にブラウザ的にはバックグラウンド通信なので レスポンス待ってる間も他の操作できるのでこれでいいやという感じで作ったのですが余計な問題が出ました
まだ気になるところ
面倒なのでもうこの問題には関わりたくないなーと思いつつも気になるところがありますNode.js のウェブサーバの setTimeout で具体的に何してるのか あと他の PHP や Python 等の場合に発生するのかです
気が向けば調べて見るかもしれません
【追記】
1 日たってやっぱり気になったので調べることにしました最終的には原因もわかって納得行く結果でした
どこが悪いかと言うなら Node.js のマナー……でしょうか
Node.js の timeout の中身
Node.js の http サーバで設定した setTimeout は timeout イベントを起こす時間を設定していて そのイベントに設定された処理は socket を destroy するというものでした他に特別なことはなさそうで 2 回目のリクエストが起きそうには見えません
また Node.js の非同期の仕組み上 socket が閉じられるだけで その request イベントのコールバック中で実行した処理は続行したままです
timeout 時に止めたいなら自分で timeout イベントを listen して 中断処理が必要です
Python の場合
curl では起きていないのでブラウザの問題な気もしますが サーバが Node.js じゃない場合も確認しておきたいので Python で Web サーバを作ってみましたimport http.server
import datetime
import time
class CustomHTTPRequestHandler (http.server.BaseHTTPRequestHandler):
def do_GET(self):
self.send_response(200)
self.send_header("Content-Type", "text/plain")
self.end_headers()
self.wfile.write("200".encode("utf8"))
def do_POST(self):
print(datetime.datetime.now())
time.sleep(3)
if __name__ == "__main__":
server_address = ("", 9000)
httpd = http.server.HTTPServer(server_address, CustomHTTPRequestHandler)
print(":" + str(server_address[1]))
httpd.serve_forever()
URL のパスではなく POST の場合のみレスポンスを返さないようにしてます
Chrome で GET でページアクセスして fetch で POST メソッドを使ったリクエストを送ります
コンソールの出力をみると
2019-10-14 12:21:51.163558
2019-10-14 12:21:54.465601
3 秒後にリトライされています
Python でも再現するので Node.js の問題ではなさそうです
timeout ってこれでいいの?
Python 版を書いてみて気になったのですが POST の場合の処理は単になにもせず待機するだけですブラウザからのエラーメッセージを見ると
POST http://localhost:9000/ net::ERR_EMPTY_RESPONSE
というもので Node.js も Python も同じなので これでいいと思ってましたが サーバ側で timeout する場合ってこれが正しい方法なのでしょうか?
自分でそういう処理を書いたことがないのでよくわかってません
調べてみると MDN にこんなページがありました
https://developer.mozilla.org/en-US/docs/Web/HTTP/Status/408
ちゃんと 408 というタイムアウトのステータスコードがありました
これを返すのが正しそうです
ページ内の注意書きを見るとこんなのがありました
Note: some servers merely shut down the connection without sending this message.
サーバによっては このメッセージを送らずに単純にコネクションを閉じるだけの場合があるようです
Node.js は送ってませんね
単純に socket の destroy メソッドを呼び出してます
ブラウザのレスポンスエラーをみても EMPTY_RESPONSE って言われてます
よくみるとタイムアウトとは言ってないのですよね
Python の場合も自分でなにもしてないのでレスポンスなしです
タイムアウトじゃなくてレスポンスを受け取らず接続が閉じられてるなら再送されるのも仕方ない気がしました
ちゃんと 408 を返せばリトライはされない気がするので Node.js でちゃんと 408 を返すように修正します
408
修正版のコードはこうなりましたhttp = require("http")
const server = http.createServer((req, res) => {
console.log(new Date(), req.url)
if(req.url === "/to") {
res.once("timeout", () => {
res.statusCode = 408
res.end("")
})
} else {
res.end("200")
}
})
server.setTimeout(2000)
server.listen(9000).on("listening", () => {console.log("Start")})
response の timeout イベントを受け取ったら statusCode に 408 を設定してレスポンスを返します
これで試したところ リトライが発生しなくなってました
Node.js で timeout イベントを listen する場合
設定した timeout の時間が経過したら場合に呼び出されるコールバックの処理はこうなっていますfunction socketOnTimeout() {
const req = this.parser && this.parser.incoming;
const reqTimeout = req && !req.complete && req.emit('timeout', this);
const res = this._httpMessage;
const resTimeout = res && res.emit('timeout', this);
const serverTimeout = this.server.emit('timeout', this);
if (!reqTimeout && !resTimeout && !serverTimeout)
this.destroy();
}
この関数自体はレスポンスを返した後でも呼び出されることがあります
res は socket._httpMessage になっていてすでにレスポンスを返していた場合には存在しません
なので res に対して timeout イベントをつけておくと良いと思います
また 最後の if のとおり timeout イベントが listen されている場合には destroy は行われません
EventEmitter の emit メソッドは そのタイプのイベントに 1 つ以上のリスナが設定されているとコールバックの内容問わず true が返されます
なにかの関数を実行したら true ということです
req, res, server のどれかの timeout イベントにリスナを設定する場合は destroy が自動で呼び出されなくなるのでなにもしないとクライアントと接続したままになります
end や destroy を自分でちゃんと呼び出す必要があります
リトライの理由
リトライが行われた理由ですが調べてみると HTTP の仕様でしたhttps://www.w3.org/Protocols/rfc2616/rfc2616-sec8.html#sec8.2.4
if the client sees the connection close before receiving any status from the server, the client SHOULD retry the request.
という一文があります
「クライアントがなにかのステータスをサーバから受け取る前にコネクションが閉じたらリクエストをリトライすべき」だそうです
ということは Chrome や Firefox ではちゃんと仕様に沿っていたということになります
devtools でリトライしたことを教えてほしいものですけど……
今回の問題が発生しなかった curl は自動リトライはしてくれないみたいですね
retry オプションはあるみたいですが 通常の接続エラーでも retry しそうでこの場合限定の設定があるかはわかりません
リトライの理由ははっきりしましたが リトライされたりされない場合があったり回数も揃ってないのが気になります
仕様のもうちょっと下に数式とかもあったので ここでリトライ回数定義してるのかなと思って Google 翻訳に入れてみた結果がこれです
1. サーバーへの新しい接続を開始します
2. リクエストヘッダーを送信する
3. サーバーへの推定往復時間(たとえば、接続の確立にかかった時間に基づいて)、または往復時間が利用できない場合は5秒の定数値に変数Rを初期化します。
4. T = R *(2 ** N)を計算します。Nは、この要求の以前の再試行回数です。
5. サーバーからのエラー応答を待つか、T秒(どちらか早い方)待つ
6. エラー応答が受信されない場合、T秒後に要求の本文を送信します。
7. 接続が時期尚早に閉じられたことをクライアントが確認した場合、要求が受け入れられるか、エラー応答が受信されるか、ユーザーが待ち焦がれて再試行プロセスを終了するまで、手順1から繰り返します。
いずれかの時点でエラーステータスが受信された場合、クライアントは
- 続行しないでください
- 要求メッセージの送信が完了していない場合、接続を閉じる必要があります。
計算式はリクエストボディの送信までの時間 T 秒を求めてるだけでリトライ回数は決まってないみたいです
正常にレスポンスが返ってくるかエラーが返ってくるかユーザが中断するまで繰り返すとあります
この辺はブラウザが適当に決めてるのでしょうか
あと この仕様を眺めてると 408 ステータスコードの説明が「クライアントはあとで変更なしでリトライしてもよい」となってたのが気になりますが 実際にはリトライされてないのでたぶん大丈夫でしょう
まとめ
タイムアウト時にレスポンス何も返さずコネクション閉じるのはダメちゃんと 408 レスポンスを返しましょう
Node.js のデフォルトは設定してくれてません
【追記2】
408 でもリトライするかもって部分が気になったのでもうちょっとだけ調べましたChrome だとトップフレームで普通にページを開いたときに 408 が返ってくるとリトライするようです
2 回リトライで 3 回アクセスがありました
回数は単純な通信切断時みたいに変わるかもしれません
fetch を使ったバックグラウンドでのリクエストの場合はリトライなしのエラー 1 回で終了していました
ページとして開く場合に なんどかアクセスするというのはなんとなくわかりますね
エラー画面表示しておいても不便ですし 普段からエラー画面になると定期的に再アクセスしてるような動きはしてます
ただ form を使った POST の場合でもリトライされます
トップフレームでアクセスする場合でタイムアウトするほど待たせるつくりにはしないのでこれは別にいいかなと思います
ただバックグラウンド通信でリトライしないというのが保証されてるわけではないと思うので 408 を返すのではなく
{ ok: false, error: "timeout" }
のような JSON を 200 として返したほうがいいかもしれません
JSON を受け取る前提ならステータスコードのエラーよりも一括して JSON 内のエラー情報をチェックするほうが扱いやすいですし なによりステータスコードにおけるブラウザの挙動を考えなくて済みます
【追記3】
タイムアウトが 2 分の場合にリトライ回数が多かった理由がわかりました半日ほど放置してたら登録されたデータ数が 500 件を超えていました
すべて 2 分おきなのでずっとリトライされて続けてたようです
なんでこの場合だけこんなにリトライするのかわからなかったのですが 調べていると同サーバへ別のリクエストが定期的に行われていました
こっちは正常にレスポンスを受け取れています
タイムアウトするまでに同じサーバへの別リクエストがあってそれが正常ならたまたまの可能性もあるしリトライしとこう とブラウザが判断してるみたいです
別リクエストがない場合は 1 回か 2 回でエラーになって終わっていました
簡単に再現できるよう方法はまずこのコードを実行して毎秒リクエストを送ります
setInterval(() => fetch("/"), 1000)
その後 タイムアウトするリクエストを送ります
5 秒でタイムアウトになります
fetch("/a")
コンソールをみると 1 回しかリクエストしてないのに 5 秒ごとのリトライが続いています
13:04:20
13:04:25
13:04:30
13:04:35
13:04:40
13:04:45
13:04:50
13:04:55
13:05:00
...
ちゃんとした仕様は見つけれてないですが 直近でそのサーバと正常に通信できたことがあればリトライして そうでないなら諦めるというようにブラウザが判断してるようです