Troubleshooting Connectivity #4 - 接続エラーの調査方法

11/09/2012

高橋理香
SQL Developer Support Escalation Engineer

こんにちは。

SQL Server への接続シリーズも今回で 4 回目となりました。だいぶ時間空いてますけど、その点はご容赦ください。。。

それでも、少しでも、読んでくださっている皆さんのお役に立っているといいなと思う今日この頃です。

Troubleshooting Connectivity #1 - SQL Server への接続
 Troubleshooting Connectivity #2 - エラー情報からわかる失敗原因
 Troubleshooting Connectivity #3 - 予期しない接続切断

さて今回は、これまでの Troubleshooting ではなんとかならなかった、もしくは、きちんと裏を取ってから対処を行いたい、という場合にどんな情報を採取したらよいかについてご紹介したいと思います。また、実際のログなどを例に調査ポイントを説明します。

1. SQL Server への接続失敗についてまず確認すること

基本的には一般的なトラブルシューティングの場合と同様に 5W1H で考えてみましょう。

ログ採取は時には負荷を伴う場合もありますので、そういった場合には、これらの情報を頼りに、採取すべき情報の最小化を検討することになります。

WHAT (発生している現象) :

どのようなエラーが発生するか。もしくは、何を見て接続の問題と判断したか。

WHERE (現象発生環境の範囲) :

ツールやアプリケーションをどこで実行しているか。(SQL Server が動作しているサーバー上か、それとも、リモートのクライアントか。)
クライアントも複数存在する場合にはそれら全部かそれとも一部のみか。
SQL Server のインスタンスやサーバーが複数ある場合にはそれらのすべてに対してかそれとも一部のみか。

WHEN (再現性) :

問題のツールやアプリケーションを使用する場合には常にエラーとなるか。それとも時々発生するか。
使い始めた以降で成功していたことはあるか。今まで問題なかったとしたら、いつから問題が出るようになったか。

WHO (現象発生ユーザー状況) :

接続しようとしているユーザーによる違いはあるか。(接続試行するアプリケーションを実行しているユーザーや、SQL Server への認証に使用するユーザー)

HOW (具体的な操作内容) :

どのような処理を行った場合に接続エラーが発生するか。(エラーが発生したツール、アプリケーションにおける操作内容等。また、一方で、接続が成功するツールやアプリケーションはあるか。SQL Server 付属の Management Studio、Visual Studio で開発した System.Data.SqlClient を使用するアプリケーション、など)
開発アプリケーションの場合には、アプリケーションのどのような処理でエラーになるか。(SqlConnection.Open の処理でエラーとなる、など)

また、上記に加えて、補足となるような情報もあるはずですので、その内容も押さえます。

EXTEND (補足情報) :

エラー発生前に実施した作業内容
エラー発生後に試した作業内容

例えば上記に沿って接続失敗の情報を収集した例は以下の通りです。

※例1

実は上記の情報があれば、すでに原因と対処はお伝えできるレベルなのですが、��降では、これを情報採取しながら調査することを考えてみましょう。

2. SQL Server への接続失敗についての調査で参考となる情報にはどのようなものがあるか

2-1. 確実にいただきたい情報

接続エラーについての調査では、様々なログやトレースを使用することができます。

どのようなパターンにおいてもまずご用意いただきたいのが、以下の情報です。

アプリケーション情報
- エラーとなったツールの名前、アプリケーション開発で使用したテクノロジーがわかるようなソースファイル等
- 指定した接続先サーバー名、ユーザー名等の接続情報 (接続文字列) を含むスクリーンショットやファイル
発生したエラー情報 (エラー番号、メッセージ、スタックトレース等) を含むスクリーンショットやログファイル
SQL Server エラーログ
[SQL Troubleshooting] 第1回 : Tips - SQL Server エラーログとイベントログを採取する (SQL 2000 ～ 2008 R2)

特に、先のブログや先の WHAT でも記載しましたが、何はなくともエラー情報の確認 が必要です。時々、「エラーは表示されたけど忘れた」といったことを伺うこともありますが、本当に、本当に、なんとかして取得をお願いします。画面のスクリーンショットを取ってメールに貼り付けるなどの方法でも十分です。

2-2. 再現性がある場合に、切り分けのために実施いただきたい接続テスト

引き続き接続が失敗している状況 (再現性のある状況) では、以下のような検証を行った結果も問題個所を特定するための切り分け情報として参考となります。

ping 実行結果

telnet 実行結果

いずれかの付属ツールを使用した Windows 認証/SQL Server 認証での接続テスト結果

sqlcmd ユーティリティでの接続テスト結果
SQL Server への接続、クエリの実行等で使用されるコマンドラインユーティリティです。SQL Server や付属のツールがインストールされている環境で使用可能です。このユーティリティを使用して、プロトコルを明示的に指定した接続、認証方法を変更しての接続のテスト等が可能です。ツールの詳細については、sqlcmd ユーティリティのページをご覧ください。

