In this scenario we will see a Microsoft Word 2007 file modified 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.This also covers a practice often used by MS Office and other applications that use transitional and temporary files in the main file’s working directory.

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 modified (upstream) and from 2008MEM02 where it is replicated (downstream). Both servers are participating in the TESTRG3 replication group for the TESTRF3 replicated folder. The file is called “modifiedword2007.docx”. The file was already replicated previously.

<Upstream> 20080626 13:46:11.290 4040 USNC1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD:ßA temporary working file is created upstream, which is related to the real file the user just opened. The file is filtered because it has temporary attribute set as well as starts with a tilde (which is filtered by default)

+USN_RECORD:

+RecordLength:104

+MajorVersion:2

+MinorVersion:0

+FileRefNumber:0x300000000AC68ß note file ID for later, since a number of files will be created/renamed/overwritten in the Word 2007 processing

+ParentFileRefNumber: 0xF00000000A781

+USN:0xa5a270

+TimeStamp:20080626 13:46:11.290 Eastern Standard Time

+Reason:Close Data Extend File Createß file created

+SourceInfo:0x0

+SecurityId:0x0

+FileAttributes:0x22ß hidden bit set on a file

+FileNameLength:42

+FileNameOffset:60

+FileName:~$difiedword2007.docxß temporary working file name for autorecovery

+

<Upstream> 20080626 13:46:38.485 4040 USNC1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD:ß27 seconds later another pseudo-temporary file is created (not truly temporary but has a TMP extension that will be filtered by default by DFSR)

+USN_RECORD:

+RecordLength:88

+MajorVersion:2

+MinorVersion:0

+FileRefNumber:0x100000000AC69ß different File ID so we know it’s a different file

+FileName:4ED0A5C5.tmpß same file name as above (and it’s the same real file as File ID matches)

+

<Upstream> 20080626 13:46:38.505 4040 USNC2612 UsnConsumer::CreateNewRecord LDB Inserting ID Record:ß this file is created ‘new’. However this is actually a rename of the ‘4ED0A5C5.tmp’ file. Because this was previously filtered, it was not counted as a creation so the UID and GVSN will reflect a new file below.

+fid0x100000000AC69ßnote File ID matches the tmp file above

+usn0xa5a7c8

+uidVisible0

+filtered0

+journalWrapped0

+slowRecoverCheck0

+pendingTombstone0

+internalUpdate0

+dirtyShutdownMismatch0

+meetInstallUpdate0

+meetReanimated0

+recUpdateTime16010101 00:00:00.000 GMT

+present1ß now live in the replicated folder

+nameConflict0

+attributes0x20

+ghostedHeader0

+data 0

