0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

@80-cloud

【Rails】S3 の認証情報を渡さずに起動したら、169.254.169.254 を探しに行って起動が遅くなっていた話

0
Posted at

はじめに

Rails の API サーバーを、手元の Docker で本番用の設定のまま起動していたときのことです。起動ログの途中に、見慣れないエラーが出ていました。

Error retrieving instance profile credentials: Failed to open TCP connection to 169.254.169.254:80 (execution expired)

169.254.169.254 という見慣れない IP アドレスに接続しようとして、タイムアウトしたようです。起動自体は最後まで進んでいましたが、「何かを待たされているのでは？」と気になりました。

先に結論：画像の保存先に S3 を使う設定なのに、AWS の認証情報を渡していませんでした。そのため AWS SDK for Ruby が認証情報を順番に探し、最後に「EC2 のインスタンスメタデータ（IMDS）」に問い合わせて、タイムアウトしていました。測ってみると、CPU 制限なしで約 2 秒、CPU 0.1 に制限した環境で約 6 秒、起動時間に差がありました。環境変数 AWS_EC2_METADATA_DISABLED=true を設定するか、有効な認証情報を渡すと、エラーも不要な待ちも消えました。

環境

  • Mac（Apple M2）＋ Docker Desktop（Docker Engine 29.4.1、linux/arm64）
  • Ruby 3.4.9 / Ruby on Rails 8.1.3（測定時。現在は 8.1.4 に更新済み）
  • aws-sdk-core 3.247.0 / aws-sdk-s3 1.222.0
  • Active Storage の保存先：S3（本番の設定）

config/storage.yml の S3 の設定には、アクセスキーを書いていませんでした。以前は AWS の ECS で動かしていて、コンテナに付けた IAM ロールから認証情報を受け取っていたからです。

config/storage.yml
amazon:
  service: S3
  region: <%= ENV["S3_REGION"] || "ap-northeast-1" %>
  bucket: <%= ENV["S3_BUCKET"] %>
config/environments/production.rb
config.active_storage.service = :amazon

症状

本番用のイメージを、AWS の外（手元の Docker）で起動しました。S3 の認証情報は渡していません。

docker run -d --name myapp-imds -p 3098:3000 \
  -e RAILS_MASTER_KEY=... \
  -e S3_BUCKET=dummy -e S3_REGION=ap-northeast-1 \
  （DB の接続情報など）\
  myapp-backend

起動ログを時刻つきで見ると、こうなっていました。

docker logs -t myapp-imds

=> Booting Puma
Error retrieving instance profile credentials: Failed to open TCP connection to 169.254.169.254:80 (execution expired)
Puma starting in single mode...
* Listening on http://0.0.0.0:3000

エラーが出ても起動は止まらず、最後には待ち受けを始めます。そのため、ログを流し見しているだけだと見落としがちです。

切り分け：169.254.169.254 とは何か

169.254.169.254 は、EC2 のインスタンスの中から、そのインスタンス自身の情報（インスタンスメタデータ）を取り出すためのアドレスです。EC2 に IAM ロールを付けていると、ここから一時的な認証情報を受け取れます。

AWS SDK for Ruby は、認証情報を明示的に渡されていない場合、いくつかの方法を決まった順番で試します（公式の Developer Guide より、概要）。

  1. 環境変数などで渡されたアクセスキー
  2. Web ID トークン、IAM Identity Center など
  3. （中略）
  4. ECS のコンテナ用の認証情報
  5. EC2 のインスタンスプロファイル（IMDS）

有効な認証情報が見つかった時点で、探索は止まります。今回はどれも見つからなかったので、最後の IMDS まで進みました。ところが手元の Docker には、169.254.169.254 に応答してくれる相手がいません。接続できずにタイムアウトして、冒頭のエラーになっていました。

今回は Puma が待ち受けを始める前にこのログが出ていたので、アプリの起動処理の中で、S3 関連の初期化を通じて認証情報の探索が起きていると考えました。

どれくらい遅くなっていたのか