ODBC アドミニストレーターでの接続テスト結果
UDL ファイルを使用した接続テスト結果

2-3. 接続エラーについて調査する際に採取できるトレースやログ

上記以外では、以下のような情報が調査する上で参考となります。

接続関連のレジストリ情報

プロトコルの優先順位、別名の設定などを確認するのに役立ちます。
この情報は、エラー発生環境と、正常に接続可能な環境があればその両方で採取します。

参照レジストリは以下の通りです。

32 bit 環境
[HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\MSSQLServer]

64bit 環境
[HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\MSSQLServer]
および
[HKEY_LOCAL_MACHINE\SOFTWARE\Wow6432Node\Microsoft\MSSQLServer]

接続元と接続先の両端で採取したネットワークトレース

クライアントから送信した接続要求が SQL Serer まで到達しているかどうかなど、通信経緯を把握するのに役立ちます。
採取方法については、他チームですが、ブログにて紹介しているのでそちらをご覧ください。

ご存じですか、Microsoft Network Monitor はコマンドラインでも操作できます

接続元で採取した BID トレース

データアクセスコンポーネント (ADO.NET、ODBC、OLE DB 等) のデバッグログを取得するためトレース機能です。ネットワークトレースでは把握できないアプリケーション側での処理経緯を把握するのに役立ちます。採取方法等については、以下のブログにて紹介しているのでそちらをご覧ください。

HowTo: BID トレース - データアクセスアプリケーションのトレースを採取する

接続元で採取した Process Monitor トレース

ファイルやレジストリへのアクセスをトレースするためのツールです。これにより、レジストリに格納されている情報をどのように読み取っているかなどを把握することができます。ツールの入手、ならびに、使用方法等については Process Monitor のページでご覧ください。

接続先で採取したパフォーマンスログ

接続の問題は、接続元、ネットワーク、接続先等、通信経路上の各所における負荷に起因して発生することが多いので、パフォーマンス監視も有効です。これは平常時に採取しておき、エラー時との比較をすることに意味があります。

[SQL Troubleshooting] 第2回 : Tips -パフォーマンスログの採取方法 (Windows Server 2003 ～ Windows Server 2008 R2)

SQL Server で採取したサーバートレース

SQL Server へのクエリ実行経緯を把握する必要がある場合に役立ちます。

SQL トレーススクリプトの作成、実行 (SQL Server 2005, 2008, 2008 R2)

イベントログ (サーバー側のシステム、セキュリティ、アプリケーション)

OS やサービスの再起動の状況、ハードウェアに関連したエラー等、対象マシン全体の状態を把握するために確認します。

[SQL Troubleshooting] 第1回 : Tips - SQL Server エラーログとイベントログを採取する (SQL 2000 ～ 2008 R2)

システム情報

サービスの状態、起動アカウント、NIC のドライバー等の情報を確認します。
採取のためのコマンドは以下の通りです。出力には少々時間がかかります。

接続元でのポート利用状況確認 (netstat) 結果

3. 採取した情報からどのようなことがわかるか

先の例1 の場合について調査してみましょう。

まず、エラー情報はありますので、次に SQL Server のエラーログをメモ帳で開いてみます。
この内容から、先にまとめられた確認事項を裏付ける情報を確認でき、また、特にエラーなどは発生していないために、サーバーとしては接続が可能な状態となっていると判断できます。

では次に、今回は問題の環境では常に接続が失敗していますので、切り分け検証を行ってみます。
その結果から、アプリケーション独自の問題ではなく、このクライアント環境から SQL Server への接続が失敗する状況であると判断できます。

ping 実行結果
- 正常に応答が得られる。

telnet 実行結果
- 画面が黒くなる。つまり、接続は成功している。

いずれかの付属ツールを使用した Windows 認証/SQL Server 認証での接続テスト結果
- sqlcmd コマンドユーティリティ

ODBC アドミニストレーターでの接続テスト結果

UDL ファイルを使用した接続テスト結果

では、このクライアントのみで問題が発生するのはなぜなのか、他の情報を採取して確認してみましょう。

接続関連のレジストリ情報 (HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\MSSQLServer)
- 正常に接続可能な環境 (抜粋)

エラー発生環境 (抜粋)

上記のレジストリ設定の情報から、エラーの原因は別名が作成されていないことであり、正常に接続できる環境と同じ設定で別名を作成することで、対処となる可能性が高いことがわかります。

では、なぜ別名が作成されていないとエラーとなるのかについて引き続き情報採取によって確認してみましょう。

接続元と接続先の両端で採取したネットワークトレース
- エラー発生環境 - 接続元 (抜粋)

上記から、接続先サーバーにポート 1433 でアクセスしようとしており (SYN パケットの送信)、さらに、その再転送 (Retransmission) が初回から 3秒後、2回目から 6 秒後と、2 回行われていることを確認できます。これは TCP/IP での接続時の再転送の既定のタイムアウト時間に沿った動作であり、2回目の送信から 12 秒は待って接続試行は終了します。

