Understanding DFSR debug logging (Part 4: A Very Small File Added to Replicated Folder on Windows Server 2008)

Article
03/25/2009

In this scenario we will see a small file copied into the replicated folder and how it is replicated between two servers. This is useful to understand in order to troubleshoot issues where problems within the USN journal, the DFSR JET database, the staging folder structure, and the network (including RPC) are preventing replication from working correctly. If you haven't read Part 3, this isn't going to make as much sense, so make sure you review that.

(tinyfiledownstream - Dfsr00005 - 2008.log and tinyfiledownstream - Dfsr00005 - 2008.log)

These are two Windows Server 2008 servers called 2008MEM01 and 2008MEM02 in the fabrikam.com domain. The logs are from 2008MEM01 where the file is created (upstream) and from 2008MEM02 where it is replicated (downstream). Both servers are participating in the TESTRG replication group for the TESTRF replicated folder. The file is called "tinyfile.txt". It is smaller than 64KB so it will not need to be staged for RDC usage nor will it be XPRESS compressed.

<Upstream> 20080624 12:04:56.359 3196 JOIN 1122 Join::SubmitUpdate LDB Updating ID Record: ß this should start looking familiar by now.
+ fid 0x200000000A752
+ usn 0x930508
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 20080624 16:04:56.339 GMT
+ present 1
+ nameConflict 0
+ attributes 0x20 ß file, not a folder
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 ß file is new, as the UID and GVSN match
+ parent {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080624 16:04:56.339 GMT (0x1c8d6140ba94250)
+ createTime 20080624 16:04:56.258 GMT
+ csId {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}
+ hash 00000000-00000000-00000000-00000000
+ similarity 00000000-00000000-00000000-00000000
+ name tinyfile.txt ß the file we will replicate
+
<Downstream> 20080624 12:04:56.362 3932 INCO 4803 InConnection::ReceiveUpdates Upstream credits:32 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf creditsUsed:1 creditsAvailable:32
<Downstream> 20080624 12:04:56.362 3932 INCO 4868 InConnection::ReceiveUpdates Received: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 fileName:tinyfile.txt session:11 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf
<Downstream> 20080624 12:04:56.362 3284 MEET 1207 Meet::Install Retries:0 updateName:tinyfile.txt uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csName:testrf updateType:remote
<Downstream> 20080624 12:04:56.362 3932 INCO 4932 InConnection::ReceiveUpdates Session has been closed. sessionId:11 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf
<Downstream> 20080624 12:04:56.362 1940 INCO 3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00AB85B0 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf changeType:notify
<Downstream> 20080624 12:04:56.362 3932 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} reqType:UpdateRequest reqState:Completed status:0 ptr:00B316E0
<Downstream> 20080624 12:04:56.362 3932 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} reqType:VvUpRequest reqState:Completed status:0 ptr:00AB85B0
<Downstream> 20080624 12:04:56.362 3284 MRSH 3959 MarshalContext::Initialize Create file:[tinyfile-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29.txt] with attributes:0x20 ß File transfer process begins from the downstream server
<Upstream> 20080624 12:04:56.369 980 INCO 3959 InConnection::ReceiveVvUp Received VvUp connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf vvUp:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 10..28}
+ {910170E6-8BD6-49A9-85F1-A2F3FF43C76B} |-> { 10}
+
<Upstream> 20080624 12:04:56.369 980 INCO 3966 InConnection::ReceiveVvUp Creating new session:6 requestState:00872A98 connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf vvDown:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 10..29}
+ {910170E6-8BD6-49A9-85F1-A2F3FF43C76B} |-> { 10}
<Upstream> 20080624 12:04:56.369 980 OUTC 784 OutConnection::OpenFile Received request for update: ß File transfer process begins from the downstream server
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29
+ parent {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080624 16:04:56.339 GMT (0x1c8d6140ba94250)
+ createTime 20080624 16:04:56.258 GMT
+ csId {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}
+ hash 00000000-00000000-00000000-00000000
+ similarity 00000000-00000000-00000000-00000000
+ name tinyfile.txt
+ rdcDesired:1 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} rgName:TestRG
<Upstream> 20080624 12:04:56.369 980 OUTC 1534 OutConnection::OpenFile Sent file uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 name:tinyfile.txt fileSize:346 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} rgName:TestRG ß the file is going into the replication phase. This is going to be much simpler than a large file send as the file will not be staged upstream (no RDC, no compression)
<Upstream> 20080624 12:04:56.369 980 CSMG 4844 ContentSetManager::UpdateHash LDB Updating ID Record:
+ fid 0x200000000A752
+ usn 0x930508
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 20080624 16:04:56.339 GMT
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29
+ parent {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080624 16:04:56.339 GMT (0x1c8d6140ba94250)
+ createTime 20080624 16:04:56.258 GMT
+ csId {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}
+ hash 2F14F066-27FB1C64-8ED4E567-10B71F79
+ similarity 00000000-00000000-00000000-00000000
+ name tinyfile.txt
+
<Upstream> 20080624 12:04:56.369 980 SRTR 2357 InitializeFileTransferAsyncState::ProcessIoCompletion Initialized connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} rdc:1 context:00000000,00000000,00000000 uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 gvsn{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 ptr:00853DD0 ß the file is in transit
<Downstream> 20080624 12:04:56.372 3284 INCO 5610 InConnection::LogTransferActivity Received RAWGET uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 fileName:tinyfile.txt connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} stagedSize:362 ß performance counter data being updated. Note the RAWGET showing the file was copied without RDC. In this case it was not compressed either as it was never staged upstream.
<Downstream> 20080624 12:04:56.372 3284 MEET 2032 Meet::Download Download Succeeded : true updateName:tinyfile.txt uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csName:testrf csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} ß the transfer was successful.
<Downstream> 20080624 12:04:56.372 3284 MEET 2837 Meet::InstallRename File moved. rootVolume:{3EA8BD01-416E-11DD-A317-806E6F6E6963} parentFid:0x100000000A6D1 fidInInstalling:0x100000000A72C usn:0x8a41b8 updateName:tinyfile.txt uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csName:testrf ß the file is moved directly into the replicated folder without entering the downstream staging or installing directory.
<Downstream> 20080624 12:04:56.372 3284 MEET 6759 Meet::InsertIdRecord LDB Inserting ID Record: ß database updated from USN update
+ fid 0x100000000A72C
+ usn 0x8a41b8
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 1 ß file exists through inbound replication
+ meetReanimated 0
+ recUpdateTime 16010101 00:00:00.000 GMT
+ present 1 ß it is now in the replicated folder
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29
+ parent {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080624 16:04:56.339 GMT (0x1c8d6140ba94250)
+ createTime 20080624 16:04:56.258 GMT
+ csId {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}
+ hash 2F14F066-27FB1C64-8ED4E567-10B71F79
+ similarity 00000000-00000000-00000000-00000000 ß there is no RDC similarity data, it was never staged
+ name tinyfile.txt
+
<Downstream> 20080624 12:04:56.372 3284 MEET 2949 Meet::InstallRename -> DONE Install-rename completed updateName:tinyfile.txt uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csName:testrf csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} ßdone moving file into replicated folder
<Downstream> 20080624 12:04:56.372 3284 INCO 5897 InConnection::UpdateProcessed Received Update. updatesLeft:0 processed:1 failures:0 sessionId:11 open:0 updateType:0 processStatus:0 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf update: ß done replicating any files from the upstream server.
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v29
+ parent {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080624 16:04:56.339 GMT (0x1c8d6140ba94250)
+ createTime 20080624 16:04:56.258 GMT
+ csId {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}
+ hash 2F14F066-27FB1C64-8ED4E567-10B71F79
+ similarity 00000000-00000000-00000000-00000000
+ name tinyfile.txt
+

- Ned Pyle

tinyfileupstream-debug-2008.zip

Understanding DFSR debug logging (Part 4: A Very Small File Added to Replicated Folder on Windows Server 2008)

Additional resources