Zenn
✨

Rails on ECSな構成でFluent Bitを利用して快適なロギングを実現する

2021/12/31に公開
AWS
Rails
Fluentd
tech

最近、ECS環境を構築する機会に恵まれました。当初はDockerのログドライバにawslogsを
指定してログをCloudWatch Logsに配信したのですが、このやり方には問題がありました。
ログストリームに複数行のログが１行ずつ蓄積されていくことです。

例えば、Railsの開発をしているとき下記のログを確認しながら開発を進めていくと思いますが、これらが1行ずつログストリームに配信されてしまいます。これでは不具合が発生した際、詳細を把握するのが困難になります。

Started GET "/" for 172.21.0.1 at 2021-12-31 12:30:46 +0000
Cannot render console from 172.21.0.1! Allowed networks: 127.0.0.0/127.255.255.255, ::1
Processing by WelcomeController#index as HTML
  Rendering layout layouts/application.html.slim
  Rendering welcome/index.html.slim within layouts/application
  Rendered application/_flash.html.slim (Duration: 0.2ms | Allocations: 28)
  Rendered layout layouts/application.html.slim (Duration: 96.8ms | Allocations: 10334)
Completed 200 OK in 144ms (Views: 90.0ms | ActiveRecord: 13.0ms | Allocations: 16439)

この記事は？？

この記事では、上記の問題を解消するためにログをJSON形式で出力する様に修正する方法を
ご紹介します。

また、CloudWatchにはアプリケーションのログ以外にヘルスチェックのログも配信されますが、
Fluent Bitを利用してアプリケーションのログとヘルスチェックのログを異なるログストリームに
配信する方法もご紹介します。

この記事のゴール

  • RailsのログをJSON形式に構造化して、CloudWatch Logsに配信する
  • Fluent Bitでログルーティングの仕組みを構築する

ログをJSON形式に変換する

ログをJSON形式に変形するためにlogrageというライブラリを使用します。

logrageを導入

gem 'lograge'

まず、logrageをインストールします。

次にlogrageを有効化します。
environments配下の環境ごとのファイルに記述しても良いのですが、initializers配下にlograge.rbを作成してそこにlogrageの設定を記述することにします。完成形はこちらになります。

# frozen_string_literal: true

Rails.application.configure do
  config.lograge.enabled = true

  config.lograge.custom_payload do |controller|
    request = controller.request
    current_user = controller.try(:current_user)
    log = {
      request_id: request.request_id,
      remote_ip:  request.remote_ip,
      host:       request.host,
      url:        request.original_url,
      user_agent: request.user_agent
    }
    log = log.merge(current_user: current_user) if current_user
    log
  end
end

controllerメソッドにアクセスしてお馴染みのcurrent_userやrequestオブジェクトを取得し
それらをログに含ませることも可能です。この部分は要件によって変わってくると思うので、
ご自由にカスタマイズしてください。ただしuser_agentに関しては後述するヘルスチェックのログルーティングのために必須となります。

ここまで完了したら一度開発環境でログがどの様に変更されたか確認してみましょう。logrageのformatterはデフォルトでLograge::Formatters::KeyValueが使われているみたいなので、

method=GET path=/ format=html controller=WelcomeController action=index status=200 duration=13532.57 request_id=e053318a-e42c-4287-9376-0f45578afdd3 remote_ip=172.21.0.1 host=localhost url=http://localhost:3000/ user_agent=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.110 Safari/537.36

こんな感じになるかと思います。request_idやuser_agentなど新たに追加した項目が確認出来ますが、まだJSON形式にはなっていませんね。次はFormatterを自作してJSON形式でログが配信されることを目指します。

logrageのFormatterを実装する

$ mkdir app/lib/lograge/formatters/fluent_bit_json.rb

# frozen_string_literal: true

module Lograge
  module Formatters
    class FluentBitJson
      def call(payload)
        current_user = payload[:current_user]
        status = payload[:status]

        log = {
          level:             level(status),
          status:            status,
          method:            payload[:method],
          path:              payload[:path],
          format:            payload[:format],
          controller:        "#{payload[:controller]}\##{payload[:action]}",
          duration:          payload[:duration],
          request_id:        payload[:request_id],
          remote_ip:         payload[:remote_ip],
          host:              payload[:host],
          url:               payload[:url],
          user_agent:        payload[:user_agent]
        }
        log = log.merge("user_id": current_user.id) if current_user

        log.to_json
      end
    end
  end
end

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

Formatterにはpayloadを引数にとるcallメソッドを実装していきます。内容は要件次第です
が、一先ず最低限必要な項目を追加しておきました。

# frozen_string_literal: true

