DFSRの複製の仕組みを理解する(後編)


 こんにちは。サポート担当の比留間です。

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

用意するもの

o    レプリケーショングループに参加している各サーバーで採取した DFSR のデバッグログ

o    GZip 形式が展開できる圧縮・解凍用のツール

o    使い慣れたテキストエディタ

o    レプリケーショングループの構成情報

o    追跡したいファイルの更新が行われた日時の情報

o    追跡したいファイルの、ファイルサーバーのローカル上でのフルパスの情報

o    前日の十分な睡眠

以前のポストでもご紹介したとおり、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. updatesLeft:237 processed:1171 sessionId:1 open:1 updateType:0 processStatus:0 connId:{D0BF5598-9457-4C32-8C50-7558BCD76610} csId:{1697E5EB-BBD0-45B7-AC2F-11EBE7B3FD47} csName:dfsrprestaged update:
+    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

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

o    前半のログの name と 後半のログの FileName (ファイル名の情報です)

o    前半のログの fid と 後半のログの FileRefNumber (これらの値は、NTFS 上のファイル IDを示しています)

o    前半のログの usn と 後半のログの USN (ファイルの新規作成に対し USN ジャーナル上で割り当てた USN です)

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

o    2010/06/22 13:37:18.280 に、NTFS ファイル ID   0x20000000043FB である testfile.txt というファイルの更新を検出した。

o    USN ジャーナル上に記録された USN 0x41dcd68 であり、更新理由は Close Data Extend File Create であった。

