2020年02月22日の日記です


node-tyrant のバグ修正  2020-02-22 15:31:35  コンピュータ

今日は、プログラマ向けのちょっとした推理小説。

まぁ、実際に今週体験したことなのだけど。




世の中には多くのデータベースソフトがあるが、SQL とそうでないものに大別される。

そして、「そうでないもの」の中に、key value store と呼ばれる種別のデータベースがある。


ざっくりと違いを書くと、SQL は多機能だが、高速ではない。

key value store は非常に貧弱な機能しかないが、無茶苦茶高速だ。



SQL ってのは多機能なので作るのが大変で、昔は高価なソフトしかなかった。

それが、PostgreSQL と MySQL の台頭で、無料でも使えるようになり、普及した。


ちょうど WEB の黎明と重なり、最初は重宝された。

しかし、WEB が当たり前の社会インフラになると、1秒で何千というページアクセスを支える必要があり、より高速な DB が求められ始めた。


そこに登場したのが key value store だ。


memcached というソフトが最初のきっかけとだったと考えていい。

現在人気があるのは、Redis だと思う。




Tokyo Cabinet は国産の key value store で、10 年くらい前に人気があった。


本当に機能が少なく、ネットワークにも対応していない。

これをネットワーク対応にする後付けのソフトが Tokyo Tyrant だ。


ちなみに「Cabinet」は、書棚などの意味。データを保管する場所だな。

しかし、英語では「内閣」などの意味もある。政治の中枢を担う組織。


そして、Tyrant は「暴君」の意味だ。

Cabinet を意のままに操るもの。面白い名前だと思う。




さて、現在お手伝いしている仕事のプログラムで、Tokyo Tyrant (以下 TT と表記)を使用していた。

以前は PHP で扱っていたらしいのだが、プログラムを完全に作り直していて、Javascript (node.js) ベースになっている。


移植は僕がやったわけではなく、他の方の作業によるもの。

ここで、完全に一から作るのは大変なので、フリーのライブラリを利用したらしい。




…というわけで探してみたら、これだな。

node-tyrant


開発開始から半年以上たつが、特に問題なく使っていた。




先週頭くらいに、僕が新機能を実装していたところ、なぜかサーバー (node.js) が停止する、というバグに見舞われた。


まぁ、自分がプログラムを作っていてバグが出るのだから、自分が悪いのだろうと思って調査を開始する。


プログラムは、とあるきっかけでデータベースのフラグを操作するものだった。

もともと「ボタンを押したとき」に処理をするプログラムが存在したのだ。


しかし、新たに「設定時刻が来たとき」に処理する機能を追加した。


ところが、ボタンを押したときは正常に動作するのに、設定時刻が来たときにエラー停止する。



設定時刻が来た、というのは、cron などの意味ではない。

それでは、せいぜい1分単位の処理で、ユーザー操作とかみ合わない場合があるからだ。


ユーザーが見たときに、設定時刻が来たのであれば、その瞬間に画面に反映されている必要があった。

なので、画面を作るときに、データに記録された時刻を見て、期限を過ぎていたらフラグを操作する。


同じ処理関数を呼んでいるだけなのに、この処理をするとサーバーが停止する。



cron だと、動作するときにユーザー権限が違っていて不具合を起こすようなことがあるが、今回の話はそうではない。ユーザー権限の問題ではない。

じゃぁ、何が問題なのか。問題の切り分け作業に入る。


調査は難航したが、最後に分かったのはこういうことだ。


ボタンを押したときは、ユーザーのアクションを伴うため、フラグが変わった後にページ全体のデータをリロードしていた。

しかし、時刻が来た場合は、サーバー側でフラグ操作するため、必要なデータを書き換えるだけでリロードは起こっていなかった。



そして、「リロードすれば問題ないが、リロードしないと停止する」のだった。




ここで、先に書いた node-tyrant のライブラリだが、さらに改造して使用していた、ということを書いておく。


改造は多岐にわたるが、そのうち一つに「TT からの反応がない場合は、サーバー異常と見なしてサーバーを再起動させる」というものがあった。


サーバー停止は、この機能が働くためだった。

(実際は、停止するとサーバー監視サーバーによって再起動される)


ここで、TT との通信についても触れる必要がある。


TT には、コマンドを送ると、返答が返ってくる。

データはバイナリストリームで、基本的にはデータ長とデータがセットになった chunk 構造だ。


ただし、内部構造はコマンド毎に多少異なる。


バイナリストリームなので、「改行で終了」とかではない。

データ長を信じて処理することになる。




もう一つ、Javascript としての処理の方法を書いておく必要がある。


データはバイナリなので、改行で終了ではないと書いた。

