はじめに
ある新サービスの環境構築中、Azure DevOpsのPipelineからApp Serviceをデプロイしたところ、
Azure SQL Databaseへの接続で
Login failed for user '{ユーザー ID}'.
というエラーが発生し、調査に時間を要しました。
結果として、パスワード間違いのログイン試行を繰り返したためにSQL DatabaseにApp ServiceのIPアドレスがBANされていたのですが、調査の流れについてまとめておきます。
状況
SQL Databaseの設定状況
- 開発期間等の関係から、ID/Passwordを使ったSQL Server認証を利用（いずれAzure Active Directory認証を利用したい・・・）
- [Azureサービスを許可する]をオン、追加で開発するオフィスとVPN回線のIPアドレスを許可
エラーの発生条件
- Azureサービス以外に追加で許可しているIPからのローカルデバッグでは正常にアクセスできる
- 問題のApp Serviceから、別サブスクリプションに同一構成で構築しているSQL Databaseには問題なくアクセスできる
接続文字列の不正、パスワード内の記号の文字化け、Azure PipelineのYamlの記述ミス等疑ってみましたが、どれも関係なし。
もしかして、問題のApp ServiceのIPアドレスが「Azureサービスを許可する」の範囲に含まれていないのでは？と疑いましたが、上に書いたように、別のSQL Databaseに接続できているので関係ないはずです。たまに特定のリソースだけ更新がうまくいかず・・・なんてこともあるので、念のため許可をON/OFFしてみましたが、変わりなし。
SQL Databaseの監査ログを取ろう
切り分けを繰り返すより、拒否してる大元のSQL Databaseのログを見たほうが早いよね、ということで監査ログをとりました。
設定方法はこちらを参考
https://docs.microsoft.com/ja-jp/azure/sql-database/sql-database-auditing
ログインエラーが発生するとこんな感じで.xelファイルが生成されます。
ダウンロードしてきて、SQl Server Management Studioで開くとこんな感じに監査ログが確認できます。
ログを探っていくとこんな記録を確認できました。
| フィールド | 値 |
|---|---|
| action_name | DATABASE AUTHENTICATION FAILED |
| additional_information | 18456113 |
色々検索するとerror_state=113というのは、SQL Database側が接続元のIPを一時的にBANしている状態のようです。
マイクロソフトのサポートに問い合わせて、やはりBANされていました。
原因は、おそらくパスワードを誤ってデプロイしてしまい、何度もログイン認証に失敗したためです。
その後、正しい接続文字列に直してBANされているのでエラーになっていたのでした。
ローカルデバッグでは上手くいっていたのも納得です。
なお、こうなってしまうと我々で回復することはできません。IPのBANは一時的なものなので、ほとぼりが冷めるのを待つしかないようです。
数十分で回復する場合もあるようですが、私の場合は数時間は回復しませんでした。
（夜中に数時間色々試してうまくいかなかったが、翌日には正常に接続できていました）
まとめ
設定間違いには気を付けましょうね、というのと原因の絞り込みはやはりエラー内容に近いところからやった方が効率的です。