Rails.application.configure do
  config.lograge.enabled = true
  # 略
  config.lograge.formatter = Lograge::Formatters::FluentBitJson.new
end

自作したFormatterを指定して再度配信されるログを確認します。

{
  "level": "INFO",
  "status": 200,
  "method": "GET",
  "path": "/",
  "format": "html",
  "controller": "WelcomeController#index",
  "duration": 2816.18,
  "request_id": "05a486ff-7d22-47c5-8e93-ca356b2a629a",
  "remote_ip": "172.21.0.1",
  "host": "localhost",
  "url": "http://localhost:3000/",
  "user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.110 Safari/537.36",
}

この様にJSON形式で配信されていればOKです。

これでリクエストに関してはログを構造化することが出来たのですが、Rails.loggerを使ってもJSON形式で出力されません。次はこの問題を解消していきます。

Rails.loggerのFormatterを実装する

今度は Rails.logger のFormatterを実装することになるのですが、その前にロギングにおける
タグについて理解する必要があります。

Rails.logger.tagged('hoge') { Rails.logger.info('piyo') }

を実行すると、

[hoge] piyo

といったようにタグを付与することが出来ます。これはこちらを読むと分かります。

production.rb ではデフォルトで

config.log_tags = %i[request_id]

となっているので、[05a486ff-7d22-47c5-8e93-ca356b2a629a] JSON形式のログという形式で
配信されることになります。

そうなんです。せっかくlogrageでJSON形式に変換しても文字列に変換されてしまうんです。
このタグが付与される挙動を頭に入れつつFormatterを実装していきます。

$ mkdir app/lib/logging/formatters/fluent_bit_json.rb

# frozen_string_literal: true

module Logging
  module Formatters
    class FluentBitJson < ::Logger::Formatter
      def call(severity, _timestamp, _progname, message)
        log = {
          level: severity
        }

        if (tags = current_tags).present?
          # tagをjsonの中に追加して、messageからは削除する
          message = message.split("[#{tags.last}] ").last
          log[:tags] = tags
        end

        JSON.extend JSONExtension
        parsed = JSON.custom_parse(message, symbolize_names: true)

        log = if parsed.is_a?(Hash)
                log.merge(parsed)
              else
                log.merge(message: parsed)
              end
        "#{log.to_json}\n"
      end

      module JSONExtension
        def custom_parse(message, **args)
          JSON.parse(message, args)
        rescue JSON::ParserError
          message
        end
      end
    end
  end
end

logrageのFormatterを実装した時同様、callメソッドを実装していきます。ログの中身は要件次第なのでここでは言及しませんが、ポイントとしてはtags_textの部分をJSON構造の中に追加して、messageからtags_textの部分を削除している部分です。

またlogrrageから渡ってきたmessageはあまりjsonのネストを深くしたくないのでmergeして

Rails.logger.info('hoge')

といった文字列などが渡ってきた時は message という項目を追加しています。

ここまで実装出来たら、

Rails.logger.tagged('hoge') { Rails.logger.info('piyo') }

とconsoleで動作検証してみましょう。JSONで出力されればOKです。
次は、ログの配信先を内容によって振り分ける方法を解説していきます。

FireLensとFluent Bitでログルーティングを実現する

ログルーティングを実現するためにFireLensとFluent Bitを利用します。
各々の詳しい解説は公式に委ねて、この記事ではログルーティングに焦点を当てて解説します。

ログルーティングの流れ

まず手順ですが以下の様になります。

  1. タスク定義にFireLensコンテナを追加する
  2. Fluent Bitの設定ファイルを作成する
  3. ECRにイメージをプッシュする
  4. タスクを再起動

手順から分かる通り、FireLensを使うメリットは複雑な設定は全てAWSに任せて、私たち開発者はFluent Bitの設定ファイルを作成するだけでログルーティングを実装出来ることです。

タスク定義にFireLensを追加する

私はECSのデプロイツールにecs-cliを採用したので、今回はdocker-compose.ymlと
ecs-params.ymlを修正していきます。タスク定義をjsonで記述している場合は公式ドキュメントに詳しい解説が載っているので、こちらを参照してみてください。

logging:
  driver: awsfirelens

まずRailsコンテナのログドライバを awsfirelens に変更します。
awsfirelens というログドライバは存在しないのですが、これはあくまでタスク定義用の
シンタックスシュガーで実際はFluentdまたはFluent Bitのプライグインに変換されています。

次にFireLensをタスク定義に追加します。以下の様に記述します。

log_router:
  image: 5924384318712.dkr.ecr.ap-northeast-1.amazonaws.com/fluent-bit-ecr:latest
  logging:
    driver: awslogs
    options:
      awslogs-group: log-group
      awslogs-region: ap-northeast-1
      awslogs-stream-prefix: firelens

