調査しやすいロギング環境について社内勉強会で発表したやつをまとめたやつです。
問題が起きたときなどにログを調査することはよくあることだが、ここでは調査しやすログとはどのようなもので、どうやって構築していくかについて述べる。
何も考えずにロギングしたときの問題点
- ログファイルが巨大すぎて大変
- ログファイルが複数に大量に分かれて大変
- 複数のリクエストのログが混ざって識別が困難
- ログを検索するときに正規表現などで検索しなければならず大変
調査や集計などがしやすいロギング環境への改善
上記の問題を解決するためには以下を行う。
- ログをローテーションする
- ログを集約する
- リクエストを判別できるリクエストIDなどを付与する
- ログをJSONなどに構造化する
ログをローテーションする
ActiveSupport::Logger や logrotate を使う
ログを集約する
- CloudWatch Logs / CloudWatch Logs agent などを使って集約する
リクエストを判別できるリクエストIDなどを付与する
- リクエストIDとはリクエストごとに発行される一意なIDのこと
- これをロギング時に付与することにより、リクエストレベルで検索可能
- サーバーは複数あったり、マルチプロセス/マルチスレッドでリクエストを複数同時に処理するため、各リクエストのログが混ざってよくわからなくなりがち
よいこと
わるいこと
- ログサイズが膨れがち
- 付与する情報が多いと人間が見にくくなる
Railsでの実現はどうするか？
ActiveSupport::TaggedLogging によって可能- デフォルトだとproduction環境で付与するようになっているはず
- 任意のLoggerオブジェクト に
tagged(*tags) というメソッドを追加するもの
- このメソッドによりメッセージにタグを付与することが可能
logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))
logger.info 'baz'
logger.tagged('hoge') { logger.info 'baz' }
logger.tagged('hoge','foo') { logger.info 'baz' }
logger.info '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)
@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
def call(severity, timestamp, progname, msg)
super(severity, timestamp, progname, "#{tags_text}#{msg}")
end
...
— https://github.com/rails/rails/blob/v6.0.3/activesupport/lib/active_support/tagged_logging.rb#L22-L24
このままだと、タグ情報を構造化してログ出力できない。そのため、以下のように 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 を使ってリクエスト毎の情報をまとめてロギングする
- リクエスト単位で実行時間やエラーなどのログを出力できるので便利
- lograge のログにリクエストIDを出力するようにするとRails標準のログと照会できて便利
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)
@exception = e
render plain: 'error 500'
end
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を使うと楽
ActiveJob
[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;
};
そして Rails 標準のログを以下のように定義する。
type RailsLog = LogBase & {
sub_type: 'server' | 'job' | 'other';
request_id: string | null;
job_name: string | null;
job_id: string | null;
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 で集約・検索
- AWSを使っているならCloudWatch Logs を使う
- JSONによる構造化ロギングをサポートしている
- JSON メトリクスフィルターによる高度な検索
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を使う
- Athena とは S3 にあるログファイルをSQLによって検索・集計することができる
- ログファイルが膨大になってくるとスキャン時の課金が多くなるので、パーティションに分ける
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 などでより高度な検索もできるようになる。
最後に、以下に本エントリーのための検証プロジェクトを示す。
