DFSRの複製の仕組みを理解する（後編）

Article
07/02/2010

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

前回に引き続き、今回は 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 のバージョンの違いにより出力内容に若干差異がある可能性がありますので、ご了承ください。

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