RailsをAmazon ECS(AWS Fargate)で運用する際のログ設定で工夫した点

こんにちは、Webエンジニアの本間です。

今回、Railsアプリケーションを Amazon ECS、しかも AWS Fargate の上で運用する機会に恵まれました。その中でログに関する話を書こうと思います。

というのも、これまでのEC2インスタンス上でのログと、ECSでのログでは扱いが大きく異なっており、色々と注意＆工夫しないと障害調査等で苦労することがわかったためです。従来から変更しないといけない点、それを見据えて工夫した点をばーっと書いていきたいと思います。

従来との変更点

実サーバーやEC2インスタンス上でRailsアプリケーションを運用した時との変更点です。

出力先

通常、Railsアプリケーションでは $RAILS_ROOT/logs 以下にファイルとして出力していくと思いますが、Dockerを使った環境ではこれはできません。理由としては2点あります。

特に対策をしないと、コンテナを落とした際にログが消える
ログファイルを見ることが困難

上記に加えて、ログをファイル出力しているとディスクフルになる危険性あります。 Fargateでは10GBしかディスクがないため発生しやすいです。このため、ファイル出力は絶対にしない ほうが良いと思います。

では、どこにログを出力するのかというと、Railsレベルでは 標準出力 が基本になります。 Amazon ECSには、標準出力に出力されたログをCloudWatchに送信する機能がありますので、これを使用してCloudWatchで保管することになります。

2018年12月7日現在、FargateではCloudWatchにしかログを送信できないようですが、EC2ベースのECSならばfluentdなどの送信方法も選択できるようです（以下のページの logConfiguration を参照）。

https://docs.aws.amazon.com/ja_jp/AmazonECS/latest/developerguide/task_definition_parameters.html#container_definition_storage

閲覧、検索

ログをCloudWatchで保管することにより、閲覧や検索方法も大きく変わります。今まではサーバーにsshで繋いでgrepで検索、といった運用だったのですが、まずsshで接続できませんし、接続できるようにしてもログファイルがないため閲覧、検索ができません。

やり方は大きく2つあって、「CloudWatchの画面から閲覧、検索する」か「awslogsコマンドを使用して検索する」になります。

f:id:ryu39:20181207174436p:plain — CloudWatchの画面とawslogsコマンド

f:id:ryu39:20181207174512p:plain — CloudWatchの画面とawslogsコマンド

手っ取り早く使うにはCloudWatchの画面ですが、 awslogs コマンドのほうが従来のログの閲覧、検索に近い感じでできそうです。 awslogs コマンドもCloudWatchをコンソールで見ているだけなので、 CloudWatchで閲覧、検索しやすいようにログを出力する ということが重要になります。

ログの種類

ある程度の規模のアプリケーションになるとRailsの標準ログ以外に、外部サービスとのやりとりは専用のログファイルを作ったりすると思います。過去に弊社開発部ブログで複数のログファイルに共通の変数を出力する仕組みを紹介しています。

tech.unifa-e.com

しかし、ECSではログは全て標準出力に出さないといけないため、ログの種類でファイルを分けるといったことができません。これに関しては、工夫した点で回避策を書いていますので、参考にしていただければと思います。

工夫した点

出力形式

出力は通常のテキスト形式ではなく JSON形式 で行なっています。その理由は以下の2つです。

CloudWatchが、複数行にまたがるログを別々のログと認識してしまう
CloudWatchの JSONPathによる強力な検索が可能

前者に関して、複数行にまたがるログというのは、エラーのスタックトレースだったり、改行入りの生SQLだったりです。これらはテキスト形式で出力すると別々のログとして扱われてしまうのですが、JSON形式にすることで1つのログとして扱われるようになります。これだけだとあまりメリットがなさそうに見えますが、次のJSONPathによる検索を使うと、これがメリットして機能してきます。

CloudWatchでは、JSONPathという記法でJSON形式のデータのキーと値を指定して、検索することができます。例えば、 error レベルのログだけを抽出するには以下のように入力します。

{ $.level = "error" }

すると、JSONのキーが level、値が "error" であるログだけがヒットします。

f:id:ryu39:20181207155408p:plain

そして、その中の1つのログを見てみると、スタックトレースが全部格納されていることがわかります。

f:id:ryu39:20181207155426p:plain

テキスト形式で出力していると他のログと混じってしまう可能性がありますし、この強力なJSONPathの検索に 2行目以降がヒットしません。 CloudWatchに出力する環境であれば、JSON形式で出力した方が確実にメリットがあると思います（ただし、ローカルの開発環境では情報量が少なく、見やすいテキスト形式がおすすめです）。

使用しているライブラリ

RailsのログをJSON形式で出力するライブラリとして以下のgemを使用しています。

rails_semantic_logger

このgemは semantic_logger というログ全般を扱うgemをrailsで使いやすいように設定してくれるgemです。中身の大半は、このsemantic_loggerになっています。

