恐れ多くもtokyo tyrantのソースに文句をつけてみる。

とあるシステムで tokyo tyrant を導入するべく、負荷テストをやってもらっている。
で、負荷テストで.tct ファイルで双方向レプリケーションしていた tokyo tyrant に負荷をかけていたら応答を返さなくなったらしい。
接続は pecl php tokyo tyrant経由で tokyo tyrant に接続し、php(httpd) に負荷をかけて計測していた。
そしたら、 php の session error が表示されてしまったらしい。
#session_handler = tokyo_tyrant でやってます。

ただ、そうなったのは、一回だけで、それ以降はどんなに負荷をかけて再現しなかったとのこと。
復旧はとりあえず tokyo tyrant を再起動したら直ったそうだ。

うーん。不安だ。
まだ構築段階だからいいけど、なんかサービスインが怖い気がする。
運が悪かったで済む問題なんだろうか。

このままでは不安で困るので、トラブルが起きた時刻に何がおきたか tokyo tyrant のログを見てみる。

ログには、

ERROR: do_slave: tcreplopen failed

と、書かれていた。

むむ。

レプリケーションかー。もしかしたら双方向レプリケーションがよくないのかもしれない。
次はそれをoffにして負荷検証をする予定だ。

一応いろいろ調べてみる。

まずは google 検索。
ERROR: do_slave: tcreplopen failed で調べてもあんまり事例は出ない。うーん。

こうなったら仕方ないので、エラーの内容で tokyo tyrant のソースを検索してみる。
#こーゆーのが簡単にできるところはオープンソースの素晴らしいところだなぁ。

/* replicate master data */
static void do_slave(void *opq){
  REPLARG *arg = opq;
  TCADB *adb = arg->adb;
  TCULOG *ulog = arg->ulog;
  uint32_t sid = arg->sid;
  if(arg->fatal) return;
  if(arg->host[0] == '\0' || arg->port < 1) return;
  if(arg->mts > 0){
    char rtsbuf[NUMBUFSIZ];
    int len = sprintf(rtsbuf, "%llu\n", (unsigned long long)arg->mts);
    if(!tcwritefile(arg->rtspath, rtsbuf, len))
      ttservlog(g_serv, TTLOGERROR, "do_slave: tcwritefile failed");
    arg->mts = 0;
  }
  int rtsfd = open(arg->rtspath, O_RDWR | O_CREAT, 00644);
  if(rtsfd == -1){
    ttservlog(g_serv, TTLOGERROR, "do_slave: open failed");
    return;
  }
  struct stat sbuf;
  if(fstat(rtsfd, &sbuf) == -1){
    ttservlog(g_serv, TTLOGERROR, "do_slave: stat failed");
    close(rtsfd);
    return;
  }
  char rtsbuf[NUMBUFSIZ];
  memset(rtsbuf, 0, NUMBUFSIZ);
  arg->rts = 0;
  if(sbuf.st_size > 0 && tcread(rtsfd, rtsbuf, tclmin(NUMBUFSIZ - 1, sbuf.st_size)))
    arg->rts = tcatoi(rtsbuf);
  TCREPL *repl = tcreplnew();
  pthread_cleanup_push((void (*)(void *))tcrepldel, repl);
  if(tcreplopen(repl, arg->host, arg->port, arg->rts + 1, sid)){      ←この関数が失敗するらしい。
    ttservlog(g_serv, TTLOGINFO, "replicating from sid=%u (%s:%d) after %llu",
              repl->mid, arg->host, arg->port, (unsigned long long)arg->rts);
    arg->fail = false;
    arg->recon = false;
    bool err = false;
    uint32_t rsid;
    const char *rbuf;
    int rsiz;
    uint64_t rts;
    while(!err && !ttserviskilled(g_serv) && !arg->recon &&
          (rbuf = tcreplread(repl, &rsiz, &rts, &rsid)) != NULL){
      if(rsiz < 1) continue;
      bool cc;
      if(!tculogadbredo(adb, rbuf, rsiz, ulog, rsid, repl->mid, &cc)){
        err = true;
        ttservlog(g_serv, TTLOGERROR, "do_slave: tculogadbredo failed");
      } else if(!cc){
        if(arg->opts & RDBROCHKCON){
          err = true;
          arg->fatal = true;
          ttservlog(g_serv, TTLOGERROR, "do_slave: detected inconsistency");
        } else {
          ttservlog(g_serv, TTLOGINFO, "do_slave: detected inconsistency");
        }
      }
      if(lseek(rtsfd, 0, SEEK_SET) != -1){
        int len = sprintf(rtsbuf, "%llu\n", (unsigned long long)rts);
        if(tcwrite(rtsfd, rtsbuf, len)){
          arg->rts = rts;
        } else {
          err = true;
          ttservlog(g_serv, TTLOGERROR, "do_slave: tcwrite failed");
        }
      } else {
        err = true;
        ttservlog(g_serv, TTLOGERROR, "do_slave: lseek failed");
      }
    }
    tcreplclose(repl);
    ttservlog(g_serv, TTLOGINFO, "replication finished");
  } else {
    if(!arg->fail) ttservlog(g_serv, TTLOGERROR, "do_slave: tcreplopen failed");   ←ここ
    arg->fail = true;
  }
  pthread_cleanup_pop(1);
  if(close(rtsfd) == -1) ttservlog(g_serv, TTLOGERROR, "do_slave: close failed");
}

