none
Troubleshooting Connectivity #4 – 接続エラーの調査方法 (後編) RRS feed

  • Question

    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, Dis"top" width="127">名前つきパイプで既定のパイプに接続試行したがアクセスが拒否された。

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

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

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

    Monday, April 8, 2019 4:10 AM
    Owner