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


 

高橋 理香
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

発生している現象               
以下のエラーが発生して SQL Server に接続できない。
----------
System.Data.SqlClient.SqlException: SQL Server への接続を確立しているときにネットワーク関連またはインスタンス固有のエラーが発生しました。サーバーが見つからないかアクセスできません。インスタンス名が正しいこと、および SQL Server がリモート接続を許可するように構成されていることを確認してください。 (provider: 名前付きパイプ プロバイダ, error: 40 - SQL Server への接続を開けませんでした)
----------
このエラーはデバッグ実行で画面上に表示された。

現象発生環境の範囲
新規に用意した Windows 7 のマシンにアプリケーションを配置して実行した。
SQL Server は 2008 R2 で別の Windows Server 2008 R2 上で動作している。
以前に導入済みの他のクライアントについては正常動作している。
SQL Server はこの 1 つの既定インスタンスしかインストールしていない。               
               
再現性
新規のマシンでは一度も成功したことはない。

現象発生ユーザー状況
ユーザーによる違いはない。

具体的な操作内容
Visual Studio 2008 C# で開発した Windows フォーム アプリケーション。
SQL Server へのアクセスには System.Data.SqlClient を使用している。
SqlConnection.Open の個所でエラーとなる。

補足情報
SQL Server 構成マネージャーから、共有メモリプロトコルと TCP/IP の待ち受けが有効となっていることは確認済み。
また、TCP/IP のポート番号は 1500 と表示されていた。
Windows ファイアウォールは有効だが、 TCP ポート 1500 を例外として許可するよう設定されている。
SQL Server Browser サービスは開始している。
クライアントからサーバーへの telnet での接続も可能であることは確認した。

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

 

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


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

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

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

  • アプリケーション情報
    • エラーとなったツールの名前、アプリケーション開発で使用したテクノロジーがわかるようなソース ファイル等
    • 指定した接続先サーバー名、ユーザー名等の接続情報 (接続文字列) を含むスクリーンショットやファイル

  • 発生したエラー情報 (エラー番号、メッセージ、スタックトレース等) を含むスクリーンショットやログ ファイル
  • SQL Server エラーログ
    [SQL Troubleshooting] 第1回 : Tips - SQL Server エラーログとイベント ログを採取する (SQL 2000 ~ 2008 R2)
  •  

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

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

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

  • ping 実行結果
    • コマンドは以下の3つ。
      ping 接続先IPアドレス
      ping 接続先ホスト名
      ping -a 接続先IP アドレス

  • telnet 実行結果
    • コマンドは以下の2つ。
      telnet 接続先IPアドレス 待ち受けポート番号
      telnet 接続先ホスト名 待ち受けポート番号

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

      - プロトコル指定なし、Windows 認証で接続する

      sqlcmd –S 接続先SQLServer名 –E –m-1

      - プロトコル指定なし、SQL Server 認証で接続する

      sqlcmd –S 接続先SQLServer名 –U ログイン名 -P パスワード –m-1

      - TCP/IP、ポート 2500 に対して Windows 認証で接続する

      sqlcmd –S tcp:接続先SQLServer名,2500 –E –m-1

      - 名前付きパイプ、SQL Server 認証で接続する

      sqlcmd –S np:接続先SQLServer名 –U ログイン名 -P パスワード –m-1

      • ODBC アドミニストレーターでの接続テスト結果
      • ODBC アドミニストレーターを使って、sqlcmd ユーティリティの場合と同様に、接続先 SQL Server 名にプロトコルやポート番号を指定した場合や、認証方法を変更した場合に接続が可能かのテストが可能です。
        以下は ODBC アドミニストレーターでの接続手順です。(ODBC ドライバとして SQL Server Native Client 10.0 を使用した場合の例です。)

        1) odbcad32.exe を起動します。(WOW64 の場合には、%Windir%\SysWOW64\odbcad32.exe)
        2) [追加] ボタンをクリックすると、ODBC ドライバ選択の画面が表示されるので、使用したい ODBC ドライバを選択して [完了] します。(図では SQL Server Native Client 10.0 を選択しています。)
        image

        3) [名前] の欄には任意の名前を指定し、[サーバー] には接続先 SQL Server 名を指定して、[次へ] をクリックします。
        image

        4) 認証方法を選択して、[次へ] をクリックします。"SQL Server に接続して追加の構成オプションの既定設定を取得する" のチェックが入っている場合、ここで SQL Server へ接続します。
        image

        接続が成功すると、次のような画面が表示されます。失敗すると、エラーメッセージが表示されます。
        image

      • UDL ファイルを使用した接続テスト結果
      • UDL ファイル (データ リンク ファイル) を使用すると、OLE DB Provider を使って、sqlcmd ユーティリティの場合と同様に、接続先 SQL Server 名にプロトコルやポート番号を指定した場合や、認証方法を変更した場合に接続が可能かのテストが可能です。
        以下は UDL ファイルによる接続テスト手順です。(OLE DB Provider として SQL Server Native Client 10.0 を使用した場合の例です。)

        1) デスクトップ上の空いているところで右クリックし、[新規作成] - [テキスト ドキュメント] を選択します。
        image

        2) ファイル名を拡張子 .udl のついた任意の名前に変更し、右クリックで [プロパティ] を選択します。
        image

        3) [プロバイダー] ������で接続に使用する OLE DB プロバイダーを選択し、[接続] タブを表示します。
        image  image

        4) サーバー名に接続先 SQL Server 名を入力し、ログオンのための情報を選択、入力した後、データベースの選択はせずに [接続テスト] をクリックします。成功すると、次のメッセージが表示されます。失敗すると、エラーメッセージが表示されます。
        image

    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 のドライバー等の情報を確認します。
    採取のためのコマンドは以下の通りです。出力には少々時間がかかります。

    Windows Server 2003/Windows XP の場合:

      winmsd /report <システム情報出力パス>

    Windows Vista、Windows 7、Windows Server 2008、Windows Server 2008 R2 の場合:

      msinfo32 /report <システム情報出力ファイルパス>

    • 接続元でのポート利用状況確認 (netstat) 結果
    • TCP ポート枯渇による接続失敗等の可能性がないかを確認するのに役立ちます。コマンドは以下の通りです。           

      netstat –ano

      20秒間隔で実行した結果をファイルに書き出す場合には以下の通り。

      netstat –ano 20 > c:\temp\netstat.log

       

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



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

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

      2012-11-01 16:20:15.93 Server Microsoft SQL Server 2008 R2 (RTM) - 10.50.1600.1 (X64)
      Apr 2 2010 15:48:46
      Copyright (c) Microsoft Corporation
      Express Edition (64-bit) on Windows NT 6.1 <X64> (Build 7601: Service Pack 1)

      2012-11-01 16:20:15.96 Server (c) Microsoft Corporation.
      2012-11-01 16:20:15.96 Server All rights reserved.
      2012-11-01 16:20:15.96 Server Server process ID is 11728.
      2012-11-01 16:20:15.96 Server System Manufacturer: 'Hewlett-Packard', System Model: 'HP Compaq dc7800p Convertible Minitower'.

      SQL Serevr のバージョンは 10.50.1600.1 で Enterprise Edition x64 版であることがわかります。また、OS は 6.1 ですので、Windows 7 または Windows Server 2008 R2 で SP1 が適用されています。

      2012-11-01 16:20:15.96 Server Authentication mode is MIXED.
      2012-11-01 16:20:15.96 Server Logging SQL Server messages in file 'c:\Program Files\Microsoft SQL Server\MSSQL10_50.SQLEXPRESSR2\MSSQL\Log\ERRORLOG'.
      2012-11-01 16:20:15.99 Server This instance of SQL Server last reported using a process ID of 1932 at 2012/06/15 16:20:09 (local) 2012/06/15 7:20:09 (UTC). This is an informational message only; no user action is required.
      2012-11-01 16:20:15.99 Server Registry startup parameters:
      -d c:\Program Files\Microsoft SQL Server\MSSQL10_50.MSSQLServer\MSSQL\DATA\master.mdf
      -e c:\Program Files\Microsoft SQL Server\MSSQL10_50.MSSQLServer\MSSQL\Log\ERRORLOG
      -l c:\Program Files\Microsoft SQL Server\MSSQL10_50.MSSQLServer\MSSQL\DATA\mastlog.ldf
      2012-11-01 16:20:16.04 サーバー SQL Server is starting at normal priority base (=7). This is an informational message only. No user action is required.
      2012-11-01 16:20:16.04 サーバー Detected 2 CPUs. This is an informational message; no user action is required.
      2012-11-01 16:20:16.34 サーバー Using dynamic lock allocation. Initial allocation of 2500 Lock blocks and 5000 Lock Owner blocks per node. This is an informational message only. No user action is required.
      2012-11-01 16:20:16.89 サーバー Node configuration: node 0: CPU mask: 0x0000000000000003:0 Active CPU mask: 0x0000000000000003:0. This message provides a description of the NUMA configuration for this computer. This is an informational message only. No user action is required.
      2012-11-01 16:20:17.17 spid7s Starting up database 'master'.
      2012-11-01 16:20:17.37 spid7s Recovery is writing a checkpoint in database 'master' (1). This is an informational message only. No user action is required.
      2012-11-01 16:20:17.75 spid7s FILESTREAM: effective level = 0, configured level = 0, file system access share name = 'MSSQLServer'.
      2012-11-01 16:20:17.97 spid7s SQL Trace ID 1 was started by login "sa".
      2012-11-01 16:20:18.01 spid7s Starting up database 'mssqlsystemresource'.
      2012-11-01 16:20:18.06 spid7s The resource database build version is 10.50.1600. This is an informational message only. No user action is required.
      2012-11-01 16:20:18.33 spid10s Starting up database 'model'.

      認証モードは混合 (SQL Server 認証モードと Windows 認証モード) の設定です。

      2012-11-01 16:20:18.34 spid7s Server name is 'Server01'. This is an informational message only. No user action is required.
      2012-11-01 16:20:18.46 spid7s Starting up database 'msdb'.
      2012-11-01 16:20:19.08 spid10s Clearing tempdb database.
      2012-11-01 16:20:19.34 サーバー A self-generated certificate was successfully loaded for encryption.

      この SQL Server の名前は Server01 で既定インスタンスです。

      2012-11-01 16:20:19.62 サーバー Server is listening on [ 'any' <ipv6> 1500].
      2012-11-01 16:20:19.62 サーバー Server is listening on [ 'any' <ipv4> 1500].
      2012-11-01 16:20:19.64 サーバー Server local connection provider is ready to accept connection on [ \\.\pipe\SQLLocal\MSSQLServer ].
      2012-11-01 16:20:19.64 サーバー Server local connection provider is ready to accept connection on [ \\.\pipe\sql\query ].
      2012-11-01 16:20:19.64 サーバー Dedicated administrator connection support was not started because it is disabled on this edition of SQL Server. If you want to use a dedicated administrator connection, restart SQL Server using the trace flag 7806. This is an informational message only. No user action is required.

      TCP/IP については、ipv4 および ipv6 のいずれについても受信可能で、そのポート番号は 1500 です。

      名前付きパイプも既定の名前で待ち受けしています。

      2012-11-01 16:20:19.79 サーバー The SQL Server Network Interface library successfully registered the Service Principal Name (SPN) [ MSSQLSvc/Server01.domain01.com ] for the SQL Server service.
      2012-11-01 16:20:19.79 サーバー The SQL Server Network Interface library successfully registered the Service Principal Name (SPN) [ MSSQLSvc/Server01.domain01.com:1500 ] for the SQL Server service.

      Kerberos 認証を使用するために必要となる SPN も登録が成功しています。

      2012-11-01 16:20:19.80 サーバー SQL Server is now ready for client connections. This is an informational message; no user action is required.
      2012-11-01 16:20:20.24 spid10s Starting up database 'tempdb'.
      2012-11-01 16:20:20.50 spid13s The Service Broker protocol transport is disabled or not configured.
      2012-11-01 16:20:20.50 spid13s The Database Mirroring protocol transport is disabled or not configured.
      2012-11-01 16:20:20.58 spid13s Service Broker manager has started.
      2012-11-01 16:20:20.62 spid7s Recovery is complete. This is an informational message only. No user action is required.

      クライアントからの接続待ち受けが完了しています。

       

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

        • ping 実行結果
          • 正常に応答が得られる。
          • telnet 実行結果
            • 画面が黒くなる。つまり、接続は成功している。
            • いずれかの付属ツールを使用した Windows 認証/SQL Server 認証での接続テスト結果
              • sqlcmd コマンドユーティリティ

              C:\Windows\system32>sqlcmd -E -S Server01

              HResult 0x5、レベル 16、状態 1
              名前付きパイプのプロバイダー : SQL Server への接続を開けませんでした [5].
              Sqlcmd: エラー: Microsoft SQL Server Native Client 10.0: SQL Server への接続の確立中に、ネットワーク関連のエラーまたはインスタンス固有のエラーが発生しました。サーバーが見つからないか、アクセスできません。インスタンス名が正しいことと、SQL Server がリモート接続を許可するように構成されていることを確認してください。詳細については、SQL Server オンライン ブックを参照してください。。
              Sqlcmd: エラー: Microsoft SQL Server Native Client 10.0: ログイン タイムアウトが時間切れになりました。

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

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

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

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

                        キー名:              HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\MSSQLServer
                        クラス名:             <クラスなし>
                        最終書き込み時刻:  2012/06/19 - 14:57

                        キー名:              HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\MSSQLServer\Client
                        クラス名:             <クラスなし>
                        最終書き込み時刻:  2012/11/01 - 11:30
                        値 0
                          名前:            SharedMemoryOn
                          種類:            REG_DWORD
                          データ:            0

                        キー名:              HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\MSSQLServer\Client\ConnectTo
                        クラス名:             <クラスなし>
                        最終書き込み時刻:  2012/11/01 - 12:02
                        値 0
                          名前:            Server01
                          種類:            REG_SZ
                          データ:            DBMSSOCN,Server01,1500

                        Server01 に対して TCP/IP で (DBMSSOCN)、ポート番号 1500 で接続するための別名 Server01 が作成されています。

                            • エラー発生環境 (抜粋)

                            キー名:              HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\MSSQLServer
                            クラス名:             <クラスなし>
                            最終書き込み時刻:  2012/06/19 - 14:57

                            キー名:              HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\MSSQLServer\Client
                            クラス名:             <クラスなし>
                            最終書き込み時刻:  2012/11/01 - 11:30
                            値 0
                              名前:            SharedMemoryOn
                              種類:            REG_DWORD
                              データ:            0

                            キー名:              HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\MSSQLServer\Client\ConnectTo
                            クラス名:             <クラスなし>
                            最終書き込み時刻:  2012/09/05 - 9:45

                            正常に接続できる環境とは異なり、別名の設定はありません。

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

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

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

                            Frame Number Time And Date Source Destination Protocol Name Description
                            112 12:17:38 2012/11/01 192.168.1.100 192.168.1.200 TCP TCP:Flags=......S., SrcPort=39025, DstPort=1433, PayloadLen=0, Seq=207727522, Ack=0, Win=8192 ( Negotiating scale factor 0x8 ) = 8192 {TCP:71, IPv4:70}
                            572 12:17:41 2012/11/01 192.168.1.100 192.168.1.200 TCP TCP:[SynReTransmit #112]Flags=......S., SrcPort=39025, DstPort=1433, PayloadLen=0, Seq=207727522, Ack=0, Win=8192 ( Negotiating scale factor 0x8 ) = 8192 {TCP:71, IPv4:70}
                            1057 12:17:47 2012/11/01 192.168.1.100 192.168.1.200 TCP TCP:[SynReTransmit #112]Flags=......S., SrcPort=39025, DstPort=1433, PayloadLen=0, Seq=207727522, Ack=0, Win=65535 ( Negotiating scale factor 0x8 ) = 65535 {TCP:71, IPv4:70}

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

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

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

                                     

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

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

                            Event Name, Clock-Time, 

                            System.Data, 129963234805588042, "<prov.DbConnectionHelper.ConnectionString_Set|API> 1#, 'Data Source=Server01;Initial Catalog=testdb;Integrated Security=SSPI;' "
                            System.Data, 129963234805597716, "enter_01 <sc.SqlConnection.Open|API> 1# "

                            System.Data, 129963234805686434, "<prov.DbConnectionPool.
                            TransactedConnectionPool.TransactedConnectionPool|RES|CPOOL> 1#, Constructed for connection pool 1# "
                            System.Data, 129963234805686469, "<prov.DbConnectionPool.DbConnectionPool|RES|CPOOL> 1#, Constructed. "
                            System.Data, 129963234805686600, "<prov.DbConnectionPool.Startup|RES|INFO|CPOOL> 1#, CleanupWait=190000 "
                            System.Data, 129963234806527032, "<prov.DbConnectionPool.GetConnection|RES|CPOOL> 1#, Getting connection. "
                            System.Data, 129963234807420624, "<prov.DbConnectionPool.GetConnection|RES|CPOOL> 1#, Creating new connection. "
                            System.Data, 129963234807420866, "<prov.DbConnectionPool.ReclaimEmancipatedObjects|RES|CPOOL> 1# "
                            System.Data, 129963234807421659, "<sc.SqlInternalConnectionTds.LoginNoFailover|ADV> 4#, host=Server01"

                            指定した接続文字列


                            接続処理開始

                            System.Data, 129963234807917653, "<sc.TdsParser.Connect|SEC> SSPI authentication "
                            System.Data.SNI, 129963234807918234, "enter_02 <SNIOpenSyncEx|API|SNI> pConsumerInfo: 00000000002CD638, wszConnect: 'Server01', ppConn: 00000000002CD630, fIntSec: 1{BOOL}, cbBuffer: 65791, pBuffer: 0000000002901A80, pInstanceName: 0000000002911C10, fOverrideCache: 0{BOOL}, fSync: 1{BOOL}, timeout: -1 "

                             

                            System.Data.SNI, 129963234807918411, "enter_03 <ConnectParameter::ParseConnectionString|API|SNI> szConnect: 'Server01' "
                            System.Data.SNI, 129963234807918915, "<ConnectParameter::ParseConnectionString|SNI> m_szProtocolName: '', m_szServerName: 'server01', m_szInstanceName: '', m_szProtocolParameter: '', m_szAlias: 'server01', m_fCanUseCache: 0{bool} "

                            接続文字列の解析

                            System.Data.SNI, 129963234807920051, "enter_03 <Connect|API|SNI> pConsumerInfo: 00000000002CD638, pProtElem: 0000000000B59260, ppConn: 00000000002CD630, fIntSec: 1{BOOL}, cbBuffer: 65791, pBuffer: 0000000002901A80, fSync: 1{BOOL}, timeout: -1 "

                             

                            System.Data.SNI, 129963234807920809, "enter_05 <Tcp::Open|API|SNI> pConn: 0000000000B59AA0{SNI_Conn*}, pProtElem: 0000000000B59260{ProtElem}, ppProv: 00000000002CC7B8{SNI_Provider**}, timeout: -1 "
                            System.Data.SNI, 129963234807920863, "ObtainIDa 2# <Tcp::Tcp|ID|SNI> 0000000000B59C00{.} created by 1#{SNI_Conn}"
                            System.Data.SNI, 129963234807920913, "enter_06 <Tcp::FInit|API|SNI> 2# "
                            System.Data.SNI, 129963234807920944, "<Tcp::FInit|RET|SNI> 0{WINERR} "
                            System.Data.SNI, 129963234807920956, "leave_06 "
                            System.Data.SNI, 129963234808086531, "enter_06 <Tcp::SocketOpenSync|API|SNI> AI: 000000001C4D9900{ADDRINFO*}, ai_family: 2, event: FFFFFFFFFFFFFFFF{HANDLE}, timeout: -1 "

                            TCP/IP による通信のための処理開始              
                                          
                                             

                                              
                                              
                                             

                            System.Data.SNI, 129963235018256483, "<Tcp::SocketOpenSync|RET|SNI> 10060{WINERR} "
                            System.Data.SNI, 129963235018256513, "leave_06 "
                            System.Data.SNI, 129963235018256594, "enter_06 <Tcp::SocketOpenSync|API|SNI> AI: 000000001C4D9880{ADDRINFO*}, ai_family: 23, event: FFFFFFFFFFFFFFFF{HANDLE}, timeout: -1 "
                            System.Data.SNI, 129963235228544667, "<Tcp::SocketOpenSync|RET|SNI> 10060{WINERR} "
                            System.Data.SNI, 129963235228544694, "leave_06 "
                            System.Data.SNI, 129963235228544775, "enter_06 <Tcp::SocketOpenSync|API|SNI> AI: 000000001C4D98C0{ADDRINFO*}, ai_family: 23, event: FFFFFFFFFFFFFFFF{HANDLE}, timeout: -1 "
                            System.Data.SNI, 129963235438833102, "<Tcp::SocketOpenSync|RET|SNI> 10060{WINERR} "
                            System.Data.SNI, 129963235438833129, "leave_06 "

                            通信の結果はエラーコード 10060 (WSAETIMEDOUT)

                            System.Data.SNI, 129963235438833233, "<Tcp::Open|ERR|SNI> ProviderNum: 7{ProviderNum}, SNIError: 0{SNIError}, NativeError: 10060{WINERR} "
                            System.Data.SNI, 129963235438833283, "RecycleIDa 2# <Tcp::~Tcp|ID|SNI> "
                            System.Data.SNI, 129963235438833437, "<Tcp::Open|RET|SNI> 10060{WINERR} "

                            TCP/IP による通信を 10060 のエラーコードで処理終了。

                            System.Data.SNI, 129963235438833753, "enter_03 <Connect|API|SNI> pConsumerInfo: 00000000002CD638, pProtElem: 0000000000B59680, ppConn: 00000000002CD630, fIntSec: 1{BOOL}, cbBuffer: 65791, pBuffer: 0000000002901A80, fSync: 1{BOOL}, timeout: -1 "

                             

                            System.Data.SNI, 129963235438834469, "enter_05 <Np::Open|API|SNI> pConn: 0000000000B59AA0{SNI_Conn*}, pProtElem: 0000000000B59680{ProtElem*}, ppProv: 00000000002CC7B8{SNI_Provider**} "
                            System.Data.SNI, 129963235438834526, "ObtainIDa 4# <Np::Np|ID|SNI> 0000000000B59C00{.} created by 3#{SNI_Conn}"
                            System.Data.SNI, 129963235438834549, "enter_06 <Np::FInit|API|SNI> 4# "
                            System.Data.SNI, 129963235438834584, "<Np::FInit|RET|SNI> 0{WINERR} "
                            System.Data.SNI, 129963235438834596, "leave_06 "
                            System.Data.SNI, 129963235438834642, "enter_06 <Np::OpenPipe|API|SNI> 4#, szPipeName: '\\server01\PIPE\sql\query', dwTimeout: 5000 "
                                 

                            プロトコルを名前つきパイプに切り替えての接続試行開始。

                            System.Data.SNI, 129963235438937041, "<Np::OpenPipe|ERR|SNI> ProviderNum: 1{ProviderNum}, SNIError: 40{SNIError}, NativeError: 5{WINERR} "
                            System.Data.SNI, 129963235438937076, "<Np::OpenPipe|RET|SNI> 5{WINERR} "

                            System.Data.SNI, 129963235438937095, "leave_06 "
                            System.Data.SNI, 129963235438937187, "RecycleIDa 4# <Np::~Np|ID|SNI> "
                            System.Data.SNI, 129963235438937249, "<Np::Open|RET|SNI> 5{WINERR} "

                            名前付きパイプによる接続試行はエラー コード 5 で失敗。

                            System.Data, 129963235439806503, "<sc.SqlError.SqlError|ERR> infoNumber=5, errorState=0, errorClass=20, errorMessage='SQL Server への接続を確立しているときにネットワーク関連またはインスタンス固有のエラーが発生しました。サーバーが見つからないかアクセスできません。インスタンス名が正しいこと、および SQL Server がリモート接続を許可するように構成されていることを確認してください。 (provider: 名前付きパイプ プロバイダ, error: 40 - SQL Server への接続を開けませんでした)', procedure='None', lineNumber=0 "
                            System.Data, 129963235439897488, "<sc.TdsParserStateObject.DecrementPendingCallbacks|ADV> 1#, after decrementing _pendingCallbacks: 0 "
                            System.Data, 129963235439897523, "<sc.TdsParser.Connect|ERR|SEC> Login failure "
                            System.Data, 129963235441072408, "<sc.SqlInternalConnectionTds.LoginFailure|RES|CPOOL> 4# "

                            名前つきパイプによる通信も失敗したので、この結果を踏まえてのエラーメッセージ

                              上記からは、接続先として指定した接続文字列の内容や、使用したプロトコル、通信の結果としてのエラーコードやメッセージがわかります。もしも、実行しているアプリケーションがどのような 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.1343971    WinSQLConNDP2CS.exe    9400    RegOpenKey    HKLM\SOFTWARE\Microsoft\MSSQLServer\Client\ConnectTo    SUCCESS    Desired Access: Read
                              19:46:16.1344333    WinSQLConNDP2CS.exe    9400    RegQueryValue    HKLM\SOFTWARE\Microsoft\MSSQLServer\Client\ConnectTo\Server01    SUCCESS    Type: REG_SZ, Length: 58, Data: DBMSSOCN,Server01,1500
                              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.2226684    WinSQLConNDP2CS.exe    9400    RegQueryKey    HKLM    SUCCESS    Query: HandleTags, HandleTags: 0x0
                                19:36:33.2227049    WinSQLConNDP2CS.exe    9400    RegOpenKey    HKLM\SOFTWARE\Microsoft\MSSQLServer\Client\ConnectTo    SUCCESS    Desired Access: Read
                                19:36:33.2227642    WinSQLConNDP2CS.exe    9400    RegQueryValue    HKLM\SOFTWARE\Microsoft\MSSQLServer\Client\ConnectTo\Server01    NAME NOT FOUND    Length: 144
                                19:36:33.2228073    WinSQLConNDP2CS.exe    9400    RegCloseKey    HKLM\SOFTWARE\Microsoft\MSSQLServer\Client\ConnectTo    SUCCESS
                                   

                                別名 Server01 を検索したが見つからなかった。

                                19:36:36.2773011    WinSQLConNDP2CS.exe    9400    TCP Reconnect    Client01.domain01.com:34017 -> Server01.domain01.com:ms-sql-s    SUCCESS    Length: 0, seqnum: 0, connid: 0
                                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

                                TCP/IP で Server01 の ms-sql-s つまりポート 1433 に接続試行。

                                19:37:36.3351328    WinSQLConNDP2CS.exe    9400    CreateFile    \\server01\PIPE\sql\query    ACCESS DENIED    Desired Access: Generic Read/Write, Disposition: Open, Options: Non-Directory File, Attributes: N, ShareMode: None, AllocationSize: n/a

                                名前つきパイプで既定のパイプに接続試行したがアクセスが拒否された。

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

                                   

                                   

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

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



                                  過去の Troubleshooting Connectivity シリーズはこちら。clip_image001

                                   Troubleshooting Connectivity #1 - SQL Server への接続

                                   Troubleshooting Connectivity #2 - エラー情報からわかる失敗原因

                                   Troubleshooting Connectivity #3 - 予期しない接続切断

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

                                   Troubleshooting Connectivity #5 - セッション確立までの動作

                                   Troubleshooting Connectivity #6 - 接続タイムアウトは悪なのか?

                                   Troubleshooting Connectivity #7 - 接続タイムアウトエラーまでの時間は?

                                  Comments (1)

                                  1. Microsoft Japan SQL Server Support Team より:

                                    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

                                  Skip to main content