この内容から、SQL Server が本来待ち受けている TCP ポート 1500 ではなく、既定インスタンスの既定の待ち受けポート番号 1433 へのアクセスを行っているために接続が失敗したと判断できます。また、接続成功のためには、クライアントで 1500 という番号を渡すようにしなければならないことがわかります。これが別名を作成しなければならない理由です。

なお、もしも待ち受けは 1433 で間違いない場合には、接続先サーバーでもネットワークトレースを採取することで、上記のパケットが到着しているかどうかを確認しましょう。到着していなければネットワーク中継機器を疑い、到着しているならば遅延の可能性を疑うことができます。

さて、上記で原因と対処はわかりましたので他の情報はこの時点で採取する必要はないのですが、動作についての説明のために、BID トレースと Process Monitor トレースについても見てみましょう。

接続元で採取した BID トレース
- エラー発生環境 (抜粋 - 列もフィルタしたもの)

上記からは、接続先として指定した接続文字列の内容や、使用したプロトコル、通信の結果としてのエラーコードやメッセージがわかります。もしも、実行しているアプリケーションがどのような API を使用して接続しようとしているのかがわからない場合や、アプリケーションが本来のエラーメッセージをラップしているような場合には、このトレースを採取することで概ね把握することもできる可能性があるといえます。

なお、上記の Clock-Time はシステムの時刻です。パフォーマンスの問題などの場合には、各ステップの差分からどの処理に時間を要していたのかを把握できます。今回の例では Tcp::SocketOpenSync の処理で約 21秒 (210169952) の差分があります。先の通り、TCP/IP の場合には 2回の Retransmission でタイムアウトする時間は 21 秒ですので、それとほぼ一致しています

なお、以下のような方法で日付時刻のフォーマットに変換できます。

String clocktime = Console.ReadLine();
long l = long.Parse(clocktime);
DateTime dt = DateTime.FromFileTime(l);
Console.WriteLine(dt.ToString("yyyy/MM/dd HH:mm:ss.fffffff"));

接続元で採取した Process Monitor トレース
- 正常に接続可能な環境 (抜粋)

19:46:16.1344599 WinSQLConNDP2CS.exe 9400 RegQueryValue HKLM\SOFTWARE\Microsoft\MSSQLServer\Client\ConnectTo\Server01 SUCCESS Type: REG_SZ, Length: 58, Data: DBMSSOCN,Server01,1500
19:46:16.1344922 WinSQLConNDP2CS.exe 9400 RegCloseKey HKLM\SOFTWARE\Microsoft\MSSQLServer\Client\ConnectTo SUCCESS

別名 Server01 が検索で見つかり、そのプロトコルは TCP/IP (DBMSSOCN) で、ポート番号は 1500 であることを確認している。

エラー発生環境 (抜粋)

19:36:33.2228073 WinSQLConNDP2CS.exe 9400 RegCloseKey HKLM\SOFTWARE\Microsoft\MSSQLServer\Client\ConnectTo SUCCESS
19:36:42.2833091 WinSQLConNDP2CS.exe 9400 TCP Reconnect Client01.domain01.com:34017 -> Server01.domain01.com:ms-sql-s SUCCESS Length: 0, seqnum: 0, connid: 0 19:36:57.2905622 WinSQLConNDP2CS.exe 9400 TCP Reconnect Client01.domain01.com:34021 -> Server01:ms-sql-s SUCCESS Length: 0, seqnum: 0, connid: 0

上記からは、最初に別名を検索していることを確認できます。また、成功する環境では別名から接続先の待ち受けポートが 1500 であることを検知しています。一方でエラーとなる環境では、別名は存在しないため、既定の待ち受けポートである 1433 への TCP/IP でのアクセス、ならびに、名前付きパイプでの接続試行を行って失敗しています。Process Monitor を使用することで、レジストリやファイルアクセスを確認できますので、クライアントによって動作が異なるような場合にはその比較のための資料として活用できます。

今回の情報採取に関しては以上です。

次回は、上記でも出てきた別名など、接続試行するまでにどのようなアクセスが行われるか、特に名前付きインスタンスの場合を中心にご紹介する予定です。

Comments

Anonymous
August 29, 2013
Troubleshooting Connectivity #1 - SQL Server への接続 blogs.msdn.com/.../troubleshooting-connectivity-1-sql-server.aspx Troubleshooting Connectivity #2 - エラー情報からわかる失敗原因 blogs.msdn.com/.../troubleshooting-connectivity-2.aspx Troubleshooting Connectivity #3 - 予期しない接続切断 blogs.msdn.com/.../troubleshooting-connectivity-3.aspx Troubleshooting Connectivity #5 - セッション確立までの動作 blogs.msdn.com/.../troubleshooting-connectivity-5.aspx Troubleshooting Connectivity #6 - 接続タイムアウトは悪なのか？ blogs.msdn.com/.../troubleshooting-connectivity-6.aspx