Zenn
🚀

Rails on GKEでも理想の構造化ログを目指す

2021/02/26に公開
Google Cloud
Rails
GKE
log
tech

はじめに

最近GKEに触り始めたのですが、ログ周りでGCPで理想の構造化ログを出力する方法という記事が非常に勉強になりました。その記事ではGoだったので、Railsでも理想の構造化ログを目指してみました。ちょっとコードは整理されていないですが、とりあえずいい感じにログは見れるようになったと思うので公開します。言語に依存しない、どうすれば理想の構造化ログになるのか、に関しては上の記事をみてください。

Rails Serverのログ

大枠としては以下のようになります。

  • アクセスログを独自のフォーマッタを使ったlogrageを使いSTDOUTに出力
  • アプリケーションログにはRails.loggerを使い、独自のフォーマッタでSTDERRに出力
  • アクセスログとアプリケーションログをグループ化するための"logging.googleapis.com/trace"はActionDispatch::RequestIdが作るリクエストIDを元に作る

STDERRに出力するのが少し気持ち悪いですが、アクセスログとアプリケーションログの親子関係を作るために必要なのでやむなしです。

アクセスログ

logrageは普通にインストールしておきます。

Gemfile
group :production do
  gem "lograge"
end

これから説明していきますが、logrageの設定は以下です。

config/environments/production.rb
require_relative "../lib/lograge/formatters/google_cloud_logging"

Rails.application.configure do
  # ...
  proxies = ENV.fetch("TRUSTED_PROXIES", "").split(",").map {|cidr| IPAddr.new(cidr) }
  config.action_dispatch.trusted_proxies = proxies + ActionDispatch::RemoteIp::TRUSTED_PROXIES

  config.lograge.enabled = true
  config.lograge.logger = ActiveSupport::Logger.new(STDOUT)
  config.lograge.custom_options = lambda do |event|
    { time: Time.now }
  end
  config.lograge.custom_payload do |controller|
    request = controller.request
    {
        request_id: request.request_id,
        url: request.original_url,
        user_agent: request.user_agent,
        forwarded_for: request.forwarded_for || [],
        remote_ip: request.remote_ip,
        server_ip: ENV["POD_IP"],
        referer: request.referer,
        protocol: request.env["SERVER_PROTOCOL"],
    }
  end
  config.lograge.formatter = Lograge::Formatters::GoogleCloudLogging.new
  # ...
end

  proxies = ENV.fetch("TRUSTED_PROXIES", "").split(",").map {|cidr| IPAddr.new(cidr) }
  config.action_dispatch.trusted_proxies = proxies + ActionDispatch::RemoteIp::TRUSTED_PROXIES

では後々remote_ipをとる上でロードバランサのIPがremote_ipとされてしまわないように指定しています。config.action_dispatch.trusted_proxiesはArrayを渡すと完全に上書き、Stringだと既存のものに追加されるので実は= ENV["LB_STATIC_IP"]でもいいのですが、不安になる見た目をしているので明示的にデフォルトのものと合わせてArrayで指定しています。
TRUSTED_PROXIESには$LOAD_BALANCER_STATIC_IP/32,130.211.0.0/22,35.191.0.0/16のような値を設定しています。
130.211.0.0/22と35.191.0.0/16は自分が運用している環境では入ってきていませんが、外部 HTTP(S) 負荷分散の概要によると入ってくる可能性もあるので入れておいたほうがいいかと思います。

config.lograge.logger = ActiveSupport::Logger.new(STDOUT)

config.lograge.loggerを設定しないとRails.loggerが使われてしまうので必須です。

  • Rails.loggerには後でアプリケーションログを理想の構造化ログとして出力できるようにフォーマッタを指定します。なのでRails.loggerにmessageとして、logrageでフォーマットをしたものを渡すと入れ子のJSONになってしまい、アクセスログが理想の構造化ログになりません。
  • ActiveSupport::LoggerはデフォルトのフォーマッタとしてActiveSupport ::Logger::SimpleFormatterが使われます。これは装飾なしにmessageを表示してくれるものです。logrageでフォーマットされたものがこのloggerに渡されるので、logger自体にはフォーマッタは指定しません。

config.lograge.custom_optionsとconfig.lograge.custom_payloadではhttpRequestに必要になるものを集めています。
serverIpは

The IP address (IPv4 or IPv6) of the origin server that the request was sent to.
https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#HttpRequest

とのことで、これでいいのか確信はもてていないのですがpodのプライベートIPにしています。マニフェストで以下のようにしています。

env:
  - name: POD_IP
    valueFrom:
      fieldRef:
        fieldPath: status.podIP

参考: kubernetes - How to know a Pod's own IP address from inside a container in the Pod? - Stack Overflow

config.lograge.formatter = Lograge::Formatters::GoogleCloudLogging.new

ここで指定しているフォーマッタは

