はじめに

こんにちは、エンジニアの遠藤です。

先日、とあるお客様からの依頼で、以下のようなシステムを作りました。

  • 1時間に1回、ちょっとした集計をした後、RDBに書き込む
  • 書き込んだデータは、Webから csv でダウンロードできる
  • Webへのアクセスは、月に1回程度

元々お客様が Azure のアカウントをお持ちでしたので、 Azure 上に Function + App Service （Node.js） + SQL Server という構成で構築しました。

SQL Serverへの接続は node-mssqlという NPMパッケージを使っています。

その際に、なぜか DB への Session が増え続けとても困った、というお話です。

結論

結論から書きますと、 Prepared Statement の解除漏れでした。
https://www.npmjs.com/package/mssql#prepared-statement

システムの概要

冒頭でも記載しましたが、この時作成したシステムは、バッチ的に1時間に1回集計処理を行うというものでした。
1時間に1回のトリガーは、 Function のタイマートリガーを使いました。

Function → https リクエスト → App Service → SQL Server

という流れです。

Function から直接SQLを叩くという方法もありましたが、

  • ダウンロード画面の提供が必要
  • ダウンロード時にもDBに接続する
  • 色々な場所からDB接続させたくない

といった理由で、不採用にしています。

逆に Function を使わず、 App Service 上で node-cron を使って定期実行することも考えましたが、App Service 上で、長期間運用できるか未検証だったので、採用しませんでした。

各種スペック

App Service

OS: Linux
スタック: Node 12 LTS
プラン: Basic B1

SQL Server

プラン: Standard S0: 10 DTU

Function

OS: Windows
スタック: Node 12 LTS
プラン: 従量課金

何が起きたのか

以下はAzureコンソールから確認できる、問題発生時の Sessions percentage のメトリックです。

session_max_comment

①の部分を拡大すると、以下のようなグラフになっています。
ちょうど定期実行のタイミングに合わせて、Sessionが増えているのがわかります。

session_zoom

②、③では軽微な機能改善などのデプロイを仕掛けており、そのタイミングでもSessionが削除されています。
この時点では、メトリックを見ておらず、問題に気付いていません。
後でグラフを見て、そういえばデプロイしていたなぁ、となりました。

そして、④で SQL Server に設定したSession数の上限に到達し、⑤で再起動するまでDBへの新規接続ができない状態となっていました。
これはお客様からの 「csv をダウンロードできない。」という指摘で気付きました。

DBへの接続ができない状態だったので、ダウンロードできないのは当然ですね。

また、当該期間のデータも全て LOST していました。
（色々なログから頑張って復旧しましたが、それはまた別の機会に。。）

もう少しよく見てみる

①の部分をよく見ると、それ以前には Session percentage は増加していないことが分かります。
つまり①でのデプロイが何かしら悪さをしているわけです。

ところが、このデプロイではDB接続部分の改修はしていませんでした。
その時に実行されていたコードを抜粋すると、以下のようなものでした。

const pool = new mssql.ConnectionPool(config);
let result = true;
try {
    await pool.connect();
    const ps = new mssql.PreparedStatement(pool);
    let query = ""; // SQL文

    // PreparedStatement 用の Object を用意
    queryObj["tm"] = Timestamp;
    ps.input("tm", mssql.BigInt);

    // PreparedStatement を実行する
    await ps.prepare(query);
    await ps.execute(queryObj);

    // PreparedStatement を解除
    await ps.unprepare();

    // Connectionを切断
    pool.close();
} catch (err) {
    // 例外発生時も、Connectionは切断
    pool.close();
}

ここまで読まれた方なら、すぐにピンと来るかと思いますが、例外発生時に ps.unprepare(); を呼んでいないことが原因でした。
実装時は、 pool.close() を呼んでおけば適切に Session が切断されるだろと思っていたのですが、そんなことはありませんでした。

何が原因だったのか

さて、そもそも①のデプロイでは何をしたか説明します。

このデプロイの数日前に1度、DBへ接続できずに失敗するケースが発生しました。
費用的に監視を入れることも難しく、また再現性がなく原因の究明に時間がかかりそうだったため、暫定対応として、同じ処理を時間を置いて、複数回実行するように変更していました。

DBにはユニーク制約を設けているので、複数回実行しても、「エラーになって」余計なデータが入ることはありません。
完璧な対応だなと思いました。

はい。
というわけで、1時間に1回、必ず、 catch に入り、PreparedStatement が解除されない状態になっていました。

1時間に1回というタイミングで、綺麗にSessionが増加していたので、原因が特定し易かったです。

修正後のコード

以下の通り、例外発生時も PreparedStatement を解除するように修正し、その後は安定して動作するようになりました。

const pool = new mssql.ConnectionPool(config);
// catch 内で処理をするため ps を try の外で定義
let ps = undefined;
try {
    await pool.connect();
    ps = new mssql.PreparedStatement(pool);
    let query = ""; // SQL文

    // PreparedStatement 用の Object を用意
    queryObj["tm"] = Timestamp;
    ps.input("tm", mssql.BigInt);

    // PreparedStatement を実行する
    await ps.prepare(query);
    await ps.execute(queryObj);

    // PreparedStatement を解除
    await ps.unprepare();

    // Connectionを切断
    pool.close();
} catch (err) {
    try {
        // psが定義されていれば、 unprepare する
        if (ps !== undefined) {
            await ps.unprepare();
        }
    } catch (e) {
        // エラーログ
    }
    // 例外発生時も、Connectionは切断
    pool.close();
}

弊社の代表によるレビューを経て

さて、修正後のコードを代表にレビューいただいたところ、 「finally 使ったら？」とご指摘をいただきました。
ぐうの音も出ない正論でしたので、さらに以下の通り修正しました。

const pool = new mssql.ConnectionPool(config);
// catch 内で処理をするため ps を try の外で定義
let ps = undefined;
try {
    await pool.connect();
    ps = new mssql.PreparedStatement(pool);
    let query = ""; // SQL文

    // PreparedStatement 用の Object を用意
    queryObj["tm"] = Timestamp;
    ps.input("tm", mssql.BigInt);

    // PreparedStatement を実行する
    await ps.prepare(query);
    await ps.execute(queryObj);

} catch (err) {
    // エラーログ
} finally {
    try {
        // psが定義されていれば、 unprepare する
        if (ps !== undefined) {
            await ps.unprepare();
        }
    } catch (e) {
        // エラーログ
    }
    // 例外発生時も、Connectionは切断
    pool.close();
}

（PR） 弊社では、しっかりとしたコードレビューの文化が根付いており、また、代表がエンジニア出身なので技術力が高い点も自慢のポイントの1つです。

ライブラリのリファレンスには？

https://www.npmjs.com/package/mssql#prepared-statement

IMPORTANT: Remember that each prepared statement means one reserved connection from the pool. Don't forget to unprepare a prepared statement when you've finished your queries!

You can execute multiple queries against the same prepared statement but you must unprepare the statement when you have finished using it otherwise you will cause the connection pool to run out of available connections.

pool から接続を一つ使うので、ちゃんと、 unprepare してね、とは書いてありますが、 pool.close() したらどうなるかは分かりませんでした。

感想（自戒の念をこめて）

ライブラリなどを使用する場合は、思い込みに頼らず、しっかり挙動を理解して、時には中身のコードも読んでから使いこなせると良いですね。
特にDB周りは、ミスをすると取り返しのつかないことになるケースが多いので、さらに注意が必要だなと思いました。