メドピア開発者ブログ

集合知により医療を再発明しようと邁進しているヘルステックカンパニーのエンジニアブログです。読者に有用な情報発信ができるよう心がけたいので応援のほどよろしくお願いします。

ClinPeer Railsプロジェクトのオブザーバビリティ強化施策

ClinPeerアプリ開発の裏側 Rails Ruby

こんにちは。サーバーサイドエンジニアの三村（@t_mimura39）です。

N番目の「ClinPeerアプリ開発の裏側連載記事」でございます（連載記事を同時執筆しているため本記事が何番目になるのかもはや不明）。 tech.medpeer.co.jp

今回はClinPeerで実践した「Railsプロジェクトのオブザーバビリティ強化施策」の紹介記事になります。少しマイナーなネタですね。

目次

オブザーバビリティとは

正直「オブザーバビリティ（可観測性）」という言葉を使いたかっただけなので、本記事を読むにあたってオブザーバビリティの定義について知らなくても大丈夫です。

詳細について知りたい方はこちらの記事やご自身で「オブザーバビリティ」について検索してください。
aws.amazon.com

ちなみにここ最近「オブザーバビリティ」とセットで語られがちの OpenTelemetry については本記事で取り扱いません。あくまでRailsアプリケーションに特化した施策の紹介をします。

「それ、オブザーバビリティ関係なくね？」という内容も多数含まれているかとは思いますが細かいことは気にしない方向でお願いします。

ログ

アクセスログの構造化

Rails標準のアクセスログは人間には読みやすいのですが、構造化されていないため機械的な検索で不便です。 Lograge などを活用してアクセスログを構造化しましょう。

Rails標準アクセスログ

Started GET "/" for 127.0.0.1 at 2012-03-10 14:28:14 +0100
Processing by HomeController#index as HTML
  Rendered text template within layouts/application (0.0ms)
  Rendered layouts/_assets.html.erb (2.0ms)
  Rendered layouts/_top.html.erb (2.6ms)
  Rendered layouts/_about.html.erb (0.3ms)
  Rendered layouts/_google_analytics.html.erb (0.4ms)
Completed 200 OK in 79ms (Views: 78.8ms | ActiveRecord: 0.0ms)
Lograge適用後

method=GET path=/ format=json controller=HomeController action=index status=200 duration=79.0 view=78.8 db=0.0

さらにClinPeerでは Lograge::Formatters::Json を利用して、JSON形式のログを出力しています。

{
  "method": "GET",
  "path": "/",
  "format": "json",
  "controller": "HomeController",
  "action": "index",
  "status": 200,
  "duration": 79.0,
  "view": 78.8,
  "db": 0.0
}

その他ログの構造化

LogrageはあくまでActionControllerのアクセスログのみを取り扱います。Jobのログや Rails.logger.info などで手動で出力するログなんかも構造化するために専用のJSONログフォーマッターを定義します。

ただJSON形式に変換するだけでなく、以下のような処理もいれています。

  • プロセスIDとスレッドID、Gitリビジョンなどのメタ情報の自動付与
  • Rails.logger.tagged により付与されるタグ情報の加工
