エラー対応のない世界にしたい

2017年11月16日公開 2019年1月4日更新

初めまして、サーバーサイドエンジニアのホルモンと申します。あだ名です。レバーは苦手です。
運用に2年間携わったあと、新規開発を進めている間に意識していたことについて紹介したいと思います。

テーマ

新規開発・運用問わず、開発をしたいのに開発を進められないときがあります。そうです。
「開発サーバーやJenkins上で起きたエラー（異常系）に対する調査及び対応作業」です。

エラー対応が発生する流れのイメージ

新規成果物を反映する
エラーが出る_(:3」∠)_
調査をする
対策をする

エラーが出てしまうと当初予定していない調査や対策をすることになるため、開発コストとなってしまいます。開発中のエラーゼロはとてもとても難しいですが、多いのはプロダクトとしても健全ではありません。

エラー対応コストを減らす方針として2つの観点があると考えています。

観点1: エラーを起こさせない
観点2: 平常時を知る

これらの観点をもとに具体的な策を紹介していきます。

前提

紹介の前に、まずはエラーが引き起こす対象を整理します。スマートフォンゲーム開発において、開発サーバーに対して行われる新規成果物は大まかに分けると下記4種になります。

サーバーサイドコード
クライアントサイドコード
マスターデータ（全ユーザー共通の静的なデータ）
リソース（2D画像や3Dモデル等々）

例1. 後方互換を意識した実装手順

これはサーバーサイドコード、クライアントサイドコードへのアプローチです。

仕様変更に伴い既存実装の一部を削除するときや、データ構造はそのままだけどカラムの意味を変える場合があります。何も考えずに旧式から新式へ一括変更を行うとサーバーとクライアントの間のデータ不整合や、ユーザーデータとマスターデータの不整合が起きてしまいます。こんなときには実装の順番を意識することでエラーなしで改修を実現できることが多いです。

例えばとあるテーブルのカラムを削除するようなときには

クライアントエンジニアが対象カラムを利用しないように修正を行う
1と同時にサーバーサイドはDB上はカラムを削除するがI/F部分は仮の値を返すようにしておく
クライアント、サーバーエンジニアともにカラムを参照しない形を確認してからI/F部分を削除する

このようにすれば他の開発メンバーがアプリのバージョンを意識せずともエラーが出ることない状態で作業を完了させることができます。

例2. マスターデータに適切なチェックを行う

エンジニアコードについてはテストを書くなどできますが、マスターデータとリソースについてはゲームとして正しい状態こそが正しいため、どうテストを書けばいいか迷うものです。

※ ゲームとして正しい＝キャラクターAは高レアキャラなのでボスからしかドロップしてはいけないなど

エラーを起こさせない観点でいうとゲームとして正しいかは一旦置いといて、「データ構造上守られていなければならないチェックだけは常に行う」ことがベターとなります。

現在のマスターデータ運用

現在のプロダクトでのマスターデータ管理は以下のような特徴を持っています。

サーバーエンジニアが扱うときにはYamlを採用
– サーバーコードとともにgit管理（以後ServerRepo）
– 1テーブル1ファイルなyamlファイル管理（以後table yaml）
– ActiveRecord利用のデータベースだけでなく、オンメモリ上で管理するActiveHash(ActiveYaml)も利用
プランナーのデータ入力方法はExcelを利用
– git管理しているがデータ調整によりリポジトリが肥大化するため、サーバーコードとは別リポジトリで管理されている（以後MasterDataRepo）
– Seedtableを用いることでExcelが正となるようなデータ状態ではなく、yamlが正の状態となるようにしている
– git diffによる差分を見やすくするためにテーブル毎ではなく1レコード1ファイルに分割されたYaml形で管理（以後record yaml)

これらをもとにマスターデータのフローは以下のようになっています。

プランナー、データ入力を行う
プランナー、データをMasterDataRepoにpushする
プランナー、Jenkinsの「MasterDataRepoのデータを確認用サーバーに反映させるジョブ」を実行
– record yaml⇢table yamlにコンバート
– 開発サーバーにtable yamlをアップロード
プランナー、任意のタイミングでJenkinsの「マスターデータチェックジョブ」を実行
データFIXするまで2~4を繰り返す。
プランナー、Jenkinsの「ServerRepoへのプルリクエストを作成するジョブ」を実行
– record yaml⇢table yamlにコンバート
– ServerRepoにtable yamlをコミット＆プッシュ
サーバーエンジニア、プルリクエストを確認し、ServerRepoへマージ

マスターデータチェック手法

データベースだけで管理しているのであればスキーマ情報をもとに多くのチェックが自動的にされることになりますが、オンメモリのActiveHashを利用していることや、データの複雑性を考慮した結果、独自のデータチェックの仕組みを作っています。