o    この更新に対して、DFSR UID {9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 を割り当てた。

o    同様に、この更新に対して、DFSR GVSN {9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 を割り当てた。

o    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 の更新内容」を要求しています。

 

実際に更新を複製する JOIN MEET

更新内容の要求をダウンストリームサーバーから受け取ると、アップストリームサーバーは実際に更新内容を転送する準備に入ります。この時に目印となるのが JOIN というモジュールの動作です。GVSN {9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 の更新について処理が行われているのお分かりいただけると思います。

20100622 13:37:18.280 1960 JOIN  1122 Join::SubmitUpdate LDB Updating ID Record:
+    fid                             0x20000000043FB
+    usn                             0x41dcd68
+    uidVisible                      1
+    filtered                        0
+    journalWrapped                  0
+    slowRecoverCheck                0
+    pendingTombstone                0
+    internalUpdate                  0
+    dirtyShutdownMismatch           0
+    meetInstallUpdate               0
+    meetReanimated                  0
+    recUpdateTime                   20100622 04:37:18.280 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.295 1960 JOIN  1167 Join::SubmitUpdate Sent: uid:{9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 gvsn:{9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 name:testfile.txt connId:{2C09B78B-6629-473C-BB07-CA4DB3B6A6A8} csId:{7BD16799-5FAA-4B72-9B04-82807A6832BF} csName:repl
20100622 13:37:18.295 3340 OUTC   784 OutConnection::OpenFile Received request for update:
+    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
+     rdcDesired:1 connId:{2C09B78B-6629-473C-BB07-CA4DB3B6A6A8} rgName:testdfsr.local\public\repl
20100622 13:37:18.295 3340 OUTC  1534 OutConnection::OpenFile Sent file uid:{9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 gvsn:{9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 name:testfile.txt fileSize:299 connId:{2C09B78B-6629-473C-BB07-CA4DB3B6A6A8} rgName:testdfsr.local\public\repl

 

一方、受け側となるダウンストリーム側で目印となるのが、MEET というモジュールの動作です。

 

20100622 13:37:18.305 1636 INCO  4868 InConnection::ReceiveUpdates Received: uid:{9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 gvsn:{9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 fileName:testfile.txt session:3 connId:{2C09B78B-6629-473C-BB07-CA4DB3B6A6A8} csId:{7BD16799-5FAA-4B72-9B04-82807A6832BF} csName:repl
20100622 13:37:18.305  472 MEET  1207 Meet::Install Retries:0 updateName:testfile.txt uid:{9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 gvsn:{9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 connId:{2C09B78B-6629-473C-BB07-CA4DB3B6A6A8} csName:repl updateType:remote
20100622 13:37:18.305  472 MEET  2032 Meet::Download Download Succeeded : true updateName:testfile.txt uid:{9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 gvsn:{9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 connId:{2C09B78B-6629-473C-BB07-CA4DB3B6A6A8} csName:repl csId:{7BD16799-5FAA-4B72-9B04-82807A6832BF}
20100622 13:37:18.305  472 MEET  2837 Meet::InstallRename File moved. rootVolume:{8FE73079-7D09-11DF-B87E-806E6F6E6963} parentFid:0x1A000000002B95 fidInInstalling:0x7000000003CA5 usn:0x3fac478 updateName:testfile.txt uid:{9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 gvsn:{9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 connId:{2C09B78B-6629-473C-BB07-CA4DB3B6A6A8} csName:repl
20100622 13:37:18.305  472 MEET  6759 Meet::InsertIdRecord LDB Inserting ID Record:
+    fid                             0x7000000003CA5
+    usn                             0x3fac478
+    uidVisible                      1
+    filtered                        0
+    journalWrapped                  0
+    slowRecoverCheck                0
+    pendingTombstone                0
+    internalUpdate                  0
+    dirtyShutdownMismatch           0
+    meetInstallUpdate               1
+    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                            5A5C2837-5F8E61B7-F7E98AC4-A87B9CF0
+    similarity                      00000000-00000000-00000000-00000000
+    name                            testfile.txt
+   
20100622 13:37:18.305  472 MEET  2949 Meet::InstallRename -> DONE Install-rename completed updateName:testfile.txt uid:{9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 gvsn:{9EFED9E2-F496-4BE2-A17B-73D22B1AD383}-v13 connId:{2C09B78B-6629-473C-BB07-CA4DB3B6A6A8} csName:repl csId:{7BD16799-5FAA-4B72-9B04-82807A6832BF}
20100622 13:37:18.305  472 INCO  5897 InConnection::UpdateProcessed Received Update. updatesLeft:0 processed:1 failures:0 sessionId:3 open:0 updateType:0 processStatus:0 connId:{2C09B78B-6629-473C-BB07-CA4DB3B6A6A8} csId:{7BD16799-5FAA-4B72-9B04-82807A6832BF} csName:repl update:
+    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                            5A5C2837-5F8E61B7-F7E98AC4-A87B9CF0
+    similarity                      00000000-00000000-00000000-00000000
+    name                            testfile.txt

 

ここまで来て、やっとダウンストリームサーバーのレプリケートフォルダに、testfile.txt というファイルが複製された状態となります。

以上、駆け足で複製の際の基本的な流れを追跡してみました。実際には複製処理の際にステージングを行ったり、差分を圧縮して転送する RDC が動作したり、レプリケーショングループに参加しているサーバーが複数台になったりと、より複雑な出力内容になりますが、複製の動作を追跡する際の基本的な流れは共通です。

o    ファイル名やフォルダ名、タイムスタンプ、ファイルシステムに加えた更新の内容を手がかりに、該当する USNC モジュールの処理を特定する。

o    NTFS の ファイル ID および USN を手がかりに、対応する UID GVSN を特定する。

o    親フォルダの UID を確認し、階層構造を把握する。

o    アップストリーム側の JOIN モジュールの処理を確認する。

o    ダウンストリーム側の MEET モジュールの処理を確認する。

US Directory Service Team Blog に、より詳細な DFSR のデバッグログのパターン解説の記事 (URL) が投稿されております。21章構成という大作ですが、もしも DFSR の処理の詳細に興味がある方は、是非ご一読をお勧めします。

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

 

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


Comments (0)

Skip to main content