データがどのように更新されてきたのか追跡する

こんにちは。技術部の吉川です。

みなさんは、異常なデータを見つけたが、どうしてそのような状態になったのか追跡できず困ったという経験はないでしょうか。 今回は、そんなときにクックパッドで利用されているAuditログについてご紹介します。

Auditログとは

クックパッドでのAuditログは特定のデータレコードに対して発生したイベントをコンテキストとともに記録するものです。 一般的に監査ログ、証跡ログといったものがありますが、それらとは多少異なっています。

ここでのイベントとは、あるデータレコードが

  • 作成された
  • 更新・変更された
  • 削除された

といったものです。またそれ以外にもログインした、ログアウトした、セキュアな情報が閲覧された、といったイベントも含まれています。 コンテキストは以下のようなものを記録します。

  • いつ
  • どこで
    • 処理が行われたホスト
  • 何が
    • イベント
  • 何を
    • 対象データの情報
      • スキーマやテーブル、変更されたカラム、レコードIDなど
  • 誰が
    • リクエスト元のIP、UA、ログイン中のユーザーID
  • どのように
    • HTTPリクエストであればアクセスエンドポイント、バッチ処理であれば呼び出し元のメソッド

Auditログのユースケース

開発者のデバッグ・調査

例えば異常なデータレコードがあった場合に、どうしてそのような状態になったのかを追跡することができます。 リクエストがあって正常に更新されたが、その後バッチ処理が意図しない挙動をして更新している、といったような調査ができるのです。

カスタマーサポートのアシスト

ユーザーの操作履歴を調べて、この設定変更をしているのが問題だ、といったようなアシストができます。 またその操作がユーザー自身が行ったのか、サポートスタッフが管理ツールから行ったのかといったことも確認できます。

Auditログをどのストレージに保存するか

Auditログを実装する上で悩ましいポイントの一つがストレージの選定です。

クックパッドではもともとTreasure Dataが多く利用されていましたが、例えばサポートスタッフがユーザーと電話対応中にも履歴を検索する場合、 クエリを考えてジョブキューになげてMapReduceを待つことはできません。というのも電話中に数分待つことができないためです。 当時はPresto Query Engineもなく、より即応性の高いものが必要でした。

また行動ログなどと比べると、個別のケースを追いかけるわけですから抽出条件が非常に多岐にわたります。 調査の際にはいろいろな切り口でトライアンドエラーで調査するケースが多いです。

これらのことを考えると、RDBMSのようなインターフェイスのほうが取り扱いはしやすそうです。 クックパッドで利用しているストレージではAmazon Redshiftがぴったりでした。

どうやってイベントのコンテキスト情報を記録するか

Auditログの実装する上でもう一つ悩ましいポイントが、どのようにコンテキスト情報を集めるかという点です。

データレコードを中心においているのですから、当然発火する場所はモデルの処理ということになります。 ところがモデルは一般的にHTTPリクエストの内容を知りません。頑張ってコントローラーからパラメータを引き回すこともできそうですが、実装が辛そうです。 そこでスレッドローカル変数としてコンテキストを保存する方法を採用しています。

このロギング処理については、各サービス担当者が簡単に利用できるように共通ログインターフェイスを用意しています。 社内ではFiglogと呼ばれています。例えばあるモデルのAuditログを取得したい場合、 Figlog::AuditObserver を include するだけです。

class User < ActiveRecord::Base
  include Figlog::AuditObserver
    ...
end

あるいは、モデルにincludeせずにconfigとして設定もできます。

Figlog::AuditObserver.observes %i(user recipe)

これだけで、create/update/delete時に、スキーマ、テーブル、レコードIDとどのカラムが変更されたかが記録されます。 ActiveRecord以外にもデータソースラッパーを指定でき、Redisなどを使っていても同じインターフェイスで利用できます。

また先程のコンテキストを取得するメソッドが用意されており、通常はコントローラーの共通フィルタでセットするようにします。

class ApplicationController < ActionController::Base
  before_action :set_figlog_user_context
    ...

  def current_user
    @user
  end
end

これでそのリクエストにまつわるコンテキストが保存され、以降使いまわせるようになります。 またこの処理が前回のコンテキストをリセットする処理も兼ねています。

ログインユーザーの情報は、コントローラのcurrent_userメソッドからFiglogが自動で取得しその情報を記録します。 そのため利用する場合はcurrent_userを実装する必要があります。

pros/cons

このAuditログのような機能を実装する場合、シンプルなものとしては変更履歴レコードを作る方法があります。 そういった手法と比べると、メリットとして

  • 抜け漏れが発生しづらい
    • モデルの変更操作で自動取得するため、あるケースだけログ処理が抜けていた、ということが発生しづらい
  • 導入コストが低い
    • 利用者がログフォーマットなどを意識する必要がなく、簡単に利用できる
    • サービスごとの独自仕様が発生しない
  • サービスを横断した検索がしやすい

といった点があげられます。

デメリットは、ログが記録されていることを保証しきれないという点です。 例えば同じRDBでログと対象データを管理していれば、トランザクションで一貫性を保つことも可能なはずです。 しかしモデルのコールバックによって処理され、実データは非同期に保存されるため、同じように一貫性を保つことができません。

[Appendix] 共通ログ基盤Figlog

ここまでAuditログの話をしてきましたが、Figlogは社内では共通ログ基盤という位置づけです。 Auditログ以外にもPVログや行動ログなど様々なログに対応しています。

例えば行動ログはTreasure Dataを利用しており、ストレージとしては全く別物です。 しかしインターフェイスを共通にすることで、開発者の学習・導入コストを減らし簡単に扱えるようにする狙いがあります。

Figlog::Activity.log(message: 'User acts something')

ここで先ほどのコンテキストが既に保存されていれば、自動でそれも記録されます。 そのためAuditログ同様にロジックの深い部分までログパラメータを引き回す必要がありません。

まとめ

クックパッドでのログの活用事例としてAuditログと共通ログ基盤をご紹介しました。

なお、Figlogは技術的に難しいことをやっている訳ではありません。むしろユースケースとログストレージの間をつなぐビジネスロジックに近い存在です。 そういった性質からOSS化は難しいものの、インターフェイスなどの参考になれば幸いです。