Microsoft's official enterprise support blog for AD DS and more
In this scenario we will see a folder added and how that change is replicated between servers. This is useful to understand in order to troubleshoot issues where problems within the USN journal, the DFSR JET database, and the network (including RPC) are preventing replication from working correctly.
(addedfolderupstream - Dfsr00006 - 2003.log and addedfolderdownstream - Dfsr00007 - 2003.log)
These are two Windows Server 2003 servers called 2003MEM01 and 2003MEM02 in the contoso.com domain. The logs are from 2003MEM01 where the folder is created (upstream) and from 2003MEM02 where it the creation is replicated (downstream). Both servers are participating in the TESTRG2 replication group for the TESTRF2 replicated folder. The folder was called “subfolder”.
<Upstream> 20080627 10:34:47.983 692 LDBX 3567 Ldb::Insert Inserting idRecord: ß the DFSR database is being updated upstream
+ fid 0x1000000002FF8 ß note the file ID. This useful for cross referencing with USN updates in the log
+ usn 0xb6370
+ uidVisible 0
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ recUpdateTime 16010101 00:00:00.000 GMT
+ present 1
+ nameConflict 0
+ attributes 0x10 ß marks the object as a folder, not a file
+ gvsn {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30
+ uid {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 ß UID and GVSN match, this shows the change as an original creation on the upstream server
+ parent {5666BB91-265D-42E8-9F57-1B49F4E581B7}-v1
+ fence 16010101 00:00:00.000
+ clock 20080627 14:34:47.983
+ createTime 20080627 14:34:47.983 GMT
+ csId {5666BB91-265D-42E8-9F57-1B49F4E581B7}
+ hash 00000000-00000000-00000000-00000000
+ similarity 00000000-00000000-00000000-00000000
+ name subfolder ß the folder is named ‘subfolder’
+
<Upstream> 20080627 10:34:48.043 692 USNC 2448 UsnConsumer::CreateNewRecord ID record created from USN_RECORD: ß the USN journal has been updated. Note that this actually occurred before the database being updated, it is just a log idiosyncrasy that the debug log entry occurs later.
+ USN_RECORD:
+ RecordLength: 80
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x1000000002ff8 ß note that File ID is the same as above
+ ParentFileRefNumber: 0x1000000002f92
+ USN: 0xb6370
+ TimeStamp: 20080627 10:34:47.983 Eastern Standard Time
+ Reason: Close Rename New Name ß the folder object is newly created.
+ SourceInfo: 0x0
+ SecurityId: 0x1af
+ FileAttributes: 0x10 ß it’s a folder, not a file
+ FileNameLength: 18
+ FileNameOffset: 60
+ FileName: subfolder ß named ‘subfolder’
<Upstream> 20080627 10:34:48.043 692 LDBX 4083 Ldb::InsertWalkerJob Inserting dirWalkerJob:uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 moveType:MoveIn (1) at time:20080627 14:34:47.983 ß a DirWalker job is created. Dirwalker checks that when a folder is created, what sub folders/files it contains.
<Upstream> 20080627 10:34:48.063 692 LDBX 1228 LdbManager::UpdateVersionVectorCache Wake up callback 00ADF8C0
<Upstream> 20080627 10:34:48.063 692 DIRW 511 DirWalkerTask::QueueMoveinJob Queuing move-in. uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 fid:0x1000000002FF8 name:subfolder ß the dirwalker job is queued for running
<Upstream> 20080627 10:34:48.063 172 DIRW 256 DirWalkerTask::Run Start walking directory. ß the dirwalker job runs
<Upstream> 20080627 10:34:48.063 172 DIRW 937 DirWalkerTask::MoveinStep Starting to process move-in job. uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 ß the results of the dirwalker job are evaluated.
<Upstream> 20080627 10:34:48.063 172 DIRW 101 DirWalkerTask::Job::Finish MoveIn csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 ß the dirwalker job is complete. This was very fast here as there were no sub-files or folders.
<Upstream> 20080627 10:34:48.063 172 DIRW 786 DirWalkerTask::RemoveJob Removing job type:1 uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 ß the Dirwalker job is ready to be removed.
<Upstream> 20080627 10:34:48.063 172 LDBX 4119 Ldb::DeleteWalkerJob Deleting dirWalkerJob. uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 ß the dirwalker job is removed
<Upstream> 20080627 10:34:48.063 172 DIRW 303 DirWalkerTask::Run Exit.
<Upstream> 20080627 10:34:48.083 1176 SRTR 1257 SERVER_RequestVersionVector Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} seqNumber:4 changeType:all
<Upstream> 20080627 10:34:48.083 1176 SRTR 1304 SERVER_AsyncPoll Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD}
<Upstream> 20080627 10:34:48.093 1176 SRTR 498 SERVER_RequestUpdates Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} credits:32 requestType:all
<Upstream> 20080627 10:34:48.093 1176 SRTR 1304 SERVER_AsyncPoll Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD}
<Downstream> 20080627 10:34:48.098 1788 INCO 2761 InConnection::RequestVvUp Requested upstream version vector. requestState:00A86E70 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 changeType:all ß the downstream server requests version vector info from the upstream partner
<Downstream> 20080627 10:34:48.098 1720 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00A8F4A0
<Upstream> 20080627 10:34:48.103 172 LDBX 3684 Ldb::Update Updating idRecord: ß DFSR database updated to reflect that the folder is available for replication now, with a visible UID (this is slightly different than files, since folders can contain other objects)
+ fid 0x1000000002FF8
+ uidVisible 1
+ recUpdateTime 20080627 14:34:47.983 GMT
+ attributes 0x10
+ uid {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30
+ createTime 20080627 14:34:35.555 GMT
+ name subfolder
<Upstream> 20080627 10:34:48.103 172 JOIN 1171 Join::SubmitUpdate Sent: uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 name:subfolder connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 ß the upstream server sends downstream the update information metadata. Since this is a folder an actual ‘folder’ is not sent, just security, name, and parent info.
<Upstream> 20080627 10:34:48.103 1176 SRTR 1257 SERVER_RequestVersionVector Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} seqNumber:5 changeType:notify
<Upstream> 20080627 10:34:48.103 1620 OUTC 588 OutConnection::OpenFile Received request for update: ß the upstream server is requested to serve the folder to the downstream
+ rdcDesired:1 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} rgName:TestRG2
<Upstream> 20080627 10:34:48.103 1620 OUTC 1056 OutConnection::OpenFile Sent file uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 name:subfolder fileSize:360 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} rgName:TestRG2 ß the folder is being sent
<Upstream> 20080627 10:34:48.103 1620 MRSH 3487 Marshaller::Marshal FileAttrs in metadata : 0x10 ß the folder data was marshaled for RPC
<Downstream> 20080627 10:34:48.108 1720 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} reqType:VvUpRequest reqState:Completed status:0 ptr:00A86E70
<Downstream> 20080627 10:34:48.108 1720 INCO 2947 InConnection::ReceiveVvUp Received VvUp connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 vvUp:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6} |-> { 10..30}
<Downstream> 20080627 10:34:48.108 1720 INCO 2954 InConnection::ReceiveVvUp Creating new session:2 requestState:00A86E70 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 ß downstream server has received the version vector info
<Downstream> 20080627 10:34:48.108 1788 INCO 3347 InConnection::RequestUpdates Requesting updates. credits:32 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 requestType:all cursor:{00000000-0000-0000-0000-000000000000}-v0 delta::{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6} |-> { 30} ß the version is 30
<Downstream> 20080627 10:34:48.108 1720 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00A8F4A0
<Downstream> 20080627 10:34:48.128 1720 INCO 3534 InConnection::ReceiveUpdates Upstream credits:32 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2
<Downstream> 20080627 10:34:48.128 1720 INCO 3597 InConnection::ReceiveUpdates Received: uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 fileName:subfolder session:2 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 ß the downstream server receives the marshaled folder metadata information
<Downstream> 20080627 10:34:48.128 1788 MEET 1190 Meet::Install Retries:0 updateName:subfolder uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2 ß the new folder is ready to be created in the downstream replicated folder. Note the lack of staging, installing process. There is no RDC or compression used in folder object replication.
<Downstream> 20080627 10:34:48.128 1720 INCO 3661 InConnection::ReceiveUpdates Session has been closed. sessionId:2 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2
<Downstream> 20080627 10:34:48.128 2008 INCO 2761 InConnection::RequestVvUp Requested upstream version vector. requestState:00A86E70 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 changeType:notify
<Downstream> 20080627 10:34:48.128 1720 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} reqType:UpdateRequest reqState:Completed status:0 ptr:00A86340
<Downstream> 20080627 10:34:48.128 1788 MRSH 2957 MarshalContext::Initialize Create file:[subfolder-{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30] with attributes:0x10 ß the folder is created in the downstream server replicated folder
<Downstream> 20080627 10:34:48.128 1788 INCO 4112 InConnection::LogTransferActivity Received RAWGET uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 fileName:subfolder connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} stagedSize:356 ß the process of replication is logged as a RAWGET (i.e. no RDC). While there is info on ‘stagedsize’ it is not actually staged, this is a logging idiosyncrasy.
<Downstream> 20080627 10:34:48.128 1788 MEET 1898 Meet::Download Download Succeeded : true updateName:subfolder uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2 csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} ß the replication process has completed and the folder has been successfully ‘downloaded’.
<Downstream> 20080627 10:34:48.128 1788 MEET 2190 Meet::InstallRename File moved. rootVolume:{05853FA6-411C-11DD-A156-806E6F6E6963} parentFid:0x1000000002F8C fidInInstalling:0x1000000002FF3 usn:0xbbe88 updateName:subfolder uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2 ß the subfolder now fully exists in the replicated folder.
<Downstream> 20080627 10:34:48.128 1788 LDBX 3567 Ldb::Insert Inserting idRecord: ß the DFSR database is updated on the downstream server to track the new subfolder
+ fid 0x1000000002FF3
+ usn 0xbbe88
+ hash BD3BC9A8-67A8EA8B-B5D77ACF-4DBD26A0
<Downstream> 20080627 10:34:48.128 1720 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} reqType:VvUpRequest reqState:Completed status:0 ptr:00A86E70
<Downstream> 20080627 10:34:48.158 1788 MEET 2233 Meet::InstallRename -> DONE Install-rename completed updateName:subfolder uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2 csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} ß the installation process has been completed.
<Downstream> 20080627 10:34:48.158 1788 INCO 4378 InConnection::UpdateProcessed Received Update. updatesLeft:0 processed:1 sessionId:2 open:0 updateType:0 processStatus:0 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 update:
<Downstream> 20080627 10:34:48.168 1788 LDBX 1228 LdbManager::UpdateVersionVectorCache Wake up callback 00AD6080
<Downstream> 20080627 10:34:48.168 1788 INCO 4617 InConnection::CommitSession Connection in sync connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD}
<Downstream> 20080627 10:34:48.168 1788 UPMG 413 UpdateWorker::ConsumeUpdates No pending updates. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2
<Downstream> 20080627 10:34:48.168 2008 INCO 2787 InConnection::ContentSetContext::Hibernate Hibernating: connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7}
Understanding DFSR debug logging (Part 1: Logging Levels, Log Format, GUID’s)Understanding DFSR debug logging (Part 2: Nested Fields, Module ID's)Understanding DFSR debug logging (Part 3: The Log Scenario Format, File Added to Replicated Folder on Windows Server 2008)Understanding DFSR debug logging (Part 4: A Very Small File Added to Replicated Folder on Windows Server 2008) Understanding DFSR debug logging (Part 5: File Modified on Windows Server 2003 R2)Understanding DFSR debug logging (Part 6: Microsoft Office Word 97-2003 File Modified on Windows Server 2008)Understanding DFSR debug logging (Part 7: Microsoft Office Word 2007 File Modified on Windows Server 2008)Understanding DFSR debug logging (Part 8: File Deleted from Windows Server 2003 R2) Understanding DFSR debug logging (Part 9: File is Renamed on Windows Server 2003 R2)Understanding DFSR debug logging (Part 10: File Conflicted between two Windows Server 2008)Understanding DFSR debug logging (Part 11: Directory created on Windows Server 2003 R2)Understanding DFSR debug logging (Part 12: Domain Controller Bind and Config Polling on Windows Server 2008)Understanding DFSR debug logging (part 13: A New Replication Group and Replicated Folder between two Windows Server 2008 members)Understanding DFSR debug logging (Part 14: A sharing violation due to a file locked upstream between two Windows Server 2008) Understanding DFSR debug logging (Part 15: Pre-Seeded Data Usage during Initial Sync)Understanding DFSR debug logging (Part 16: File modification with RDC in very granular detail (uses debug severity 5))Understanding DFSR debug logging (Part 17: Replication failing because of blocked RPC ports (uses debug severity 5))Understanding DFSR debug logging (Part 18: LDAP queries failing due to network (uses debug severity 5))Understanding DFSR debug logging (Part 19: File Blocked Inbound by a File Screen Filter Driver (uses debug severity 5))Understanding DFSR debug logging (Part 20: Skipped temporary and filtered files (uses debug severity 5))Understanding DFSR debug logging (Part 21: File replication performance from throttling (uses debug severity 5))
- Ned Pyle
In this scenario we will see a file that has been changed on two servers in between replication convergence and how that conflict resolution is replicated between servers. This is useful to understand in order to troubleshoot issues (or perception of issues that are actually expected behavior) leading to conflicts.
(conflictwinner - Dfsr00001 - 2008.log and conflictloser - Dfsr00001 - 2008.log)
These are two Windows Server 2008 servers called 2008x86FSRV10 and 2008x86SRV11 in the contoso.com domain. The logs are from 2008x86FSRV10 (where the conflict is won) and from 2008x86SRV11 (where the conflict is lost). Both servers are participating in the TESTRG3 replication group for the TESTRF3 replicated folder. The file was called “confile.rtf”.
<Upstream> 20080908 08:40:20.994 3104 USNC 2361 UsnConsumer::UpdateIdRecord LDB Updating ID Record: ß File modified and information being added to the DFSR database
+ fid 0x400000000BA14 ß File ID for cross-reference purposes with USN journal
+ usn 0x25f7898
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 20080908 15:31:45.162 GMT
+ attributes 0x20 ß file, not folder
+ ghostedHeader 0
+ data 0
+ gvsn {5CB120DE-D2C2-452A-8280-B45FC155224F}-v15 ßversion is higher than UID so we know this file has been modified at least once (but remember that versions are not sequential for a file, they are sequential for the file server.)
+ uid {5CB120DE-D2C2-452A-8280-B45FC155224F}-v11 ß GUID matches between versions, so the file was created and last modified on this server
+ parent {009349B5-8677-4352-AC4F-13BCC111BAA0}-v1
+ clockDecrementedInDirtyShutdown 0
+ clock 20080908 15:40:20.979 GMT (0x1c911c933ac2f01)
+ createTime 20080908 15:31:45.131 GMT
+ csId {009349B5-8677-4352-AC4F-13BCC111BAA0}
+ name confile.rtf ß file name is ‘confile.rtf’
<Upstream> 20080908 08:40:20.994 3104 USNC 2364 UsnConsumer::UpdateIdRecord ID record updated from USN_RECORD: ß USN journal is updated at the same time to show a modification record (technically it happens before the DB update, this is a logging idiosyncrasy’)
+ RecordLength: 88
+ FileRefNumber: 0x400000000BA14 ß note that FID’s match between USN and LDB debug log entries. We know this is the same file.
+ ParentFileRefNumber: 0x2100000000A77C
+ USN: 0x25f7898
+ TimeStamp: 20080908 08:40:20.979 Pacific Standard Time
+ Reason: Close Data Extend Data truncation ß reason code indicates the file has been modified (extend & truncate)
+ SecurityId: 0x0
+ FileAttributes: 0x20 ß file, not folder
+ FileNameLength: 22
+ FileName: confile.rtf ß same file name
<Upstream> 20080908 08:40:29.682 2824 SRTR 1927 SERVER_AsyncPoll Received from connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} ß server receives
<Upstream> 20080908 08:40:42.339 2352 RSMG 1036 [WARN] ReplicaSetManager::EstablishConnection Shutting down existing connection. connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} rgName:ConRG
<Upstream> 20080908 08:40:42.339 2352 OUTC 487 OutConnection::Shutdown Shutdown connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} rgName:ConRG
<Upstream> 20080908 08:40:42.339 2352 SRTR 712 SERVER_EstablishConnection Succeeded on connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} replicaSetId:{1551E20B-36F1-4EE4-B6D0-3154E5C28E44} rgName:ConRG partnerAddress:2008x86FSRV11.contoso.com
<Upstream> 20080908 08:40:42.339 2352 OUTC 2610 OutConnection::EstablishSession Replacing content set. csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} rgName:ConRG
<Upstream> 20080908 08:40:42.339 2352 SRTR 794 SERVER_EstablishSession Established connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0}
<Upstream> 20080908 08:40:42.339 2824 SRTR 1927 SERVER_AsyncPoll Received from connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771}
<Upstream> 20080908 08:40:42.339 2824 SRTR 1880 SERVER_RequestVersionVector Received from connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} seqNumber:1 changeType:notify
<Upstream> 20080908 08:40:42.339 2824 SRTR 1880 SERVER_RequestVersionVector Received from connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} seqNumber:2 changeType:all
<Downstream> 20080908 08:40:42.340 2212 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00D01BF8
<Downstream> 20080908 08:40:42.340 2212 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} reqType:VvUpRequest reqState:Completed status:0 ptr:00C80FE0
<Downstream> 20080908 08:40:42.340 2212 INCO 3959 InConnection::ReceiveVvUp Received VvUp connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} csName:conrf vvUp:{5CB120DE-D2C2-452A-8280-B45FC155224F} |-> { 10..15} ß version vector exchange occurs and the (future) loser gets the chain from partner (local is 10, remote is 15)
<Downstream> 20080908 08:40:42.340 2212 INCO 3966 InConnection::ReceiveVvUp Creating new session:5 requestState:00C80FE0 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} csName:conrf vvDown:{0E1F0993-5130-4BB2-B409-FD13366B9A0C} |-> { 10}
+ {5CB120DE-D2C2-452A-8280-B45FC155224F} |-> { 10..14} ß previous chain was local 10, remote 14
<Downstream> 20080908 08:40:42.340 2596 INCO 4619 InConnection::RequestUpdates Requesting updates. credits:32 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} csName:conrf requestType:all cursor:{00000000-0000-0000-0000-000000000000}-v0 delta::{5CB120DE-D2C2-452A-8280-B45FC155224F} |-> { 15} ß new high watermark version from remote will be 15, which matches the version on our file upstream
<Downstream> 20080908 08:40:42.340 2212 INCO 4803 InConnection::ReceiveUpdates Upstream credits:32 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} csName:conrf creditsUsed:1 creditsAvailable:32 ß downstream server gets a credit out of his 32 credit pool with partner
<Downstream> 20080908 08:40:42.340 2212 INCO 4868 InConnection::ReceiveUpdates Received: uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v11 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v15 fileName:confile.rtf session:5 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} csName:conrf ß update information has been sent to the downstream server (now it knows about date/time as well, which will be used to break the tie and cause downstream to lose)
<Downstream> 20080908 08:40:42.340 2596 MEET 1207 Meet::Install Retries:0 updateName:confile.rtf uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v11 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v15 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csName:conrf updateType:remote ß downstream ready to pull file
<Downstream> 20080908 08:40:42.340 2596 MEET 5674 Meet::LocalDominates Conflicting gvsn:{0E1F0993-5130-4BB2-B409-FD13366B9A0C}-v10 updateName:confile.rtf uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v11 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v15 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csName:conrf ß a somewhat confusing message – the function ‘localdominates’ makes it sound like the downstream server has won, but this is just because the function is called localdominates (i.e. ‘checking IF local dominates’). If DebugLogSeverity=5 here there will additional trace logging that will show “Local version dominates localgvsn” or “"Remote version dominates localgvsn”). In this case, local has lost.
<Downstream> 20080908 08:40:42.340 2212 INCO 4932 InConnection::ReceiveUpdates Session has been closed. sessionId:5 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} csName:conrf
<Downstream> 20080908 08:40:42.340 2212 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} reqType:UpdateRequest reqState:Completed status:0 ptr:00C80EE8
<Downstream> 20080908 08:40:42.340 3244 INCO 3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00C805E0 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} csName:conrf changeType:notify
<Downstream> 20080908 08:40:42.340 2212 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} reqType:VvUpRequest reqState:Completed status:0 ptr:00C805E0
<Upstream> 20080908 08:40:42.355 2824 SRTR 882 SERVER_RequestUpdates Received from connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} credits:32 requestType:all
<Upstream> 20080908 08:40:42.355 2824 SRTR 1927 SERVER_AsyncPoll Received from connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771}
<Upstream> 20080908 08:40:42.355 2548 JOIN 1167 Join::SubmitUpdate Sent: uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v11 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v15 name:confile.rtf connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} csName:conrf ß upstream is now serving the file
<Upstream> 20080908 08:40:42.355 2824 SRTR 1880 SERVER_RequestVersionVector Received from connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} seqNumber:3 changeType:notify
<Upstream> 20080908 08:40:42.355 2008 OUTC 784 OutConnection::OpenFile Received request for update: ß upstream gets an RPC request to serve the file to downstream partner
+ attributes 0x20
+ gvsn {5CB120DE-D2C2-452A-8280-B45FC155224F}-v15
+ uid {5CB120DE-D2C2-452A-8280-B45FC155224F}-v11
+ name confile.rtf
+ rdcDesired:1 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} rgName:ConRG
<Upstream> 20080908 08:40:42.355 2008 OUTC 1534 OutConnection::OpenFile Sent file uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v11 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v15 name:confile.rtf fileSize:47783 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} rgName:ConRG ß file is being replicated. Note the lack of staging process below, this file is only 47KB.
<Upstream> 20080908 08:40:42.355 2008 MRSH 4615 Marshaller::Marshal FileAttrs in metadata : 0x20
<Upstream> 20080908 08:40:42.355 2008 OUTC 158 SaveHashReader::Close Saving hash of served file
<Upstream> 20080908 08:40:42.355 2008 CSMG 4844 ContentSetManager::UpdateHash LDB Updating ID Record: ß DFSR database updated with hash information.
+ fid 0x400000000BA14
+ recUpdateTime 20080908 15:40:20.994 GMT
+ hash 00F1C53D-312C1265-D91F9B6A-19316BBA
<Downstream> 20080908 08:40:42.356 2596 MRSH 3959 MarshalContext::Initialize Create file:[confile-{5CB120DE-D2C2-452A-8280-B45FC155224F}-v15.rtf] with attributes:0x20 ß downstream server is replicating file from partner. The file will bypass local staging due to size and go straight into the Installing directory.
<Downstream> 20080908 08:40:42.356 2596 INCO 5610 InConnection::LogTransferActivity Received RAWGET uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v11 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v15 fileName:confile.rtf connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} stagedSize:21030
ß the file has been copied in RAW (i.e. non-RDC) form to the downstream server
<Downstream> 20080908 08:40:42.356 2596 MEET 2032 Meet::Download Download Succeeded : true updateName:confile.rtf uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v11 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v15 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csName:conrf csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} ß copying the file over was successfull
<Downstream> 20080908 08:40:42.356 2596 MEET 5674 Meet::LocalDominates Conflicting gvsn:{0E1F0993-5130-4BB2-B409-FD13366B9A0C}-v10 updateName:confile.rtf uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v11 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v15 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csName:conrf ß another mention of the conflict being lost on local downstream partner
<Downstream> 20080908 08:40:42.356 2596 MEET 2772 Meet::InstallRename Move out previous version of same file updateName:confile.rtf uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v11 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v15 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csName:conrf ß The previously existing copy of the file in the replicated folder now needs to be moved into the COnflictANdDeleted folder.
<Downstream> 20080908 08:40:42.356 2596 MEET 4867 Meet::MoveOut Moving contents and children out of replica. newName:confile-{0E1F0993-5130-4BB2-B409-FD13366B9A0C}-v10.rtf updateName:confile.rtf uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v11 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v15 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csName:conrf record: ß the previous file is now moved into the ConflictAndDeleted folder under dfsrprivate in the replicated folder. The ConflictAndDeletedManifest.XML is updated to reflect this.
+ fid 0x2100000000A77C
+ usn 0x25f2990
+ recUpdateTime 20080908 15:38:52.571 GMT
+ gvsn {0E1F0993-5130-4BB2-B409-FD13366B9A0C}-v10
+ clock 20080908 15:38:52.555 GMT (0x1c911c8fef7cd5c)
<Downstream> 20080908 08:40:42.356 2596 EVNT 725 EventLog::Report Logging eventId:4412 parameterCount:9
<Downstream> 20080908 08:40:42.356 2596 EVNT 745 EventLog::Report eventId:4412 parameter1:009349B5-8677-4352-AC4F-13BCC111BAA0
<Downstream> 20080908 08:40:42.356 2596 EVNT 745 EventLog::Report eventId:4412 parameter2:C:\conrf\confile.rtf
<Downstream> 20080908 08:40:42.356 2596 EVNT 745 EventLog::Report eventId:4412 parameter3:c:\conrf
<Downstream> 20080908 08:40:42.356 2596 EVNT 745 EventLog::Report eventId:4412 parameter4:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v11
<Downstream> 20080908 08:40:42.356 2596 EVNT 745 EventLog::Report eventId:4412 parameter5:conrf
<Downstream> 20080908 08:40:42.356 2596 EVNT 745 EventLog::Report eventId:4412 parameter6:ConRG
<Downstream> 20080908 08:40:42.356 2596 EVNT 745 EventLog::Report eventId:4412 parameter7:1551E20B-36F1-4EE4-B6D0-3154E5C28E44
<Downstream> 20080908 08:40:42.356 2596 EVNT 745 EventLog::Report eventId:4412 parameter8:D31217D6-0F05-437A-8FDF-84949FD7D2D6
<Downstream> 20080908 08:40:42.356 2596 EVNT 745 EventLog::Report eventId:4412 parameter9:confile-{0E1F0993-5130-4BB2-B409-FD13366B9A0C}-v10.rtf ß the following strings are built and written into the 4412 DFSR ‘conflict’ event in the event log.
<Downstream> 20080908 08:40:42.356 2596 MEET 2837 Meet::InstallRename File moved. rootVolume:{3C84BB07-22D1-11DD-862B-806E6F6E6963} parentFid:0x600000000A5B6 fidInInstalling:0x300000000B9FD usn:0x2618560 updateName:confile.rtf uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v11 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v15 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csName:conrf ß move to C&D folder is complete.
<Downstream> 20080908 08:40:42.356 2596 MEET 6746 Meet::UpdateIdRecord LDB Updating ID Record: ß The DFSR database must be updated to reflect the new file information on the downstream loser.
+ fid 0x300000000B9FD
+ usn 0x2618560
+ meetInstallUpdate 1 ß marks that the update was caused by inbound replication.
+ uid {5CB120DE-D2C2-452A-8280-B45FC155224F}-v11 ß the GVSN and UID are now matched to the upstream server
+ hash 00F1C53D-312C1265-D91F9B6A-19316BBA ß the hash now matches the upstream version
<Downstream> 20080908 08:40:42.356 2596 MEET 2949 Meet::InstallRename -> DONE Install-rename completed updateName:confile.rtf uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v11 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v15 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csName:conrf csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} ß the newer version of the file has now been moved into the replicated folder downstream
<Downstream> 20080908 08:40:42.356 2596 INCO 5897 InConnection::UpdateProcessed Received Update. updatesLeft:0 processed:1 failures:0 sessionId:5 open:0 updateType:0 processStatus:0 connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} csName:conrf update: ß processing of the update is complete.
<Upstream> 20080908 08:40:42.370 2008 SRTR 2357 InitializeFileTransferAsyncState::ProcessIoCompletion Initialized connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} rdc:1 context:00000000,00000000,00000000 uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v11 gvsn{5CB120DE-D2C2-452A-8280-B45FC155224F}-v15 ptr:00981B38
<Downstream> 20080908 08:40:42.387 2596 INCO 6194 InConnection::CommitSession Connection in sync connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csId:{009349B5-8677-4352-AC4F-13BCC111BAA0} csName:conrf commitedSessionsWithUpdateFailures:0
<Downstream> 20080908 08:40:42.387 2596 UPMG 418 UpdateWorker::ConsumeUpdates No pending updates. connId:{2A41E070-E3EF-4F15-8CA0-4BC0F256D771} csName:conrf csId:{009349B5-8677-4352-AC4F-13BCC111BAA0}
Ned here. The gentle giants of the DFSR development team have posted a new step-by-step guide to configuring true read-only (one-way) replication in Windows Server 2008 R2 (aka Windows 7). As you probably know by now, this marks the first time DFSR supports this mechanism natively, through the use of a filter driver and fancy automagical topology shenanigans. Check it out:
Configuring a read-only replicated folder
And say hi to Mahesh for us.
In this scenario we will see a file renamed and how that change is replicated between servers. This is useful to understand in order to troubleshoot issues where problems within the USN journal, the DFSR JET database, and the network (including RPC) are preventing replication from working correctly.
(renamedfileupstream - Dfsr00005 - 2003.log and renamedfiledownstream - Dfsr00006 - 2003.log)
These are two Windows Server 2003 servers called 2003MEM01 and 2003MEM02 in the contoso.com domain. The logs are from 2003MEM01 where the file is renamed (upstream) and from 2003MEM02 where it the rename is replicated (downstream). Both servers are participating in the TESTRG2 replication group for the TESTRF2 replicated folder. The file was originally called “mikesdoc.txt” and was then renamed to “davesdoc.txt”.
<Upstream> 20080626 15:58:36.910 1440 LDBX 3567 Ldb::Insert Inserting idRecord: ß the original file creation leads to a DFSR database update. We examine this part of the log in order to understand the later rename operation fully.
+ fid 0x2000000002FF0 ß note the file ID as a cross-reference against the UID/GVSN
+ usn 0x9db60
+ present 1 ß the file is present in the replica set
+ gvsn {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v28
+ uid {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v28 ß note the UID and GVSN are a perfect match. This is the key indicator that the file was just created on this server upstream
+ clock 20080626 19:58:36.910
+ createTime 20080626 19:58:36.910 GMT
+ name mikesdoc.txt ß the file is currently named mikesdoc.txt
<snip – removed all the replication debug log churn that this generates>
<Upstream> 20080626 16:00:17.124 1440 LDBX 3684 Ldb::Update Updating idRecord: ß some time later, a user renames the file on the upstream server. This must be recorded in the DFSR database.
+ fid 0x2000000002FF0 ß note the file ID is unchanged
+ usn 0x9e800
+ recUpdateTime 20080626 19:58:37.200 GMT
+ gvsn {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v29 ß GVSN version is incremented to the high watermark on the server. There have been no other changes on the server so the version is only one higher.
+ uid {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v28 ß remember that UID will stay the same forever. This helps us track the file.
+ clock 20080626 20:00:17.114
+ createTime 20080626 19:58:04.143 GMT
+ hash CE2505D3-E4669977-250B31C1-100B67DE
+ similarity 2A242410-2E100D1A-191A340E-041A1018
+ name davesdoc.txt ß note the file name has changed.
<Upstream> 20080626 16:00:17.124 1440 USNC 2202 UsnConsumer::UpdateIdRecord ID record updated from USN_RECORD: ß the USN journal has been updated (it is an idiosyncrasy of a multi-threaded DFSR service logging that this does not write before the database update above. Technically the USN journal update *must* have happened first.
+ FileRefNumber: 0x2000000002ff0 ß note the matching file ID to the above records. Tracking this allows you to cross reference USN and DB record updates in the log.
+ USN: 0x9e800
+ TimeStamp: 20080626 16:00:17.114 Eastern Standard Time
+ Reason: Close Rename New Name ß the rename operation is made clearer
+ SecurityId: 0x1b5
+ FileAttributes: 0x20
+ FileNameLength: 24
+ FileName: davesdoc.txt
<Upstream> 20080626 16:00:17.124 1440 LDBX 1228 LdbManager::UpdateVersionVectorCache Wake up callback 00ADF868
<Upstream> 20080626 16:00:17.134 1456 SRTR 1257 SERVER_RequestVersionVector Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} seqNumber:6 changeType:all ß the upstream server is asked by the downstream for version vectors, as the4 upstream had sent a change notification earlier (this is not logged)
<Upstream> 20080626 16:00:17.134 1456 SRTR 1304 SERVER_AsyncPoll Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD}
<Upstream> 20080626 16:00:17.144 1456 SRTR 498 SERVER_RequestUpdates Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} credits:32 requestType:all ß upstream server receives a request for pending updates
<Upstream> 20080626 16:00:17.144 1456 SRTR 1304 SERVER_AsyncPoll Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD}
<Upstream> 20080626 16:00:17.154 1644 JOIN 1171 Join::SubmitUpdate Sent: uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v28 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v29 name:davesdoc.txt connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 ß information about the updated is sent to the downstream server
<Upstream> 20080626 16:00:17.164 1832 SRTR 1257 SERVER_RequestVersionVector Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} seqNumber:7 changeType:notify
<Upstream> 20080626 16:00:17.164 1644 INCO 2761 InConnection::RequestVvUp Requested upstream version vector. requestState:00A86E70 connId:{37048901-9F48-4AD8-ADA4-04D4DC682FD8} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 changeType:all
<Upstream> 20080626 16:00:17.164 1424 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{37048901-9F48-4AD8-ADA4-04D4DC682FD8} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00A8F4A0
<Upstream> 20080626 16:00:17.164 1424 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{37048901-9F48-4AD8-ADA4-04D4DC682FD8} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} reqType:VvUpRequest reqState:Completed status:0 ptr:00A86E70
<Upstream> 20080626 16:00:17.174 1424 INCO 2947 InConnection::ReceiveVvUp Received VvUp connId:{37048901-9F48-4AD8-ADA4-04D4DC682FD8} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 vvUp:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6} |-> { 10..29}
<Upstream> 20080626 16:00:17.174 1424 INCO 2954 InConnection::ReceiveVvUp Creating new session:3 requestState:00A86E70 connId:{37048901-9F48-4AD8-ADA4-04D4DC682FD8} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2
<Upstream> 20080626 16:00:17.174 1644 INCO 2787 InConnection::ContentSetContext::Hibernate Hibernating: connId:{37048901-9F48-4AD8-ADA4-04D4DC682FD8} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7}
<Downstream> 20080626 16:00:17.509 980 INCO 2761 InConnection::RequestVvUp Requested upstream version vector. requestState:00A86340 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 changeType:all
<Downstream> 20080626 16:00:17.509 1472 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00A8F4A0
<Downstream> 20080626 16:00:17.509 1472 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} reqType:VvUpRequest reqState:Completed status:0 ptr:00A86340
<Downstream> 20080626 16:00:17.519 1472 INCO 2947 InConnection::ReceiveVvUp Received VvUp connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 vvUp:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6} |-> { 10..29}
<Downstream> 20080626 16:00:17.519 1472 INCO 2954 InConnection::ReceiveVvUp Creating new session:3 requestState:00A86340 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2
<Downstream> 20080626 16:00:17.519 980 INCO 3347 InConnection::RequestUpdates Requesting updates. credits:32 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 requestType:all cursor:{00000000-0000-0000-0000-000000000000}-v0 delta::{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6} |-> { 29}
<Downstream> 20080626 16:00:17.519 1472 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00A8F4A0
<Downstream> 20080626 16:00:17.529 1472 INCO 3534 InConnection::ReceiveUpdates Upstream credits:32 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2
<Downstream> 20080626 16:00:17.529 1472 INCO 3597 InConnection::ReceiveUpdates Received: uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v28 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v29 fileName:davesdoc.txt session:3 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 ß all update info about the file name modification has been received. Note in all the logs previous there is no RDCGET, no RAWGET, no staging, and no indications of the file actually being moved. This is because a rename operation only requires metadata to be sent over the wire in RPC.
<Downstream> 20080626 16:00:17.529 980 MEET 1190 Meet::Install Retries:0 updateName:davesdoc.txt uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v28 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v29 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2 ß The ‘installation’ has succeeded (not that anything is actually being installed)
<Downstream> 20080626 16:00:17.529 980 LDBX 3684 Ldb::Update Updating idRecord: ß the DFSR database is updated downstream
+ fid 0x2000000002FEE
+ usn 0xa3f40
+ gvsn {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v29 ßnote the GVSN has been updated
+ uid {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v28
+ name davesdoc.txt
<Downstream> 20080626 16:00:17.529 980 MEET 2770 Meet::InstallMove -> DONE Install-move completed updateName:davesdoc.txt uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v28 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v29 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2 csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} ß ß at this point the file has been renamed in the replicated folder downstream
<Downstream> 20080626 16:00:17.529 1472 INCO 3661 InConnection::ReceiveUpdates Session has been closed. sessionId:3 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 ß the actual ‘replication’ operation is complete.
<Downstream> 20080626 16:00:17.529 980 INCO 4378 InConnection::UpdateProcessed Received Update. updatesLeft:0 processed:1 sessionId:3 open:0 updateType:0 processStatus:0 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 update:
+ gvsn {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v29
<Downstream> 20080626 16:00:17.529 1472 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-
In this scenario we will see a file deleted and how that change is replicated between 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.
(deletedfileupstream - Dfsr00004 - 2003.log and deletedfiledownstream - Dfsr00005 - 2003.log)
These are two Windows Server 2003 servers called 2003MEM01 and 2003MEM02 in the contoso.com domain. The logs are from 2003MEM01 where the file is deleted (upstream) and from 2003MEM02 where it the deletion is replicated (downstream). Both servers are participating in the TESTRG2 replication group for the TESTRF2 replicated folder. The file is called “goodbye.txt”.
<Upstream> 20080625 19:55:51.522 800 LDBX 3684 Ldb::Update Updating idRecord: ß the DFSR jet DB is updated because the file is changing (even a delete is a change to the state of the file; file references stay in the database for 30 days to allow for reanimation)
+ fid 0x2000000002FED
+ usn 0x81c50
+ recUpdateTime 20080625 23:55:41.318 GMT
+ present 0 ß The file does not exist in the content set anymore
+ gvsn {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v26 ß GVSN goes up (state changed)
+ uid {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v25
+ clock 20080625 23:55:51.502
+ createTime 20080625 23:55:41.217 GMT
+ name goodbye.txt
<Upstream> 20080625 19:55:51.532 800 USNC 2599 UsnConsumer::TombstoneOrDelete ID record tombstoned from USN_RECORD:ß USN journal must be updated to reflect the deletion.
+ FileRefNumber: 0x2000000002fed
+ ParentFileRefNumber: 0x5000000002fa7
+ USN: 0x81c50
+ TimeStamp: 20080625 19:55:51.502 Eastern Standard Time ß good to know the exact time as deletions are not usually important unless it was unexpected and root cause is being analyzed.
+ Reason: Close Rename New Name
+ SecurityId: 0x1c7
+ FileNameLength: 14
+ FileName: goodbye.txt
<Upstream> 20080625 19:55:51.532 800 LDBX 1228 LdbManager::UpdateVersionVectorCache Wake up callback 00AD6308
<Downstream> 20080625 19:55:51.546 3832 INCO 3347 InConnection::RequestUpdates Requesting updates. credits:32 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 requestType:all cursor:{00000000-0000-0000-0000-000000000000}-v0 delta::{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6} |-> { 26} ß downstream server request version vector of upstream server
<Downstream> 20080625 19:55:51.546 3928 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00A8F4A0
<Upstream> 20080625 19:55:51.582 1624 SRTR 1257 SERVER_RequestVersionVector Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} seqNumber:6 changeType:all ß VV request received.
<Upstream> 20080625 19:55:51.582 1624 SRTR 1304 SERVER_AsyncPoll Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD}
<Downstream> 20080625 19:55:51.586 3928 INCO 3534 InConnection::ReceiveUpdates Upstream credits:32 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 ß downstream server request
<Downstream> 20080625 19:55:51.586 3928 INCO 3597 InConnection::ReceiveUpdates Received: uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v25 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v26 fileName:goodbye.txt session:3 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 ß the ‘data’ is replicated. Keep in mind that when replicating metadata changes (file rename, attribute data, security data, or file deletion) the actual file is not sent over the wire. There is no staging in or out. Only information necessary to describe the metadata is sent via RPC; in this case, just the ‘delete’.
<Downstream> 20080625 19:55:51.586 3832 MEET 1190 Meet::Install Retries:0 updateName:goodbye.txt uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v25 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v26 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2 ß the update was received on the downstream.
<Downstream> 20080625 19:55:51.586 3832 MEET 3700 Meet::MoveOut Moving contents and children out of replica. newName:goodbye.txt-{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v25 updateName:goodbye.txt uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v25 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v26 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2record: ß in content set terms, files are never ‘deleted’. They are moved out of the content set.
+ fid 0x1000000002FE8
+ usn 0x883a0
+ recUpdateTime 20080625 23:55:41.331 GMT
+ present 1 ß the file is still present on the downstream server, we are in process here (on the upstream a file is just deleted and that’s it. On the downstream servers, it will have to transition its way into the ConflictAndDeleted folder.)
+ gvsn {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v25
+ clock 20080625 23:55:41.227
+ hash CC8863B9-2EAB0BC2-C669B493-00C79510
<Upstream> 20080625 19:55:51.592 1624 SRTR 498 SERVER_RequestUpdates Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} credits:32 requestType:all
<Upstream> 20080625 19:55:51.592 1624 SRTR 1304 SERVER_AsyncPoll Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD}
<Downstream> 20080625 19:55:51.596 3832 LDBX 3684 Ldb::Update Updating idRecord: ß now we update jet database downstream to reflect the deletion. The file has actually now been moved to the ConflictAndDeleted folder and the conflictanddeletedmanifest.xml has been updated (but this is not covered in the deuglogseverity=4 debug logs)
+ usn 0x88608
+ present 0 ß the file is no longer present in the content set
+ gvsn {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v26 ß the deletion necessitates updating the GVSN
<Downstream> 20080625 19:55:51.596 3832 MEET 3635 Meet::InstallTombstone -> DONE Install Tombstone complete updateName:goodbye.txt uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v25 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v26 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2 csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} ß the tombstone (deletion) process is completed downstream. The file is completely out of the content set.
<Downstream> 20080625 19:55:51.596 3928 INCO 3661 InConnection::ReceiveUpdates Session has been closed. sessionId:3 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2
<Downstream> 20080625 19:55:51.596 3832 INCO 4378 InConnection::UpdateProcessed Received Update. updatesLeft:0 processed:1 sessionId:3 open:0 updateType:0 processStatus:0 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 update: ß the single update from upstream was processed with no errors
+ present 0 ß file is no longer present
+ gvsn {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v26
<Downstream> 20080625 19:55:51.596 3928 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} reqType:UpdateRequest reqState:Completed status:0 ptr:00A86E70
<Upstream> 20080625 19:55:51.602 820 JOIN 1171 Join::SubmitUpdate Sent: uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v25 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v26 name:goodbye.txt connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 ß upstream server reports completion on the update operation.
<Upstream> 20080625 19:55:51.602 1624 SRTR 1257 SERVER_RequestVersionVector Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} seqNumber:7 changeType:notify
<Downstream> 20080625 19:55:51.606 3832 LDBX 1228 LdbManager::UpdateVersionVectorCache Wake up callback 00ADEE10
<Downstream> 20080625 19:55:51.606 3832 INCO 4617 InConnection::CommitSession Connection in sync connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD}
<Downstream> 20080625 19:55:51.606 3904 INCO 2787 InConnection::ContentSetContext::Hibernate Hibernating: connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7}