lib/lograge/formatters/google_cloud_logging.rb
module Lograge
  module Formatters
    class GoogleCloudLogging
      def call(payload)
        {
            severity: severity(payload.fetch(:status)),
            timestamp: {
                seconds: payload.fetch(:time).to_i,
                nanos: payload.fetch(:time).nsec,
            },
            "logging.googleapis.com/trace": trace(payload.fetch(:request_id)),
            httpRequest: http_request(payload),
            forwarded_for: payload.fetch(:forwarded_for),
            view_duration: payload[:view],
            db_duration: payload[:db],
            controller_and_action: "#{payload[:controller]}##{payload[:action]}",
        }.to_json
      end

      def trace(request_id)
        "projects/#{ENV["PROJECT_ID"]}/traces/#{request_id}"
      end

      # https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#HttpRequest
      def http_request(payload)
        {
            requestMethod: payload.fetch(:method),
            requestUrl: payload.fetch(:url),
            status: payload.fetch(:status),
            userAgent: payload.fetch(:user_agent),
            remoteIp: payload.fetch(:remote_ip),
            serverIp: payload.fetch(:server_ip),
            referer: payload.fetch(:referer),
            latency: "%0.6fs" % ((payload[:duration] || 0) / 1e3),
            cacheLookup: false,
            cacheHit: false,
            cacheValidatedWithOriginServer: false,
            protocol: payload.fetch(:protocol),
        }
      end

      def severity(status)
        case status
        when 100..400 then "INFO"
        when 400...500 then "WARNING"
        else "ERROR"
        end
      end
    end
  end
end

余談ですが、ヘルスチェック用のリクエストをログに出したくない場合には

config.lograge.ignore_custom = lambda do |event|
  event.name == "process_action.action_controller" &&
      event.payload[:request].forwarded_for.blank? &&
      event.payload[:request].user_agent.match?(/GoogleHC/)
end

などすればできます。

アプリケーションログ

loggerの設定をしていきます。

config/environments/production.rb
require_relative "../lib/logger/google_cloud_logging_formatter"

Rails.application.configure do
  # ...
  config.log_formatter = Logger::GoogleCloudLoggingFormatter.new
  logger = ActiveSupport::Logger.new(STDERR)
  logger.formatter = config.log_formatter
  config.logger = logger  
  # ...
end

ポイントは概要で述べたように出力先がSTDERRであることと、フォーマッターです。

lib/logger/google_cloud_logging_formatter.rb
class Logger::GoogleCloudLoggingFormatter < ::Logger::Formatter
  KEY = :google_cloud_logging_formatter_trace_id

  def call(level, time, program_name, message)
    {
        severity: severity(level),
        timestamp: {
          seconds: time.to_i,
          nanos: time.nsec,
        },
        "logging.googleapis.com/trace": trace,
        message: message,
    }.to_json + "\n"
  end

  def self.set_thread_local_trace_id(id)
    Thread.current[KEY] = id
  end

  private

  def trace
    "projects/#{ENV["PROJECT_ID"]}/traces/#{thread_local_trace_id}"
  end

  def thread_local_trace_id
    Thread.current[KEY]
  end

  # https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#logseverity
  # Logger::SEV_LABEL
  def severity(level)
    case level
    when "WARN" then "WARNING"
    when "FATAL" then "CRITICAL"
    else level
    end
  end
end

リクエストIDはスレッドローカル変数に入れてみることにしました（Fiber Schedulerベースのサーバーになったら壊れる？）。

app/controllers/application_controller.rb
class ApplicationController < ActionController::Base
  prepend_before_action do
    Logger::GoogleCloudLoggingFormatter.set_thread_local_trace_id(request.request_id)
  end
end

設定されるまでの間にRails.loggerがあると間違ったグループ化がされてしまうので、setとclearするRackミドルウェアを書いて、ActionDispatch::RequestIdの直後に入れ方がいいかもしれないです。

Sidekiqのログ

Sidekiqもloggerのフォーマッタを指定することができます。

config/initialziers/sidekiq.rb
require_relative "../../lib/sidekiq/logger/formatters/google_cloud_logging"

Sidekiq.configure_server do |config|
  # ...
  config.log_formatter = Sidekiq::Logger::Formatters::GoogleCloudLogging.new  
end

フォーマッタはこんな感じにしてみました。

lib/sidekiq/logger/formatters/google_cloud_logging.rb
module Sidekiq
  class Logger
    module Formatters
      class GoogleCloudLogging < Base
        def call(level, time, program_name, message)
          hash = {
              severity: severity(level),
              timestamp: {
                  seconds: time.to_i,
                  nanos: time.nsec,
              },
              message: message,
              pid: ::Process.pid,
              tid: tid,
          }

          hash["logging.googleapis.com/trace"] = "projects/#{ENV["PROJECT_ID"]}/traces/#{ctx[:jid]}" if ctx[:jid]
          hash["class"] = ctx[:class] if ctx[:class]

          Sidekiq.dump_json(hash) << "\n"
        end

        private

        # https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#logseverity
        # Logger::SEV_LABEL
        def severity(level)
          case level
          when "WARN" then "WARNING"
          when "FATAL" then "CRITICAL"
          else level
          end
        end
      end
    end
  end
end

おわりに

これでCloud Loggingのクエリで

resource.labels.container_name="$RAILS_SERVER_CONTAINER"
logName="projects/$PROJECT_NAME/logs/stdout"

などとすると、アクセスログが一覧でみれて、各アクセスログをクリックすると、そのリクエスト内でのアプリケーションログが一覧でみれます。

まだ長時間運用したわけではないので不十分な部分もあるかもしれないですが、それなりに調べることがあったので公開してみました。問題が見つかったら修正していきます。フィードバックをもらえると嬉しいです。

Discussion