次に ecs-params.yml に log-router を追加します。

log_router:
  firelens_configuration:
    type: fluentbit
    options:
      config-file-type: file
      config-file-value: /fluent-bit/etc/extra.conf

config-file-valueに指定しているextra.confは後で作成します。
ECSエージェントがFireLensコンテナを起動すると、Fluent Bitの設定ファイルを
生成するのですが、中身はこの様になっています。

[INPUT]
    Name forward
    unix_path /var/run/fluent.sock

[INPUT]
    Name forward
    Listen 0.0.0.0
    Port 24224

[INPUT]
    Name tcp
    Tag firelens-healthcheck
    Listen 127.0.0.1
    Port 8877

[FILTER]
    Name record_modifier
    Match *
    Record ec2_instance_id i-058c27c5922eb1f0a
    Record ecs_cluster ecs-cluster
    Record ecs_task_arn arn:aws:ecs:ap-northeast-1:5924384318712:task/ecs-cluster/523734f169ca4aa8b1a83b531055d9f1
    Record ecs_task_definition ecs-service:100

@INCLUDE /fluent-bit/etc/extra.conf

[OUTPUT]
    Name null
    Match firelens-healthcheck

config-file-valueに指定した設定ファイルが @INCLUDE ディレクティブでインポートされていることが分かります。

Fluent Bitの設定ファイルを作成する

まず簡単にFluent Bitについて説明しておきます。

公式から拝借したこの図を見るのが一番分かりやすいのですが、Fluent Bitは常にこの順番でログを加工して設定したアウトプット先にログを配信します。 私たちはこの各セクションの設定をファイルに記述していく事になります。

まずFluent Bitの設定ファイルを作成します。完成版はこちらになります。

[SERVICE]
    Parsers_File /fluent-bit/etc/parsers.conf

[FILTER]
    Name         parser
    Match        app-firelens-*
    Key_Name     log
    Parser       rails
    Preserve_Key false
    Reserve_Data true

[FILTER]
    Name rewrite_tag
    Match app-firelens-*
    Rule $user_agent ^(ELB-HealthChecker/2.0)$ Helath_Check false

[OUTPUT]
    Name              cloudwatch
    Match             Helath_Check
    region            ap-northeast-1
    log_group_name    jsaas-production-logs
    log_stream_prefix firelens/

[OUTPUT]
    Name              cloudwatch
    Match             app-firelens-*
    region            ap-northeast-1
    log_group_name    production-log-group
    log_stream_prefix firelens/

上から順番に解説していきます。

SERVICEセクション

このセクションではグローバルなプロパティを定義することが出来ます。ここで定義しているParsers_FileにはFILTERセクションで使うパーサーファイルのパスを指定します。

FILTERセクション

このセクションではログに新しいフィールドを追加したり、ルーティングに使うタグを追加することが出来ます。 プロパティは利用するプラグインによって異なりますが、共通のプロパティも存在します。

プロパティ名 説明
Name プラグイン名を指定する
Match ログに付与されたタグと照合します。(大文字と小文字は区別され*を使うことが出来ます。) FireLensは自動でコンテナ名-firelens-コンテナIDというタグを付与するので、ここではapp-firelens-*としてRailsコンテナのログのみ検証しています。

parserについて

Formatterを実装してRailsのログをJSON形式で出力出来るように改修しましたが、

{"log":"{\"status\": \"up and running\"}\r\n","stream":"stdout","time":"2018-03-09T01:01:44.851160855Z"}

この様なJSON文字列が流れてきます。これでは各プロパティにアクセスすることが出来ないのでparserを使ってJSONに変換する必要があります。

parserを利用するにはまずパーサーファイルを作成します。

[PARSER]
    Name        rails
    Format      json
    # Command       |  Decoder  | Field | Optional Action   |
    # ==============|===========|=======|===================|
    Decode_Field_AS    escaped    log

Nameはextra.confで参照するのに使います。FormatにはJSON文字列を元の状態に戻したい
のでjsonを指定してください。次にデコーダーを定義するのですが、2種類指定することが可能
で今回はDecode_Field_ASを指定しました。

デコーダー 説明
Decode_Field ログをデコード出来る場合、構造化されたログを元のログに追加する
Decode_Field_AS デコードされたログは全て同じキー、同じ値に書き換えられる

次にparserプラグイン固有のプロパティを見ていきます。

プロパティ 説明
Key_Name パースするログのフィールド名を指定する。 log と記述してください。
Preserve_Key パース後のログに元のKey_Nameフィールドを保持するかどうか。ここでは不要なのでfalseを指定しました。
Reserve_Key パース後のレコードにKey_Name以外の元のフィールドを保持するかどうか。falseを指定すると、Key_Name以外のフィールドは削除されます。ここではKey_Name以外も残しておきたいのでtrueを指定しました。

