Understanding DFSR debug logging (Part 3: The Log Scenario Format, File Added to Replicated Folder on Windows Server 2008)

Understanding DFSR debug logging (Part 3: The Log Scenario Format, File Added to Replicated Folder on Windows Server 2008)

  • Comments 1
  • Likes

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

(addedlargefileupstream - Dfsr00011 - 2008.log and addedlargefiledownstream - Dfsr00008 - 2008.log)

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.

<Upstream> 20080625 11:50:03.505 3676 USNC 2612 UsnConsumer::CreateNewRecord LDB Inserting ID Record: ß the file is created in the replicated folder on 2008MEM01. This has caused the USN journal to be updated and information about the file to be sent to the DFSR JET database.
+    fid 0x300000000A7DA ß unique File ID used to track this file in the database and USN journal
+    usn 0x9ed8a8
+    uidVisible 0 ß because the file is still being processed for the first time, its UID is not yet visible and the file is not yet considered ready for replication.
+    filtered 0 ß the file does not match any filtering exclusions
+    journalWrapped 0 ß we are not writing the USN update to recover from a USN journal wrap
+    slowRecoverCheck 0
+    pendingTombstone 0
+    internalUpdate 0
+    dirtyShutdownMismatch 0
+    meetInstallUpdate 0 ß we are not replicating this file in from some other DFSR server
+    meetReanimated 0 ß this file was not reanimated (i.e. restored from recycle bin or a backup)
+    recUpdateTime 16010101 00:00:00.000 GMT
+    present 1 ß the file exists
+    nameConflict 0
+    attributes 0x20 ß this is a file, not a folder, per the rules of GetFileAttributes. Do not assume that because the name field below has (or lacks) an extension that the object is a file or folder; attributes always tells truth
+    ghostedHeader 0
+    data 0
+    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 ß this file has never been modified in the RF so the GVSN is the same as the UID.
+    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 ß this is the files original UID
+    parent {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}-v1 ß this is the parent folder (which is c:\testrf)
+    fence 16010101 00:00:00.000
+    clockDecrementedInDirtyShutdown 0
+    clock 20080625 15:50:03.505 GMT (0x1c8d6db21e76e97)
+    createTime 20080625 15:50:03.505 GMT ß the file was 'created' (i.e. added to this replicated folder) at this time
+    csId {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}
+    hash 00000000-00000000-00000000-00000000 ß the file does not yet have a hash associated at this point
+    similarity 00000000-00000000-00000000-00000000 ß the file does not yet have similarity data at this point
+    name bigdoc.rtf ß this is the actual file name in question
+    
<Upstream> 20080625 11:50:03.555 3676 USNC 2615 UsnConsumer::CreateNewRecord ID record created from USN_RECORD: ß extended information about the actions on the file is written into the USN journal
+    USN_RECORD:
+    RecordLength: 80 ß amount of data in bytes needed to store information about this file in the journal
+    MajorVersion: 2
+    MinorVersion: 0
+    FileRefNumber: 0x300000000A7DA ß The File ID. This is useful to ensure you are looking at the same update as above.
+    ParentFileRefNumber: 0x100000000A6EE
+    USN: 0x9ed8a8
+    TimeStamp: 20080625 11:50:03.505 Eastern Standard Time
+    Reason: Basic Info Change Close Data Extend Data Overwrite File Create ß what change has happened to the file. In this case it was 'created' (keeping in mind that creation is relative to DFSR; if a file is copied in to an RF, it is created in USN terms)
+    SourceInfo: 0x0
+    SecurityId: 0x0
+    FileAttributes: 0x20
+    FileNameLength: 20
+    FileNameOffset: 60
+    FileName: bigdoc.rtf ß more confirmation that this is the same file as above.
+
<Upstream> 20080625 11:50:03.575 2372 SRTR 1880 SERVER_RequestVersionVector Received from connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} seqNumber:4 changeType:all
<Upstream> 20080625 11:50:03.575 2372 SRTR 1927 SERVER_AsyncPoll Received from connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} ß the upstream 2008mem01 server receives a poll asking for any updates in response to a change notification.
<Downstream> 20080625 11:50:03.582 3768 INCO 4619 InConnection::RequestUpdates Requesting updates. credits:32 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf requestType:all cursor:{00000000-0000-0000-0000-000000000000}-v0 delta::{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 41} ß downstream server 2008mem02 sends a request for list of pending update (new/changed/deleted files) and states that he has 32 credits free currently and should be considered for downloads.
+    
<Downstream> 20080625 11:50:03.582 4068 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00F4C978 ß downstream server 2008mem02 receives a positive response that his request is being evaluated.
<Upstream> 20080625 11:50:03.595 2372 SRTR 882 SERVER_RequestUpdates Received from connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} credits:32 requestType:all ß Upstream 2008mem01 receives the request for list of updates.
<Upstream> 20080625 11:50:03.595 2372 SRTR 1927 SERVER_AsyncPoll Received from connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE}
<Upstream> 20080625 11:50:03.595 288 JOIN 1122 Join::SubmitUpdate LDB Updating ID Record: ß the file is now being truly committed to the content set and made available for replication
+    fid 0x300000000A7DA
+    usn 0x9ed8a8
+    uidVisible 1 ß ready to be replicated out
+    filtered 0
+    journalWrapped 0
+    slowRecoverCheck 0
+    pendingTombstone 0
+    internalUpdate 0
+    dirtyShutdownMismatch 0
+    meetInstallUpdate 0
+    meetReanimated 0
+    recUpdateTime 20080625 15:50:03.515 GMT
+    present 1
+    nameConflict 0
+    attributes 0x20
+    ghostedHeader 0
+    data 0
+    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41
+    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 ß still the same file (always check – there may be hundreds of files being updated simultaneously in a content set after all, with the same name)
+    parent {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}-v1
+    fence 16010101 00:00:00.000
+    clockDecrementedInDirtyShutdown 0
+    clock 20080625 15:50:03.505 GMT (0x1c8d6db21e76e97)
+    createTime 20080625 15:50:03.475 GMT
+    csId {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}
+    hash 00000000-00000000-00000000-00000000
+    similarity 00000000-00000000-00000000-00000000
+    name bigdoc.rtf
+    
<Downstream> 20080625 11:50:03.602 4068 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 ß The downstream server starts the process of getting the list of pending file updates
<Downstream> 20080625 11:50:03.602 4068 INCO 4868 InConnection::ReceiveUpdates Received: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 fileName:bigdoc.rtf session:2 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf ß The downstream server receives update information about the replication-pending file. This includes the UID, GVSN, name, and content set it belongs to.
<Downstream> 20080625 11:50:03.602 3768 MEET 1207 Meet::Install Retries:0 updateName:bigdoc.rtf uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csName:testrf updateType:remote ß downstream creates its actual pulling session as a prelude to transferring the file
<Downstream> 20080625 11:50:03.602 4068 INCO 4932 InConnection::ReceiveUpdates Session has been closed. sessionId:2 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf ß downstream has all the information about the file update to take place.
<Downstream> 20080625 11:50:03.602 3080 INCO 3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00F954C8 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf changeType:notify
<Downstream> 20080625 11:50:03.602 4068 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} reqType:UpdateRequest reqState:Completed status:0 ptr:00F4CA70 ß downstream server now actually requests the file through RPC
<Upstream> 20080625 11:50:03.605 288 JOIN 1167 Join::SubmitUpdate Sent: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 name:bigdoc.rtf connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf ß the upstream is satisfied that the downstream needs the file. The upstream server now prepares the file for being replicated by the downstream.
<Upstream> 20080625 11:50:03.625 3104 OUTC 784 OutConnection::OpenFile Received request for update: ß the file is opened for copying into staging directory
+    present 1
+    nameConflict 0
+    attributes 0x20
+    ghostedHeader 0
+    data 0
+    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41
+    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 ß same file
+    parent {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}-v1
+    fence 16010101 00:00:00.000
+    clockDecrementedInDirtyShutdown 0
+    clock 20080625 15:50:03.505 GMT (0x1c8d6db21e76e97)
+    createTime 20080625 15:50:03.475 GMT
+    csId {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}
+    hash 00000000-00000000-00000000-00000000
+    similarity 00000000-00000000-00000000-00000000
+    name bigdoc.rtf
+     rdcDesired:1 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} rgName:TestRG ß RDC can be used if possible (not RDC will be used)
<Upstream> 20080625 11:50:03.625 3104 MRSH 4615 Marshaller::Marshal FileAttrs in metadata : 0x20 ß metadata about file marshaled for RPC
<Upstream> 20080625 11:50:05.388 3104 CSMG 4844 ContentSetManager::UpdateHash LDB Updating ID Record: ß as we stage the file, it must be compressed with XPRESS and the hash/similarity information added. This happens below.
+    fid 0x300000000A7DA
+    usn 0x9ed8a8
+    uidVisible 1
+    filtered 0
+    journalWrapped 0
+    slowRecoverCheck 0
+    pendingTombstone 0
+    internalUpdate 0
+    dirtyShutdownMismatch 0
+    meetInstallUpdate 0
+    meetReanimated 0
+    recUpdateTime 20080625 15:50:03.515 GMT
+    present 1
+    nameConflict 0
+    attributes 0x20
+    ghostedHeader 0
+    data 0
+    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41
+    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41
+    parent {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}-v1
+    fence 16010101 00:00:00.000
+    clockDecrementedInDirtyShutdown 0
+    clock 20080625 15:50:03.505 GMT (0x1c8d6db21e76e97)
+    createTime 20080625 15:50:03.475 GMT
+    csId {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}
+    hash F91CD2BD-989749DC-EC8012D0-742AB147
+    similarity 2008271D-2E11290A-2A212F0C-0E301F3F
+    name bigdoc.rtf
+ ß We will see slightly more detail in the staging process if we enable debuglogseverity=5.    
<Upstream> 20080625 11:50:05.648 3104 ASYN 510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:
<Upstream> 20080625 11:50:05.648 3104 STAG 799 StageWriter::CompleteDownloadStage Completed download or stage file 41-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41-Downloaded.frx ß the staged version of the file is ready. Note how the staged name is based on concatenation of the UID and GVSN names of the file.
<Upstream> 20080625 11:50:05.648 3104 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
<Upstream> 20080625 11:50:05.648 3104 OUTC 1534 OutConnection::OpenFile Sent file uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 name:bigdoc.rtf fileSize:1318071 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} rgName:TestRG ß the upstream side of the RPC connection lets the file be pulled to the downstream
<Upstream> 20080625 11:50:05.648 3104 SRTR 2357 InitializeFileTransferAsyncState::ProcessIoCompletion Initialized connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} rdc:1 context:00F585B0,0101B728,00000000 uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 gvsn{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 ptr:00F53C90 ß the file is actually transferred over (from the upstream server's perspective. Remember that replication is pull-based from the downstream server and that it will appear that the replication is actually done in the upstream debug logs before the downstream, as the downstream has more work to do for the replication to complete.
<Downstream> 20080625 11:50:06.006 3768 INCO 5610 InConnection::LogTransferActivity Received RAWGET uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 fileName:bigdoc.rtf connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} stagedSize:1318071 ß log the statistics about how the transfer proceeded
<Upstream> 20080625 11:50:06.009 2372 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
<Downstream> 20080625 11:50:06.156 3768 ASYN 510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:
<Downstream> 20080625 11:50:06.156 3768 STAG 799 StageWriter::CompleteDownloadStage Completed download or stage file 41-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41-Downloaded.frx ß the file has been replicated into the staging directory on the downstream server.
<Downstream> 20080625 11:50:06.156 3768 MRSH 3959 MarshalContext::Initialize Create file:[bigdoc-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41.rtf] with attributes:0x20 ß the file is un-marshaled
<Downstream> 20080625 11:50:06.156 3768 MEET 2585 Meet::TransferToInstalling Transferring content from staging area into Installing updateName:bigdoc.rtf uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csName:testrf ß the file is copied from staging into the Installing directory
<Downstream> 20080625 11:50:07.398 3768 ASYN 510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:
<Downstream> 20080625 11:50:07.398 3768 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
<Downstream> 20080625 11:50:07.398 3768 MEET 2032 Meet::Download Download Succeeded : true updateName:bigdoc.rtf uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csName:testrf csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} ß downstream server now has the file in its entirety and is ready to move it into the replicated folder content set.
<Downstream> 20080625 11:50:07.398 3768 MEET 2837 Meet::InstallRename File moved. rootVolume:{3EA8BD01-416E-11DD-A317-806E6F6E6963} parentFid:0x100000000A6D1 fidInInstalling:0x600000000A5EB usn:0x8c4858 updateName:bigdoc.rtf uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csName:testrf ß the file is moved from Installing into the actual replicated folder c:\testrf
<Downstream> 20080625 11:50:07.398 3768 MEET 6759 Meet::InsertIdRecord LDB Inserting ID Record: ß the above move necessitates a USN journal update and write into the DFSR database
+    fid 0x600000000A5EB ß we have a new downstream server-specific File ID
+    usn 0x8c4858
+    uidVisible 1
+    filtered 0
+    journalWrapped 0
+    slowRecoverCheck 0
+    pendingTombstone 0
+    internalUpdate 0
+    dirtyShutdownMismatch 0
+    meetInstallUpdate 1 ß update occurred because the file was replicated in
+    meetReanimated 0
+    recUpdateTime 16010101 00:00:00.000 GMT
+    present 1
+    nameConflict 0
+    attributes 0x20
+    ghostedHeader 0
+    data 0
+    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41
+    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41
+    parent {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}-v1
+    fence 16010101 00:00:00.000
+    clockDecrementedInDirtyShutdown 0
+    clock 20080625 15:50:03.505 GMT (0x1c8d6db21e76e97)
+    createTime 20080625 15:50:03.475 GMT
+    csId {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}
+    hash F91CD2BD-989749DC-EC8012D0-742AB147
+    similarity 2008271D-2E11290A-2A212F0C-0E301F3F
+    name bigdoc.rtf
+    
<Downstream> 20080625 11:50:07.468 3768 MEET 2949 Meet::InstallRename -> DONE Install-rename completed updateName:bigdoc.rtf uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csName:testrf csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} ß completed moving file into the true RF location
<Downstream> 20080625 11:50:07.468 3768 INCO 5897 InConnection::UpdateProcessed Received Update. updatesLeft:0 processed:1 failures:0 sessionId:2 open:0 updateType:0 processStatus:0 connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf update: ß completed replicating in this pending batch of files.
+    present 1
+    nameConflict 0
+    attributes 0x20
+    ghostedHeader 0
+    data 0
+    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41
+    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v41
+    parent {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}-v1
+    fence 16010101 00:00:00.000
+    clockDecrementedInDirtyShutdown 0
+    clock 20080625 15:50:03.505 GMT (0x1c8d6db21e76e97)
+    createTime 20080625 15:50:03.475 GMT
+    csId {175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}
+    hash F91CD2BD-989749DC-EC8012D0-742AB147
+    similarity 2008271D-2E11290A-2A212F0C-0E301F3F
+    name bigdoc.rtf
+    
<Downstream> 20080625 11:50:07.468 3768 INCO 6194 InConnection::CommitSession Connection in sync connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf commitedSessionsWithUpdateFailures:0 ß replication session completed with no errors
<Downstream> 20080625 11:50:07.468 3768 UPMG 418 UpdateWorker::ConsumeUpdates No pending updates. connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csName:testrf csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} ß downstream does not need any further updates to files from upstream.
<Downstream> 20080625 11:50:07.468 3080 INCO 3779 InConnection::ContentSetContext::Hibernate Hibernating: connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} ß downstream server hibernates its connection until next time.

Next up, I'll go through what a small (under 64KB) file looks like during replication, when RDC will not be used.

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
Attachment: large-file-added-debug-logs.zip
  • Thanks as always ...

    Appreciate the time and effort you put in to color code for readability. Please continue that.