class JsonLogFormatter < Logger::Formatter
  def call(severity, timestamp, _progname, message)
    log = {
      level: severity,
      pid: ::Process.pid,
      tid:,
      timestamp: timestamp.iso8601(3),
      revision: Rails.application.config.x.revision,
    }

    # Rails.logger.taggedを利用してログ出力すると「[hoge] [fuga] message」のような形式になる
    # これを解析しやすいJSON構造に加工する
    # ref. https://github.com/rails/rails/blob/v8.0.1/activesupport/lib/active_support/tagged_logging.rb

    # `#current_tags` はRails.logger.taggedで指定されたタグ配列が返却される
    # current_tags => ["hoge", "fuga"]
    if (tags = current_tags).present?

      # ActiveSupport::TaggedLogging::Formatter が自動で付与する 「[タグ1] [タグ2] ログ」のタグ部分を削除する
      last_tag = tags.last
      message = message.split("\n").map { it.split("[#{last_tag}] ").last }.join("\n")
      log[:tags] = tags
    end

    # for lograge
    # 既にJSON形式のメッセージが指定された場合はJSONの入れ子にならないようにマージする
    begin
      parsed = JSON.parse(message, symbolize_names: true)
      if parsed.is_a?(Hash)
        log.merge!(parsed)
      else
        # JSONパース可能だがObject（Hash）でない値（数値やboolなど）はmessageフィールドに設定する
        log[:message] = message
      end
    rescue JSON::ParserError
      log[:message] = message
    end

    "#{log.to_json}\n"
  end

  private

  # Sidekiqのtidに合わせている。ClinPeerではSidekiqを利用していないが参考実装としてSidekiqの処理を流用している。
  # ref. https://github.com/sidekiq/sidekiq/blob/0226e311d02de8ea77563c17c96a3d6527d0ec7f/lib/sidekiq/logger.rb#L80-L82
  def tid
    Thread.current["clinpeer_json_log_formatter_tid"] ||= (Thread.current.object_id ^ ::Process.pid).to_fs(36)
  end
end

このJSONログフォーマッターを活用することで、Railsが出力するログが全て構造化されたJSON文字列になります。

Rails.logger.tagged("タグです") { it.info("Hello") }

{
  "level": "INFO",
  "pid": 32619,
  "tid": "h6z",
  "timestamp": "2025-03-24T14:09:55.512+09:00",
  "revision": "96c042567198fb957ff81d210d0b3435dedbca67",
  "tags": [
    "タグです"
  ],
  "message": "Hello"
}

実行コンテキスト

上記JSONログフォーマッターでは汎用的なメタ情報としてプロセスIDなどを自動付与しましたが、「ログインしているユーザーのID」や「ジョブID」などログ出力時の実行コンテキスト情報が実際のトラブル発生時の調査では知りたくなるものです。
では、これらの情報はどのように管理しログに含めると良いでしょうか。

まず、ログに含めたい「実行コンテキスト」とは何かを整理します。

ActionController系のHTTPリクエストの場合

  • X-Request-ID
    • 同一リクエスト内で出力されたログを串刺し検索しやすいようにします。
    • Railsシステムから別の内部システムのAPIを呼び出す際なんかにリクエストIDを伝搬しておくとサービスを横断してログの検索がしやすくなります。
  • リクエストホスト
    • ClinPeerはドメインを分離して複数サービスを提供しているため、ぱっと見でどのホストへのリクエストなのかを判別しやすい形としたいです。
  • UserAgent
    • 大まかにどういった端末で発生している問題なのかを判別する際に有用ですね。
  • ログインユーザーID
    • 特定ユーザーの行動を追いやすくします。
    • サービス毎にログインするユーザーモデルが異なるなんてこともありますよね。

ActiveJobで処理する非同期処理の場合

  • ジョブID
    • 同一ジョブ内で出力されたログを串刺し検索しやすいようにします
  • ジョブ名
  • ジョブ引数
    • ClinPeerでは個人情報を含むセンシティブな値を引数に指定しないルールとしています。

このように「ActionController」と「ActiveJob」で大きく異なり、その中でもリクエストやジョブに応じて項目の増減がありそうです。
これらの実行コンテキスト情報を管理する仕組みとして ActiveSupport::ExecutionContext に目をつけました。

www.rubydoc.info

ActiveSupport::ExecutionContext はグローバルなオブジェクトで ActiveSupport::ExecutionContext.to_h[:key] のように任意の値を格納する箱として利用できます。
また、その名の通り実行コンテキストを表すものであるため「ActionController（HTTPリクエスト）」や「ActiveJob（非同期処理）」の実行毎に値がリセットされます。それに加えてRailsにより自動的に ActionControllerやActiveJobのインスタンスが格納されるという特典付きです。

※ ちなみに ActiveSupport::ExecutionContext は本来Rails内部でのみ利用されるものであり nodocなAPI なのですが、とても便利なのでClinPeerでは今後の非互換な変更に恐れずに活用しています。