あった。
tcreplopen関数が失敗したときの else 句で arg->fail が false の時にこのメッセージが表示されるらしい。

なるほど。
これで、どこで問題が発生したかはよくわかった。
しかし、これでは、なぜ問題が発生したのかさっはりわからん。

失敗した tcreplopen関数の実装を見てみる。

/* Open a replication object. */
bool tcreplopen(TCREPL *repl, const char *host, int port, uint64_t ts, uint32_t sid){
  assert(repl && host && port >= 0);
  if(repl->fd >= 0) return false;
  if(ts < 1) ts = 1;
  if(sid < 1) sid = INT_MAX;
  char addr[TTADDRBUFSIZ];
  if(!ttgethostaddr(host, addr)) return false;
  int fd = ttopensock(addr, port);
  if(fd == -1) return false;
  unsigned char buf[TTIOBUFSIZ];
  unsigned char *wp = buf;
  *(wp++) = TTMAGICNUM;
  *(wp++) = TTCMDREPL;
  uint64_t llnum = TTHTONLL(ts);
  memcpy(wp, &llnum, sizeof(llnum));
  wp += sizeof(llnum);
  uint32_t lnum = TTHTONL(sid);
  memcpy(wp, &lnum, sizeof(lnum));
  wp += sizeof(lnum);
  repl->fd = fd;
  repl->sock = ttsocknew(fd);
  repl->rbuf = tcmalloc(TTIOBUFSIZ);
  repl->rsiz = TTIOBUFSIZ;
  if(!ttsocksend(repl->sock, buf, wp - buf)){
    tcreplclose(repl);
    return false;
  }
  repl->mid = ttsockgetint32(repl->sock);
  if(ttsockcheckend(repl->sock) || repl->mid < 1){
    tcreplclose(repl);
    return false;
  }
  return true;
}

これは。。。

えーと、なんというか、これだと、どこの return false で抜けたのかさっぱり分からないぞ。

なんという無口なプログラムだ。
そして、みごとにエラーを握りつぶしてくれている。
無口クールにエラーを握り潰すなんてひどいや。

tokyo tyrant は、すぐれたソフトだし、速度も申し分ないけど、ここまで無口だと障害時の調査が困る。
もうちょっとおしゃべりなプログラムにできないものだろうか。

tokyo tyrantのソースコードをいろいろ眺めてみると、エラーをログに出力をちゃんとやっているところもあれば、 return false ;で抜けているだけのところもある。
高速化したい部分や、下位レイヤーは return false;で無口になって、上位レイヤーになればなるほど log を吐くようにしているようにも思える。
ポリシーの問題だろうか？

私は保守運用もしなくてはいけないから言わしてもらえば、すべてのエラーはなぜ発生したのかをログに残していてほしい。
そうでないと、エラーが起きたときの原因解決が高く付いて困ってしまう。

たとえば、fopenが失敗したとしても、なぜ失敗したのかわからないと原因究明が難しい。
fopenが失敗する理由としては、一番おこりやすいファイルがない系エラーからディスクリプタ不足ぐらいまで幅広い原因が考えられる。
このどれがエラーを引き起こしているか、なぜダメなのかがわからないと困るのだ。

エラートラップについて考えてみる。

ついでなので、エラートラップについて考えてみる。
一番うれしいのが、 C言語の errno や windows系の GetLastError のようにその関数がなぜ失敗したのか教えてくれる機能だ。
これとどこで問題が起きたのかが分かれば、なぜ問題がおきたのか大体分かる。

if ( ! API() )
{//エラー
	DWORD err = GetLastError();
	logger("API呼び出し失敗 エラー %d",err);
}

その次にうれしいのは、戻り値や引数でエラー番号を返してくれる実装だ。

DWORD ret = API();
if (ret <= 0)
{//エラー
	logger("API呼び出し失敗 エラー %d",err);
}

//あんまりこのタイプを使う人はいないけどさw
DWORD ret;
if (! API(&ret))
{//エラー
	logger("API呼び出し失敗 エラー %d",err);
}

そのまた次にうれしいのは、例外などでエラーが発生すれば上位層にエラーを連番してくれる仕組みだ。
または、これと同じぐらいうれしいのが、エラーをログファイルに書いてくれる実装だ。
前者はプログラムでもハンドリングできるし、後者は人間が見れば内容が分かる。
ただし、両方とも副作用の欠点がある。例外はハンドルが面倒だったり、忘れたりすると悲惨な結果を生むし、ログは人間が見ないと意味がない。
ともかく何がおきたのかを知ることはできる。

次は、現在の tokyo tyrant のようにエラーがあったら return false するプログラムだ。
これは、エラーが起きたことは分かるが、なぜエラーが起きたのかさっぱり分からずに、サポートや保守で死ねる。

サイテーなのが、エラー処理ってなんですか？食えるんですかってプログラム。
これは論外。

そんなわけでエラーが発生したら、それを握りつぶさないでなぜエラーが発生したのか教えてほしいんです。
そうしないと原因追求できやしないんよ。