+gvsn{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79ß GVSN and UID match, so this is considered a new file (again, even though not truly new, previous version was filtered out)

+uid{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79

+parent{BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1

+fence16010101 00:00:00.000

+clockDecrementedInDirtyShutdown 0

+clock20080626 17:46:38.505 GMT (0x1c8d7b495a970e4)

+createTime20080626 17:46:38.505 GMT

+csId{BDD12194-91A1-4227-AB6B-9C252C6EACB8}

+hash00000000-00000000-00000000-00000000

+similarity00000000-00000000-00000000-00000000

+namemodifiedword2007.docxß Note the name is the original file name now.

<Upstream> 20080626 13:46:38.555 4040 USNC2777 UsnConsumer::TombstoneOrDelete LDB Updating ID Record:ß the original copy of the file is being deleted as it gets overwritten by the copy of the file upstream (this is still Word’s internal behavior, we have not yet done any replication obviously)

+fid0x300000000AC66ß the file ID is different because this was the older file

+usn0xa5a900

+uidVisible1

+filtered0

+journalWrapped0

+slowRecoverCheck0

+pendingTombstone0

+internalUpdate0

+dirtyShutdownMismatch0

+meetInstallUpdate0

+meetReanimated0

+recUpdateTime20080626 17:34:11.530 GMT

+present0ß no longer in the replicated folder

+nameConflict0

+attributes0x20

+ghostedHeader0

+data0

+gvsn{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v81ß Deletion still counts as a version increase

+uid{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v76ß note the old UID

+parent{BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1

+fence16010101 00:00:00.000

+clockDecrementedInDirtyShutdown 0

+clock20080626 17:46:38.515 GMT (0x1c8d7b495aaf803)

+createTime20080626 17:30:25.894 GMT

+csId{BDD12194-91A1-4227-AB6B-9C252C6EACB8}

+hash22894EE1-C5DBE0DE-F63EF65F-B42162E4

+similarity3622212A-1A3A3706-23381636-00212E2E

+namemodifiedword2007.docx

+

<Upstream> 20080626 13:46:38.555 4040 USNC2782 UsnConsumer::TombstoneOrDelete ID record tombstoned from USN_RECORD:ß USN journal updated to reflect the ‘deletion’ of the original word file, as it is now filtered.

+USN_RECORD:

+RecordLength:88

+MajorVersion:2

+MinorVersion:0

+FileRefNumber:0x300000000AC66ß old file ID

+ParentFileRefNumber: 0xF00000000A781

+USN:0xa5a900

+TimeStamp:20080626 13:46:38.515 Eastern Standard Time

+Reason:Close Object ID Change Rename New Nameß note how Word is renaming the file again prior to deletion.

<Downstream> 20080626 13:46:38.967 3980 INCO4868 InConnection::ReceiveUpdates Received: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 fileName:modifiedword2007.docx session:2 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 ß note how DFSR is trying to replicate two versions of the original file, with two separate UID’s. This is due to how Word 2007 makes copies of the files and overwrites them, leading to two distinct replication change packages being done. One is a delete and one is a replicate.

<Downstream> 20080626 13:46:38.987 4036 MEET4867 Meet::MoveOut Moving contents and children out of replica. newName:modifiedword2007-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v77.docx updateName:modifiedword2007.docx uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v76 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v81 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 record: ß Original version of the file that was previous replicated is deleted, because the original one was truly deleted upstream (not modified – Word 2007 does not truly modify files). A moveout is a delete in DFSR.

+fid0x100000000A766

+usn0x929d88

+uidVisible1

+filtered0

+journalWrapped0

+slowRecoverCheck0

+pendingTombstone0

+internalUpdate0

+dirtyShutdownMismatch0

+meetInstallUpdate1

+meetReanimated0

+recUpdateTime20080626 17:34:12.343 GMT

+present1

+nameConflict0

+attributes0x20

+ghostedHeader0

+data0

+gvsn{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v77 ß previous version of the file

+uid{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v76ß different UID than our new file we just ‘modified’

+parent{BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1

+fence16010101 00:00:00.000

+clockDecrementedInDirtyShutdown 0

+clock20080626 17:34:11.530 GMT (0x1c8d7b2d86e2ef4)

+createTime20080626 17:30:25.894 GMT

+csId{BDD12194-91A1-4227-AB6B-9C252C6EACB8}

+hash22894EE1-C5DBE0DE-F63EF65F-B42162E4

+similarity3622212A-1A3A3706-23381636-00212E2E

+namemodifiedword2007.docx

+

<Upstream> 20080626 13:46:38.996 4032 OUTC784 OutConnection::OpenFile Received request for update:ß file is being served upstream

+present1

+nameConflict0

+attributes0x20

+ghostedHeader0

+data0

+gvsn{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80

+uid{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79ß this is our new version of the file

+uid{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v76ß UID is for the older file

+parent{BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1

+fence16010101 00:00:00.000

+clockDecrementedInDirtyShutdown 0

+clock20080626 17:46:38.515 GMT (0x1c8d7b495aaf803)

+createTime20080626 17:30:25.894 GMT

+csId{BDD12194-91A1-4227-AB6B-9C252C6EACB8}

+hash22894EE1-C5DBE0DE-F63EF65F-B42162E4

+similarity3622212A-1A3A3706-23381636-00212E2E

+namemodifiedword2007.docx

+

<Downstream> 20080626 13:46:38.997 4036 MEET4794 Meet::InstallTombstone -> DONE Install Tombstone complete updateName:modifiedword2007.docxuid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v76 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v81 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} ß The file is tombstoned in the database. This means that a reference to the file remains for 30 days in the DFSR DB downstream but the actual file has now been removed.

<Upstream> 20080626 13:46:39.106 4032 CSMG4844 ContentSetManager::UpdateHash LDB Updating ID Record:ß the database is updated to reflect the file hash of the later version of the file. Apparently the file has changed somewhat as we have a new hash.

<Upstream> 20080626 13:46:39.276 4032 OUTC1534 OutConnection::OpenFile Sent file uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 name:modifiedword2007.docx fileSize:397852 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} rgName:TestRG3 ß the v80 version of the file is now being served from upstream

<Downstream> 20080626 13:46:39.378 2928 STAG987 StageWriter::AbortDownloadStage Successfully aborted staging file 1-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v1-Downloading.frx. Deleted.ß downstream, the previously staged copy of the file (v79) must be deleted as it is being superceded by the quickly-sent next version of v80.

<Downstream> 20080626 13:46:39.378 2928 RDCX1590 [WARN] Rdc::SeedFile::UseRelated (Ignored) Failed. uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 fileName:modifiedword2007.docx csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} (related: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v1 fileName:modifiedword2007.docx csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}) Error:[Error:9024(0x2340) Rdc::SeedFile::UseRelated rdc.cpp:1499 2928 C The file meta data is not synchronized with the file system]ß The RDC signature calculation process must be stopped while it was working on the previously staged file. The message about ‘meta data not synched’ refers to this as well.

<Downstream> 20080626 13:46:40.039 2928 INCO5610 InConnection::LogTransferActivity Received RAWGET uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 fileName:modifiedword2007.docx connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} stagedSize:397852 ß the replication of the newer version of file is complete. Note the RAWGET which shows RDC could not be used in this scenario.

In this scenario we will see a Microsoft Word 2003 file modified using MS Word 2003 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. This also covers a practice often used by MS Office (and to a lesser extent other) applications that use transitional and temporary files in the main file's working directory. Note that other Office file types like Excel, PowerPoint, etc. may behave differently.

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 modified (upstream) and from 2008MEM02 where it is replicated (downstream). Both servers are participating in the TESTRG3 replication group for the TESTRF3 replicated folder. The file is called "word2003large.doc". The file was already replicated previously.

In this scenario we will see a file modified 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.

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 created (upstream) and from 2003MEM02 where it is replicated (downstream). Both servers are participating in the TESTRG2 replication group for the TESTRF2 replicated folder. The file is called "setuplog.txt". The file was already staged previously.

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.

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.

Ned here. Today's post is part three in the series, where begin examining specific scenarios in the debug logs. This post is a critical read as it explains how I will go through all the debug logs; without reviewing this section below the remaining logs will be more difficult to understand.

Various logging scenarios

Now we will dissect DFSR debug logs from Windows Server 2003 R2 and Windows Server 2008. These cover a number of scenarios including both normal operations as well as common error states. It is critical that an engineer become familiar with the working scenarios of DFSR in order to see problem states more clearly. Review the two previous posts on the debug log format (Part 1 and Part 2) before continuing.

All logs referenced here are in default debug log severity 4 mode unless otherwise stated. All logs are included as downloads with each blog post. All analysis done on Windows Server 2003 R2 Enterprise x86 with SP2 with hotfixes KB948833 and KB944804 installed or on Windows Server 2008 Enterprise x86 RTM with no hotfixes installed.

IMPORTANT NOTES

An artificial field called <upstream> has been added to every full line for the upstream log file and will be highlighted yellow – these indicate the beginning of a new full line.

An artificial field called <downstream> has been added to every full line for the downstream log file will be highlighted pink – these indicate the beginning of a new full line.

Note: When reading the sample logs below, keep in mind that they are actually a combination of two actual debug logs. Hopefully this improves the understanding of the 'give and take' nature of file replication between nodes.

Sections that are highlighted turquoise are notable for that line.

Comments on a given line are called out with arrowed (ß) red text and are not included in the logs.

Not all debug file lines are necessarily included as some will be irrelevant or are repeated several times through looping.

Remember to review previous sections for details on all fields shown below.

The logs here are unrealistic in their time synchronization (all scenarios were reproduced using a single virtual host). Keep in mind that time could be off by up to five minutes of relative skew in a real world scenario, and that debug logs are written using local time of the server, not GMT/UTC time.

File Added to Replicated Folder on Windows Server 2008

In this scenario we will see a 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.

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 "bigdoc.rtf". It is larger than 64KB so it will be staged for RDC usage; it is not on the compression exclusion list so it will be compressed in staging with XPRESS.

Nested Field Format

When examining the nested (+) entries it is important to understand all of the fields that can be displayed in the debug logs. These fields give detailed information about file and folder replication, especially regarding database entries, USN changes, and RDC data. These are implemented through LogNewLine.

Below is a table describing all of these nested fields and their data output that you will see in the debug logs. All entries marked with an asterisk (*) are Windows Server 2008 only. Otherwise they apply to both Windows Server 2003 R2 as well as 2008. There is also an example of the log entry for each table.

Understanding DFSR Module ID's

Examining the third entry in any non-nested line of the DFSR debug logs can give you quick insight into what overall type of component functionality DFSR is working on. These are referred to as "Module ID's". Note the highlighted sections below in the sample log entries:

The first example is in a synchronization module organized under the 'JOIN' component of DFSR. The next example is in a configuration module under the 'CFAD' component.

Below are all the module IDentries that can be mapped back to more general functional areas of DFSR. By getting to know these we can tell at a glance roughly what a given line is referencing and if it bears further attention based on what we are troubleshooting. All entries with an asterisk (*) are Windows Server 2008 only. Entries with two asterisks (**) are Windows Server 2003 R2 only.

Functional Area

MODULE_ID References

Description

Configuration

CFAD, CCTX, CPAR, CREG, CREP, CVOL, CXML, CMGR, ADWR*, HIST*, SYSM*

Functions related to the configuration of DFSR in LDAP, the registry, WMI, and in the XML files