ということで、これでログフォーマッターの中から現在実行されている「ActionController」や「ActiveJob」のオブジェクトを参照することができるようになりました。
あとは各種コントローラーやジョブクラス毎に実行コンテキスト情報を定義できれば良いため簡易的な専用モジュールを開発しました。

# frozen_string_literal: true

module ExecutionContextStorable
  extend ActiveSupport::Concern

  included do
    class_attribute :_execution_context_procs,
                    instance_predicate: false,
                    instance_writer: false,
                    default: {}
  end

  class_methods do
    def execution_context(key, execution_context_procs)
      # Controllerの継承階層毎に設定値を分けるためにあえて冗長な代入形式で記述している。
      # class_attributeはセッターメソッド（代入）が呼び出されると新たにクラス属性を再定義する仕組みである。
      # self._execution_context_procs[key] = block と記述すると継承コントローラの設定値が破壊的に変更されてしまいController毎に設定を分離することができなくなる。
      self._execution_context_procs = { **_execution_context_procs, key => execution_context_procs }
    end
  end

  def _execution_context
    _execution_context_procs.transform_values do |execution_context_proc|
      instance_exec(&execution_context_proc)
    rescue StandardError => e
      raise if Rails.error.debug_mode

      # execution_contextの算出でエラーが発生した場合は個別にエラー通知しつつ処理を継続する
      Rails.error.report(e, context: { controller: nil, job: nil })
      "算出エラー"
    end
  end
end

使い方はこんな感じです↓

class ApplicationController < ActionController::Base
  include ExecutionContextStorable

  execution_context :host, -> { request.host }
  execution_context :request_id, -> { request.request_id }
  execution_context :remote_ip, -> { request.remote_ip }
  execution_context :user_agent, -> { request.user_agent }

module Admin
  class ApplicationController < ::ApplicationController
    execution_context :user_id, -> { Current.user&.id&.to_s }

# config/initializers/job_setup.rb
Rails.application.config.to_prepare do
  require "execution_context_storable"

  [
    ApplicationJob,
    ActionMailer::MailDeliveryJob,
    SolidQueue::RecurringJob,
    MaintenanceTasks::TaskJob,
  ].each do |job_class|
    job_class.class_exec do
      include ExecutionContextStorable

      execution_context :job_id, -> { job_id }
      execution_context :job_name, -> { self.class.name }
      execution_context :job_arguments,
                        -> { arguments.map { it.is_a?(ActiveRecord::Base) ? it.to_global_id.to_s : it } }
    end
  end
end

このように実行コンテキストを定義にすることで、程よくログを拡張することができます。

class JsonLogFormatter < Logger::Formatter
  def call(severity, timestamp, _progname, message)
    log = {
      level: severity,
      pid: ::Process.pid,
      tid:,
      timestamp: timestamp.iso8601,
      revision: Rails.application.config.x.revision,
      **execution_context, # ← 実行コンテキスト情報を自動付与
    }
  ...

  def execution_context
    context = ActiveSupport::ExecutionContext.to_h
    controler_or_job = context.delete(:controller) || context.delete(:job)
    if controler_or_job.present? && controler_or_job.respond_to?(:_execution_context)
      context.reverse_merge!(controler_or_job._execution_context)
    end

    # JSON変換できないようなオブジェクトが含まれている場合を考慮して強引に文字列変換している
    context.transform_values(&:to_s)
  end

リクエストログのトレースID

ClinPeerは「CloudFront -> ALB -> Rails(Puma)」の流れでリクエストが処理されます。
各コンポーネントで出力されるリクエストログを紐づけられるように、Railsが出力するログに二つのメタ情報を実行コンテキストとして定義します。

# app/controllers/application_controller.rb

class ApplicationController < ActionController::Base
  include ExecutionContextStorable

  # 省略

  execution_context :amzn_trace_id, -> { request.headers["HTTP_X_AMZN_TRACE_ID"] }
  execution_context :amz_cf_id, -> { request.headers["HTTP_X_AMZ_CF_ID"] }

詳細についてはAWSの記事をご参照ください。 repost.aws

