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

RubyでStackdriver Loggingを使うためには、[google-cloud-logging ライブラリ](https://github.com/googleapis/google-cloud-ruby/tree/master/google-cloud-logging)を利用します。
しかし、このライブラリには実用上いくつかの問題が存在します。
本記事では、このライブラリを拡張することで、それらの問題を解決する方法を提示します。

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

# Stackdriver 公式Rubyライブラリの問題
以下、 [google-cloud-logging ライブラリ](https://github.com/googleapis/google-cloud-ruby/tree/master/google-cloud-logging)を `公式ライブラリ` と表記します。
実際に公式ライブラリを利用してみて、実用するには以下の難点があることがわかりました。

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

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

## 構造化ログにしづらい問題について
通常、ログは下記の構文で記録します。

```ruby
logger.info { "something happened." }
```

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

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

この場合、 `textPayload` で記録されると `user_id` や `event_id` での検索が困難になり、不便です。
これを解決するために用意された方法が構造化ログです。 [参照](https://cloud.google.com/logging/docs/structured-logging)

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

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

すなわち、 `logger` にハッシュを渡せば良いです。これにより、Stackdriverコンソールで `user_id` や `event_id` による検索も可能になります。

ここで、すべてのログについて共通の情報を付加したい場合にどうすれば良いでしょうか？
現在の公式ライブラリではこの要件を華麗に実現する手段はなく、愚直に全てのログにパラメータを付加するしかありません。

```ruby
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](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/127392/20fd132f-a168-d7a3-36d9-211c0cd911f3.png)
これはある種Stackdriver Logging wayに則ったロギング方法であると思われるので、Rubyでも利用したいです。

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

* `httpStatus.requestMethod`
* `httpStatus.status`
* `httpStatus.responseSize`
* `httpStatus.latency`
* `httpStatus.userAgent`

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

# 問題を解決する
## 構造化ログにしづらい問題
この問題を解決するには、 `logger.info` や `logger.warn` などログを記録するメソッドが呼ばれるたびに、特定に情報を付加すれば良いです。
その機能を実現するための仕組みは色々考えられますが、今回は [`logger.formatter`](https://ruby-doc.org/stdlib-2.6.4/libdoc/logger/rdoc/Logger.html#formatter) という既に用意された仕組みを利用します。

どういうわけか、公式ライブラリでは `formatter` を利用しない仕様となっています。 [参照](https://github.com/googleapis/google-cloud-ruby/blob/13d26a0ce6c8c5516d068e6f6b1382612670b706/google-cloud-logging/lib/google/cloud/logging/logger.rb#L97-L99)
このため、 `formatter` を利用するように `Google::Cloud::Logging::Logger` を拡張します。

```ruby:問題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` から実装を流用しています。 [参考](https://github.com/ruby/ruby/blob/03fdf02321d4ac3123fb6908e7be53e232a92b67/lib/logger.rb#L576-L586)

これにより、 `formatter` を利用できるようになりました。
実際に利用する際は、各リクエストのエントリーポイントなどで、下記のようにformatter を設定すれば良いでしょう。

```ruby:formatterの設定例
logger.formatter = proc { |severity, datetime, progname, msg|
  { text: msg, user_id: user_id, event_id: event_id}
}
```

ログ呼び出しも下記のように簡潔になります。

```ruby
logger.info  { "something happened." }
logger.warn  { "something seems wrong." }
logger.error { "an error occurred finally." }
```

これで第1の課題は解決できました。

## `httpRequest` の情報を含めることができない問題
公式ライブラリのコードを読むと、 `httpRequest` を記録するためには `write_entry` で生成しているログエントリに `http_request` フィールドをセットすれば良いことが[わかります](https://github.com/googleapis/google-cloud-ruby/blob/13d26a0ce6c8c5516d068e6f6b1382612670b706/google-cloud-logging/lib/google/cloud/logging/entry.rb#L371-L375)。

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

```ruby:問題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](https://gist.github.com/tmokmss/61cb67d0c7fc1e4e6163282cf87a6ebc) に貼りました。
（利便性のためコンストラクタも追加しています。）

この実装を用いることで、下記のようにログを記録できます。

```ruby
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!')
```