LoginSignup
2
2

More than 3 years have passed since last update.

RubyでもまともにStackdriver Loggingを使いたい

Posted at

RubyでStackdriver Loggingを使うためには、google-cloud-logging ライブラリを利用します。
しかし、このライブラリには実用上いくつかの問題が存在します。
本記事では、このライブラリを拡張することで、それらの問題を解決する方法を提示します。

なお、以下のコードはRuby 2.6.3で動作を確認しています。

Stackdriver 公式Rubyライブラリの問題

以下、 google-cloud-logging ライブラリ公式ライブラリ と表記します。
実際に公式ライブラリを利用してみて、実用するには以下の難点があることがわかりました。

  1. 構造化ログにしづらい
  2. httpRequest の情報を含めることができない

次にこれらの問題の詳細を説明します。

構造化ログにしづらい問題について

通常、ログは下記の構文で記録します。

logger.info { "something happened." }

このとき、このログエントリーはStackdriverの textPayload として記録されます。
このような単純なログの場合はそれでも許容できますが、下記のようなログはどうでしょう?

logger.info { "something happened. user_id: 123, event_id: 2" }

この場合、 textPayload で記録されると user_idevent_id での検索が困難になり、不便です。
これを解決するために用意された方法が構造化ログです。 参照

下記のコードでロギングすることで、 jsonPayload による構造化ログを利用することができます。

logger.info { { text: "something happened.", user_id: 123, event_id: 2 } }

すなわち、 logger にハッシュを渡せば良いです。これにより、Stackdriverコンソールで user_idevent_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リクエストの情報をラベルとして表示することができます。
image.png
これはある種Stackdriver Logging wayに則ったロギング方法であると思われるので、Rubyでも利用したいです。

このラベルを表示するためには、次の情報をログに含めれば良いようです:

  • httpStatus.requestMethod
  • httpStatus.status
  • httpStatus.responseSize
  • httpStatus.latency
  • httpStatus.userAgent

しかしながら、公式ライブラリをそのまま利用する限り、これらの情報をログに付加する方法はありません。これが第2の問題です。

問題を解決する

構造化ログにしづらい問題

この問題を解決するには、 logger.infologger.warn などログを記録するメソッドが呼ばれるたびに、特定に情報を付加すれば良いです。
その機能を実現するための仕組みは色々考えられますが、今回は logger.formatter という既に用意された仕組みを利用します。

どういうわけか、公式ライブラリでは formatter を利用しない仕様となっています。 参照
このため、 formatter を利用するように Google::Cloud::Logging::Logger を拡張します。

問題1を解決する実装
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 を設定すれば良いでしょう。

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 フィールドをセットすれば良いことがわかります

そのように実装を修正します。

問題2を解決する実装
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!')
2
2
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
2
2