When CloudFront forwards an HTTP request to its origin, it automatically injects the X-Amz-Cf-Id header, which contains an opaque string uniquely identifying the request. This value is logged in the CloudFront access logs under the x-edge-request-id field. Similarly, ALB automatically injects the X-Amzn-Trace-Id header when forwarding a request to the target group. This header's value is logged in the ALB access logs under the trace_id field.

CloudFront が HTTP リクエストをそのオリジンに転送すると、X-Amz-Cf-Idリクエストを一意に識別する不透明な文字列を含むヘッダーが自動的に挿入されます。この値は、CloudFront アクセス ログのx-edge-request-idフィールドに記録されます。 同様に、ALB はX-Amzn-Trace-Idリクエストをターゲット グループに転送するときにヘッダーを自動的に挿入します。このヘッダーの値は、ALB アクセス ログのtrace_idフィールドに記録されます。

ログ出力例

ここまでの「構造化」や「実行コンテキストの定義」を整備することで、以下のようなログが出力されるようになります。

ActionController（HTTPリクエスト）

{
  "level": "INFO",
  "pid": "12345",
  "tid": "54321",
  "timestamp": "2024-07-23T22:38:57.512+09:00",
  "revision": "96c042567198fb957ff81d210d0b3435dedbca67",
  "host": "example.com",
  "request_id": "1d30c56b-5354-4f46-92e7-fb5286bd09e0",
  "remote_ip": "127.0.0.1",
  "user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) ...",
  "amzn_trace_id": "Root=1-67565de7-4e2740f76c1c1df17ee5f652",
  "amz_cf_id": "iJCXbHIkFi7CSfYGlHL3DWJZ1JQQKAToCOfunzS1T3xzatQ7-2TBRA==",
  "user_id": "1234",
  "message": "abc"
}

ActiveJob（非同期処理）

{
  "level": "INFO",
  "pid": "12345",
  "tid": "54321",
  "timestamp": "2024-07-23T22:38:57.512+09:00",
  "revision": "96c042567198fb957ff81d210d0b3435dedbca67",
  "job_id": "e99344cd653d255cc259330a",
  "job_name": "MaintenanceTasks::TaskJob",
  "job_arguments": "[]",
  "message": "abc"
}

これくらいの情報が半自動的にログ出力されるようになっているため、何かトラブルが発生してもログから大抵の状況は判別可能です。

query_log_tagsの有効化

ActiveRecordが発行するSQLに自動でコメントを付与してくれる機能も有効化します。これは、スロークエリーの原因調査などでとても重宝します。

api.rubyonrails.org

Rails.application.configure do
  config.active_record.query_log_tags_enabled = true
  config.active_record.cache_query_log_tags = true
  config.active_record.query_log_tags = [
    :application,
    :namespaced_controller,
    :action,
    :job,
    {
      revision: -> { Setting.revision },
      request_id: ->(context) { context[:controller]&.request&.request_id },
      job_id: ->(context) { context[:job]&.job_id },
    },
  ]
end

余談ですが、ブロック引数として渡されている context の正体は前述の ActiveSupport::ExecutionContext です。元々は本query_log_tagsに特化した実行コンテキスト管理の仕組みをRails内で汎用的に利用できるように切り出されたものが ActiveSupport::ExecutionContext だったりします。

github.com

この設定を有効化することで、発行されるSQLに以下のようにコメントが付与されるようになります。（ここでは見やすいように改行をいれています）

INSERT INTO `admin_users` (`created_at`, `updated_at`, `email_address`, 省略...) 
/*
action='create',
application='Clinpeer',
namespaced_controller='admin%2Fadmin_users',
request_id='158a5197-71b8-4864-a714-4fed2a523db7',
revision='36b596184898d19be179bd13d5572256f12b2bba'
*/

さて、ログの話は少し飽きてきたので話題を変えましょう。

ActiveStorage+S3

ClinPeerでは「Amazon S3」と「ActiveStorage」の組み合わせでファイルを管理しています。
ただ単純にファイルのアップロード・ダウンロード・配信をするだけであれば素直にActiveStorageを利用するだけで良いのですが、少し手を加えてより良い形でファイルを管理してみます。

