こんにちは！プラットフォーム開発部 SRE チームの jeff です。
先日起こった AWS CodeDeploy の事象について備忘録がてら書いていきます。
AWS CodeDeploy とは？
AWS が提供するアプリケーションのデプロイを自動的に行うマネージドサービスです。EC2, Lambda, ECS, オンプレミスインスタンスに対応しています。
気づいたきっかけ
ある日QAチームから、弊社で開発運用しているとあるアプリケーションのレスポンスがエラーになる時があるとの連絡を受けました。
構成など
今回問題が起きていたアプリケーションの簡単な構成は以下になります。
- java で作られた REST API
- EC2 （AmazonLinux2）上で動いている
- CodeDeploy でデプロイを行なっている
- アプリケーションを AutoScalingGroupで管理していて、インスタンス起動時に CodeDeploy によってアプリケーションがデプロイされる
何が起きているか
アプリケーションログを見てみる
QAから以下のようなエラーがアプリケーションログに出ているとの報告がありました。
Could not open JDBC Connection for transaction; nested exception is java.lang.NoClassDefFoundError: Could not initialize class sun.security.ssl.SSLContextImpl$TLSContext
普段あまり見ることのないクラスが見つからないエラー・・・。 プログラムのバグではなく、ビルド関連や環境に問題がありそうに思いました。
その後SREでもアプリケーションログを確認し、アプリケーションが開始されたタイミングで以下のようなエラーが出ているのを発見しました。
※ バージョンはマスクしています。
Handler dispatch failed; nested exception is java.lang.InternalError: java.io.FileNotFoundException: /usr/lib/jvm/java-1.xx.0-openjdk-1.xx.0.123.b01-1.amzn2.x.x.x86_64/jre/lib/jce.jar
パッケージを確認してみる
java のパスが見つからない？という状況になっています。 java は yum のパッケージを使用しているため、インスタンス上に存在しているか確認します。
$ yum list installed | grep "openjdk" java-1.xx.0-openjdk.x86_64 1:1.xx.0.456.b01-1.amzn2.x.x
ログに書かれているバージョンと yum でインストールされているバージョンに差異があります(マスクしていてわかりづらいですが、マイナーバージョン部分に違いがあります)。 アプリケーション側で認識しているバージョンと yum のバージョンに差異があるということは yum update が行われた可能性があります。 開発チームに確認しましたが誰かが yum update を行ったわけではなさそうでした。
cloud-init を確認してみる
他に考えられるのは cloud-init によるインスタンス起動時の yum update です。
cloud-init のログ（/var/log/cloud-init.log）で yum update が行われていることを確認します。
May 10 00:45:19 cloud-init[2309]: util.py[DEBUG]: Running command ['yum', '-t', '-y', 〜（中略）〜, 'upgrade'] with allowed return codes [0] (shell=False, capture=False)
yum の実行記録ログ（/var/log/yum.log）も確認します。
〜（中略）〜 May 10 00:45:51 Updated: 1:java-1.xx.0-openjdk-1.xx.456.b01-1.amzn2.x.x.x86_64 〜（中略）〜
cloud-init のログに近い時間帯で jdk がアップデートされているのでインスタンス起動時に更新があったことが確認できます。
java のアップデートがあったこと自体は問題ないと考えてます（セキュリティ担保のためには必要）。問題は CodeDeploy の方にありそうです。
CodeDeploy のログを確認してみる
CodeDeploy の実行に問題がないかログを確認してみます。
CodeDeploy 実行ログ
CodeDeploy の実行ログは /opt/codedeploy-agent/deployment-root/deployment-logs/codedeploy-agent-deployments.log なので、こちらを見てみます。
# Logfile created on 2023-05-10 00:45:09 +0000 by logger.rb/xxxxx [2023-05-22 00:45:09.119] [d-XXXXXXXXX]LifecycleEvent - BeforeInstall 〜（中略）〜
デプロイは正常に開始されているけど cloud-init と同時ぐらいのタイミングで実行されています。
CodeDeploy エージェントログ
一応 CodeDeploy エージェントのログ（/var/log/aws/codedeploy-agent/codedeploy-agent.log）も見てみます。
〜（中略）〜 2023-05-10T00:45:07 INFO [codedeploy-agent(XXXXX)]: Started master XXXXX with 1 children 〜（中略）〜
エージェントも cloud-init と同時ぐらいのタイミングで実行されています。
改めて何が起こっているか
以上のことからインスタンス起動時の cloud-init と CodeDeploy の実行がほぼ同時のことから、CodeDeploy でのデプロイ後に cloud-init の yum update でパッケージが更新され、 java のパスが変わることによってこの事象が起きていることが分かりました。
以下のような流れです。
冒頭に書いた「エラーになる時がある」についてはここの挙動が絡んでいて、タイミングによっては yum update が行われていた後にデプロイが実行されるため JAVA_HOME のパスもアップデート後にものが正常に読み込めて問題が起きないとなっていました。
CodeDeploy について
起こっていることは理解できましたがひとつ思ったのが「CodeDeployってcloud-initより後に実行されないんだっけ？」でした。 AWSのドキュメントを見てみると以下のように記載されています。
cfn-init (または cloud-init) を使用して新しくプロビジョニングした Linux ベースのインスタンスでスクリプトを実行する場合、インスタンスの開始後に発生するイベントの順序を厳密に制御しないと、デプロイは失敗することがあります。
AmazonLinux1 の頃から CodeDeploy を使ってて、以前は実行順は制御されていたかと思いますが AmazonLinux2 以降は使う側で実行順を制御する必要があるということでしょうか。
実行順の確認
AmazonLinux1
/etc/init.d から実行順を確認します。
# cloud-init chkconfig: 2345 51 50
# codedeploy-agent chkconfig: 2345 98 02
実行の優先順位は 51 と 98 の部分で数字が小さい方が優先されるため、AmazonLinux1 だと cloud-init の方が優先されるようです。
AmazonLinux2
systemctl コマンドで確認します。
$ systemctl list-dependencies default.target 〜（中略）〜 ● └─multi-user.target 〜（中略）〜 ● ├─codedeploy-agent.service 〜（中略）〜 ● ├─cloud-init.target ● │ ├─cloud-config.service ● │ ├─cloud-final.service ● │ ├─cloud-init-local.service ● │ └─cloud-init.service 〜（中略）〜
この結果によると、AmazonLinux2 以降だと cloud-init と codedeploy-agent が横並びのため、優先順位は決まっていません。なので cloud-init と CodeDeploy が同時に実行されることになります。
対応について
cloud-init と codedeploy-agent にデフォルトで依存関係がないのでEC2のユーザーデータの最後にCodeDeployエージェントを起動させるという対応を取りました。
#!/bin/bash -xe
〜（中略）〜
REGION=$(curl -s 169.254.169.254/latest/dynamic/instance-identity/document | jq -r ".region")
wget https://aws-codedeploy-${REGION}.s3.amazonaws.com/latest/install
chmod +x ./install
./install auto
service codedeploy-agent start
他の対応方法
ユーザーデータに手を加える方法の他に systemd の設定ファイルを変更して cloud-init と codedeploy-agent の実行順を担保する方法もあります。ただ、この方法だと事前に codedeploy-agent の設定変更を AMI に焼き付けておく必要がある点に注意です。
参考
/usr/lib/systemd/system/codedeploy-agent.service を /etc/systemd/system/ にコピーして以下を追記します。
[Unit] … After=cloud-final.service … [Install] WantedBy=cloud-init.target
結果
以上の対応を行ったところ cloud-init の実行後に CodeDeploy によるデプロイが行われることを確認できました。
cloud-init の完了ログ
May 12 07:46:03 cloud-init[2608]: handlers.py[DEBUG]: finish: modules-final: SUCCESS: running modules for final
CodeDeploy の実行開始時のログ
# Logfile created on 2023-05-12 07:46:09 +0000 by logger.rb/xxxxx
最後に
AWS のデプロイに便利な CodeDeploy ですが、思わぬところに落とし穴がありました。 最近はコンテナやサーバーレスのデプロイが増えてきましたがまだEC2にデプロイする機会もありますので、今後使用する際のナレッジにもなったかと思います。
みらい翻訳ではSREを募集しています
アプリケーションのデプロイに興味がある方、その他運用改善など SRE に興味がある方を募集しております。 ご興味がおありの方は下記のリンクからご応募・お問い合わせをお待ちしております。