rewrite_tagについて

rewrite_tagを使うと新しいタグを付与してログレコードを再発行出来ます。再発行した際元のログを破棄するかどうか選択することも出来ます。

Ruleプロパティでどのようにタグを付与するかの条件を定義することが出来、構成は

KEY REGEX NEW_TAG KEEP

となります。

KEYにログのフィールドを記述します。例えば今回のケースですとログは

{
  "level": "INFO",
  "status": 200,
  "method": "GET",
  "path": "/",
  "format": "html",
  "controller": "WelcomeController#index",
  "duration": 2816.18,
  "request_id": "05a486ff-7d22-47c5-8e93-ca356b2a629a",
  "remote_ip": "172.21.0.1",
  "host": "localhost",
  "url": "http://localhost:3000/",
  "user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.110 Safari/537.36",
}

という構成ですので、user_agentを指定する場合$user_agentと書けます。
もし、ネストしたフィールドを指定したい場合は、$hoge['piyo']と書くことが出来ます。

REGEXにはマッチングさせたいパターンを記述し、NEW_TAGには新しく付与したいタグを記述します。そしてKEEPには古いタグを持つ元のログを保持するかどうかをboolean値で指定します。

今回はヘルスチェックのログのみに Health_Checkというタグを付与したいので、

Rule $user_agent ^(ELB-HealthChecker/2.0)$ Helath_Check false

Ruleプロパティはこの様に記述しました。

以上でFILTERセクションの解説は終わりですが、他にもたくさんのプラグインがあるので公式のドキュメントもチェックしてみてください。

OUTPUTセクション

このセクションではログの配信先を定義します。指定できる配信先はCloudWatch LogsやAmazon Kinesis Data StreamsからSlackまでかなり種類が豊富です。

今回はCloudWatch Logsに配信したいので、 Nameにはcloudwatchを指定しました。
Matchにはログに付与されたタグと照合するパターンを記述します。

[OUTPUT]
    Name              cloudwatch
    Match             Helath_Check
    region            ap-northeast-1
    log_group_name    jsaas-production-logs
    log_stream_prefix firelens/

[OUTPUT]
    Name              cloudwatch
    Match             app-firelens-*
    region            ap-northeast-1
    log_group_name    production-log-group
    log_stream_prefix firelens/

ルーティングしたいタグに応じてOUTPUTセクションを複数定義することが可能で、この場合
配信先のログストリームはそれぞれfirelens/app-firelens-6ef6872b0d3f44f1ab47a3332caecbbとfirelens/Health_Check となります。

この様にFluent Bitではタグに応じて複数のOUTPUTセクションを定義することで
ログルーティングを実現することが出来ます。

ECRにイメージをプッシュする

設定ファイルを作成したら次はAWS公式のFluent BitのイメージをベースにしてDokcerイメージを
作成します。今回作成したパーサーファイルと設定ファイルを/fluent-bit/etc/ディレクトリに
コピーするだけでOKです。

FROM amazon/aws-for-fluent-bit:2.21.2

COPY ./parsers.conf /fluent-bit/etc/parsers.conf
COPY ./extra.conf /fluent-bit/etc/extra.conf

Dockerファイルを作成したらbuildしてpushします。

AWS_ECR_ACCOUNT_URL="5924384318712.dkr.ecr.ap-northeast-1.amazonaws.com"
REPOSITORY="fluent-bit"

docker build -t "$AWS_ECR_ACCOUNT_URL/$REPOSITORY:latest" .
aws ecr get-login-password --region ap-northeast-1 | docker login --username AWS --password-stdin $AWS_ECR_ACCOUNT_URL
docker push "$AWS_ECR_ACCOUNT_URL/$REPOSITORY:latest"

毎回実行するのも面倒なのでシェルスクリプトを作っておきます。

タスクを再起動する

最後にタスクを再起動してCloudWatch Logsで配信先のロググループの中でRailsのログと
ヘルスチェックのログが別々のログストリームに配信されていれば作業は完了になります。

さいごに

RailsのログをJSON形式に変換する方法とログの内容に応じてログルーティングする方法の
解説は以上となりますが、Fluent Bitで出来ることはまだまだこんなものではありません。
今後もサービスの成長過程で適切なロギングの仕組みを作っていければと思っています。

参考資料

https://aws.amazon.com/jp/blogs/news/under-the-hood-firelens-for-amazon-ecs-tasks/
https://docs.aws.amazon.com/ja_jp/AmazonECS/latest/developerguide/firelens-using-fluentbit.html
https://docs.fluentbit.io/manual/

GitHubで編集を提案

Discussion