採用の理由としては、ローカルの開発環境ではテキスト形式、それ以外ではJSON形式といった切り替えが容易だったことと、#tagged メソッドを実装しておりログへのタグ付けが可能だったことが挙げられます。

リクエストIDの出力

これはECSに限らずという工夫ですが、Railsでは#tagged というメソッドに応答するロガーを使用することで、ログにリクエストIDを簡単につけることができます。 #tagged に応答するロガーとしては、公式の ActiveSupport::TaggedLogging もありますし、前述したsemantic_loggerも使用可能です。

やり方は config/application.rb で以下の1行を入れるだけで対応できます。

# config/application.rb

module MyApplication
  class Application < Rails::Application
    # :
    config.log_tags = [:request_id]
    # :
  end
end

この設定でJSON形式でログを出力すると以下のようになります。一部は省略していますが、 tags というキーの中にリクエストIDが出力されています。

[  
  {  
    "timestamp":"2018-12-07T06:37:22.165276Z",
    "level":"info",
    "tags":[  
      "[\"d09c4e6e-df5c-4f46-8574-cf735e2e0da8\"]"
    ],
    "message":"Started",
  },
  {  
    "timestamp":"2018-12-07T06:37:22.417212Z",
    "level":"info",
    "duration":"26.1ms",
    "tags":[  
      "[\"d09c4e6e-df5c-4f46-8574-cf735e2e0da8\"]"
    ],
    "message":"Completed #show",
  }
]

rails_semantic_loggerを使っている場合はさらにオススメの設定があります。以下のように設定することで名前付きのタグでリクエストIDを出力することが可能です。

# config/application.rb

module MyApplication
  class Application < Rails::Application
    # :

    # config.log_tags = [:request_id]
    config.log_tags = { request_id: :request_id }

    # :
  end
end

[  
  {  
    "timestamp":"2018-12-07T06:45:22.623479Z",
    "level":"info",
    "named_tags":{  
      "request_id":"5783b811-02f9-4a17-a48d-a3f5a2c565bf"
    },
    "message":"Started",
  },
  {  
    "timestamp":"2018-12-07T06:45:22.927387Z",
    "level":"info",
      "request_id":"5783b811-02f9-4a17-a48d-a3f5a2c565bf"
    },
    "message":"Completed #show",
  }
]

最初の設定では、 tags というキーの中の配列の1要素としてリクエストIDが出力されていましたが、この設定では named_tags の request_id というキーの値としてリクエストIDが出力されています。このようにキーが指定されていると、CloudWatchでの検索がやりやすいです。リクエストIDで検索する場合、以下のようになります。

f:id:ryu39:20181207160010p:plain

このようにすることで、とある1つのリクエストで発生したログを全部取得する、ということができるため、エラーになったリクエストの原因調査がかなり捗ると思います。今後はリクエストID以外にも、ユーザーIDなど 検索のキーに使いたい属性 を名前付きタグとして出力していきたいです。

ログの種類の分け方

注意点で記載した通り、ログの種類をファイルで分けることができないため、何らかの工夫が必要です。そこで、リクエストIDの出力と同じくタグをつけることでどの機能で出力されたログか判別できるようにしました。下記のように、特殊な機能呼び出しの前後で #tagged を実行しタグをつけることで、あとでログ上でどの機能で出力されたログか、見分けをつけやすくしています。

Rails.logger.info "1" # => {  ..., "message": "1" }

# 特殊な機能呼び出しstart
Rails.logger.tagged('special app') do
  Rails.logger.info "2" # => {  ..., "tags": ["special app"], "message": "2" }
  Rails.logger.info "3" # => {  ..., "tags": ["special app"], "message": "3" }
end
# 特殊な機能呼び出しend

Rails.logger.info "4" # => {  ..., "message": "4" }

最終的な設定

rails_semantic_loggerを使用した場合の最終的な設定は以下のようになっています。

# config/application.rb

module MyApplication
  class Application < Rails::Application
    # :
    config.log_level = :info
    config.colorize_logging = false

    # ログにrequest_idの名前付きタグをつける
    config.log_tags = { request_id: :request_id }

    # ログをファイル出力しない
    config.rails_semantic_logger.add_file_appender = false

    # 標準出力のみにJSON形式で出力
    config.semantic_logger.add_appender(io: $stdout, level: config.log_level, formatter: :json
    # :
  end
end

まとめ

今回、RailsアプリケーションをAmazon ECSやAWS Fargateで運用する際、ログで注意する点、工夫した点を書きました。今までの運用と比べ異なる点が多く、慣れない点も多いのですが、ECSやFargateにはメリットも多いので、なんとか使いこなしていきたいと思っています。

以上になります、最後までご覧いただきありがとうございました。

ユニファ開発者ブログ

ユニファ株式会社プロダクトデベロップメント本部メンバーによるブログです。