現在、全てのマスターデータのテーブル、カラムに対して下記のように出来る限りチェックを設定しています。

# JSON Schemaに近い記述を拡張したもの. データ自体はぼやかしています
# このYamlを書くだけで全データに対してチェックしてくれるrspecのshared contextを実装しています
properties:
 id:
  type: bigint
 name:
  type: string
 example: "ドリコム太郎"
 base_character_id:
  type: bigint
  relation: base_characters
 skill_ids:
  type: string
  string_type: array
  example: "[123, 456]"
  description: "所持skillsのIDを配列で記述"
 release_at:
  type:
   - time
   - "null"

チェックできる項目

Integer / String / Boolean / Timeの型チェック
Json構造になっているか、Array構造になっているか
NULL許容かどうか
リレーション先が存在しているか
正規表現マッチ

データ構造を対象にしているため、もしチェックが落ちていた場合にはコード上でエラーになる可能性が高いですし、逆にエラーになっていないときにはそちらのほうが恐ろしい状態とも言えます。また、ゲーム的な仕様変更が行われてもデータ構造さえ変わっていなければYamlが変わることもないため、メンテナンスコストも少なくなっています。

チェックを行う前までは下手すると一日中データ調査を行うこともありましたが、現在はマスターデータ不整合は劇的に減り健全度が増しました。

例3. 平常時を知る

ある日突然、プランナーが利用している「データをサーバーに反映するJenkinsジョブ」の実行時間が1分だったものが5分に膨れ上がることがありました。
（厳密にはエラーではないのですが、作業上は異常事態なので今回扱います）

全体の実行時間が5倍になったという情報だけでは色々考えられます。

今回だけ？
マシン内で併設でアプリビルドも行っているゆえにCPUをそちらに利用されているだけ？
ネットワークが遅くなった？
データ設定が悪い？
久しぶりのジョブ実行でリポジトリのcloneに時間かかった？

こんなときのためにあらかじめJenkinsスクリプトにジョブ内の主要な処理の実行時間を毎回表示するように仕込んでおきました。
Jenkinsにはタイムスタンプをログに表示してくれるTimestamperプラグインがありますが、ひと目見て自分が仕込んだ処理の実行時間が見れるというのは状況を把握するときには調査時間を減らすことができるため大変有効です。

# Jenkinsコンソール
# ※コマンド自体はぼやかしています

17:07:11 -- measured ----------------------------------
17:07:11 1.77 [s]: setup:repository
17:07:11 19.43 [s]: RAILS_ENV=development bundle exec rake db:schema:load
17:07:11 15.59 [s]: bundle exec rake yaml_convert
17:07:11 1.47 [s]: bundle exec cap server01 upload FILES='SEED_FILE_PATH/*.yml'
17:07:11 11.12 [s]: bundle exec cap server01 db:seed
17:07:11 9.50 [s]: bundle exec cap server01 unicorn:reload
17:07:11
17:07:11 SUMMARY 58.88[s]

ジョブ毎の数字を比較することでいつもはどれくらいの時間なのかを後からでも見ることができ、遅くなった箇所の特定をすることができるようになります。
今回のケースではyaml_convert部分が遅くなっていて、単純に変換するデータ量が大量に増えただけでした。

今後、時間が長いから最適化したいときに、どこでどれだけ時間かかっているかが見える化されているため未来にも生きています。本質的には変換に関係なさそうなわりに19秒かかっているdb:schema:loadですね。

参考までに、JenkinsスクリプトをRakefileで実装しているため計測用コードはRubyで、アプリコードではないためとても雑コードも載せておきます。

module Measure
 @elapsed_time = {}

 class　<<　self
  def time(name)
   before_time = Time.now.to_f
   result = yield
   after_time = Time.now.to_f
   @elapsed_time[name] = after_time - before_time
   result
  end

  def result
   puts ""
   puts "-- measured ----------------------------------"
   max_length = @elapsed_time.values.map { |t| time_format(t) }.max_by(&:size).size
   all_time = 0.0
   @elapsed_time.each do |k, v|
    all_time += v
    puts "#{time_format(v).rjust(max_length)} [s]: #{k}"
   end
   puts ""
   puts "%-#{max_length + 2}s #{all_time} [s]" % "SUMMARY"
  end

  private

   def time_format(num)
    "%.2f" % num
   end
 end
end

# Jenkinsでshで実行するのは大抵実行が重いので時間計測付きのメソッドを生やしておく
def sh_with_measure(str)
 Measure.time(str) do
  sh str
 end
end

実行したいシェルコマンドをsh_with_measureで実行して、最後にMeasure.resultを実行することで各コマンドの実行時間が表示される仕組みです。