こんにちは。サーバーサイドエンジニアの三村（@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,
}
if (tags = current_tags).present?
last_tag = tags.last
message = message.split("\n").map { it.split("[#{last_tag}] ").last }.join("\n")
log[:tags] = tags
end
begin
parsed = JSON.parse(message, symbolize_names: true)
if parsed.is_a?(Hash)
log.merge!(parsed)
else
log[:message] = message
end
rescue JSON::ParserError
log[:message] = message
end
"#{log.to_json}\n"
end
private
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)
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
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 }
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
context.transform_values(&:to_s)
end
リクエストログのトレースID
ClinPeerは「CloudFront -> ALB -> Rails(Puma)」の流れでリクエストが処理されます。
各コンポーネントで出力されるリクエストログを紐づけられるように、Railsが出力するログに二つのメタ情報を実行コンテキストとして定義します。
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"
}
これくらいの情報が半自動的にログ出力されるようになっているため、何かトラブルが発生してもログから大抵の状況は判別可能です。
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`, 省略...)
さて、ログの話は少し飽きてきたので話題を変えましょう。
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の正規な利用方法では上記のような対応はできないため、少しだけモンキーパッチを当てて対応しています。
プログラマなら言葉ではなくコードで語れ ということで実装をそのまま紹介します。
frozen_string_literal:true
raise("Consider removing this patch") unless ActiveStorage::VERSION::STRING.in?(["8.0.2", "8.1.0.alpha"])
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
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
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