ActiveStorageを利用してファイルをS3にアップロードした場合、 ActiveStorageが管理するテーブルである active_storage_blobs にS3オブジェクトのパス情報が格納されます。
通常これで困ることはないのですが、一つ気になる点がありました。

それは「active_storage_blobs のレコードは物理削除されたが、S3バケット上にオブジェクトが残されると当該S3オブジェクトは迷子になってしまう」という点です。
本来 active_storage_blobs のレコードが削除（destroy）されると、自動で対応するS3オブジェクトも削除されますが以下のようなケースでは注意が必要です。

  • active_storage_blobs をActiveRecordのコールバックが発火されない形（delete など）で削除した場合
  • S3のライフサイクルポリシーの設定により「削除マーカー」が有効化されており、削除したと思っていたオブジェクトが実は削除マーカーによる論理削除状態であった場合

こういった状況では迷子になったS3オブジェクトがどのような経緯でアップロードされたのか、お掃除的に完全物理削除して良いのかの判断が困難になります。
ということで、ClinPeerではS3オブジェクトそのもののメタ情報を拡充させることにしました。

Amazon S3にはオブジェクトアップロード時に任意の値を同時に登録することができる「オブジェクトメタデータ」という仕組みがあります。ここにファイルアップロード時の情報を格納することでオブザーバビリティを向上させようという狙いです。

docs.aws.amazon.com

ActiveStorageの正規な利用方法では上記のような対応はできないため、少しだけモンキーパッチを当てて対応しています。
プログラマなら言葉ではなくコードで語れ　ということで実装をそのまま紹介します。

# lib/monkey_patches/active_storage_blob_trace_custom_metadata.rb
# frozen_string_literal: true

raise("Consider removing this patch") unless ActiveStorage::VERSION::STRING.in?(["8.0.2", "8.1.0.alpha"])

# https://github.com/rails/rails/blob/v8.0.2/activestorage/app/models/active_storage/blob.rb
# rubocop:disable Layout/LineLength
module MonkeyPatches
  module ActiveStorageBlobTraceCustomMetadata
    extend ActiveSupport::Concern

    prepended do
      attr_accessor :record

      before_validation :set_trace_custom_metadata, if: :new_record?
    end

    private

    def set_trace_custom_metadata
      execution_context = ActiveSupport::ExecutionContext.to_h
      execution_context_attrs = {}
      if (controller = execution_context[:controller]).present?
        execution_context_attrs[:request] = "#{controller.class}/#{controller.request.request_id}"
      end
      if (job = execution_context[:job]).present?
        execution_context_attrs[:job] = "#{job.class}/#{job.job_id}"
      end
      self.custom_metadata = {
        uploaded_by: record&.to_global_id&.to_s,
        revision: Rails.application.config.x.revision,
        **execution_context_attrs,
        **custom_metadata.symbolize_keys,
      }
    end

    class_methods do
      # https://github.com/rails/rails/blob/v8.0.2/activestorage/app/models/active_storage/blob.rb#L80-L99
      # 基本的な処理はそのままで引数として渡されてきたrecordをnewまで引き回すようにしているだけ
      def build_after_unfurling(io:, filename:, key: nil, content_type: nil, metadata: nil, service_name: nil, identify: true, record: nil)
        new(key:, filename:, content_type:, metadata:, service_name:, record:).tap do |blob|
          blob.unfurl(io, identify:)
        end
      end

      def create_after_unfurling!(io:, filename:, key: nil, content_type: nil, metadata: nil, service_name: nil, identify: true, record: nil)
        build_after_unfurling(key:, io:, filename:, content_type:, metadata:, service_name:, identify:, record:).tap(&:save!)
      end

      def create_and_upload!(io:, filename:, key: nil, content_type: nil, metadata: nil, service_name: nil, identify: true, record: nil)
        create_after_unfurling!(key:, io:, filename:, content_type:, metadata:, service_name:, identify:, record:).tap do |blob|
          blob.upload_without_unfurling(io)
        end
      end
    end
  end
end
# rubocop:enable Layout/LineLength