入ってくるデータを常に監視しておく必要があるが、 Javascript では「常に監視」というようなプログラムは書けない。


そこで、EventListenr を使う。何かあったら関数を呼び出して、とシステムに依頼する方法だ。

TT との通信では、「データを受信したら呼び出す」関数を指定しておく。



ところで、ネットワーク越しのシステムなので、リクエストコマンドと返信データの間にはタイムラグが発生する。

そこで、リクエスト時にコマンドをキューに入れておき、データが戻った時はキューを見て処理方法を判断する。

先に書いたがデータ構造はコマンド毎に異なるため、こうしないと処理方法がわからないのだ。



ここで、データが改行区切りなどではない、ということに気をつけないといけない。

Javascript は「何らかの方法で」データが一区切りした、と考えて関数に渡す。


しかし、この区切りが何であるかはよくわからない。

データが途中で切れる、ということはなさそうだが、複数のデータをまとめて受信することはあり得るようだ。




断片的な話が続いて申し訳ないが、必要なことなのでもう少し続ける。


先に「TTからの反応がない時はエラー終了」するようにしてあった、と書いたが、この「反応がない」の定義が重要だ。


上に書いたように、TTへのリクエスト時にキューが積まれ、データが来たときにキューが消費される。

そこで、「最後のリクエストから3秒立ってもキューが解消していないとき」は、TTの反応がなかったとみなされるようになっていた。


TTは高速を売りにするデータベースなので、3秒というのはあり得ないくらい長い時間だ。

そんなに時間が空いたら異常と見なす、というのは、別に悪くないだろう。




さて、「リロードしないとエラー停止」は、この「キューの積み残し」が原因だった。

何らかの原因で、TTが処理できていない、と見なされるのだ。


しかし、エラー停止した直後にDBを確認しても、正しく記録はされていた。

DBからの返事がないだけで、動作はしているのだ。


さらに調べると、返事があるにも関わらずに受け取れていない、と判明した。


この「受け取れていない」は、Javascript が受け取れていないのではなかった。

Javascript が受け取っているにもかかわらず、「プログラムが」取りこぼすのだ。


なぜ取りこぼすのか調べる必要があった。

どんなコマンドを発行して、どんな返事が返ってくるかを調査する。


put コマンド(データの保存を意味する)を送った時、返事が 5byte …「正常終了コード」 1byte と、4byte (32bit) の「0」だとわかった。

これをプログラムが取りこぼす。




プログラムの流れを追いかけると…

先に示したライブラリを、読める人は読んでみるといい。


最終的に、コマンドの結果は 232 行目からの responseMisc で扱っている。

この中で、


if (data.length<9) return [null, -1, null];


という行があった。これは「9バイト未満のデータは扱えないものとして保留させる」指示だ。


5バイトが返ってくるにも関わらず、9バイト未満を認めない。

バグの原因は、どうやらこれらしかった。



しかし、ここで修正を加えるのは早計だ。

こんな単純なバグであれば、「必ず」バグが出て、プログラムがまともに動かないはずなのだ。


にもかかわらず、プログラムは通常動いていて、むしろ停止することの方が少ない。

何かがあるはずだ。



「保留させる」処理の後を考えてみる。

保留は本当に保留で、データを処理しないし、キューも処理しない。

そして、次のデータが来たとき、残っていたデータに「追加」されて、データ処理を再開する。


すると、データが「追記」されたために、データのサイズが増えている。

今度は9バイト以上になっている場合、処理が続行されて、正常な処理になる。



なるほど。普段は問題が出なかった理由が分かった。

先に、「処理の後、データのリロードをしている場合は問題がない」と示したが、追加データがあると処理がうまくいくのだった。




ここまで分かったところで、僕は一旦発注元の会社に報告をした。

自分のプログラムのバグだと思って確認していたが、データベースを扱うプログラムにバグがある。


これは大問題なので、プログラムの作者(古い PHP プログラムを移植した担当者)に連絡が行く。

彼なら TT のハンドリングがわかると思ったからだ。


しかし、彼はライブラリを見つけてきて、目的に合わせて少し改造しただけだという。

すでにある程度ライブラリを調査している僕の方がよほど理解していそうだった。



この時点ですでに僕の仕事は遅れ気味だった。

どうしても取れないバグで悩んでいて、さんざん調査してここまでたどり着いたところだったのだから。



だから、上からの指示は「僕はこの問題を離れ、本来のプログラムの作成に戻ること」だった。

しかし、この問題が解決しないと、プログラムのバグは取れない。


まぁ、「バグは僕のせいではない」ことにして、溜まっている他の個所の作業に取り掛かった。


しかし、他の人の調査報告を横目で見ながら、気になることがあれば手早くできる範囲で調査を続けた。




