none
DFSRの複製の仕組みを理解する(後編)- Part 1 - RRS feed

  • 全般的な情報交換

  • こんにちは。Windows Commercial Support Directory Services チームです。

    に引き続き、今回は DFSR のデバッグログを確認しながら複製の仕組みを見て行きたいと思います。

    用意するもの

    • レプリケーショングループに参加している各サーバーで採取した DFSR のデバッグログ
    • GZip 形式が展開できる圧縮・解凍用のツール     
    • 使い慣れたテキストエディタ     
    • レプリケーショングループの構成情報     
    • 追跡したいファイルの更新が行われた日時の情報     
    • 追跡したいファイルの、ファイルサーバーのローカル上でのフルパスの情報     
    • 前日の十分な睡眠     

    以前のポでもご紹介したとおり、DFSRのデバッグログは最新の世代以外のものは、GZip 形式で圧縮されております。そのため、あらかじめ展開用のツールで圧縮を解除しておく必要があります。

    また、DFSR のデバッグログは出力量が膨大です。検索をいかに効率よく行えるかが、デバッグログ解析の効率をも左右すると言っても過言ではありません。是非、使い慣れたエディタを用意下さい。さらに、デバッグログの解析に着手する前に、事前に少しでも追跡したい動作の内容を把握しておくことが重要になります。

    最後の項目は、私個人がデバッグログの解析を行う際に心がけていることですが… Windows が出力する各種のデバッグログの中でも、DFSR は内容が難解なもののひとつとして数えられています。集中力を切らさないように、がんばりましょう!

     

    デバッグログの出力形式

    では、まずは DFSR のデバッグログがどのような形式で出力されるのかを確認してみましょう。

    デバッグログのヘッダ

    各世代のデバッグログの冒頭には、デバッグログのヘッダが書き込まれます。

    例:

    * FRS Log Sequence:1 Index:1 Computer:2003MEM20 TimeZone:Eastern Standard Time (GMT-05:00) Build:[Feb 16 2007 20:14:20 built by: srv03_sp2_rtm] Enterprise=1 * Configuration logLevel:4 maxEntryCount:200000 maxFileCount:100 logPath:\\.\C:\WINDOWS\debug\

    各フィールドの意味は以下のとおりとなります。

    フィールド

    説明

    FRS Log Sequence & Index

    DFSR の循環ログの中の、何循環目の何世代目のログであるかを示します。

    Computer

    デバッグログが記録されたコンピュータ名が記録されます。

    TimeZone

    タイムゾーンとGMTからの時差が記録されます。

    Build

    OSのバージョンが記録されます。

    Configuration loglevel

    ログの出力レベルが記録されます。

    Maxentrycount

    1世代のデバッグログで出力できるエントリ数が記録されます。

    Maxfilecount

    循環ログを構成する世代数が記録されます。

    Logpath

    デバッグログの出力パスが記録されます。

     

    メッセージ

    解析の主な対象となるログエントリです。

    例:

    20080111 15:12:30.996 3876 JOIN 1171 Join::SubmitUpdate Sent: uid:{AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v33846 gvsn:{AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v33846 name:USRSTAT.EXE connId:{CC694D38-7E97-467C-A963-B3D9B6E308B9} csId:{1697E5EB-BBD0-45B7-AC2F-11EBE7B3FD47} csName:dfsrprestaged

    以下のようなフィールドで構成されています。

    フィールド

    説明

    上記の例での該当箇所

    日時

    ローカル時刻でのタイムスタンプです。   形式は YYYYMMDD HH:MM:SS:MS です。

    20080111 15:12:30.996

    スレッド

    DFSR.EXE Windows Server 2008 以降では DFSRS.EXE)上のスレッド番号です。

    3876

    モジュールID

    DFSR 内のサブコンポーネントの名称です。

    JOIN

    行番号

    ソースコード上の行番号です。

    1171

    クラス名

    処理が行われたクラス名です。

    Join

    メソッド名

    処理が行われたメソッドまたは関数の名称です。

    SubmitUpdate

    データ

    ログで出力される情報の部分です。

    Sent: uid:{AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v33846   gvsn:{AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v33846 name:USRSTAT.EXE   connId:{CC694D38-7E97-467C-A963-B3D9B6E308B9}   csId:{1697E5EB-BBD0-45B7-AC2F-11EBE7B3FD47} csName:dfsrprestaged

     

    データの部分が複数行に及ぶ場合、行頭に + を出力することで、ひとつのエントリであることが示されます。

    例:

    20080111 11:44:28.873 1640 INCO 4378 InConnection::UpdateProcessed Received Update. updatesnbsp;   present 1 +    nameConflict 0 +    attributes 0x10 +    gvsn {AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v29102 +    uid {AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v29102 +    parent {AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v28024 +    fence 16010101 00:00:00.000 P +    clock 20080110 19:05:43.167 +    createTime 20080110 19:05:43.157 GMT +    csId {1697E5EB-BBD0-45B7-AC2F-11EBE7B3FD47} +    hash 37123A73-30C1AFF0-B4EE5252-46212327 +    similarity 00000000-00000000-00000000-00000000 +    name acctsid

     

    お気づきかもしれませんが、DFSR のデバッグログには GUID 形式で表示される情報がかなり頻繁に出てきます。このあたりが DFSR のデバッグログが難しいとされる一因となっているような気がします…

     

    ファイルの更新USNC を捕まえる

    DFSR のファイル更新検出の仕組みは、USN ジャーナルの監視に依存していることを前回お話いたしました。実際には DFSR USNC (USN Consumer) というモジュールが、USN ジャーナルの更新を検出する役割を担っています。デバッグログからファイルの更新と複製処理を追跡する場合、USNC のログエントリを特定することが出発点となります。例えば、testfile.txt というファイルをレプリケートフォルダの直下に新規作成すると、以下のようなデバッグログが出力されます。

    20100622 13:37:18.280 1956 USNC  2640   UsnConsumer::CreateNewRecord LDB Inserting ID Record: +      fid                               0x20000000043FB +      usn                               0x41dcd68 +    uidVisible                        0 +      filtered                          0 +      journalWrapped                    0 +    slowRecoverCheck                  0 +      pendingTombstone                  0 +    internalUpdate                    0 +      dirtyShutdownMismatch             0 +      meetInstallUpdate                 0 +      meetReanimated                    0 +      recUpdateTime                     16010101 00:00:00.000 GMT +      present                           1 +      nameConflict                      0 +      attributes                        0x20 +      ghostedHeader                     0 +      data                              0 +      gvsn                              {9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13   +      uid                               {9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13   +    parent                            {7BD16799-5FAA-4B72-9B04-82807A6832BF}-v1   +      fence                             16010101 00:00:00.000 +    clockDecrementedInDirtyShutdown 0   +      clock                             20100622 04:37:18.280 GMT (0x1cb11c498ab11c6) +    createTime                        20100622 04:37:18.280 GMT +      csId                              {7BD16799-5FAA-4B72-9B04-82807A6832BF} +      hash                              00000000-00000000-00000000-00000000 +      similarity                        00000000-00000000-00000000-00000000 +      name                              testfile.txt +   

    20100622 13:37:18.280 1956 USNC  2643   UsnConsumer::CreateNewRecord ID record created from USN_RECORD:   +    USN_RECORD: +      RecordLength:        88   +    MajorVersion:        2   +    MinorVersion:        0   +    FileRefNumber:       0x20000000043FB +      ParentFileRefNumber: 0x20000000042DE +      USN:                   0x41dcd68 +      TimeStamp:             20100622 13:37:18.280 東京 (標準時) +      Reason:                Close Data Extend File Create   +      SourceInfo:          0x0   +      SecurityId:          0x0   +    FileAttributes:      0x20 +      FileNameLength:      24 +      FileNameOffset:      60 +      FileName:              testfile.txt

    前半のログエントリと後半のログエントリを比較すると、以下の項目の内容が同じであり、同一ファイルの同一の更新について言及しているログであることが分かります。

    • 前半のログの name と 後半のログの FileName (ファイル名の情報です)
    • 前半のログの fid と 後半のログの FileRefNumber (これらの値は、NTFS 上のファイル IDを示しています)
    • 前半のログの usn と 後半のログの USN (ファイルの新規作成に対し USN ジャーナル上で割り当てた USN です)

    つまりこれらの情報を結合すると、以下のような意味になります。

    • 2010/06/22 13:37:18.280 に、NTFS ファイル ID   0x20000000043FB である testfile.txt というファイルの更新を検出した。
    • USN ジャーナル上に記録された      USN 0x41dcd68 であり、更新理由は      Close Data Extend File Create であった。
    • この更新に対して、DFSR UID {9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 を割り当てた。
    • 同様に、この更新に対して、DFSR GVSN {9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 を割り当てた。
    • DFSR が管理している情報上、親フォルダの UID {7BD16799-5FAA-4B72-9B04-82807A6832BF}-v1 である。

    USN ジャーナル上の更新理由 (Reason) は、より詳細には、USN_RECORD 構造体の Reason メンバのフラグに対応しています。今回の場合では、(USN_REASON_CLOSE || USN_REASON_DATA_EXTEND || USN_REASON_FILE_CREATE) の組み合わせであり、「ファイルを新規作成し、データを追加し、ファイルを閉じた」という内容であると判断できます。(種明かしをすると、このデバッグログの採取を行った際の操作として、”echo aaa > \\testdfsr.local\public\repl\testfile.txt” というコマンドを実行して、ファイルの作成とデータの書き込みを同時に行いました。)

    また、今回はファイルの新規作成ですので、UID GVSN は同じ値になります。

    (parent) フォルダの UID について、DB GUID の部分が見慣れない GUID になっていることにお気づきの方もいらっしゃるかもしれません。実はレプリケートフォルダが親フォルダとなっている場合には、特別な場合としてレプリケートフォルダ自身の GUID と、Version として v1 が使用されるのです。そろそろおなじみになった dfsrdiag guid2name コマンドを使用すると、レプリケートフォルダ (DFSRの内部では、ContentSet とも呼ばれています)のGUID が使用されていることがわかります。

    C:\Users\Administrator>dfsrdiag guid2name   /RGName:testdfsr.local\public\repl   /guid:{7BD16799-5FAA-4B72-9B04-82807A6832BF}

       オブジェクトGUID:   7BD16799-5FAA-4B72-9B04-82807A6832BF    オブジェクトの種類: msDFSR-ContentSet      オブジェクトのDN:   CN=repl,CN=Content,CN=testdfsr.local\\public\\repl,CN=DFSR   -GlobalSettings,CN=System,DC=testdfsr,DC=local    LDAP サーバー: TEST-DFSR1.testdfsr.local

    成功した操作

     

    更新の内容を通知する

    ファイルの更新を検出したら、レプリケートグループ内の他のサーバーに通知を行います。

    20100622 13:37:18.280 3260 SRTR  1880 SERVER_RequestVersionVector Received from connId:{2C09B78B-6629-473C-BB07-CA4DB3B6A6A8} csId:{7BD16799-5FAA-4B72-9B04-82807A6832BF} seqNumber:9 changeType:all 20100622 13:37:18.280 3260 SRTR  1927 SERVER_AsyncPoll Received from connId:{2C09B78B-6629-473C-BB07-CA4DB3B6A6A8}

    この処理は、更新の送り側となるアップストリームサーバーのデバッグログを見ても分かりづらいのですが、更新の受け側となるダウンストリームサーバーのデバッグログを見ると、もう少し詳細な情報が確認できます。

    20100622 13:37:18.289 1636 INCO  3959 InConnection::ReceiveVvUp Received VvUp connId:{2C09B78B-6629-473C-BB07-CA4DB3B6A6A8} csId:{7BD16799-5FAA-4B72-9B04-82807A6832BF} csName:repl vvUp:{9EFED9E2-F496-4BE2-A17B-73D22B1AD383} |-> { 10..13} +    20100622 13:37:18.289 1636 INCO  3966 InConnection::ReceiveVvUp Creating new session:3 requestState:012261D0 connId:{2C09B78B-6629-473C-BB07-CA4DB3B6A6A8} csId:{7BD16799-5FAA-4B72-9B04-82807A6832BF} csName:repl vvDown:{9EFED9E2-F496-4BE2-A17B-73D22B1AD383} |-> { 10..12} +    20100622 13:37:18.289  472 INCO  4619 InConnection::RequestUpdates Requesting updates. credits:32 connId:{2C09B78B-6629-473C-BB07-CA4DB3B6A6A8} csId:{7BD16799-5FAA-4B72-9B04-82807A6832BF} csName:repl requestType:all cursor:{00000000-0000-0000-0000-000000000000}-v0 delta::{9EFED9E2-F496-4BE2-A17B-73D22B1AD383} |-> { 13} +   

    まず最初のエントリで、アップストリームサーバーから、「自分は {9EFED9E2-F496-4BE2-A17B-73D22B1AD383} というデータベースで管理している更新について、v10 から v13 までを把握した状態になった」という通知を受信します。

    次のエントリで、ダウンストリームサーバーは、自身が把握している情報を確認し、「自分は {9EFED9E2-F496-4BE2-A17B-73D22B1AD383} というデータベースで管理している更新について、v10 から v12 までしか把握していない状態」であることを確認します。

    最後のエントリで、ダウンストリームサーバーは、差分となる 「{9EFED9E2-F496-4BE2-A17B-73D22B1AD383} というデータベースで管理している v13 の更新内容」を要求しています。

    DFSRの複製の仕組みを理解する(後編)- Part 2 -」に続きます。

    注:この記事のコマンド実行結果やデバッグログの出力結果などは、Windows Server 2008 SP2 を基準としております。OS のバージョンの違いにより出力内容に若干差異がある可能性がありますので、ご了承ください。

    「コミュニティにおけるマイクロソフト社員による発言やコメントは、マイクロソフトの正式な見解またはコメントではありません。」

    2019年3月21日 22:59
    所有者