こんにちは。Supershipでデータ分析基盤の保守運用を担当している井波です。
この記事は、Supershipグループ Advent Calendar 2024の19日目の記事になります。
TL;DR
- Github actions上で動作させていたSnowflakeリソースのTerraformデプロイ処理が遅延して失敗するようになった
- あれこれ調査してサポートにも頼ったが、結局原因がわからないまま自然に解消してしまった。
- 教訓は得られたが、原因がわかっていないのでモヤモヤしている
- 供養したい
はじめに
弊社ではSnowflakeを用いたデータ分析基盤を構築しており、Web広告やインストリーム広告の配信時に発生したログやターゲティング用のユーザーリストなどを蓄積しています。
分析利用者にデータを安全に利用してもらえるようなリソース構成を運用するため、ユーザー作成や権限の設定などでSnowflakeのリソースを追加、変更は頻繁に行われます。Terraformにてリソースを管理し、Github actionsを用いて自動的なデプロイをすることで、この運用を効率的に実現しています。
※ 弊社のSnowflake運用の構成について説明したスライドを公開しています。ぜひご覧ください!
https://speakerdeck.com/supership/snowflakedeshi-xian-surudetagabanansu
ですがある日、このGithub actionsでのデプロイが大きく遅延した上で異常終了してしまいました。この症状はそれから数ヶ月にわたり断続的に続くことになります。
原因究明と事象の解消のためいろいろ戦ってはみましたが、先に言ってしまうと原因がわからないまま自然に事象が解消してしまいました。めっちゃ悔しい…
この記事では、戦ってきた内容を振り返るとともに、原因の推察や得られた教訓についてもまとめていきます。
起こったことを時系列で並べる
2024/4/2
- 最初の当該事象が発生
- 筆者困る
- ワークフローを再実行するたびにエラーが変わる
- Snowflakeで実行されたクエリを確認 → 実行時間は問題なし
- tfstateが壊れたことを疑い確認 → 問題なし
- コネクションタイムアウトのエラーログが出現
- Snowflakeへサポートケースを起票
2024/4/3
- ワークフローを再実行し、遅延しながらもterraform planが通るケースが発生
- Githubへサポートケースを起票
2024/4/4
- Terraform Snowflake Providerのアップデートを実施 → 状況変化せず
- BackendのあるAWSアカウントのCloudshellでTerraform環境を構築
- AWSからplan実施 → plan正常終了(遅延なし)
2024/4/8
- AWSで臨時のデプロイ環境&運用ルールを構築 → 運用開始
2024/4/10
- 事象が自然解消、Github actionsで遅延なくデプロイが成功するように…
2024/4/25
- 事象再発
- 筆者キレる
2024/4/26
- Githubへサポートケースを起票(2回目)
2024/5/17
- Github actionsのランナーであるUbuntuのバージョンを最新化して実行し、事象が解消
- 原因がUbuntuのバージョンだったのかは明確にならぬまま、サポートケースもクローズ
2024/07/11
- 事象再発
- 筆者息絶える
2024/08/05
- 事象が自然解消、Github actionsで遅延なくデプロイが成功するように
2024/12/19
- 3度目の事象解消以降、再発はしていない状況
事象の詳細と試したこと
terraform planのエラー
エラーが発生したWorkflowは複数ありました。Snowflakeのリソースを管理するWorkflowと、権限設定を管理するWorkflowがあり、それぞれ本番環境用と検証環境用が用意されています。合計で4つのWorkflowが対象となります。
いずれも共通点としては
- Snowflake Terraform Providerを利用し、Snowflakeの何らかのリソースを扱っている
がありました。
通常時はどのWorkflowもおよそ2〜3分でplan/applyが正常終了するのですが、事象発生後はどれも15〜20分ほど動作し、正常終了したり異常終了したりしました。
このエラーはこのリポジトリの全てのプルリクエストで発生し、エラーが発生するリソースやエラーメッセージも実行のたびにランダムで変化しました。以下は発生したエラーメッセージの例です。
Error: 394303 (08004): !394303!
Error: unable to scan row for SHOW DATABASES: 394303 (08004): !394303!
Error: 390144 (08004): JWT token is invalid. [00622ff3-7920-4bbc-b61a-545a8985d7fb]
-
Error: read tcp 172.18.0.2:53818->XXX.XXX.XXX.XXX:443: read: connection timed out
- IPアドレスはAWS東京リージョンで保持しているものと調査で判明
弊社のSnowflakeがホストされているのもAWS東京リージョンなので、Github actions → Snowflake のコネクションがタイムアウトになったものと思われる
- IPアドレスはAWS東京リージョンで保持しているものと調査で判明
-
Error: read tcp 172.18.0.2:49292->XXX.XXX.XXX.XXX:443: read: connection reset by peer
- IPアドレスはAWS東京リージョンで保持しているものと調査で判明
なお、Snowflakeをデプロイしない別のリポジトリのGithub actionsでは問題なく稼働していました。
tfstateの状態を確認
まずは事象の切り分けとして「Terraformなどソフトウェアの問題」と「動作基盤などハードウェアの問題」を切り分けるため、Terraformに問題があるのかを確認しようとしました。
ですが、インフラを別環境にしてterraformを動作させるためには、デプロイ先へのクレデンシャル情報の作成などのステップがあり、急ぎでの確認は出来なさそうでした。(後々やることにはなるのですが…)
そこでひとまずtfstateの中身を見ていくことにしました。
terraformのbackendがあるAWSでcloudshellを起動し、terraformのリポジトリをcloneしてから以下を実行しました。
terraform state list > tfstate_list.txt
で、tfstate_list.txt
の中身を次のような観点で確認します。
- 重複したリソースがないか
- エラーメッセージのようなものがないか
結果:特に問題なさそうでした。
terraform planのデバッグ実行
tfstateだけではTerraformが原因ではないと言い切れないので、続いてTerraformのデバッグ実行をして詳細なログを見ることにしました。
Github actionsのWorkflowの、Terraform planを実行するコマンドの前にTF_LOG=DEBUG
を入れて、planを走らせます。
- name: Terraform Plan
id: plan
if: github.event_name == 'pull_request'
run: TF_LOG=DEBUG terraform plan
これでplan実行時にデバッグログが出力されます。
結果:デバッグログから、snowflake providerのplan動作時の挙動として発行されるリソースのSHOWコマンドが、クエリ発行から結果の返却までに最大で15分程度かかっていることが判明しました。全てのSHOWコマンドではないですが、複数でこの事象が発生していました。
Snowflake側のクエリ履歴の確認
クエリ発行から返却まで最大で15分程度かかっている原因を調べるため、Snowflakeのクエリ履歴を覗いて発行されたSHOWコマンドがどれだけの時間で完了したかを確認しました。
結果:全て数百msで実行完了していました。
エラー発生リソースの規則性の確認
この事象が特定のリソースに関連して発生しているのかを確認するため、事象が発生した複数回のterraform planのエラーログを見比べ、同じリソースでエラーが発生しているのかを確認しました。
結果:毎回エラーが発生するリソースは別のものであることが確認されました。
仮説の取りまとめ
ここまで調べてきたことを取りまとめました。
- terraform planは成功したり失敗したりする
→ 成功する場合があるのでterraformそのものが原因である可能性は低そう - Snowflake側ではクエリは想定通り1秒以下で完了している
→ Github actions or ネットワークに要因がありそう…? - ネットワーク関連のエラーメッセージが出ている
→ ネットワークの問題説が濃厚
ネットワーク起因の説が濃厚になってきましたが、そうなると「自分たちにはどうにもできない」状況である可能性が高まってきました…
terraform snowflake providerのバージョンアップ
Snowflakeのサポートへの問い合わせに対し、
JWT token is invalid エラーが発生しておりますが、古い terraform snowflake provider にはJWTに関する不具合がございます。
最新のterraform snowflake providerを利用し、事象が改善されるかの確認をお願い出来ますでしょうか。
という旨の回答をいただきました。
確認をするため、terraform snowflake provider のバージョンを下記のようにアップデートしました。
リソース管理:0.47.0 -> 0.73.0
権限管理:0.69.0 -> 0.73.0
実施当時の最新バージョンは0.87.0でしたが、0.74.0以上を反映した場合に発生するエラーがすぐには乗り越えられず、0.73.0までダウングレードしました。
terraform planの実行用のCredentialとして、Snowflakeユーザーにキーペア認証を設定して使用していたのですが、0.74.0以降はパスワードの入力を求められるようになり、Github actions上でホストしているため入力できずエラーになるというものでした。
おそらくSnowflakeのUser typeが影響していたのかなと思われます。
検証の成功条件は「とにかくplanが想定内の所要時間で終わればいい」なので、バージョン差異によるソースの変更などは考慮せず、ただproviderのアップデートだけを優先してplanの実行を行いました。
terraform {
required_providers {
snowflake = {
source = "Snowflake-Labs/snowflake"
- version = "0.47.0"
+ version = "0.73.0"
}
}
}
結果:バージョンアップ後の実行でも事象は解消しませんでした。
AWS Cloudshellでterraform実行環境構築
「tfstateの状態を確認」の項にて検討していた別インフラでのterraform実行ですが、
- ネットワーク経路のうちのどこが遅延の要因になっているのかの切り分け
- (もし通るなら)Github actionsでの事象が解消するまでのterraform実行の代替手段
というニーズがあり、AWS Cloudshellを用いて環境構築を進めることにしました。
terraformそのもののインストールやGithubで管理されているソースコードの取得は何も問題ないのですが、デプロイ先のSnowflake(とAWS)へアクセスするためのクレデンシャル情報をどうするかが課題となりました。普段はGithub actionsで実行しているため、GithubのSecretsとしてこれらの情報は埋め込まれており、我々はその中身を見ることはできません。
あるべき対応はこれらのクレデンシャル情報の再作成をして使用することだと思いますが、クレデンシャルの入れ替えによって別のエラーが出て切り分けられなくなることを懸念し、なるべく安全な方法でGithub actionsのSecretsを読み出す方法を選びました。
参考にさせていただいたのはこちらの記事です。
他の人には読めない形式でGitHubのSecretsの値を読み出す
※ Snowflakeユーザー認証に使用する秘密鍵は「扱うSecretsデータサイズが大きい場合」のコマンドを用いることで取得できました。
これにより、安全にSecretsの値を取り出してCloudshell環境に埋め込むことができました。
結果:想定の時間内にterraform planが実行完了しました!plan内容を見ても、特に遅延などが発生しているリソースはありませんでした。
これにより、以下のようなことが言えるようになりました。
- terraformそのものはやはり問題なさそう
- ネットワークについても、Snowflake側には問題はなさそう
- terraformを用いたSnowflakeリソースのデプロイが一切できなくなる状況は回避できそう
ランナーのUbuntuのバージョンアップ
こちらはGithubのサポートへの問い合わせへの回答で
ランナーのUbuntuのバージョンをlatestに指定しているが、最近のImageのアップデートでterraformのバージョンが1.8.0 -> 1.8.1に変更になった。これが影響している可能性がある。
terraformのエンジニアチームに問題を提起してみてほしい。
といただきました。
我々のワークフローの実行コンテナとしては
jobs:
terraform:
name: 'Terraform'
runs-on: ubuntu-latest
container:
image: hashicorp/terraform:1.6.1
このようにコンテナイメージでterraform1.6.1を指定しています。ので、1.6.1が使用されているはず。
ただ、ランナーが影響している可能性を否定できないため、疑心暗鬼ではありながらもUbuntuのランナーのバージョンを少し下げて固定し、検証をしてみました。
- runs-on: ubuntu-latest
+ runs-on: ubuntu-20.04
結果:まさかの事象解消!
しかし、念の為もう一度ランナーをlatestに戻してもう一度実行してもやはり事象が解消されていたため、たまたま自然解消したタイミングだっただけでした…
自然解消
この事象は、すべて自然解消という結果で終わっています。
1回目:8日間
2回目:23日間
3回目:26日間
SnowflakeとGithubのサポートケースを起票したり、社内外の有識者の知恵を借りたりしながらも、原因の究明までは辿り着けませんでした。無念…
最後の事象解消からおよそ4ヶ月が経過しており、この間は再発せずに過ごせてはいるものの、この事象と向き合うことにかなり苦労したこともあり、幾分かの不安が拭えないままです。
臨時運用フローの構築
ここまでは起こったことの振り返りをしてきましたが、ここからは再び前を向いて進もうということで、この事象へ向き合った結果良かったことを取り上げていきたいと思います。
まず、このCIを前提としたリソース管理が機能しないという状況を乗り越えるために構築した臨時運用フローについて記載します。
振り返りの中の「AWS Cloudshellでterraform実行環境構築」にて、Cloudshellからであればデプロイすることができるようになりました。このことを活かして臨時運用フローを構築するために
- 実行環境構築手順の作成 → メンバーへの展開
- 臨時デプロイの作業手順を細かく設定
- 利用するコマンドのチートシートを作成して利用してもらう
- planとapplyの実施管理表を作成し、都度情報を埋めていく運用
を実施しました。
これにより、(通常の場合より5倍くらいは作業時間が増えますが)Terraformを用いたリソース管理を継続することができました。最初の解消までの8日間のうちに構築しましたが、その後20日以上の事象発生が2回もあったため、本当に作っておいて良かったなぁと思っています。
根本原因の仮説
結局最後まで真因がわからないまま事象が解消してしまったのですが、たとえ検証できない仮説だとしても、しっかり考えることには意味があるかなと思います。
私が仮説として考えているは、Github actionsの実行環境内でのネットワーク障害です。
- Github actions全体で発生している事象ではない → トラフィックの渋滞とかではなさそう
- 遅延するのがSnowflakeとの通信のみ → ルーティングか名前解決にトラブルがありそう?
- 一部パケットのみ無限にぐるぐるしてタイムアウトしていたとか…?
私自身、そこまでネットワークに詳しいわけではないのですが、がっつりネットワークエンジニアな友人にこの事象について話してみると「よくあるネットワーク障害のパータンで、本腰入れないとなかなか直らない」とコメントをもらいました。
SaaSの奥のネットワークのことまでは自分ではどうにもできないことなので、モヤモヤはしますが自然解消してくれて良かったとは思っています。
得られた教訓
この一連の対応の中で苦しんだことも多くありましたが、その分得られた教訓もありました。
ロックインと向き合う
この記事で触れている範囲だけでも、SnowflakeやGithub(actions)などのプラットフォームに依存して我々としての仕組みを構築していることが認められます。
このような仕組みを構築するときには、プラットフォーム側の障害に引きずられて我々のビジネスも止まってしまうリスクと向き合う必要があることを再認識しました。
このリスクへの向き合い方としては、今は「リスクを受け入れる(保有)」の状態になっています。起こる確率は小さく、データ基盤もビジネスクリティカルなものではなかったので、事象が発生するまではこの選択に疑いの余地はありませんでした。(そもそもリスクだとも思っていなかったかも)
この事象を受けて、改めてこのリスクへの対応を考えてみると、
- リスク保有:リスクを受け入れてプラットフォームを利用する
- リスク軽減:プラットフォームの使用不能時の代替の仕組みを構築する
- リスク移転:?(AWSとかだと責任共有モデルがあり、それがこれに近いかなと)
- リスク回避:プラットフォームの利用を避け、必要な仕組みを自前で構築する
といったことが考えられました。
とりわけCIという概念に関して、リスク軽減は対応の途中で作成した臨時運用フローがそれに該当するものになるかなと思いますし、リスク移転についてもサポートへの問い合わせができる(ように会社がお金を出してくれている)というところで完璧ではないですが対策ができていた部分もあったのかなと思いました。
リスク回避についてもCIの仕組みであれば自前で構築できないこともないのかなぁとは思いますが、そこまでの発生可能性はないと思うので、引き続きある程度はリスクを保有しながら祈るようにこれらのプラットフォームを利用していくことになると思います。
事業継続のための準備
先のリスクの話にも通じるところがありますが、いざトラブルがあったときに以下にこの事業を継続するかというのをさまざまなリスクを考慮しながら計画しておくのは重要だなと感じました。
今回は事象発生から数日後に臨時運用のためのルールと環境を構築して事業を再開しました。長期化を見越して素早くこのルールを用意できたのはよかったなと思っています。が、もっとビジネスクリティカルなシステムの保守をしていたりする場合であれば数日遅れなどは致命傷になります。こういった時のための事業継続計画というのは、事前にあらゆる事象の起こる確率を見越して立てておく必要があるのだと実感しました。
期待は捨てよう
この事象への対応中、何度も「きっとサポートが全てを解決してくれる」という期待をしてしまっていました。
もちろん問い合わせをさせていただいたサポートも、あれこれ専門知識を駆使しながら対応にあたってくれたとは思いますが、今回のような根が深いトラブルでは原因の特定までに相当時間がかかるものです。結果的には原因の特定より先に自然解消してしまい、原因はわからずじまいでした。
正直、対応中はいろんなものにがっかりしてばかりでした。この「がっかり」という感情の裏にはやはり「誰かがなんとかしてくれる」という期待があったと思います。このことは反省すべきだなと思っています。
自分がコントロールできない他者の行為に対して深く入れ込みすぎている状況が「期待」という状態なので、やはり思い通りいかないのが当然です。そのくせ思い通りいかないと「がっかり」になりますし、思い通りにいってもそこまで感動しない、というとても損なマインドだなぁと実感しました。
仕事だけでなく普段から、「期待」は捨ててありのままの現実を受け入れることを大切にしようと思いました。何事も評価するマインドを脱却し、なんでもどんとこいの姿勢でこれからも過ごしていきたいものです。
とはいえ、トラブルどんとこいとは口が滑っても言えないですけどね!!
おわりに
私の身の回りでは一切聞かなかったのですが、もし同じような事象に遭遇された方がいらっしゃれば、解決した/しなかったに関わらずぜひコメントをいただきたいです。
こんな仮説があるかもよ、というものもあればぜひ!
最後に宣伝です。
Supershipではプロダクト開発やサービス開発に関わる人を絶賛募集しております。
ご興味がある方は以下リンクよりご確認ください。
Supership 採用サイト
是非ともよろしくお願いします。