RubyでStackdriver Loggingを使うためには、google-cloud-logging ライブラリを利用します。
しかし、このライブラリには実用上いくつかの問題が存在します。
本記事では、このライブラリを拡張することで、それらの問題を解決する方法を提示します。
なお、以下のコードはRuby 2.6.3で動作を確認しています。
Stackdriver 公式Rubyライブラリの問題
以下、 google-cloud-logging ライブラリを 公式ライブラリ
と表記します。
実際に公式ライブラリを利用してみて、実用するには以下の難点があることがわかりました。
- 構造化ログにしづらい
-
httpRequest
の情報を含めることができない
次にこれらの問題の詳細を説明します。
構造化ログにしづらい問題について
通常、ログは下記の構文で記録します。
logger.info { "something happened." }
このとき、このログエントリーはStackdriverの textPayload
として記録されます。
このような単純なログの場合はそれでも許容できますが、下記のようなログはどうでしょう?
logger.info { "something happened. user_id: 123, event_id: 2" }
この場合、 textPayload
で記録されると user_id
や event_id
での検索が困難になり、不便です。
これを解決するために用意された方法が構造化ログです。 参照
下記のコードでロギングすることで、 jsonPayload
による構造化ログを利用することができます。
logger.info { { text: "something happened.", user_id: 123, event_id: 2 } }
すなわち、 logger
にハッシュを渡せば良いです。これにより、Stackdriverコンソールで user_id
や event_id
による検索も可能になります。
ここで、すべてのログについて共通の情報を付加したい場合にどうすれば良いでしょうか?
現在の公式ライブラリではこの要件を華麗に実現する手段はなく、愚直に全てのログにパラメータを付加するしかありません。
logger.info { { text: "something happened.", user_id: 123, event_id: 2 } }
logger.warn { { text: "something seems wrong.", user_id: 123, event_id: 2 } }
logger.error { { text: "an error occurred finally.", user_id: 123, event_id: 2 } }
上記のように、ログ記録メソッドの呼び出しが冗長になることが、第1の問題です。
httpRequest
の情報を含めることができない問題について
Stackdriver Loggingのコンソールでは、下記のようにHTTPリクエストの情報をラベルとして表示することができます。
これはある種Stackdriver Logging wayに則ったロギング方法であると思われるので、Rubyでも利用したいです。
このラベルを表示するためには、次の情報をログに含めれば良いようです:
httpStatus.requestMethod
httpStatus.status
httpStatus.responseSize
httpStatus.latency
httpStatus.userAgent
しかしながら、公式ライブラリをそのまま利用する限り、これらの情報をログに付加する方法はありません。これが第2の問題です。
問題を解決する
構造化ログにしづらい問題
この問題を解決するには、 logger.info
や logger.warn
などログを記録するメソッドが呼ばれるたびに、特定に情報を付加すれば良いです。
その機能を実現するための仕組みは色々考えられますが、今回は logger.formatter
という既に用意された仕組みを利用します。
どういうわけか、公式ライブラリでは formatter
を利用しない仕様となっています。 参照
このため、 formatter
を利用するように Google::Cloud::Logging::Logger
を拡張します。
class StackdriverLogger < Google::Cloud::Logging::Logger
private
def write_entry(severity, message)
# 既存のwrite_entryメソッドに、この処理だけを追加した
message = format_message(format_severity(severity), Time.now, progname, message)
super(severity, message)
end
SEV_LABEL = %w(DEBUG INFO WARN ERROR FATAL ANY).each(&:freeze).freeze
def format_severity(severity)
SEV_LABEL[severity] || 'ANY'
end
def format_message(severity, datetime, progname, msg)
@formatter.call(severity, datetime, progname, msg)
end
end
write_entry
メソッドは、公式ライブラリにおいてログのエントリを作成しStackdriverに送信するメソッドです。
引数の message
が、 logger.info
の引数と同一のため、ここで message
に情報を付加することができます。
format_severity
, format_message
の実装は、Ruby公式の lib/logger.rb
から実装を流用しています。 参考
これにより、 formatter
を利用できるようになりました。
実際に利用する際は、各リクエストのエントリーポイントなどで、下記のようにformatter を設定すれば良いでしょう。
logger.formatter = proc { |severity, datetime, progname, msg|
{ text: msg, user_id: user_id, event_id: event_id}
}
ログ呼び出しも下記のように簡潔になります。
logger.info { "something happened." }
logger.warn { "something seems wrong." }
logger.error { "an error occurred finally." }
これで第1の課題は解決できました。
httpRequest
の情報を含めることができない問題
公式ライブラリのコードを読むと、 httpRequest
を記録するためには write_entry
で生成しているログエントリに http_request
フィールドをセットすれば良いことがわかります。
そのように実装を修正します。
class StackdriverLogger < Google::Cloud::Logging::Logger
module EntryRefinement
# http_requestにaccessorを設けるモンキーパッチ
refine Google::Cloud::Logging::Entry do
attr_accessor :http_request
end
end
using EntryRefinement
private
def write_entry(severity, message)
message = format_message(format_severity(severity), Time.now, progname, message)
entry = Google::Cloud::Logging::Entry.new.tap do |e|
e.timestamp = Time.now
e.severity = gcloud_severity(severity)
e.payload = message
# ここでhttp_requestをセットする
e.http_request = Google::Cloud::Logging::Entry::HttpRequest.new.tap do |h|
h.method = message.delete(:method)
h.user_agent = message.delete(:ua)
h.url = message.delete(:path)
h.status = message.delete(:status)
if message[:payload].is_a?(Hash)
h.size = message[:payload][:request_params]&.inspect&.length
h.response_size = message[:payload][:response_body]&.inspect&.length
end
end
# super 使えないので仕方なく公式ライブラリ実装をコピペ
actual_log_name = log_name
info = request_info
if info
actual_log_name = info.log_name || actual_log_name
unless info.trace_id.nil? || @project.nil?
entry.trace = "projects/#{@project}/traces/#{info.trace_id}"
end
entry.trace_sampled = info.trace_sampled if entry.trace_sampled.nil?
end
writer.write_entries entry, log_name: actual_log_name,
resource: resource,
labels: entry_labels(info)
end
end
修正内容はコメントに記載のとおりです。
Entry.http_request
は読み取り専用なので、外から書き込みできるようにしています。
HttpRequest
の初期化に必要な情報をどのように write_entry
メソッドに渡すかについては様々な方法が考えられますが、ここでは最も単純に message
を介して渡しています。
先の formatter
を活用することで、このような処理も可能になります。
上記の修正により、 httpRequest
フィールドもロギングされるようになりました。
まとめ
上記の実装をまとめたものは、Gist に貼りました。
(利便性のためコンストラクタも追加しています。)
この実装を用いることで、下記のようにログを記録できます。
logger = StackdriverLogger.new(log_name: 'hoge_api', labels: { env: 'production' })
logger.formatter = proc { |severity, datetime, progname, msg|
{ text: msg, user_id: user_id, method: method, user_agent: user_agent}
}
logger.info('logger improved!')