そもそも9バイト未満のデータを認めない、という処理に妥当性があるのか。


Tokyo Tyrant のプロトコルを調査する。


…少し古いものしか見つからなかった。


ここに、put の返答は処理コード1バイトのみ、と書いてある。

0 なら成功、それ以外ならエラーだ。


しかし、確認するとどうも5バイト返ってきている。

何がどうなっているのか。


プロトコル表あったよー、という返事だけしておく。

TT の現在のバージョンでプロトコルが変化している可能性もある。


うん、きっとそうだ。




別の人が、直接 TT を操作するプログラムを書いてみた。


put コマンドでデータを送り込むと、結果は 1byte が返ってくる、ということだった。


プロトコルのバージョンが違うのでは、という予想は違うことになる。

むしろ、なんで Javascript だと5バイトを受け取るんだ?



再びプロトコル表を見て、気になる。

今まで「返事」のプロトコルばかり気にしていた。put の送信プロトコルは正しいのか?



プロトコル表には、put に対するバイナリコードが書かれている。

プログラム内からこのコードを探す。たしか、先頭付近でバイナリコードの定義が行われていたはず。



// List of Command hex codes for Tyrant var commandCode = { misc: String.fromCharCode(0x90), get: String.fromCharCode(0x30), out: String.fromCharCode(0x20), vsiz: String.fromCharCode(0x38), iterinit: String.fromCharCode(0x50), iternext: String.fromCharCode(0x51), status: String.fromCharCode(0x88), addint: String.fromCharCode(0x60), }


…愕然とした。「put」のコードは、書かれていなかった。



しかし、node-tyrant で put コマンドを呼び出したときに、処理しているプログラムはある。

この処理関数を読んで、やっと気づいた。


node-tyrant のプログラムでは、put コマンドを送るために、put コマンドを使っていない。


TT には misc (それ以外)というコマンドがあり、このコマンドを経由して「隠しコマンド」が呼び出せる


node-tyrant の put は、misc 経由で呼び出される、隠しコマンドとしての put だった。



こうなると、返答データも put と違って当然だ。

プロトコル表に、ちゃんと misc の返答プロトコルが書いてある。


[code:1][rnum:4][{[esiz:4][ebuf:*]}:*]



問題は、この表記方法は作者が定めただけのもので、特に意味は説明されていないことだな。

しかし、コマンド毎に返信データの形式が書かれているので、読んでいるとなんとなく意味が分かる。



[ ] はデータを意味していて、:n はバイト数のようだ。

ここには書かれていないが、省略可能な場合は ( ) で括られる。

複数回繰り返す場合は { } で括られる。



つまり、こういうことだ。


先頭に、処理コード1バイト(0 は成功、それ以外は失敗)

続いて、データ長が4バイト。


さらに、文字列長が4バイト。

文字列が不定バイト。


最後の2行は、セットになっていてデータ長の数だけ続く。



返事を処理する関数での制限、「9バイト」というのは、文字列長までは入っているだろう、という前提のものだったようだ。


後半が ( ) ではないので、省略されることはない、と考えたのだろう。


しかし、{ }:* という書き方が「0回以上の繰り返し」を意味しているようだ。

( ) で括っていないにもかかわらず、0回の場合は消滅する。


つまり、返答データが5バイトの場合がある。


(先に書いたように、間違っていてもなんとなく動くプログラムになっているので、作者が間違いに気づかなかったのだろう)




そういうわけで、最終的にプログラムは一カ所、1byte だけ書き換えられた。

「9」を「5」にしたのだ。これで動作して、安定している。



僕は、ここでの「長さ制限」自体が不要だ、と主張した。

データはバイナリ列のストリームで、「最後までの長さ」という概念がないはずだ。

にもかかわらず、長さで制限するのがおかしい。


実際、そんなおかしな前提だから、「次のデータがくっついたら動作する」などという、曖昧な処理になってしまうんだ。



しかし、データベースのインターフェイスは重要な根幹部分だ。

変更はできるだけ最小限が望ましい、というのが、発注元のプログラマの主張だった。



まぁ、その言い分もものすごくよくわかる。

1byte の変更で問題が解消する、というのは、最善の落としどころだろう。





同じテーマの日記(最近の一覧)

コンピュータ

別年同日の日記

03年 美術と芸術

05年 確定申告

10年 八景島

12年 経験した中で最大のバグ

14年 雪・科学館・おゆうぎ会

16年 スティーブ・ブリストー 命日(2015)

19年 完全停止


申し訳ありませんが、現在意見投稿をできない状態にしています


戻る
トップページへ

-- share --

0000

-- follow --




- Reverse Link -