ActiveSupport.on_load(:active_storage_blob) do
  prepend(MonkeyPatches::ActiveStorageBlobTraceCustomMetadata)
end

主にニ種類の情報をS3オブジェクトのメタデータとして登録しています。

ファイルアップロードのきっかけとなったレコード情報

user.avatar.attach(params[:avatar]) のようなアップロード処理を実行した際に、 uploaded_by = gid://clinpeer/User/123 のようなメタ情報を付与します。こうすることで、どのレコードに関連するファイルだったのかをS3オブジェクトのメタデータから読み取ることができます。
また、ActiveStorageで管理するBlobデータは複数レコードに関連することができます。これをS3メタデータ上に表現することはややこしくなるためあくまで「アップロード時のレコード情報」に限定しています。

モンキーパッチは些細なもので、元々ファイルアップロード時に ActiveStorage::Blob モデルまで渡されてきたレコード情報をもう少し引き回して ActiveStorage::Blob#custom_metadata に格納するだけです。

ActiveStorage::Blob#custom_metadata にメタ情報を設定しておくとS3アップロード時のオブジェクトメタデータとして登録してくれるのですが、どうやら正規の手段ではこのcustom_metadataをファイルアップロード時に指定する方法がないようです。

ファイルアップロード時の実行コンテキスト情報

前述のログ出力時の実行コンテキストと似たような内容です。ここでも ActiveSupport::ExecutionContext を活用してファイルアップロード時の「ActionController」や「ActiveJob」の情報をS3オブジェクトのメタ情報として登録します。
ここではログより簡素に "#{controller.class}/#{controller.request.request_id}" "#{job.class}/#{job.job_id}" のようななオレオレフォーマットでHTTPリクエストと非同期処理Jobを特定できる情報を設定しています。

ログと同様に実行コンテキスト情報を充実させても良かったのですが、本件はログより参照する機会が限定されていると考えてメタデータは必要最低限に留めるようにしました。

モンキーパッチやめたい

この程度でもモンキーパッチを抱えることは負債につながるリスクがあるため、できればRails本家に一定サポートして欲しいものです。
本件の内容をProposalとして https://discuss.rubyonrails.org に投げましたが現在はまだ反応がありません。

discuss.rubyonrails.org

Amazon S3 メタデータ

ちなみに最近「Amazon S3 メタデータ」と呼ばれる機能が新規にリリースされました。これはS3オブジェクトのメタデータをApache Icebergテーブルに保存し、Amazon Athenaなどのツールを活用することで高速にメタデータの検索ができるようになるものです。

dev.classmethod.jp

これを活用するとさらにオブザーバビリティが向上しそうですが、手が回っておらず今後の伸び代ということで寝かせています。

APM

先の述べた通り、OpenTelemetryなんかは利用しておらず直接DataDog APMを活用している現状です。
特筆するほどの工夫はないため割愛します。

docs.datadoghq.com

エラー管理

弊社では主に Rollbar を利用しています。
ClinPeerではRollbarへのエラー通知処理に関しても実行コンテキストの渡し方を少し工夫しているのですが、それに関しては後日別の記事でご紹介予定です。

おわり

今回はClinPeerで実践した「Railsプロジェクトのオブザーバビリティ強化施策」について紹介しました。
システム運用する上で、何か問題が発生した際に「推測」ではなく「決定的な根拠」を元に起きている事象を説明できる状態が重要だと考えます。そのためにも「ただ動くものを作って終わり」ではなく「万が一この事象が発生したらどうなるのか」「予めこのような考慮をいれておいたら役に立つことがあるのではないか」などを常日頃考えるようにすると良いかと思います。

本記事が世間のRailsプロジェクトのオブザーバビリティレベルにほんの少しでも貢献できたら幸いです。

是非読者になってください！

メドピアでは一緒に働く仲間を募集しています。
ご応募をお待ちしております！

■募集ポジションはこちら medpeer.co.jp

■エンジニア紹介ページはこちら engineer.medpeer.co.jp

■メドピア公式YouTube　 www.youtube.com

■メドピア公式note
style.medpeer.co.jp