テスト(production)環境でのバグ追跡

昨日1日ドハマりして大変だったので、一応書き残しておく。

前提条件としては以下の通り

テスト期間中で開発チームだけでなくテストチームも触っているサーバー
- 簡単にサーバーの再起動はできない
- 当然だけどデプロイも勝手にできない
ログレベルはinfo
テスト環境に入ってるデータはRails Consoleで参照可能
設定系のデータはGitで管理されている*1
バグはローカル環境では再現しないが、テスト環境では再現する

1.とりあえず再現させてみよう

最初は何かしらのデータ不備だろうと思ったので、ローカル環境でテスト環境と同じようなテストデータを作り再現させようと試みた。しかし、再現することが出来なかった。

2.ログを確認してみよう

この時点で何かがおかしいと思ったのでログを見れば分かるかもと思って、sshで接続してログを確認することにした。しかし、ログレベルがinfoだったため有用な情報を得ることが出来なかった。今までtail -f使う機会なかったけど、使うと結構便利だなって…。

3.ソースコードを解析してみよう

画面にはエラーメッセージが出力されていて、それは設定ファイル*2で管理されていたのでそのメッセージを吐き出している位置を特定することにした。幸運なことに2箇所でしかそのメッセージは使われておらず、そのどちらかであることは明白だった。
ちなみにそのときのコードは以下のような感じで、外部のAPIを叩いて結果を取得するような感じだった。

def create_output
  begin
    param = { foo: 'foo', bar: 'bar' }
    output = Output.new(param)

    logger.info '### output_url: #{output.request_url}'
    output.request

    unless output.success?
      result[:error] = Message.faild.message
      return result
    end

  rescure
    result[:error] = Message.faild.message
  end

  result
end

で、ログを確認しているときに上記のコードのlogger.infoを確認することは出来なかった。そうなると落ちている処理としてはOutput.newかlogger.infoとなるんだけど、ログを吐く箇所で落ちる訳がないという先入観があったため、文字列の中で変数を展開していることを見落としていた。あたりをつけて、一先ずOutputクラスのinitializeを確認してみるも初期値の設定しかしておらず、全くエラーになる要素がなかった。暗礁に乗り上げ過ぎである。

4.デプロイされているソースコードを改変する

サーバーの設定を変えて再起動してログレベルの変更とか出来たら、簡単にログにバグが出たんだろうけどそういうわけにはいかず直接デプロイされているソースコードを改変して、Rails Consoleから確認することにした。改変内容はそもそも例外を握りつぶしてしまっているところで、例外を出力するように変更するだけ。

rescue => e
  Rails.logger.error(e.message)
  e.backtrace.each{|b| Rails.logger.error(b) }

こうすることによってどうにか、loggerで使っていたoutput.request_urlが中で設定ファイルから読み込んだデータを文字列結合をしようとして落ちていることに気がつけた。まぁ、つまるところデータ不備でデータを取得しようとしたらnilが返ってきていて、それを文字列結合しようとしているんだから当然だ…。

まとめ

例外握りつぶすのつらい

*1:ymlで管理されている設定がある

*2:yml

(define -ayalog '())

括弧に魅せられて道を外した名前のないプログラマ

テスト(production)環境でのバグ追跡

まとめ