同じイメージを、条件だけ変えて起動し比べました。「Rails の起動開始（Booting Puma）から、待ち受け開始（Listening on）まで」の時間を、ログの時刻から読み取っています。

条件 CPU 制限なし CPU 0.1 に制限
認証情報なし（そのまま） 2 秒（エラーあり） 27 秒（エラーあり）
AWS_EC2_METADATA_DISABLED=true 0 秒（エラーなし） 21 秒（エラーなし）
ダミーのアクセスキーを渡す 1 秒（エラーなし） （未測定）

CPU 制限なしでは約 2 秒、CPU 0.1 では約 6 秒の差が出ました。ただし、各条件 1 回だけの測定です。IMDS への問い合わせのタイムアウトは経過時間で決まるので、特に CPU 0.1 側の差には、Rails の起動時間そのもののばらつきも含まれている可能性があります。ここでは、「IMDS の探索を止めると、エラーと不要な待ちが消えた」ことを確認できた、と捉えています。

ちなみに、IMDS から認証情報を取り出す Aws::InstanceProfileCredentials は、HTTP の接続と読み取りのタイムアウトが既定で 1 秒です。公式の API リファレンスによると、デフォルトの探索経路から使われる場合は、やり直しの回数が 0 回になります。実際の問い合わせの回数は使い方によって変わりますが、今回観測した約 2 秒の遅れとも矛盾しない挙動でした。

最初にこのエラーに気づいたときは、ログの間隔から「15 秒も待たされている」と思い込んでいました。でも、測り直すとその大部分は、CPU を絞った環境での Rails 本体の読み込みでした。ログの間隔は、そのまま待ち時間ではない、というのも今回の学びです。

解決：IMDS を使わない環境では、探索を止める

対処は、使い方に合わせて 2 つあります。

1. その環境で S3 を使うなら、有効な認証情報を設定する

AWS の外から S3 を使う場合は、その実行環境に合った方法で、有効な AWS の認証情報を設定します。手元での検証なら、環境変数や AWS の設定ファイルなどが使えます。有効な認証情報があれば、SDK は IMDS を使いません（公式にも「有効な認証情報が設定されたクライアントは IMDS を使わない」と書かれています）。

上の表の「ダミーのアクセスキー」は、探索が止まることを確かめるための実験です。ダミーでは S3 に実際に読み書きできないので、本番では使えません。

2. IMDS を使わない環境では、AWS_EC2_METADATA_DISABLED=true を設定する

EC2 の上ではなく、IMDS を使わないことが分かっている環境（手元の Docker や、今回利用する PaaS など）では、必要に応じて環境変数で探索を止める方法があります。

docker run ... -e AWS_EC2_METADATA_DISABLED=true myapp-backend

AWS の公式ドキュメントでは、この設定は「不要な通信を防ぎ、IMDS がなりすまされ得る信頼できないネットワークでの安全性を高める」ものとして紹介されています。

もし、その環境で S3 そのものを使わないなら、config.active_storage.service を実際に使う保存先に合わせて変えるのが、いちばん根本的な対処です。今回は「本番の設定のまま、AWS の外で起動した」ことが、エラーの出発点でした。

教訓

  • AWS SDK は、認証情報が見つからないと、最後に IMDS（169.254.169.254）まで探しに行きます。IMDS が無い環境で動かすと、ここでタイムアウトして、起動に余計な待ちが入ることがあります
  • 起動自体が成功していても、Error が出ていたら一度内容を確認してみると、今回のような余計な待ちに気づけることがあります
  • IMDS を使わない環境では、AWS_EC2_METADATA_DISABLED=true を設定するか、使わない S3 の設定を見直す方法があります
  • 「どれくらい遅いか」は、ログの間隔だけで判断せず、条件を変えて測り比べると、思い込みに気づけます

おわりに

見慣れない IP アドレスのエラーに最初はドキッとしましたが😅、調べてみると「AWS の外なのに、AWS の中にいるつもりで認証情報を探していた」という、分かってみれば納得の挙動でした。

ECS や EC2 から別の環境へアプリを移すときに、同じログに出会った方の参考になれば嬉しいです🙌

参考

0
0
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
Sign upLogin
0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?