検索・集計がしやすいロギング環境の構築
調査しやすいロギング環境について社内勉強会で発表したやつをまとめたやつです。
問題が起きたときなどにログを調査することはよくあることだが、ここでは調査しやすログとはどのようなもので、どうやって構築していくかについて述べる。
何も考えずにロギングしたときの問題点
調査や集計などがしやすいロギング環境への改善
上記の問題を解決するためには以下を行う。
ログをローテーションする
ActiveSupport::Loggerやlogrotateを使う
ログを集約する
- CloudWatch Logs / CloudWatch Logs agent などを使って集約する
リクエストを判別できるリクエストIDなどを付与する
よいこと
- 検索性が上がる
- 集計しやすくなる
わるいこと
- ログサイズが膨れがち
- 付与する情報が多いと人間が見にくくなる
Railsでの実現はどうするか？
ActiveSupport::TaggedLoggingによって可能- デフォルトだとproduction環境で付与するようになっているはず
ActiveSupport::TaggedLogging とは
- 任意のLoggerオブジェクト に
tagged(*tags)というメソッドを追加するもの - このメソッドによりメッセージにタグを付与することが可能
logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT)) logger.info 'baz' #=> baz logger.tagged('hoge') { logger.info 'baz' } #=> [hoge] baz logger.tagged('hoge','foo') { logger.info 'baz' } #=> [hoge] [foo] baz logger.info 'baz' #=> baz
リクエストIDを付与する
config.log_tags を設定することにより出力可能。ここで設定された内容が Rails::Rack::Logger にて ActiveSupport::TaggedLogging#tagged(*tags) メソッドに渡されリクエスト毎にタグが付与できる。
config/application.rb:
module HogeApp class Application < Rails::Application ... config.log_tags = [ :request_id ] end end
[8075c9d7-ea51-4069-bba0-e5251a5f4763] Processing by Rails::WelcomeController#index as HTML [8075c9d7-ea51-4069-bba0-e5251a5f4763] Rendering /usr/local/bundle/gems/railties-6.0.3/lib/rails/templates/rails/welcome/index.html.erb [8075c9d7-ea51-4069-bba0-e5251a5f4763] Rendered /usr/local/bundle/gems/railties-6.0.3/lib/rails/templates/rails/welcome/index.html.erb (Duration: 6.8ms | Allocations: 294) [8075c9d7-ea51-4069-bba0-e5251a5f4763] Completed 200 OK in 12ms (Views: 9.6ms | ActiveRecord: 0.0ms | Allocations: 1539) [66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Started GET "/" for 172.29.0.1 at 2020-05-11 08:31:51 +0000 [66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Cannot render console from 172.29.0.1! Allowed networks: 127.0.0.0/127.255.255.255, ::1 [66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Processing by Rails::WelcomeController#index as HTML [66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Rendering /usr/local/bundle/gems/railties-6.0.3/lib/rails/templates/rails/welcome/index.html.erb [66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Rendered /usr/local/bundle/gems/railties-6.0.3/lib/rails/templates/rails/welcome/index.html.erb (Duration: 6.3ms | Allocations: 179) [66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Completed 200 OK in 10ms (Views: 8.6ms | ActiveRecord: 0.0ms | Allocations: 784)
ここで config.log_tags では、以下コードに示すとおり、シンボル、Procオブジェクト、文字列などが利用できる。
module Rails module Rack class Logger < ActiveSupport::LogSubscriber ... def call(env) request = ActionDispatch::Request.new(env) if logger.respond_to?(:tagged) logger.tagged(compute_tags(request)) { call_app(request, env) } else call_app(request, env) end end ... def compute_tags(request) # :doc: @taggers.collect do |tag| case tag when Proc tag.call(request) when Symbol request.send(tag) else tag end end end ... end end end
— https://github.com/rails/rails/blob/v6.0.3/railties/lib/rails/rack/logger.rb
- シンボルを渡すと、
ActionDispatch::Requestオブジェクトのメソッドを呼び、その戻り値がタグとして利用される - Proc オブジェクトを渡すと
ActionDispatch::Requestオブジェクトが渡され、呼び出し時の戻り値がタグとして利用される - それ以外の文字列などはそのままタグとして利用される
これを踏まえると、以下のように設定することもできる。
module HogeApp class Application < Rails::Application ... config.log_tags = [ 'Server', :method, ->(req){ URI.parse(req.fullpath).path }, :request_id ] end end
結果は以下のようになる。
[Server] [GET] [/] [8075c9d7-ea51-4069-bba0-e5251a5f4763] Processing by Rails::WelcomeController#index as HTML [Server] [GET] [/] [8075c9d7-ea51-4069-bba0-e5251a5f4763] Rendering /usr/local/bundle/gems/railties-6.0.3/lib/rails/templates/rails/welcome/index.html.erb [Server] [GET] [/] [8075c9d7-ea51-4069-bba0-e5251a5f4763] Rendered /usr/local/bundle/gems/railties-6.0.3/lib/rails/templates/rails/welcome/index.html.erb (Duration: 6.8ms | Allocations: 294) [Server] [GET] [/] [8075c9d7-ea51-4069-bba0-e5251a5f4763] Completed 200 OK in 12ms (Views: 9.6ms | ActiveRecord: 0.0ms | Allocations: 1539) [Server] [GET] [/] [66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Started GET "/" for 172.29.0.1 at 2020-05-11 08:31:51 +0000 [Server] [GET] [/] [66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Cannot render console from 172.29.0.1! Allowed networks: 127.0.0.0/127.255.255.255, ::1 [Server] [GET] [/] [66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Processing by Rails::WelcomeController#index as HTML [Server] [GET] [/] [66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Rendering /usr/local/bundle/gems/railties-6.0.3/lib/rails/templates/rails/welcome/index.html.erb [Server] [GET] [/] [66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Rendered /usr/local/bundle/gems/railties-6.0.3/lib/rails/templates/rails/welcome/index.html.erb (Duration: 6.3ms | Allocations: 179) [Server] [GET] [/] [66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Completed 200 OK in 10ms (Views: 8.6ms | ActiveRecord: 0.0ms | Allocations: 784)
ログをJSONなどに構造化する
- いわゆる構造化ロギングで、JSONなどの構造化されたフォーマットでロギングすること
よいこと
- 検索性が上がる
- 集計しやすくなる
- プログラムで処理しやすい
わるいこと
- ログサイズが膨れがち
- 人間にとっては見にくい
Railsでの実現はどうするか？
JSONに出力するFormatterを使えばいいが、タグを付与する ActiveSupport::TaggedLogging で少々問題になる。
たとえば、 ActiveSupport::TaggedLogging で使用する Formatter では、タグとメッセージを連結してからオリジナルのFormatterを呼び出している。
module TaggedLogging module Formatter # :nodoc: # This method is invoked when a log event occurs. def call(severity, timestamp, progname, msg) super(severity, timestamp, progname, "#{tags_text}#{msg}") end ...
このままだと、タグ情報を構造化してログ出力できない。そのため、以下のように ActiveSupport::TaggedLogging を拡張するラッパークラスを作成する。
module Logging module JsonStructuredTaggedLogging module Formatter def call(severity, timestamp, progname, message) result = { severity: severity.to_s, timestamp: timestamp.iso8601, progname: progname.to_s, tags: current_tags.map(&:to_s), message: message.to_s, } result = result.to_json + "\n" result end end def self.new(logger) logger = ActiveSupport::TaggedLogging.new(logger) unless logger.respond_to?(:tagged) logger.formatter.extend Formatter logger.extend self logger end end end
ここまでできたら、 Rails.logger などで使用していく。
config/application.rb:
class Application < Rails::Application ... config.logger = Logging::JsonStructuredTaggedLogging.new(ActiveSupport::Logger.new(STDOUT)) end
ロギングをよりよくする
Lograge を使ってリクエスト毎の情報をまとめてロギングする
config/initializers/lograge.rb:
Rails.application.configure do config.lograge.enabled = true config.lograge.keep_original_rails_log = true config.lograge.logger = ActiveSupport::Logger.new(STDOUT) config.lograge.formatter = Lograge::Formatters::Json.new config.lograge.custom_options = lambda do |event| data = { request_id: event.payload[:request_id], } data end end
app/controllers/application_controller.rb:
class ApplicationController < ActionController::Base protected def append_info_to_payload(payload) super payload[:request_id] = request.request_id end end
rescue_from などでエラーを補足したときは必ずログにエラー内容を出力する
- なにが起きたのかがわからなくなるため
- エラーだけでなく前後でなにが起きたのかも見たいので、Sentry などのエラートラッキングサービスをつかっていても出力する
- lograge を使っている場合は、例外オブジェクトを
append_info_to_payloadで追加する
app/controllers/application_controller.rb:
class ApplicationController < ActionController::Base rescue_from StandardError, with: :error_500 rescue_from ActiveRecord::RecordNotFound, with: :error_404 protected def error_404(e) Rails.logger.warn e.inspect @exception = e render plain: 'error 404' end def error_500(e) Rails.logger.error [e.inspect, *e.backtrace].join("\n") Raven.capture_exception(e) # Sentry に通知 @exception = e render plain: 'error 500' end # action => rescue_from => append_info_to_payload の順で呼ばれる def append_info_to_payload(payload) super payload[:request_id] = request.request_id if @exception.present? payload[:exception_object] ||= @exception payload[:exception] ||= [@exception.class.name, @exception.message] end end end
config/initializers/lograge.rb:
Rails.application.configure do ... config.lograge.custom_options = lambda do |event| data = { request_id: event.payload[:request_id], } if event.payload[:exception].present? data[:exception] = event.payload[:exception] data[:exception_backtrace] = event.payload[:exception_object]&.backtrace end data end end
バックグラウンドjobやrakeタスクなども job id や task id などを出力して検索しやすくする
[Rake][hoge_task][xxx-bbb-ddd]みたいな感じでタグを付与する- これによってログの調査がしやすくなる
- IDはUUID v4を使うと楽
SecureRandom.uuid
ActiveJob
- ActiveJobはJobIDをログに付与する
[ActiveJob] もしくは [ActiveJob] [<job-name>] [<job-id>] というプレフィックスがつく
[ActiveJob] Enqueued ExampleJob (Job ID: 6b7b2799-3479-4647-a5cf-b9b371b7e7bb) to Sidekiq(default) [ActiveJob] [ExampleJob] [6b7b2799-3479-4647-a5cf-b9b371b7e7bb] Performing ExampleJob (Job ID: 6b7b2799-3479-4647-a5cf-b9b371b7e7bb) from Sidekiq(default) enqueued at 2020-05-11T09:01:14Z [ActiveJob] [ExampleJob] [6b7b2799-3479-4647-a5cf-b9b371b7e7bb] ### test [ActiveJob] [ExampleJob] [6b7b2799-3479-4647-a5cf-b9b371b7e7bb] Performed ExampleJob (Job ID: 6b7b2799-3479-4647-a5cf-b9b371b7e7bb) from Sidekiq(default) in 0.92ms
Rake タスクなど
ActiveSupport::TaggedLogging#tagged(*tags) を利用して以下のようにする。
namespace :example do logging = ->(type, &block) { Rails.logger.tagged('Rake', "example:#{type}", SecureRandom.uuid, &block) } task :exec => [:environment] do logging[:exec] do Rails.logger.info 'test' end end end
$ rails example:exec $ cat log/development.log [Rake] [example:exec] [e64f4190-1c70-4ff0-9a4d-c913c5e77ec4] test
構造化されたログの型付け
Rails が出力するログのほかにも様々なログがあるので、ログの型を決めておくとあとで検索がしやすい。 そのため型付けをどうするかについて述べる。
まず、すべての構造化ログは最低でも以下のプロパティを持つものとする。
type LogBase = { type: 'rails' | 'lograge'; level: 'DEBUG' | 'INFO' | 'WARN' | 'ERROR' | 'FATAL' | 'ANY'; time: string; // ISO 8601 };
そして Rails 標準のログを以下のように定義する。
type RailsLog = LogBase & { sub_type: 'server' | 'job' | 'other'; request_id: string | null; // for server job_name: string | null; // for active job job_id: string | null; // for active job message: string; tags: Array<string>; };
次に Lograge のログはユーザで拡張できるので拡張部分と基本部分をあわせて以下のように定義する。
type LogrageBaseLog = { method: string; path: string; format: string; controller: string; action: string; status: number; duration: number; view: number; db: number; } type LogrageAppendedLog = LogBase & { request_id: string; exception: [string, string] | null; exception_backtrace: string[] | null; }; type LogrageLog = LogrageLog & LogrageAppendedLog;
つまり出力されるログの型は以下のようになる。共通の type により、ログの型が一意に決まる。
type Log = RailsLog | LogrageLog;
これらを踏まえて、Ruby でログイベントを扱うクラスを作る。
module Logging module Entity class LogBase TYPES = %i(rails lograge).freeze LEVELS = Logger::SEV_LABEL.freeze def self.fetch_type(value) Hash[*TYPES.map {|v| [v, v] }.flatten].fetch(value.to_s.intern) end def self.fetch_level(value) Hash[*LEVELS.map {|v| [v, v] }.flatten].fetch(value.to_s.upcase) end attr_reader :type attr_reader :time attr_reader :level def initialize(type:, level:, time:) @type = self.class.fetch_type(type) @time = time.iso8601(6) @level = self.class.fetch_level(level) end end class RailsLog < LogBase SUB_TYPES = %i(server job other) def self.fetch_sub_type(value) Hash[*SUB_TYPES.map {|v| [v, v] }.flatten].fetch(value.to_s.intern) end attr_accessor :sub_type attr_accessor :tags attr_accessor :request_id attr_accessor :job_name attr_accessor :job_id attr_accessor :message def initialize(time:, level:, message:, tags:) super(type: :rails, time: time, level: level) @sub_type = nil @tags = tags @request_id = nil @job_name = nil @job_id = nil @message = message case @tags[0] when 'Server' @sub_type = self.class.fetch_sub_type(:server) @request_id = @tags[1] when 'ActiveJob' @sub_type = self.class.fetch_sub_type(:job) if @tags.size >= 3 @job_name = @tags[1] @job_id = @tags[2] end else @sub_type = self.class.fetch_sub_type(:other) end end end class LogrageAppendedLog < LogBase attr_reader :request_id attr_reader :exception attr_reader :exception_backtrace def initialize( time:, level:, request_id:, exception: nil, exception_backtrace: nil ) super(type: :lograge, time: time, level: level) @request_id = request_id @exception = exception @exception_backtrace = exception_backtrace end end end end
JSONで構造化するロギングクラスで使い、指定の形式で出力する。
module Logging module JsonStructuredTaggedLogging module Formatter def call(severity, timestamp, _progname, message) result = Logging::Entity::RailsLog.new( time: timestamp, level: severity, message: message, tags: current_tags ) result = result.to_json + "\n" result end end ... end
Rails.application.configure do ... config.lograge.custom_options = lambda do |event| data = { time: event.payload[:time], level: event.payload[:level] || 'INFO', request_id: event.payload[:request_id], } if event.payload[:exception].present? data[:level] = event.payload[:level] || 'FATAL' data[:exception] = event.payload[:exception] data[:exception_backtrace] = event.payload[:exception_object]&.backtrace end Logging::Entity::LogrageAppendedLog.new(**data).as_json end end
ログの検索・集計
CloudWatch Logs で集約・検索
JSON メトリクスフィルターによる高度な検索
JSON メトリクスフィルターとは以下のような構文で、JSONログイベントの特定のキーの値に対する条件を記述することができる。
{ SELECTOR EQUALITY_OPERATOR STRING }
例えば、以下のようなログイベントがあったとして、
{ "type": "type1", "message": "message 1" } plain text { "type": "type1", "message": "message 2" } { "type": "type2", "message": "message 3" }
次のような構文で検索すると、
{ $.type = "type1" }
JSON ログイベントかつ type が type1 のもののみ抽出できる。
{ "type": "type1", "message": "message 1" } { "type": "type1", "message": "message 2" }
CloudWatch Logs Insights による高度な検索
CloudWatch Logs で JSONメトリクスフィルターを使って高度な検索ができるが、 CloudWatch Logs Insights というサービスで、SQLライクな構文をつかってより高度な検索が可能になる。
fields @timestamp, path, request_id, exception.1 | sort @timestamp desc | filter type = "lograge" AND level = "WARN" | limit 20
S3へのエクスポートとAthenaによる高度な検索・集計
- Cloudwatch Logs は Insights 含め、検索速度が遅く、ストレージ料金も割高である
- あくまでも一時的なログ集約場として扱うほうがよい
- 1,2週間でexpireするのがよい
- Lambdaを書き、日次でS3に書き出し
- Athenaを使う
S3へのエクスポート
Amazon Kinesis Data Firehose というサービスを使えばフルマネージドにS3にエクスポートできるが料金が高いのでLambdaとCloudWatch Eventsを用いて行う。
Lambda を Node.js で実装する場合 ADS SDK の aws.CloudWatchLogs#createExportTask() を用いて指定のS3バケットにログをエクスポートする。
// @see [Lambda + S3 で、CloudWatch Logsのログをログローテーションする - Qiita](https://qiita.com/tamura_CD/items/3a1deba9e55e8b83bd91)
// @see [Class: AWS.CloudWatchLogs — AWS SDK for JavaScript](https://docs.aws.amazon.com/AWSJavaScriptSDK/latest/AWS/CloudWatchLogs.html#createExportTask-property)
'use strict';
const aws = require('aws-sdk');
aws.config.update({ region: 'ap-northeast-1' });
exports.handler = (event, context, callback) => {
const cloudWatchLogs = new aws.CloudWatchLogs();
const range = getRange();
const params = {
destination: process.env.BucketName,
from: range.from,
to: range.to,
logGroupName: process.env.LogGroupName,
destinationPrefix: `${process.env.DestinationPrefix}/dt=${range.date}`, // hive形式で出力
taskName: `${process.env.TaskName}/${range.date}`,
};
console.log(`params: ${JSON.stringify(params)}`);
cloudWatchLogs.createExportTask(params, (error, data) => {
if (error) {
console.log(error, error.stack);
callback(null, error.stack);
}
else {
console.log(data);
callback(null, data);
}
});
};
function getRange() {
const result = {};
const time = new Date();
time.setTime(time.getTime() + 9 * 60 * 60 * 1000); // JST
time.setDate(time.getDate() - 2);
time.setHours(0);
time.setMinutes(0);
time.setSeconds(0);
time.setMilliseconds(0);
result.from = time.getTime(); // 前日の日本時間 00:00:00 のタイムスタンプ(含ミリ秒)
time.setDate(time.getDate() + 1);
result.to = time.getTime(); // 本日の日本時間 00:00:00 のタイムスタンプ(含ミリ秒)
const yyyy = time.getFullYear();
const mm = ('0' + (time.getMonth() + 1)).slice(-2);
const dd = ('0' + time.getDate()).slice(-2);
result.date = `${yyyy}-${mm}-${dd}`; // yyyy-mm-dd のフォーマット
return result;
}
しかし、この方法でエクスポートすると timestamp が JSONログの前に付与されてしまうので、valid な JSON でなくなってしまう。
2020-05-18T00:00:01.383Z {"type":"rails", ...} 2020-05-18T00:00:01.384Z {"type":"rails", ...}
Athena のテーブルを作成し、検索できるようにする
まずはデータベースを作成する。
CREATE DATABASE ecs_test;
テーブルを作成するが、上述したとおり valid な JSON ではなくなってしまっている。そのため、まずは plain text なカラムが一つあるテーブルを作成する。 Athena はスキャンしたデータ量に応じて課金されるため、日付でパーティションを切る。
CREATE EXTERNAL TABLE IF NOT EXISTS ecs_test.raw_app_logs (`text` string) PARTITIONED BY (`dt` date) LOCATION 's3://test-logs/ecs-test/' TBLPROPERTIES ('has_encrypted_data'='false');
MSCK REPAIR TABLE ecs_test.raw_app_logs;
そして、次にその plain text から JSON を抜き出して各プロパティにアクセス可能にするため、以下の view を作成する。JSONのままでもAthenaにはJSON関数があるので特定のプロパティの値を参照できる。
CREATE OR REPLACE VIEW ecs_test.json_app_logs AS SELECT dt, CAST(from_iso8601_timestamp(timestamp) AS TIMESTAMP) AS timestamp, CAST(json_extract(json, '$.type') AS VARCHAR) AS type, CAST(json_extract(json, '$.level') AS VARCHAR) AS level, CAST(from_iso8601_timestamp(CAST(json_extract(json, '$.time') AS VARCHAR)) AS TIMESTAMP) AS time, json FROM ( SELECT dt, regexp_extract(text, '^([^ ]+) ({.+})$', 1) AS timestamp, regexp_extract(text, '^([^ ]+) ({.+})$', 2) AS json FROM raw_app_logs ) WHERE json IS NOT NULL AND timestamp IS NOT NULL
このようにすることで、高度な検索・集計などができるようになる。
SELECT dt , type , level , time , CAST(json_extract(json, '$.request_id') AS VARCHAR) AS request_id , CAST(json_extract(json, '$.message') AS VARCHAR) AS message FROM json_app_logs WHERE type = 'rails' AND dt = date '2020-05-20'
最後に
ここまで述べてきたとおり、ログに原因特定のためのメタ情報を付与して、JSON等で構造化することによって、検索・集計がしやすくなる。 また、CloudWatch Logs などに集約し、Athena などでより高度な検索もできるようになる。
最後に、以下に本エントリーのための検証プロジェクトを示す。
