Blog - Title

March, 2009

  • How to Properly Disable Offline Files in Windows Vista

    Hi, it's Adam Conkle again from the Directory Services team. Today's posting covers how to correctly disable Offline Files in Windows Vista. I recently had a case where the customer was experiencing undesirable behavior with a file share only when the file server was accessed from their Windows Vista machines.

    The symptoms were:

    1. Files saved to the file share from the Vista machines will not update the file on the file server, yet the changes appear when accessed on the Vista machine.

    2. Files and folders that have been deleted from the file server continue to appear when the file share is accessed from the Vista machines. The files and folders cannot be deleted from the Vista machines because the files do not exist.

    The customer advised that they had chosen to disable Offline Files on all of their Vista machines. I looked at Control Panel and Offline Files was set to Disabled. I then looked at Services.msc and the Offline Files service was disabled. Looks good, right?

    image

    image

    Next, I decided it would be a good idea to get a Process Monitor capture while we reproduce the above symptoms. Analysis of the capture showed me that Explorer.exe was not accessing the UNC path as expected, but rather was accessing C:\Windows\CSC\<namespace_path_for_share>. That's odd. You're probably thinking: "Why is Explorer.exe trying to access the Client Side Caching database when Offline Files has been disabled?"

    That is a great question, and here is the answer:

    Client Side Caching has a kernel driver that is loaded at startup when Offline Files is enabled. You can check the status of the driver by opening System Information (Start > Run > msinfo32 > System Summary > Software Environment > System Drivers). In the name column you will find "csc" with a description of "Offline Files Driver". When Offline Files is truly disabled, the Start Mode column should be set to "Disabled"; otherwise it will be set to "System" which means it is loaded at system startup.

    image

    In my case, the customer's driver was set to "System" even though the Offline Files GUI and the Offline Files service were both disabled. Offline Files on her Vista machines was in a halfway enabled state. No synchronization with the file server was taking place, but Explorer.exe was still directed to look at the CSC database because the kernel driver was loaded.

    When the customer disabled Offline Files on the Vista machines, she manually disabled the Offline Files service on each machine, and she never made any change to the Offline Files GUI in Control Panel. I found that when you only disable the service, the Offline Files GUI does get updated and shows "Disabled", but it leaves the kernel driver startup mode set to "System". If you disable Offline Files via the Control Panel GUI, the service is disabled and the kernel driver is disabled as well. When Offline Files is disabled via the Control Panel GUI, you will be prompted to reboot the machine for this to take effect (so that the kernel driver can be unloaded).

    The supported way to disable Offline Files is to use the Offline Files GUI in Control Panel, Group Policy, or WMIC.

    To enable/disable Offline Files via Group Policy:

    This is a Computer Configuration setting under Administrative Templates\Network\Offline Files named "Allow of Disallow use of the Offline Files feature". Once the GPO applies, a reboot is required for the setting to take effect.

    image

    To enable/disable Offline Files via WMIC:

    We use the Enable method of Win32_OfflineFilesCache to enable or disable offline files. Simply pass the Enable method a Boolean value.

    Example command:

    image

    As noted in the output, a reboot is required for the new setting to take effect.

    If you have gotten your Vista machines into the state described above, enable Offline Files via one of the supported methods described above, reboot, disable Offline Files using a supported method, and then reboot once again.

    Thanks,

    Adam ‘Axe Body Wash’ Conkle

  • Understanding DFSR Debug Logging (Part 1: Logging Levels, Log Format, GUID’s)

    Ned here again. Today begins a 21-part series on using the DFSR debug logs to further your understanding of Distributed File System Replication. While there are specific troubleshooting scenarios that will be covered, the most important part of understanding any products logging is making sure you are comfortable with it before you have errors. That way you have some point of reference if things go wrong.

    As you can probably guess, these posts were a long time in development. They are based on an internal DFSR whitepaper I have worked on for six months, and which went through review by a number of excellent folks here in Support, Field Engineering, and the Product Group itself. Except for the removal of all private source code references, this series is otherwise unchanged.

    I'll start with a couple posts on the logs themselves, how they are formatted, how they can be controlled, etc. Then I'll dig into scenarios in detail, for both Windows Server 2003 R2 and Windows Server 2008. Don't feel like you have to read and memorize everything – this series is a reference guide as well.

    And yes, there will be a complete downloadable copy of this series in a few common file formats when the series is done.

    Logging levels

    DFSR writes circular log files in %systemroot%\debug that automatically compress with the GZ archive format. The debug logs can have varying levels of detail verbosity, to control how much or how little data you want written. It is also possible to control how many logs to maintain before overwriting the oldest ones, how many entries to store in each log, where the logs are stored, and whether or not logging should run. Under default log settings they should never occupy more than ~50MB of space on Windows Server 2003 R2 servers.

    The following controls the log settings and describes the defaults:

    SETTING: Debug Log Severity
    Default: 4
    Range: 1-5
    WMIC syntax:

    wmic /namespace:\\root\microsoftdfs path dfsrmachineconfig set debuglogseverity=5

    SETTING: Debug Log Messages
    Default: 200000
    Range: 1000 to 4294967295 (FFFFFFFF)
    WMIC syntax:

    wmic /namespace:\\root\microsoftdfs path dfsrmachineconfig set maxdebuglogmessages=500000

    SETTING: Debug Log Files
    Default: 100
    Range: 1 to 10000
    WMIC syntax:

    wmic /namespace:\\root\microsoftdfs path dfsrmachineconfig set maxdebuglogfiles=200

    SETTING: Debug Log File Path
    Default: %windir%\debug
    WMIC syntax:

    wmic /namespace:\\root\microsoftdfs path dfsrmachineconfig set debuglogfilepath="d:\dfsrlogs"

    NOTE: The path must be created manually; if not, at service restart, the default value %windir%\debug will be used.

    SETTING: Enable Debug Logging (NOTE: Debug logging is enabled by default)
    Default: TRUE
    Range: TRUE or FALSE
    WMIC syntax:

    wmic /namespace:\\root\microsoftdfs path dfsrmachineconfig set enabledebuglog=true

    The WMIC.EXE commands above are actually modifying the DfsrMachineConfig.XML file that is stored in the %systemdrive%\system volume information\dfsr\config. It will populate the DfsrDebug tags. If running with defaults, these would not be populated – in the example below debug log severity is now at 5:

    - <DfsrDebug>
    <EnableDebugLog>true</EnableDebugLog>
    <DebugLogFilePath>C:\WINDOWS\debug</DebugLogFilePath>
    <MaxDebugLogFiles>100</MaxDebugLogFiles>
    <DebugLogSeverity>5</DebugLogSeverity>
    <MaxDebugLogMessages>200000</MaxDebugLogMessages>
    </DfsrDebug>

    When setting Debug Log Severity you are influencing how verbose the logs are – i.e. what do we consider important enough to write. Here is a brief table:

    Level

    Setting in DFSR    

    Flag Logged

    Explanation

    0

    LogLevelNone

    N/A

    Write nothing

    1

    LogLevelAlways

    N/A

    Write log header information only

    2

    LogLevelError

    [ERROR]

    Write error events and all others above

    3

    LogLevelWarn

    [WARN]

    Write warning events and all others above

    4

    LogLevelInfo

    N/A

    Write informational events and all others above

    5

    LogLevelTrace

    N/A

    Write special tracing events and all others above

    Since the default is 4, DFSR will log everything that occurs except for tracing details. Tracing details are called out further in this guide, and are only necessary to activate under very specific troubleshooting scenarios.

    The debug log format

    The DFSR debug logs use a consistent, predictable format that consists of:

    Header – written at the top of each log file and contains (for example):

    * FRS Log Sequence:1 Index:1 Computer:2003MEM20 TimeZone:Eastern Standard Time (GMT-05:00) Build:[Feb 16 2007 20:14:20 built by: srv03_sp2_rtm] Enterprise=1
    * Configuration logLevel:4 maxEntryCount:200000 maxFileCount:100 logPath:\\.\C:\WINDOWS\debug\

    Field

    Description

    FRS Log Sequence & Index

    Describe which logs these are relative to the circular wrapping

    Computer

    Describes the server where this log was written

    TimeZone

    Describes the local time zone of the server and its relation to GMT

    Build

    Describes what OS is being used and if it is Enterprise edition or higher

    Configuration loglevel

    Describes the current log verbosity settings

    Maxentrycount

    Describes the number of lines that can be written to the debug log before it starts a new one

    Maxfilecount

    Describes the total number of circular logs maintained at any one time

    Logpath

    Describes the output folder of the logs

    Header lines always start with an asterisk (*). The header information is always written and cannot be turned off without disabling logging altogether.

    Single-line messages – written throughout the logs and always map back to one discrete operation in DFSR. So for example:

    20080111 15:12:30.996 3876 JOIN 1171 Join::SubmitUpdate Sent: uid:{AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v33846 gvsn:{AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v33846 name:USRSTAT.EXE connId:{CC694D38-7E97-467C-A963-B3D9B6E308B9} csId:{1697E5EB-BBD0-45B7-AC2F-11EBE7B3FD47} csName:dfsrprestaged

    Field

    Description

    Example from above

    Date-Time

    Stamps local time YYYYMMDD HH:MM:SS:MS

    20080111 15:12:30.996

    Thread

    The thread executing within DFSR.EXE

    3876

    Module ID

    The sub-component of DFSR

    JOIN

    Line

    The line in source code

    1171

    Class

    The class being executed

    Join

    Method

    The method (function) being executed by the class

    SubmitUpdate

    Data

    All the information being described by the logging

    Sent: uid:{AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v33846 gvsn:{AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v33846 name:USRSTAT.EXE connId:{CC694D38-7E97-467C-A963-B3D9B6E308B9} csId:{1697E5EB-BBD0-45B7-AC2F-11EBE7B3FD47} csName:dfsrprestaged

    Single-line messages always start with a date-time stamp entry. The above sample line is wrapped for readability.

    Nested messages – written throughout the logs and always map back to one discrete operation in DFSR that generates a multi-line response for better readability. So for example:

    20080111 11:44:28.873 1640 INCO 4378 InConnection::UpdateProcessed Received Update. updatesLeft:237 processed:1171 sessionId:1 open:1 updateType:0 processStatus:0 connId:{D0BF5598-9457-4C32-8C50-7558BCD76610} csId:{1697E5EB-BBD0-45B7-AC2F-11EBE7B3FD47} csName:dfsrprestaged update:
    +    present 1
    +    nameConflict 0
    +    attributes 0x10
    +    gvsn {AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v29102
    +    uid {AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v29102
    +    parent {AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v28024
    +    fence 16010101 00:00:00.000
    +    clock 20080110 19:05:43.167
    +    createTime 20080110 19:05:43.157 GMT
    +    csId {1697E5EB-BBD0-45B7-AC2F-11EBE7B3FD47}
    +    hash 37123A73-30C1AFF0-B4EE5252-46212327
    +    similarity 00000000-00000000-00000000-00000000
    +    name acctsid

    Nested messages follow single line messages that are ended with a colon. The nested messages always start with a plus sign (+). The nested lines can change depending on the class and method/function being executed so they are described in their own section below for 'File and Folder Field Information'.

    The common GUID fields

    Globally Unique Identifiers (GUID's) are used throughout the DFSR system to map the friendly names of the topology to unique entries used by the DFSR service. This can make reading the DFSR debug logs very challenging, as not all GUID's in the environment are defined in the logs. When examining the DFSR debug logs it is important to understand how to map GUID's to real objects for troubleshooting purposes. Sample log entry:

    20080403 11:19:54.349 1660 SRTR 329 SERVER_EstablishConnection Succeeded on connId:{097BFFAA-99FB-4A4D-9590-C102985A55C6} replicaSetId:{D3558FFB-1E46-483F-AE89-E840E4A6A97B} partnerAddress:2003MEM21.contoso.com
    20080403 11:19:55.710 3360 JOIN 1171 Join::SubmitUpdate Sent: uid:{AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v137449 gvsn:{AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v137449 name:samplefile.txt connId:{097BFFAA-99FB-4A4D-9590-C102985A55C6} csId:{B269F903-539D-42F2-9D33-935590097578} csName:ihaterobocopy
    20080403 11:19:55.891 572 OUTC 588 OutConnection::OpenFile Received request for update:
    +    present 1
    +    nameConflict 0
    +    attributes 0x20
    +    gvsn {AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v137449
    +    uid {AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v137449
    +    parent {B269F903-539D-42F2-9D33-935590097578}-v1
    +    fence 16010101 00:00:00.000
    +    clock 20080403 15:17:17.233
    +    createTime 20080403 15:17:17.193 GMT
    +    csId {B269F903-539D-42F2-9D33-935590097578}
    +    hash 00000000-00000000-00000000-00000000
    +    similarity 00000000-00000000-00000000-00000000
    +    name samplefile.txt

    Field

    Description

    Example from above

    ReplicaSetId

    Replication Group GUID

    {D3558FFB-1E46-483F-AE89-E840E4A6A97B}

    CSID

    Replicated Folder GUID

    {B269F903-539D-42F2-9D33-935590097578}

    ConnID

    Connection GUID

    {097BFFAA-99FB-4A4D-9590-C102985A55C6}

    Parent

    Folder holding the file

    {B269F903-539D-42F2-9D33-935590097578}-v1

    UID

    Original file record

    {AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v137449

    GVSN

    Modified file record

    {AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v137449

    There are a few tools that can be used to map the GUID's:

    DFSRADMIN.EXE and DFSRDIAG.EXE - You can use the DFSRADMIN and DFSRDIAG tools included with DFSR to enumerate the topology and determine the GUID's. Below is a sample of doing this through a CMD prompt with the data provided by the above logs:

    Dfsradmin.exe rg list /attr:rgname,rgguid

    RgName RgGuid
    SteveLovesFRS d3558ffb-1e46-483f-ae89-e840e4a6a97b

    The above command is used to return the Replication Group name, which you will see below is necessary to complete a number of further lookups. This maps to REPLICASETID.

    Dfsradmin.exe rf list /rgname:SteveLovesFRS /attr:rfname,rfguid

    RfName RfGuid
    ihaterobocopy b269f903-539d-42f2-9d33-935590097578

    The above command is used to get the GUID of the Replicated Folder so that CSID is known.

    Dfsradmin.exe conn list /rgname:SteveLovesFRS /attr:sendmem,recvmem,connguid

    SendMem RecvMem ConnGuid
    2003MEM20 2003MEM21 097bffaa-99fb-4a4d-9590-c102985a55c6
    2003MEM21 2003MEM20 d2e396a5-837b-4103-b8a2-b8fc2c71d388

    The above command is used to return the Connection GUID's that can be mapped to CONNID.

    Dfsrdiag.exe guid2name /guid:AC759213-00AF-4578-9C6E-EA0764FDC9AC /rgname:stevelovesfrs

    Object Type : DfsrVolumeInfo
    Computer : 2003MEM20.contoso.com
    Volume Guid : B8B42506-BF98-11DC-B176-0003FF3813C5
    Volume Path : E:
    Volume SN : 108172604
    DB Guid : AC759213-00AF-4578-9C6E-EA0764FDC9AC

    Finally, the above command is used to retrieve the GUID of the actual DFSR database and therefore the server it is running on. When files and folders are created or modified, the originating server is used to form the GUID portion of the name, and then the current version vector from that server is appended to complete the unique file mapping in the database. These are used for UID and GVSN.

    So having retrieved all the GUID's, we can now see that our debug log entry actually means:

    20080403 11:19:54.349 1660 SRTR 329 SERVER_EstablishConnection Succeeded on connId: 2003MEM20 replicaSetId:SteveLovesFRS partnerAddress:2003MEM21.contoso.com
    20080403 11:19:55.710 3360 JOIN 1171 Join::SubmitUpdate Sent: uid:
    2003MEM20-v137449 gvsn: 2003MEM20-v137449 name:samplefile.txt connId: 2003MEM20 csId: ihaterobocopy csName:ihaterobocopy
    20080403 11:19:55.891 572 OUTC 588 OutConnection::OpenFile Received request for update:
    +    present 1
    +    nameConflict 0
    +    attributes 0x20
    +    gvsn 2003MEM20-v137449
    +    uid 2003MEM20-v137449
    +    parent 2003MEM20-v1
    +    fence 16010101 00:00:00.000
    +    clock 20080403 15:17:17.233
    +    createTime 20080403 15:17:17.193 GMT
    +    csId {B269F903-539D-42F2-9D33-935590097578}
    +    hash 00000000-00000000-00000000-00000000
    +    similarity 00000000-00000000-00000000-00000000
    +    name samplefile.txt

    Next up – nested debug log fields and module ID's.

    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 'Cure for Insomnia' Pyle

  • Understanding DFSR debug logging (Part 2: Nested Fields, Module ID's)

    Ned here. Part two today covers the nested debug field format and what module ID's mean. If Part 2 makes no sense, you probably haven't read Part 1.

    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.

    File information

    (defined in DFSR source code and GetFileAttributes) (Severity 4)

    Field

    Description

    Data

    fid

    File ID Record stored in the DFSR database

    Unique hex value

    usn

    The USN ID record in the journal and DFSR database

    Unique hex value

    uidVisible

    Has the UID file record been replicated?

    0 or 1

    filtered

    Is the file filtered by an administrator to prevent replication?

    0 or 1

    journalWrapped

    Is the file in USN journal wrap recovery?

    0 or 1

    slowRecoverCheck

    Is the file being checked after a journal wrap recovery completed?

    0 or 1

    pendingTombstone

    Is the file in the process of being tombstoned in the database?

    0 or 1

    recUpdateTime

    Displays time/date of local changes to file (only on the originating server – on downstream will show garbage)

    YYYYMMDD HH:MM:SS.MS GMT

    present

    Is the file live or tombstoned (deleted)?

    0 or 1

    nameConflict

    Was there a conflict on the file (modified on upstream and downstream servers before replication

    0 or 1

    attributes

    Attributes on the file

    Hex value

    gvsn

    Global Version Sequence Number of the file, used to track changes and server origination

    GUID of originating server +Version #

    uid

    Unique ID of the file, used to identify original file

    GUID of modifying server + Version #

    parent

    Folder containing the file

    GUID of originating server + Version #

    fence

    Authoritative data flag (not used)

    N/A

    clock

    Time of the last change to the file on this server

    YYYYMMDD HH:MM:SS.MS

    createTime

    Time the file was created on the server

    YYYYMMDD HH:MM:SS.MS GMT

    csId

    Replicated Folder

    GUID

    hash

    SHA-1 checksum of the marshaled file,
    to include its data stream, alternate data stream, and security

    Hex value

    similarity

    SHA1 checksum information about the RDC similarity data

    Hex value

    Name

    Name of the file

    Text string

    ghostedHeader*

    <reserved for future use>

     

    Data*

    <reserved for future use>

     

    clockDecrementedInDirtyShutdown*

    <reserved for future use>

     

    +    fid 0x100000000094A
    +    usn 0x0
    +    uidVisible 1
    +    filtered 0
    +    journalWrapped 0
    +    slowRecoverCheck 0
    +    pendingTombstone 0
    +    internalUpdate 0
    +    dirtyShutdownMismatch 0
    +    meetInstallUpdate 0
    +    meetReanimated 0
    +    recUpdateTime 20080318 20:58:37.190 GMT
    +    present 1
    +    nameConflict 0
    +    attributes 0x20
    +    ghostedHeader 0
    +    data 0
    +    gvsn {AF8C06FD-E1B8-4044-8FE1-51A9E30F18AD}-v2353
    +    uid {AF8C06FD-E1B8-4044-8FE1-51A9E30F18AD}-v2353
    +    parent {5D5D914C-F585-4117-8477-7F8B37B27B01}-v1
    +    fence 16010101 00:00:00.000 P
    +    clockDecrementedInDirtyShutdown 0
    +    clock 20080318 19:28:17.026 GMT (0x1c8892e375afac0)
    +    createTime 20080318 17:36:47.960 GMT
    +    csId {5D5D914C-F585-4117-8477-7F8B37B27B01}
    +    hash 02F98A2C-31F58E81-E8598E22-DA9F8F95
    +    similarity 00000000-00000000-00000000-00000000
    +    name 0c0df164-715a-4674-bfb2-0a926eed1791

    USN update Information

    (defined in USN_RECORD structure and GetFileAttributes) (Severity 4)

    Field

    Description

    Data

    RecordLength

    Size of file record in the USN journal in bytes

    Numeric value

    MajorVersion

    USN journal underlying major version

    Always 0x2

    MinorVersion

    USN journal underlying major version    

    Always 0x0

    FileRefNumber

    USN journal internal file reference

    Unique Hex value

    ParentFileRefNumber

    USN journal internal folder parent reference

    Hex value

    TimeStamp

    USN journal timestamp of last change to file

    YYYYMMDD HH:MM:SS.MS TZ

    Reason

    Information about an actual change

    Text string

    SourceInfo

    Information about the source of the change

    Hex value

    SecurityId

    Unique security identifier assigned to the file

    Unique hex value

    FileAttributes

    Attributes on the file

    Hex value

    FileNameLength

    Size of file record in the USN journal in bytes

    Numeric value

    FileNameOffset

    The offset of the FileName member

    Numeric value

    FileName

    Name of the file

    Text string

    +    USN_RECORD:
    +    RecordLength: 136
    +    MajorVersion: 2
    +    MinorVersion: 0
    +    FileRefNumber: 0x100000000B103
    +    ParentFileRefNumber: 0x1000000000023
    +    USN: 0xb69dd0
    +    TimeStamp: 20080331 20:05:52.176 Eastern Standard Time
    +    Reason: Close File Delete
    +    SourceInfo: 0x0
    +    SecurityId: 0x0
    +    FileAttributes: 0x20
    +    FileNameLength: 72
    +    FileNameOffset: 60
    +    FileName: e7d74249-6092-475b-8e73-909516f93bdd

    Content Set and Database Information

    (Severity 4)

    Field

    Description

    Data

    contentSetId

    Replicated Folder

    GUID

    memberId

    Computer referenced for this Content Set

    GUID

    state

    The current state of the Content Set (may be:

    May return: Normal, InitialSync(Cleanup), InitialSync(Sync), InitialBuilding, RestoreInitialSync(Cleanup), RestoreInitialSync(Sync), RestoreBuilding, Unknown

    startVersion

    Last version vector for chaining if the number is lost due to a problem

    Numeric value

    authRebuilding

    Rebuilding Content Set authoritatively

    0 or 1

    stageVolumeSerialNumber

    Volume serial number for the drive containing staged data

    Unique value

    stageFid

    File ID of the staged data.

    Unique hex value

    isTombstone

    Is the Content Set tombstoned (deleted)

    0 or 1

    beingDeleted

    Is the Content Set in the process of being deleted

    0 or 1

    dbLossRecover

    Are we recovering from a lost database

    0 or 1

    tombstoneTime*

    When was the content set tombstoned

    YYYYMMDD HH:MM:SS.MS

    expirationTime*

    When the tombstone will expire and the database will purge the content set info

    YYYYMMDD HH:MM:SS.MS (tombstonetime+60 days)

    readOnlySince*

    Date that the content set was changed from Read-Write to Read-Only (unsupported)

    YYYYMMDD HH:MM:SS.MS

    +    contentSetId: {FEB21D85-154D-4AE9-AB31-32A524F1E6F7}
    +    memberId: {13828A03-E1BA-4E51-9F6F-F790671C450A}
    +    state: Normal
    +    startVersion: v150040
    +    authRebuilding: 0
    +    stageVolumeSerialNumber: ea40899d408970dd
    +    stageFid: 0x2000000000031
    +    isTombstone: 1
    +    tombstoneTime: 20080411 13:47:07.267
    +    expirationTime: 20080610 13:47:07.267
    +    readOnlySince: 16010101 00:00:00.000
    +    beingDeleted: 0
    +    dbLossRecover: 0

    RDC and XPRESS Assembler Statistics Downstream

    (Severity 5)

    Field

    Description

    Data

    Compression Ratio

    % of bandwidth savings over the wire (with RDC and XPRESS compression)

    0-100%

    Target Uncompress Size

    Total byte count of data

    Numeric value

    Target Compress Size

    Total byte count of data after accounting for compression with XPRESS and RDC

    Numeric value

    Bytes Received

    Byte count actually received (broken into signature bytes and data bytes)

    Numeric values

    Signature Bytes Received

    Signature bytes received

    Numeric value

    Number of remote calls

    RPC calls used to receive data (broken into signature, needs, and data requests)

    Numeric value

    RDC Need Size

    Number of bytes copied through RDC

    Numeric value

    Xpress Blocks

    Number of XPRESS-compressed RDC blocks copied

    Numeric value

    Uncompressed Xpress Blocks

    Number of non-XPRESS-compressed RDC blocks copied

    Numeric value

    Blocks copied to target

    RDC Blocks copied

    Numeric value

    +     TOTAL
    +     Compression Ratio 49 %
    +     Target Uncompress Size 480012
    +     Target Compress Size 249546
    +     Bytes Received 254732 Signatures: 4182 Data: 250550
    +     Signature Bytes Received 4182 4182
    +     Number of remote calls 15 Signatures: 1 Needs: 1 Data: 13
    +     SEED
    +     Rdc Need Size 0 0
    +     Xpress Blocks 0 0
    +     Uncompressed Xpress Blocks 0 0
    +     Blocks copied to target 0 0
    +     SOURCE
    +     Rdc Need Size 480012 0
    +     Xpress Blocks 59 0
    +     Uncompressed Xpress Blocks 1 0
    +     Blocks copied to target 58 0

    RDC and XPRESS Needs Statistics Upstream

    (Severity 5)

    Field

    Description

    Data

    Compression Ratio

    % of bandwidth savings over the wire (with RDC and XPRESS compression)

    0-100%

    RDC Need Size

    Total bytes covered by requests

    Numeric value

    Bytes sent to downstream

    Actual bytes sent over the wire

    Numeric value

    Uncompressed XPRESS blocks

    RDC blocks from non-compressed (by XPRESS) data

    Numeric value

    Compressed XPRESS blocks

    RDC blocks from compressed data (by XPRESS) data

    Numeric value

    Copied XPRESS Blocks

    Number of compressed blocks sent

    Numeric value

    Bytes read using async I/Os*

    Number of bytes read in using Async I/o calls

    Numeric value

    +     TOTAL
    +     Compression Ratio 47 %
    +     RDC Need Size 480012
    +     Bytes sent to downstream 254732
    +     Uncompressed XPRESS blocks 0
    +     Compressed XPRESS blocks 0
    +     Copied XPRESS Blocks 59

    RPC Information

    (Defined in RPC_EXTENDED_ERROR_INFO Structure and Extended Errors, Severity 5)

    Field

    Description

    Data

    Process ID

    PID of the DFSR service on this machine.

    Numeric value

    System Time

    Date-time on this machine

    YYYYMMDD HH:MM:SS.MS

    Generating component

    Code for component generating the error

    Numeric value

    Status

    Error returned to RPC

    Numeric error mapped within WINERROR.H that can be translated with NET HELPMSG <error #>

    Detection location

    A n entry in the Extended Error Information Detection Locations table

    Numeric value

    Flags

    Specifies whether SystemTime or FileTime is used. Set to zero to use SystemTime, or EEInfoUseFileTime to use FileTime.

    0 or 1

    NumberOfParameters

    Parameter count to function (with nested data being passed)

    Numeric value

    +    Process ID : 1676
    +    System Time : 20080318 21:49:51.310
    +    Generating component : 2
    +    Status : 1115
    +    Detection location : 102
    +    Flags : 0
    +    NumberOfParameters : 1

    USN Consumer Statistics

    (Severity 5)

    Field

    Description

    Data

    usnTotal

    Total number of USN records consumed

    Numeric value

    usnTotalNotFilteredByReason

    Total number of USN records (that are not filtered by USN reason attribute)

    Numeric value

    usnTotalDbUpdated

    Total number of USN records that caused database update

    Numeric value

    txTotal

    Total number of transactions

    Numeric value

    usnLastAverage

    Number of USN records consumed per second in last sampling period

    Numeric value

    usnLastAverageNotFilteredByReason

    Number of USN records per second that are not filtered by USN reason attribute in last sampling period

    Numeric value

    usnLastAverageDbUpdated

    Number of USN records per second that caused database update in last sampling period

    Numeric value

    txLastAverage

    Number of transaction per second in last sampling period

    Numeric value

    +    usnTotal 67433
    +    usnTotalNotFilteredByReason 54111
    +    usnTotalDbUpdated 50002
    +    txTotal 11813
    +    usnLastAverage 7
    +    usnLastAverageNotFilteredByReason 3
    +    usnLastAverageDbUpdated 0
    +    txLastAverage 0

    USN Recovery Information

    (Severity 5)

    Field

    Description

    Data

    usnId

    USN ID record in the journal

    Unique Hex value

    nextUsn

    Next USN record

    Unique Hex value

    checkpointUsn

    A special USN record to allow recovery from disk failures; used to detect whether a journal wrap or complete database rebuild will be triggered after service startup.

    Unique Hex value

    checkpointTimestamp

    Last time a checkpoint recovery was set

    YYYYMMDD HH:MM:SS.MS

    journalWrapped

    If the USN journal is wrapped

    0 or 1

    journalIdChanged

    If the USN journal ID has been changed (due to recreation of journal)

    0 or 1

    slowRecoverNotFinished

    Are we still doing a slow recover due to journal wrap

    0 or 1

    dirtyRecoveryMode

    Are we recovering from a dirty database shutdown currently

    0 or 1

    dirtyShutdownRecoveryTimestamp

    When a dirty database shutdown recovery was last done.

    YYYYMMDD HH:MM:SS.MS

    dirtyRecoveryRecordsMarkedFinished

    Was a dirty database recovery just performed

    0 or 1

    +    usnId: 0x1c8893ad4b938d0
    +    nextUsn: 0xbbe0
    +    checkpointUsn: 0xacd8
    +    checkpointTimestamp: 20080318 21:11:52.614
    +    journalWrapped: 1
    +    journalIdChanged: 0
    +    slowRecoverNotFinished: 1
    +    dirtyRecoveryMode: 1
    +    dirtyShutdownRecoveryTimestamp: 20080318 21:11:52.614
    +    dirtyRecoveryRecordsMarkedFinished: 0

    History Information

    * (Severity 5)

    Field

    Description

    Data

    syncGuid*

    Synchronization GUID

    GUID

    State*

    Current state of replication for this Replication Group

    May return: Initialized,Connecting, In Progress, Completed, In Sync, Interrupted, In Error, UnknownSyncState

    initReason*

    Reason that synchronization occurred

    May return: Schedule,Force Replication, Paused, Force Until in Sync, UnknownSyncInitReason

    connectionGuid*

    Connection GUID

    GUID

    replicationGroupGuid*

    Replication group GUID

    GUID

    replicationGroupName*

    Replication Group friendly name

    Text string

    memberGuid*

    GUID of server

    GUID

    memberName*

    Friendly name of server

    Text string

    updatedNotTransferred*

    Number of updates not replicated

    Numeric value

    updatedTransferred*

    Number of updates replicated

    Numeric value

    updatedToBeTransferred*

    Number of updates to be replicated

    Numeric value

    byteTransferred*

    Bytes replicated

    Numeric value

    tombstonesGenerated*

    Number of tombstones created

    Numeric value

    conflictsGenerated*

    Number of conflicts that occurred

    Numeric value

    currentForceReplicationEndTime*

    When a forced update window (when using DFSRDIAG SYNCNOW) will close

    YYYYMMDD HH:MM:SS.MS

    currentForceReplicationBandwidthlevel*

    Bandwidth level is of a forced replication

     

    +    syncGuid {CE6DF7C4-5AB4-48A4-871F-344D168DA7B9}
    +    state In Sync
    +    initReason Schedule
    +    connectionGuid {3AA17575-BA9B-43B3-B4C1-9DC4D90307A1}
    +    replicationGroupGuid {4D251274-283B-46DF-81EF-570801B80D90}
    +    replicationGroupName LHtest
    +    memberGuid {1CEA93F6-41D7-4BF1-9AFC-7A2502308540}
    +    memberName 2008SRV40
    +    updatedNotTransferred 0
    +    updatedTransferred 0
    +    updatedToBeTransferred 0
    +    byteTransferred 0
    +    tombstonesGenerated 0
    +    conflictsGenerated 0
    +    currentForceReplicationEndTime 16010101 00:00:00.000
    +    currentForceReplicationBandwidthlevel *

    * Windows Server 2008 only

    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:

    20080403 11:19:55.710 3360 JOIN 1171 Join::SubmitUpdate Sent: uid:{AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v137449 gvsn:{AC759213-00AF-4578-9C6E-EA0764FDC9AC}-v137449 name:samplefile.txt connId:{097BFFAA-99FB-4A4D-9590-C102985A55C6} csId:{B269F903-539D-42F2-9D33-935590097578} csName:ihaterobocopy
    20080409 11:17:21.649 3180 CFAD 8873 Config::AdReader::Peek Connection to AD is down, request full poll

    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

    Database

    DBCJ, DBGC, DIRW, JRWP, LDBX, PDBX, DBSR, USNC

    Functions related to the USN journal and the DFSR JET database

    File System

    MRSH, NTFS, FHAN,FUTL, ASYN*, OPLC*

    Functions related to NTFS, file handles, and (in Win2008) Asynchronous I/O handling.

    Main

    FSVC, SCFG, MAIN, VSSW, SCNT

    Functions for DFSR service control and data backup through VSS.

    SYSVOL Migration

    MIGM*

    Functions related to DFSRMIG.EXE for SYSVOL migration in Win2008.

    Performance

    PFV2*

    Functions wrapper for PerflibV2 in Win2008.

    Provider

    FCFG, FWMI, FWMH, PINF, PVMG, WMIC, WMIM

    Functions for DCOM and WMI providers.

    Synchronization

    CONF, CSMG, CRED, FREP, RDCS, INCO, ISYN, JOIN, MEET, OUTC, RDCX, RDCC, RSMG, SSYN, STAG, UPLK, UPMG, VLMG, XPRN, XPRS, XRNA, SLVS*

    Functions related to replicating files between DFSR nodes.

    Transport

    DOWN, RPCN, SRTR, UPST

    Functions that implement DFSR's RPC transports.

    Utility

    EVNT, PERF**, TASK, IMPE*, SRVC*, P2P*. SETT*

    Miscellaneous utility functions that cover event logging, performance logging in Win2003 R2, and other areas.

    * Windows Server 2008 only
    ** In Windows Server 2003 R2 only

    Next up, we begin the various debug log real-world scenarios, with understanding new files being added to a replicated folder.

    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

  • DS Restore Mode Password Maintenance

    Ned here again. There comes a day in nearly every administrator’s life where they will need to boot a domain controller into DS Restore Mode. Whether it’s to perform an authoritative restore or fix database issues, you will need the local administrator password. Too often, we work with customers that have not been maintaining this password and do not have a way to get in to their DC’s. Sometimes it’s because the password was set by another admin who is not available or no longer works at the company. Other times it’s because the password was set at DC promotion years ago and no one remembers it anymore. Since the password can only be set when the DC is running in normal mode, you get a nasty chicken and the egg situation if the DC cannot start Directory Services correctly. Today we’ll talk about some methods to get this password under control.

    The old fashioned way

    All domain controllers have a hard-coded local Administrator account stored in their SAM database. This account and local database are not used or generally available when the DC is running normally. You probably remember setting this password during DCPROMO:

    image

    In addition, the password can be reset later while the DC is running by using the NTDSUTIL tool:

    image

    If you know the password, you can restart the domain controller into DS Restore mode using F8 or via the boot options exposed in MSCONFIG and away you go.

    But what are the options to maintain this password, especially when your environment is in the hundreds or thousands of DC’s? Let’s dig in.

    NTDSUTIL Password Pull

    Beginning with hotfix KB961320 on Windows Server 2008, you now have the option to synchronize the DSRM password on a DC with a specific domain account. You must do every time the password is changed; it does not create an automatic sync partnership.

    1. Create a standard domain user account and set it with a complex password. It does not need to be a member of any special groups or the Domain Admins group.

    image

    2. Install the hotfix on your DC and restart.

    3. Logon to the DC normally.

    4. In an elevated CMD prompt where you have logged on as a Domain Admin, run:

    NTDSUTIL
    SET DSRM PASSWORD
    SYNC FROM DOMAIN ACCOUNT <your user here>
    Q
    Q

    So for example (using NTDSUTIL’s ability to pass in all parameters on a single command-line):

    image

    Note how there is no need to provide the actual password being used, or provide the old password. This feature will also be included in Service Pack 2 for Win2008.

    Group Policy Preference Automation of NTDSUTIL

    So what if we want to automate this NTDSUTIL command so that is run via a scheduled task? This is easily done using Group Policy Preferences.

    Note: Before you get too excited that I’ve missed something – no, GPP Local User password does not work with the DSRM passwords on domain controllers. You cannot use it to push a new password to the local administrator on DC’s; it only works only on member computers. Trust me, I’ve tried.

    The beauty of this solution is that there is no password stored anywhere except in Active Directory itself and the system effectively self maintains – the only administrator intervention needed is to periodically change the special user’s password, and to make sure the scheduled task is working on the DC’s. The same way you should be checking to make sure those backups will actually function for a restore if you ever need to use this password.

    So let’s set this up:

    1. Start GPMC on a Windows Server 2008 or Windows Vista computer running RSAT.

    2. Create and link a new policy on the Domain Controllers OU (you are doing all this in a test domain first, right?).

    image

    3. Create the GPP Scheduled task settings.

    image

    Note here that I have set:

    A) Action of ‘Update’ (this will create the task if it does not exist).

    B) Run command of the built-in GPP variable for %SystemDir% to specify the System32 directory, along with the ntdsutil.exe to be called.

    C) The command line exactly as it would be done by hand with ntdsutil, including the quotation marks:

    “SET DSRM PASSWORD” “SYNC FROM DOMAIN ACCOUNT DsrmUser” Q Q

    D) The task is Enabled with a checkbox so that it will run, not just be created.

    image

    E) Then I have set this to run as a daily task at 9AM (it’s fairly likely that the DC will be running at that point). I could also run this hourly, weekly, etc – whatever I want.

    4. After having created the policy and letting it apply to DC’s, I now see it is working by examining the scheduled tasks on one of my domain controllers. There it is (as well as another one I added to run every night too – can’t be too careful):

    image

    5. Once the right time has come and gone, I boot a DC into DS Repair mode and check – sure enough, my new password has taken affect automagically.

    And there you go.

    - Ned ‘That’s the same combination I have on my luggage!’ Pyle

    Reviewer’s note: We made Ned change his smart card PIN to something other than ‘12345’ after he let it slip in this blog post.

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

    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
  • Understanding DFSR debug logging (Part 6: Microsoft Office Word 97-2003 File Modified on Windows Server 2008)

    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.

    (word2003modifyupstream - Dfsr00015 - 2008.log and word2003modifydownstream - Dfsr00012 - 2008.log)

    These are two Windows Server 2008 servers called 2008MEM01 and 2008MEM02 in the fabrikam.com domain. The logs are from 2008MEM01 where the file is 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.

    <Upstream> 20080626 11:32:31.284 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD: ß the real file "word2003large.doc" was opened and Word automatically creates a temporary working file. Because it is both temporary and covered by the $ default filter in DFSR it will not be a candidate for replication.
    +    USN_RECORD:
    +    RecordLength: 96
    +    MajorVersion: 2
    +    MinorVersion: 0
    +    FileRefNumber: 0x100000000AC61
    +    ParentFileRefNumber: 0xF00000000A781
    +    USN: 0xa2e688
    +    TimeStamp: 20080626 11:32:31.274 Eastern Standard Time
    +    Reason: Close Data Extend File Create ß file created new
    +    SourceInfo: 0x0
    +    SecurityId: 0x0
    +    FileAttributes: 0x22 ß 0x20+0x2 means hidden file, per GetFileAttributes function.
    +    FileNameLength: 34
    +    FileNameOffset: 60
    +    FileName: ~$rd2003large.doc ß name of file
    +    
    <Upstream> 20080626 11:33:51.191 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD: ß Word creates a pseudo-temporary file
    +    USN_RECORD:
    +    RecordLength: 88
    +    MajorVersion: 2
    +    MinorVersion: 0
    +    FileRefNumber: 0x100000000AC66
    +    ParentFileRefNumber: 0xF00000000A781
    +    USN: 0xa2f108
    +    TimeStamp: 20080626 11:33:51.181 Eastern Standard Time
    +    Reason: Close Data Extend Data Overwrite File Create ß file created new with data added
    +    SourceInfo: 0x0
    +    SecurityId: 0x0
    +    FileAttributes: 0x20 ß not temporary
    +    FileNameLength: 24
    +    FileNameOffset: 60
    +    FileName: ~WRD0002.tmp ß marked with tilde (~) and TMP extension so still filtered out by DFSR by default
    +    
    <Upstream> 20080626 11:33:51.191 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD: ß Word deletes the temporary file (pretty much instantly)
    +    USN_RECORD:
    +    RecordLength: 88
    +    MajorVersion: 2
    +    MinorVersion: 0
    +    FileRefNumber: 0x100000000AC66 ß same file ID as above. Important to watch FID's with apps that create lots of temporary and pseudo-temporary working files, as the UID/GVSN will not be created most of the time because the file is excluded from replication.
    +    ParentFileRefNumber: 0xF00000000A781
    +    USN: 0xa2f160
    +    TimeStamp: 20080626 11:33:51.181 Eastern Standard Time
    +    Reason: Close File Delete ß deleted
    +    SourceInfo: 0x0
    +    SecurityId: 0x0
    +    FileAttributes: 0x20
    +    FileNameLength: 24
    +    FileNameOffset: 60
    +    FileName: ~WRD0002.tmp ß same file as above
    +    
    <Upstream> 20080626 11:33:51.861 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD: ß Word does this again with yet another pseudo-temporary file
    +    USN_RECORD:
    +    RecordLength: 88
    +    MajorVersion: 2
    +    MinorVersion: 0
    +    FileRefNumber: 0x200000000AC66 ß remember to watch FID's with unreplicated files; there's no guarantee that there won't be lots of files with the same name present in the replicated folder, especially as we can see that Word is not attempting to randomize the name.
    +    ParentFileRefNumber: 0xF00000000A781
    +    USN: 0xa2f9d0
    +    TimeStamp: 20080626 11:33:51.861 Eastern Standard Time
    +    Reason: Close Data Extend Data Overwrite File Create ß created, added some data
    +    SourceInfo: 0x0
    +    SecurityId: 0x0
    +    FileAttributes: 0x20 ß not temporary
    +    FileNameLength: 24
    +    FileNameOffset: 60
    +    FileName: ~WRD0003.tmp
    +    
    <Upstream> 20080626 11:33:51.982 3128 USNC 1995 UsnConsumer::UpdateUsnOnly LDB Updating ID Record: ß the real document has an entry added in DFSR database due to USN update (next full line)
    +    fid 0x70000000000B9 ß note for later in log entries that do not include UID/GVSN
    +    usn 0xa2fb88
    +    uidVisible 1
    +    filtered 0
    +    journalWrapped 0
    +    slowRecoverCheck 0
    +    pendingTombstone 0
    +    internalUpdate 0
    +    dirtyShutdownMismatch 0
    +    meetInstallUpdate 0
    +    meetReanimated 0
    +    recUpdateTime 20080626 15:30:22.932 GMT
    +    present 1
    +    nameConflict 0
    +    attributes 0x20
    +    ghostedHeader 0
    +    data 0
    +    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 ß original file has not yet been modified (UID and GVSN match); this is because Word will use the temporary working file for most of its transactions in order to provide 'auto recover document' functionality
    +    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
    +    parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
    +    fence 16010101 00:00:00.000
    +    clockDecrementedInDirtyShutdown 0
    +    clock 20080626 15:30:22.932 GMT (0x1c8d7a18ca3f2b2)
    +    createTime 20080626 15:30:22.912 GMT
    +    csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    +    hash 4992549E-7564D836-ED346C90-D5FD88B3
    +    similarity 2C131C03-12383C0B-15071E36-131A0C27
    +    name word2003large.doc ß the file
    +    
    <Upstream> 20080626 11:33:51.982 3128 USNC 1997 UsnConsumer::UpdateUsnOnly USN-only update from USN_RECORD: ß a USN only update means the file is not actually modified in a way that will trigger any form of replication (including metadata)
    +    USN_RECORD:
    +    RecordLength: 96
    +    MajorVersion: 2
    +    MinorVersion: 0
    +    FileRefNumber: 0x70000000000B9 ß same file as above
    +    ParentFileRefNumber: 0xF00000000A781
    +    USN: 0xa2fb88
    +    TimeStamp: 20080626 11:33:51.972 Eastern Standard Time
    +    Reason: Close Object ID Change ß the file is closed without being modified
    +    SourceInfo: 0x0
    +    SecurityId: 0x0
    +    FileAttributes: 0x20
    +    FileNameLength: 34
    +    FileNameOffset: 60
    +    FileName: word2003large.doc ß same file as above
    +    
    <Upstream> 20080626 11:33:51.982 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD:
    +    USN_RECORD:
    +    RecordLength: 88
    +    MajorVersion: 2
    +    MinorVersion: 0
    +    FileRefNumber: 0x200000000AC66 ß this is the FID from the working file
    +    ParentFileRefNumber: 0xF00000000A781
    +    USN: 0xa2fc40
    +    TimeStamp: 20080626 11:33:51.972 Eastern Standard Time
    +    Reason: Basic Info Change Close Data Extend Data Overwrite Data truncation ß data has been added to the file
    +    SourceInfo: 0x0
    +    SecurityId: 0x0
    +    FileAttributes: 0x20
    +    FileNameLength: 24
    +    FileNameOffset: 60
    +    FileName: ~WRD0003.tmp ß the pseudo-temporary working file
    +    
    <Upstream> 20080626 11:33:51.982 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD:
    +    USN_RECORD:
    +    RecordLength: 88
    +    MajorVersion: 2
    +    MinorVersion: 0
    +    FileRefNumber: 0x200000000AC66
    +    ParentFileRefNumber: 0xF00000000A781
    +    USN: 0xa2fcf0
    +    TimeStamp: 20080626 11:33:51.972 Eastern Standard Time
    +    Reason: Close Security Change ß the file is closed with a security change
    +    SourceInfo: 0x0
    +    SecurityId: 0x0
    +    FileAttributes: 0x20
    +    FileNameLength: 24
    +    FileNameOffset: 60
    +    FileName: ~WRD0003.tmp
    +    
    <Upstream> 20080626 11:33:51.982 3128 USNC 2777 UsnConsumer::TombstoneOrDelete LDB Updating ID Record: ß file deleted
    +    fid 0x70000000000B9
    +    usn 0xa2ff68
    +    uidVisible 1
    +    filtered 0
    +    journalWrapped 0
    +    slowRecoverCheck 0
    +    pendingTombstone 0
    +    internalUpdate 0
    +    dirtyShutdownMismatch 0
    +    meetInstallUpdate 0
    +    meetReanimated 0
    +    recUpdateTime 20080626 15:30:22.932 GMT
    +    present 0 ß deleted
    +    nameConflict 0
    +    attributes 0x20
    +    ghostedHeader 0
    +    data 0
    +    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v65 ßversion goes up (even during a deletion, as a deletion counts as a modification)
    +    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
    +    parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
    +    fence 16010101 00:00:00.000
    +    clockDecrementedInDirtyShutdown 0
    +    clock 20080626 15:33:51.972 GMT (0x1c8d7a2093ceab9)
    +    createTime 20080626 15:30:22.912 GMT
    +    csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    +    hash 4992549E-7564D836-ED346C90-D5FD88B3
    +    similarity 2C131C03-12383C0B-15071E36-131A0C27
    +    name word2003large.doc ß Word is renaming the original file. This is a prelude to copying data from the pseudo-temporary working files into a new file named the same as the original. This operation is considered a delete/tombstone because the file is being renamed to a filtered extension that will not replicate.
    +    
    <Upstream> 20080626 11:33:51.982 3128 USNC 2782 UsnConsumer::TombstoneOrDelete ID record tombstoned from USN_RECORD:
    +    USN_RECORD:
    +    RecordLength: 88
    +    MajorVersion: 2
    +    MinorVersion: 0
    +    FileRefNumber: 0x70000000000B9
    +    ParentFileRefNumber: 0xF00000000A781
    +    USN: 0xa2ff68
    +    TimeStamp: 20080626 11:33:51.972 Eastern Standard Time
    +    Reason: Close Rename New Name ß the word2003large.doc file is renamed to a file named ~wrl004.tmp. Note how the File Reference Number never changed!
    +    SourceInfo: 0x0
    +    SecurityId: 0x0
    +    FileAttributes: 0x20
    +    FileNameLength: 24
    +    FileNameOffset: 60
    +    FileName: ~WRL0004.tmp ß new name
    +    
    <Upstream> 20080626 11:33:51.982 3128 USNC 3341 UsnConsumer::UidTunnelReanimate LDB Updating ID Record: ß the UID is reused from previous due to the same file name/path
    +    fid 0x200000000AC66 ß note that File ID is same as ~WRD0003.tmp
    +    usn 0xa30000
    +    uidVisible 1
    +    filtered 0
    +    journalWrapped 0
    +    slowRecoverCheck 0
    +    pendingTombstone 0
    +    internalUpdate 0
    +    dirtyShutdownMismatch 0
    +    meetInstallUpdate 0
    +    meetReanimated 0
    +    recUpdateTime 20080626 15:33:51.982 GMT
    +    present 1 ß added back into the replicated folder
    +    nameConflict 0
    +    attributes 0x20
    +    ghostedHeader 0
    +    data 0
    +    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 ß new GVSN when file recreated
    +    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 ß Old UID reused
    +    parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
    +    fence 16010101 00:00:00.000
    +    clockDecrementedInDirtyShutdown 0
    +    clock 20080626 15:33:51.972 GMT (0x1c8d7a2093ceaba)
    +    createTime 20080626 15:30:22.912 GMT
    +    csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    +    hash 00000000-00000000-00000000-00000000
    +    similarity 00000000-00000000-00000000-00000000
    +    name word2003large.doc ß was ~WRD0003.tmp
    +    
    <Upstream> 20080626 11:33:51.982 3128 USNC 3346 UsnConsumer::UidTunnelReanimate UID tunnelling: ID record reanimated because of UID tunnelling: ß the renaming of the file back into a previous one is counted as a USN reanimation
    +    USN_RECORD:
    +    RecordLength: 96
    +    MajorVersion: 2
    +    MinorVersion: 0
    +    FileRefNumber: 0x200000000AC66
    +    ParentFileRefNumber: 0xF00000000A781
    +    USN: 0xa30000
    +    TimeStamp: 20080626 11:33:51.972 Eastern Standard Time
    +    Reason: Basic Info Change Close Object ID Change Rename New Name Security Change ß ~WRD0003.tmp is renamed to word2003large.doc
    +    SourceInfo: 0x0
    +    SecurityId: 0x0
    +    FileAttributes: 0x20
    +    FileNameLength: 34
    +    FileNameOffset: 60
    +    FileName: word2003large.doc
    +    
    <Upstream> 20080626 11:33:51.992 3128 USNC 1995 UsnConsumer::UpdateUsnOnly LDB Updating ID Record:
    +    fid 0x200000000AC66
    +    usn 0xa301c8
    +    uidVisible 1
    +    filtered 0
    +    journalWrapped 0
    +    slowRecoverCheck 0
    +    pendingTombstone 0
    +    internalUpdate 0
    +    dirtyShutdownMismatch 0
    +    meetInstallUpdate 0
    +    meetReanimated 0
    +    recUpdateTime 20080626 15:33:51.982 GMT
    +    present 1
    +    nameConflict 0
    +    attributes 0x20
    +    ghostedHeader 0
    +    data 0
    +    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66
    +    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
    +    parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
    +    fence 16010101 00:00:00.000
    +    clockDecrementedInDirtyShutdown 0
    +    clock 20080626 15:33:51.972 GMT (0x1c8d7a2093ceaba)
    +    createTime 20080626 15:30:22.912 GMT
    +    csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    +    hash 00000000-00000000-00000000-00000000
    +    similarity 00000000-00000000-00000000-00000000
    +    name word2003large.doc
    +    
    <Upstream> 20080626 11:33:51.992 3128 USNC 1997 UsnConsumer::UpdateUsnOnly USN-only update from USN_RECORD:
    +    USN_RECORD:
    +    RecordLength: 96
    +    MajorVersion: 2
    +    MinorVersion: 0
    +    FileRefNumber: 0x200000000AC66
    +    ParentFileRefNumber: 0xF00000000A781
    +    USN: 0xa301c8
    +    TimeStamp: 20080626 11:33:51.982 Eastern Standard Time
    +    Reason: Close Object ID Change ß file closed
    +    SourceInfo: 0x0
    +    SecurityId: 0x0
    +    FileAttributes: 0x20
    +    FileNameLength: 34
    +    FileNameOffset: 60
    +    FileName: word2003large.doc
    +
    <Downstream> 20080626 11:33:51.996 3616 INCO 3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00A4CCE8 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 changeType:all ß downstream server requests version vectors
    <Downstream> 20080626 11:33:51.996 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00A501C0
    <Upstream> 20080626 11:33:52.062 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD:
    +    USN_RECORD:
    +    RecordLength: 88
    +    MajorVersion: 2
    +    MinorVersion: 0
    +    FileRefNumber: 0x70000000000B9
    +    ParentFileRefNumber: 0xF00000000A781
    +    USN: 0xa30388
    +    TimeStamp: 20080626 11:33:52.062 Eastern Standard Time
    +    Reason: Basic Info Change Close Object ID Change ß closed the tmp file
    +    SourceInfo: 0x0
    +    SecurityId: 0x0
    +    FileAttributes: 0x2
    +    FileNameLength: 24
    +    FileNameOffset: 60
    +    FileName: ~WRL0004.tmp
    +    
    <Upstream> 20080626 11:33:52.062 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD:
    +    USN_RECORD:
    +    RecordLength: 88
    +    MajorVersion: 2
    +    MinorVersion: 0
    +    FileRefNumber: 0x70000000000B9
    +    ParentFileRefNumber: 0xF00000000A781
    +    USN: 0xa303e0
    +    TimeStamp: 20080626 11:33:52.062 Eastern Standard Time
    +    Reason: Close File Delete ß deleted the tmp file
    +    SourceInfo: 0x0
    +    SecurityId: 0x0
    +    FileAttributes: 0x2
    +    FileNameLength: 24
    +    FileNameOffset: 60
    +    FileName: ~WRL0004.tmp
    +    
    <Upstream> 20080626 11:33:52.062 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD:
    +    USN_RECORD:
    +    RecordLength: 96
    +    MajorVersion: 2
    +    MinorVersion: 0
    +    FileRefNumber: 0x100000000AC61
    +    ParentFileRefNumber: 0xF00000000A781
    +    USN: 0xa30438
    +    TimeStamp: 20080626 11:33:52.062 Eastern Standard Time
    +    Reason: Close File Delete ß deleted the original renamed temporary file for the document
    +    SourceInfo: 0x0
    +    SecurityId: 0x0
    +    FileAttributes: 0x22
    +    FileNameLength: 34
    +    FileNameOffset: 60
    +    FileName: ~$rd2003large.doc
    +    
    <Downstream> 20080626 11:33:52.286 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:VvUpRequest reqState:Completed status:0 ptr:00A4CCE8 ß finished processing version vectors
    <Downstream> 20080626 11:33:52.286 1092 INCO 3959 InConnection::ReceiveVvUp Received VvUp connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 vvUp:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 49..66} ß have received the VV's
    +    
    <Downstream> 20080626 11:33:52.286 1092 INCO 3966 InConnection::ReceiveVvUp Creating new session:6 requestState:00A4CCE8 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 vvDown:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 49..64} ß calculating the version vector delta
    +    
    <Downstream> 20080626 11:33:52.286 3616 INCO 4619 InConnection::RequestUpdates Requesting updates. credits:32 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 requestType:all cursor:{00000000-0000-0000-0000-000000000000}-v0 delta::{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 65, 66} ß requesting the actual files from the upstream server based on missing versions
    +    
    <Downstream> 20080626 11:33:52.286 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId
    {00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00A501C0
    <Upstream> 20080626 11:33:52.292 4052 SRTR 1880 SERVER_RequestVersionVector Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} seqNumber:15 changeType:all
    <Upstream> 20080626 11:33:52.292 4052 SRTR 1927 SERVER_AsyncPoll Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D}
    <Downstream> 20080626 11:33:52.296 1092 INCO 4803 InConnection::ReceiveUpdates Upstream credits:32 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 creditsUsed:1 creditsAvailable:32
    <Downstream> 20080626 11:33:52.296 1092 INCO 4868 InConnection::ReceiveUpdates Received: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 fileName:word2003large.doc session:6 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3
    <Downstream> 20080626 11:33:52.296 3616 MEET 1207 Meet::Install Retries:0 updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 updateType:remote ß the file is ready to be received downstream
    <Downstream> 20080626 11:33:52.296 1092 INCO 4932 InConnection::ReceiveUpdates Session has been closed. sessionId:6 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3
    <Downstream> 20080626 11:33:52.296 3976 INCO 3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00A4CBF0 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 changeType:notify
    <Downstream> 20080626 11:33:52.296 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:UpdateRequest reqState:Completed status:0 ptr:00A42780
    <Upstream> 20080626 11:33:52.302 4052 SRTR 882 SERVER_RequestUpdates Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} credits:32 requestType:all
    <Upstream> 20080626 11:33:52.302 4052 SRTR 1927 SERVER_AsyncPoll Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D}
    <Upstream> 20080626 11:33:52.302 2688 JOIN 1167 Join::SubmitUpdate Sent: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 name:word2003large.doc connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 ß upstream acknowledges that it is ready to have the file pulled
    <Upstream> 20080626 11:33:52.302 1516 OUTC 784 OutConnection::OpenFile Received request for update: ß upstream serving file
    +    present 1
    +    nameConflict 0
    +    attributes 0x20
    +    ghostedHeader 0
    +    data 0
    +    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 ß this the version of the file to be replicated
    +    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
    +    parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-1
    +    fence 16010101 00:00:00.000
    +    clockDecrementedInDirtyShutdown 0
    +    clock 20080626 15:33:51.972 GMT (0x1c8d7a2093ceaba)
    +    createTime 20080626 15:30:22.912 GMT
    +    csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    +    hash 00000000-00000000-00000000-00000000
    +    similarity 00000000-00000000-00000000-00000000
    +    name word2003large.doc ß this is our file to be replicated
    +     rdcDesired:1 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} rgName:TestRG3
    <Downstream> 20080626 11:33:52.306 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:VvUpRequest reqState:Completed status:0 ptr:00A4CBF0
    <Upstream> 20080626 11:33:52.312 4052 SRTR 1880 SERVER_RequestVersionVector Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} seqNumber:16 changeType:notify
    <Upstream> 20080626 11:33:52.342 1516 MRSH 4615 Marshaller::Marshal FileAttrs in metadata : 0x20 ß file attributes marshaled
    <Upstream> 20080626 11:33:53.703 1516 CSMG 4844 ContentSetManager::UpdateHash LDB Updating ID Record:
    +    fid 0x200000000AC66
    +    usn 0xa301c8
    +    uidVisible 1
    +    filtered 0
    +    journalWrapped 0
    +    slowRecoverCheck 0
    +    pendingTombstone 0
    +    internalUpdate 0
    +    dirtyShutdownMismatch 0
    +    meetInstallUpdate 0
    +    meetReanimated 0
    +    recUpdateTime 20080626 15:33:51.982 GMT
    +    present 1
    +    nameConflict 0
    +    attributes 0x20
    +    ghostedHeader 0
    +    data 0
    +    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66
    +    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
    +    parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-1
    +    fence 16010101 00:00:00.000
    +    clockDecrementedInDirtyShutdown 0
    +    clock 20080626 15:33:51.972 GMT (0x1c8d7a2093ceaba)
    +    createTime 20080626 15:30:22.912 GMT
    +    csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    +    hash 66E49D5D-344B5F47-D192C5EA-6C30377D
    +    similarity 2C131C03-12383C0B-15071E36-131A0C27
    +    name word2003large.doc
    +    
    <Upstream> 20080626 11:33:53.903 1516 ASYN 510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:
    <Upstream> 20080626 11:33:53.903 1516 STAG 799 StageWriter::CompleteDownloadStage Completed download or stage file 66-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66-Downloaded.frx ß the file has been staged (compressed, RDC signatures calculated) on the upstream server
    <Upstream> 20080626 11:33:53.903 1516 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
    <Upstream> 20080626 11:33:53.903 2688 STAG 108 StagingCleanupTask::Run Start to cleanup private staging directory. csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    <Upstream> 20080626 11:33:53.963 1516 OUTC 1534 OutConnection::OpenFile Sent file uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 name:word2003large.doc fileSize:4821514 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} rgName:TestRG3 ß the file is truly ready for replication upstream
    <Upstream> 20080626 11:33:53.963 1516 SRTR 2357 InitializeFileTransferAsyncState::ProcessIoCompletion Initialized connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} rdc:1 context:00AB0248,00AA1BA8,00000000 uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 ptr:00AA3EC0 ß outbound RPC session ready on the upstream server, file can be replicated anytime now
    <Downstream> 20080626 11:33:54.169 3616 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
    <Upstream> 20080626 11:33:55.524 3128 USNC 2361 UsnConsumer::UpdateIdRecord LDB Updating ID Record: ß Word touched the file again for some reason. +    fid 0x200000000AC66
    +    usn 0xa32330
    +    uidVisible 1
    +    filtered 0
    +    journalWrapped 0
    +    slowRecoverCheck 0
    +    pendingTombstone 0
    +    internalUpdate 0
    +    dirtyShutdownMismatch 0
    +    meetInstallUpdate 0
    +    meetReanimated 0
    +    recUpdateTime 20080626 15:33:51.982 GMT
    +    present 1
    +    nameConflict 0
    +    attributes 0x20
    +    ghostedHeader 0
    +    data 0
    +    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 ß Upstream, Word changes the file one more time as part of its internal workings. This is going to force the download process to happen all over again below unfortunately. This highlights how applications are often the cause of DFSR replication inefficiencies. Fortunately we will see below that the file was not altered materially and will not need to be restaged.
    +    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
    +    parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
    +    fence 16010101 00:00:00.000
    +    clockDecrementedInDirtyShutdown 0
    +    clock 20080626 15:33:55.524 GMT (0x1c8d7a20b5b0f15)
    +    createTime 20080626 15:30:22.912 GMT
    +    csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    +    hash 00000000-00000000-00000000-00000000
    +    similarity 00000000-00000000-00000000-00000000
    +    name word2003large.doc
    +    
    <Upstream> 20080626 11:33:55.524 3128 USNC 2364 UsnConsumer::UpdateIdRecord ID record updated from USN_RECORD:
    +    USN_RECORD:
    +    RecordLength: 96
    +    MajorVersion: 2
    +    MinorVersion: 0
    +    FileRefNumber: 0x200000000AC66
    +    ParentFileRefNumber: 0xF00000000A781
    +    USN: 0xa32330
    +    TimeStamp: 20080626 11:33:55.524 Eastern Standard Time
    +    Reason: Close Data Overwrite ß file closed again.
    +    SourceInfo: 0x0
    +    SecurityId: 0x0
    +    FileAttributes: 0x20
    +       ParentFileRefNumber: 0xF00000000A781
    +       USN:                 0xa2f9d0
    +       TimeStamp:           20080626 11:33:51.861 Eastern Standard Time
    +       Reason:              Close Data Extend Data Overwrite File Create ß created, added some data
    +       SourceInfo:          0x0
    +       SecurityId:          0x0
    +       FileAttributes:      0x20 ß not temporary
    +       FileNameLength:      24
    +       FileNameOffset:      60
    +       FileName:            ~WRD0003.tmp
    +    FileNameLength: 34
    +    FileNameOffset: 60
    +    FileName: word2003large.doc
    +    
    <Downstream> 20080626 11:33:55.531 3976 INCO 3750 InConnection::RequestVvUp Requested upstream version vector. requestState:04569008 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 changeType:all
    <Downstream> 20080626 11:33:55.531 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00A501C0
    <Downstream> 20080626 11:33:55.531 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:VvUpRequest reqState:Completed status:0 ptr:04569008
    <Downstream> 20080626 11:33:55.531 1092 INCO 3959 InConnection::ReceiveVvUp Received VvUp connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 vvUp:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 49..67} ß we had to send the higher version vector info to downstream again
    +    
    <Downstream> 20080626 11:33:55.531 1092 INCO 3966 InConnection::ReceiveVvUp Creating new session:7 requestState:04569008 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 vvDown:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 49..64}
    +    
    <Downstream> 20080626 11:33:55.531 1092 INCO 3982 InConnection::ReceiveVvUp Adding difference from previous session connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 vvDiff:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 65, 66}
    +     vvDown:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 49..66}
    +    
    <Downstream> 20080626 11:33:55.531 3976 INCO 4619 InConnection::RequestUpdates Requesting updates. credits:32 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 requestType:all cursor:{00000000-0000-0000-0000-000000000000}-v0 delta::{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 67} ß downstream re-requests the update again (the other –v66 update is still ongoing)
    +    
    <Downstream> 20080626 11:33:55.531 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00A501C0
    <Upstream> 20080626 11:33:55.535 4052 SRTR 1880 SERVER_RequestVersionVector Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} seqNumber:17 changeType:all
    <Upstream> 20080626 11:33:55.535 4052 SRTR 1927 SERVER_AsyncPoll Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D}
    <Upstream> 20080626 11:33:55.535 4052 SRTR 882 SERVER_RequestUpdates Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} credits:32 requestType:all
    <Upstream> 20080626 11:33:55.535 4052 SRTR 1927 SERVER_AsyncPoll Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D}
    <Upstream> 20080626 11:33:55.535 2688 JOIN 1167 Join::SubmitUpdate Sent: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 name:word2003large.doc connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3
    <Downstream> 20080626 11:33:55.541 1092 INCO 4803 InConnection::ReceiveUpdates Upstream credits:32 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 creditsUsed:1 creditsAvailable:32
    <Downstream> 20080626 11:33:55.541 1092 INCO 4868 InConnection::ReceiveUpdates Received: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 fileName:word2003large.doc session:7 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 ß downstream ready to pull the updates again.
    <Downstream> 20080626 11:33:55.541 3976 UPMG 413 UpdateWorker::ConsumeUpdates Available updates were locked. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    <Downstream> 20080626 11:33:55.541 1092 INCO 4932 InConnection::ReceiveUpdates Session has been closed. sessionId:7 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 ß the file updates have been transferred over the wire
    <Downstream> 20080626 11:33:55.541 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:UpdateRequest reqState:Completed status:0 ptr:00A4CBF0
    <Downstream> 20080626 11:33:55.541 3976 INCO 3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00A4CBF0 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 changeType:notify
    <Downstream> 20080626 11:33:55.541 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:VvUpRequest reqState:Completed status:0 ptr:00A4CBF0
    <Upstream> 20080626 11:33:55.545 4052 SRTR 1880 SERVER_RequestVersionVector Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} seqNumber:18 changeType:notify
    <Downstream> 20080626 11:33:55.721 3616 ASYN 510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:
    <Downstream> 20080626 11:33:55.721 3616 RDCX 1811 Rdc::SyncClientState::Flush Rdc Need Assembler Statistics: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 fileName:word2003large.doc connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} ß the downstream server can now gather statistics about what happened during the file transfer process.
    +     TOTAL
    +     Compression Ratio 2
    +     Target Uncompress Size 4905740 ß the true file size
    +     Target Compress Size 4814322 ß file size after being XPRESS compressed in staging directory. Note how the size difference is not great here. In this scenario, the Word document was filled with JPG images which are already compressed.
    +     Bytes Received 49704 Signatures: 4718 Data: 44986 ß actual bytes to be sent over the wire thanks to savings from RDC. The breakout here is total bytes, then the number of bytes that are just signature checksums, then the actual data blocks.
    +     Signature Bytes Received 4718 1616 3102
    +     Number of remote calls 5 Signatures: 3 Needs: 1 Data: 1
    +     SEED
    +     Rdc Need Size 0 0 0
    +     Xpress Blocks 589 589 0
    +     Uncompressed Xpress Blocks 7 7 0
    +     Blocks copied to target 0 0 0
    +     SOURCE
    +     Rdc Need Size 113076 0
    +     Xpress Blocks 17 0
    +     Uncompressed Xpress Blocks 4 0
    +     Blocks copied to target 11 0
    <Downstream> 20080626 11:33:55.721 3616 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
    <Downstream> 20080626 11:33:55.721 3616 INCO 5610 InConnection::LogTransferActivity Received RDCGET uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 fileName:word2003large.doc connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} stagedSize:4821514 ß the file transfer over the wire is complete and the file now exists in staging on the downstream server.
    <Downstream> 20080626 11:33:55.721 3616 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
    <Downstream> 20080626 11:33:55.721 3976 STAG 108 StagingCleanupTask::Run Start to cleanup private staging directory. csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    <Upstream> 20080626 11:33:55.725 4052 RDCX 2833 Rdc::SyncServerState::~SyncServerState RDC Need Reader Statistics: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} ß statistics are now written to show what actually was sent over the wire (as opposed to the previous stats which were planned work) +     TOTAL
    +     Compression Ratio 57
    +     RDC Need Size 113076
    +     Bytes sent to downstream 49704
    +     Uncompressed XPRESS blocks 0
    +     Compressed XPRESS blocks 2
    +     Copied XPRESS Blocks 13
    +     Bytes read using async I/Os 0
    <Upstream> 20080626 11:33:55.725 4052 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
    <Downstream> 20080626 11:33:55.781 3616 STAG 799 StageWriter::CompleteDownloadStage Completed download or stage file 66-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66-Downloaded.frx ß we leave the staging functions and the name of the staged file is written to log
    <Downstream> 20080626 11:33:55.781 3616 MRSH 3959 MarshalContext::Initialize Create file:[word2003large-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66.doc] with attributes:0x20 ß data is unmarshalled
    <Downstream> 20080626 11:33:55.781 3616 MEET 2585 Meet::TransferToInstalling Transferring content from staging area into Installing updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 ß the staged file is decompressed as a copy into the Installing directory
    <Downstream> 20080626 11:33:56.542 3976 UPMG 413 UpdateWorker::ConsumeUpdates Available updates were locked. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    <Downstream> 20080626 11:33:56.542 3616 ASYN 510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:
    <Downstream> 20080626 11:33:56.542 3616 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
    <Downstream> 20080626 11:33:56.542 3616 MEET 2032 Meet::Download Download Succeeded : true updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} ß the copy of the file in the Installing directory is now moved into the replicated folder, replacing an existing copy of the file
    <Downstream> 20080626 11:33:56.542 3616 MEET 2772 Meet::InstallRename Move out previous version of same file updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 ß since this was a modification of an existing file that exists on both servers, the downstream copy must be overwritten. So the older copy downstream is deleted.
    <Downstream> 20080626 11:33:56.542 3616 MEET 4867 Meet::MoveOut Moving contents and children out of replica. newName:word2003large-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61.doc updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 record: ß indicates the deletion is occurring downstream
    +    fid 0x200000000A6D1
    +    usn 0x903d38
    +    uidVisible 1
    +    filtered 0
    +    journalWrapped 0
    +    slowRecoverCheck 0
    +    pendingTombstone 0
    +    internalUpdate 0
    +    dirtyShutdownMismatch 0
    +    meetInstallUpdate 1
    +    meetReanimated 0
    +    recUpdateTime 20080626 15:30:27.557 GMT
    +    present 1
    +    nameConflict 0
    +    attributes 0x20
    +    ghostedHeader 0
    +    data 0
    +    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 ß note the old unmodified version
    +    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
    +    parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
    +    fence 16010101 00:00:00.000
    +    clockDecrementedInDirtyShutdown 0
    +    clock 20080626 15:30:22.932 GMT (0x1c8d7a18ca3f2b2)
    +    createTime 20080626 15:30:22.912 GMT
    +    csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    +    hash 4992549E-7564D836-ED346C90-D5FD88B3
    +    similarity 2C131C03-12383C0B-15071E36-131A0C27
    +    name word2003large.doc
    +    
    <Downstream> 20080626 11:33:56.542 3616 MEET 4989 Meet::MoveOut Purge existing file in Deleted updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 ß the older file is moved into the Deleted folder, then purged from the disk
    <Downstream> 20080626 11:33:56.542 3616 MEET 4995 Meet::MoveOut RenameDelete file fid:0x200000000A6D1 updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 ß DFSR notes that the old file is gone now.
    <Downstream> 20080626 11:33:56.542 3616 MEET 2837 Meet::InstallRename File moved. rootVolume:{3EA8BD01-416E-11DD-A317-806E6F6E6963} parentFid:0xC00000000A514 fidInInstalling:0x900000000A5D4 usn:0x906ec0 updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 ß the new copy of the file is copied into the replicated folder.
    <Downstream> 20080626 11:33:56.542 3616 MEET 6746 Meet::UpdateIdRecord LDB Updating ID Record: ß Database is updated to reflect the file now existing in the replicated folder
    +    fid 0x900000000A5D4
    +    usn 0x906ec0
    +    uidVisible 1
    +    filtered 0
    +    journalWrapped 0
    +    slowRecoverCheck 0
    +    pendingTombstone 0
    +    internalUpdate 0
    +    dirtyShutdownMismatch 0
    +    meetInstallUpdate 1 ß indicates the update was due to replication and not an originating change
    +    meetReanimated 0
    +    recUpdateTime 16010101 00:00:00.000 GMT
    +    present 1 ß file is present and accessible by users
    +    nameConflict 0
    +    attributes 0x20
    +    ghostedHeader 0
    +    data 0
    +    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66
    +    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
    +    parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
    +    fence 16010101 00:00:00.000
    +    clockDecrementedInDirtyShutdown 0
    +    clock 20080626 15:33:51.972 GMT (0x1c8d7a2093ceaba)
    +    createTime 20080626 15:30:22.912 GMT
    +    csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    +    hash 66E49D5D-344B5F47-D192C5EA-6C30377D ß note that we have a new hash for the file after it was modified
    +    similarity 2C131C03-12383C0B-15071E36-131A0C27
    +    name word2003large.doc
    +
    <Downstream> 20080626 11:33:56.552 3616 MEET 2949 Meet::InstallRename -> DONE Install-rename completed updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} ß the process of moving file into the replicated folder is complete
    <Downstream> 20080626 11:33:56.552 3616 INCO 5897 InConnection::UpdateProcessed Received Update. updatesLeft:0 processed:1 failures:0 sessionId:6 open:0 updateType:0 processStatus:0 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 update:
    +    present 1
    +    nameConflict 0
    +    attributes 0x20
    +    ghostedHeader 0
    +    data 0
    +    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66
    +    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
    +    parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
    +    fence 16010101 00:00:00.000
    +    clockDecrementedInDirtyShutdown 0
    +    clock 20080626 15:33:51.972 GMT (0x1c8d7a2093ceaba)
    +    createTime 20080626 15:30:22.912 GMT
    +    csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    +    hash 66E49D5D-344B5F47-D192C5EA-6C30377D
    +    similarity 2C131C03-12383C0B-15071E36-131A0C27
    +    name word2003large.doc
    +    
    <Downstream> 20080626 11:33:56.552 3616 MEET 1207 Meet::Install Retries:0 updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 updateType:remote ß note the GVSN changed. This is the subsequent update that occurred when Word re-closed the file as part of its internal processing.
    <Downstream> 20080626 11:33:56.562 3620 SRTR 1880 SERVER_RequestVersionVector Received from connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} seqNumber:12 changeType:all
    <Downstream> 20080626 11:33:56.562 2716 SRTR 1927 SERVER_AsyncPoll Received from connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9}
    <Downstream> 20080626 11:33:56.572 2716 SRTR 1927 SERVER_AsyncPoll Received from connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9}
    <Downstream> 20080626 11:33:56.572 2716 SRTR 1880 SERVER_RequestVersionVector Received from connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} seqNumber:13 changeType:notify
    <Upstream> 20080626 11:33:56.575 1516 OUTC 784 OutConnection::OpenFile Received request for update: ß the subsequent file change is now being requested
    +    present 1
    +    nameConflict 0
    +    attributes 0x20
    +    ghostedHeader 0
    +    data 0
    +    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67
    +    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
    +    parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
    +    fence 16010101 00:00:00.000
    +    clockDecrementedInDirtyShutdown 0
    +    clock 20080626 15:33:55.524 GMT (0x1c8d7a20b5b0f15)
    +    createTime 20080626 15:30:22.912 GMT
    +    csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    +    hash 00000000-00000000-00000000-00000000 ß note that the change is causing us to recalculate the hash (this is by design)
    +    similarity 00000000-00000000-00000000-00000000
    +    name word2003large.doc
    +     rdcDesired:1 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} rgName:TestRG3
    <Upstream> 20080626 11:33:56.575 1516 MRSH 4615 Marshaller::Marshal FileAttrs in metadata : 0x20
    <Upstream> 20080626 11:33:56.585 752 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00AB0058
    <Upstream> 20080626 11:33:56.585 2688 INCO 3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00AA2038 connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 changeType:all
    <Upstream> 20080626 11:33:56.585 752 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:VvUpRequest reqState:Completed status:0 ptr:00AA2038
    <Upstream> 20080626 11:33:56.585 752 INCO 3959 InConnection::ReceiveVvUp Received VvUp connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 vvUp:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 49..66}
    +    
    <Upstream> 20080626 11:33:56.585 752 INCO 3966 InConnection::ReceiveVvUp Creating new session:6 requestState:00AA2038 connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 vvDown:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 49..67} <- version vector information updated
    +    
    <Upstream> 20080626 11:33:56.585 752 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00AB0058
    <Upstream> 20080626 11:33:56.585 2688 INCO 3779 InConnection::ContentSetContext::Hibernate Hibernating: connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    <Upstream> 20080626 11:33:56.585 2688 INCO 3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00AB0150 connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 changeType:notify
    <Upstream> 20080626 11:33:56.585 752 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:VvUpRequest reqState:Completed status:0 ptr:00AB0150
    <Downstream> 20080626 11:33:57.543 3976 UPMG 418 UpdateWorker::ConsumeUpdates No pending updates. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    <Upstream> 20080626 11:33:57.927 1516 CSMG 4844 ContentSetManager::UpdateHash LDB Updating ID Record: ß the file info is re-added into the database, now with hash below, on the upstream server.
    +    fid 0x200000000AC66
    +    usn 0xa32330
    +    uidVisible 1
    +    filtered 0
    +    journalWrapped 0
    +    slowRecoverCheck 0
    +    pendingTombstone 0
    +    internalUpdate 0
    +    dirtyShutdownMismatch 0
    +    meetInstallUpdate 0
    +    meetReanimated 0
    +    recUpdateTime 20080626 15:33:55.524 GMT
    +    present 1
    +    nameConflict 0
    +    attributes 0x20
    +    ghostedHeader 0
    +    data 0
    +    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67
    +    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
    +    parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
    +    fence 16010101 00:00:00.000
    +    clockDecrementedInDirtyShutdown 0
    +    clock 20080626 15:33:55.524 GMT (0x1c8d7a20b5b0f15)
    +    createTime 20080626 15:30:22.912 GMT
    +    csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    +    hash 66E49D5D-344B5F47-D192C5EA-6C30377D ß hash is the same as the –v66 version of the file. So the file did not actually change, it was just Word opening, making some non-data change, then closing for reasons unknown.
    +    similarity 2C131C03-12383C0B-15071E36-131A0C27
    +    name word2003large.doc
    +    
    <Upstream> 20080626 11:33:58.077 1516 ASYN 510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:
    <Upstream> 20080626 11:33:58.077 1516 STAG 799 StageWriter::CompleteDownloadStage Completed download or stage file 67-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67-Downloaded.frx ß the file is staged upstream.
    <Upstream> 20080626 11:33:58.077 1516 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
    <Upstream> 20080626 11:33:58.077 2688 STAG 108 StagingCleanupTask::Run Start to cleanup private staging directory. csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    <Downstream> 20080626 11:33:58.124 3616 RDCX 808 Rdc::SeedFile::Initialize The hashes coincide. The download is redundant, uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 fileName:word2003large.doc csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} ß after exchanging hash information, the downstream server now realizes that there is no need to replicate the file as it is unchanged upstream.
    <Upstream> 20080626 11:33:58.147 1516 OUTC 1534 OutConnection::OpenFile Sent file uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 name:word2003large.doc fileSize:4821514 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} rgName:TestRG3
    <Upstream> 20080626 11:33:58.147 1516 SRTR 2357 InitializeFileTransferAsyncState::ProcessIoCompletion Initialized connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} rdc:1 context:00AB0248,00AA1BA8,00000000 uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 ptr:00AA3EC0
    <Downstream> 20080626 11:33:58.184 3616 DOWN 5186 [ERROR] DownstreamTransport::RdcGet Failed on connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} rgName:TestRG3 update: ß failed is not an error in this case – it is an acknowledgment that there is no need to replicate the file downstream after all. However the version vector info is sent to keep the DFSR-related metadata about the file in sync going forward.
    +    present 1
    +    nameConflict 0
    +    attributes 0x20
    +    ghostedHeader 0
    +    data 0
    +    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 ß version updated
    +    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
    +    parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
    +    fence 16010101 00:00:00.000
    +    clockDecrementedInDirtyShutdown 0
    +    clock 20080626 15:33:55.524 GMT (0x1c8d7a20b5b0f15)
    +    createTime 20080626 15:30:22.912 GMT
    +    csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    +    hash 66E49D5D-344B5F47-D192C5EA-6C30377D ß hash unchanged
    +    similarity 2C131C03-12383C0B-15071E36-131A0C27
    +    name word2003large.doc
    +     Error:
    +    [Error:9047(0x2357) RpcFinalizeContext downstreamtransport.cpp:1096 3616 C The download is redundant]
    +    [Error:9047(0x2357) Rdc::SyncClientState::Download rdc.cpp:2546 3616 C The download is redundant]
    +    [Error:9047(0x2357) Rdc::SeedFile::Initialize rdc.cpp:944 3616 C The download is redundant]
    +    [Error:9047(0x2357) Rdc::SeedFile::Initialize rdc.cpp:810 3616 C The download is redundant] ß More spurious 'errors' – a redundant download is not a true error.
    <Downstream> 20080626 11:33:58.184 3616 INCO 5599 InConnection::LogTransferActivity Failed to receive RDCGET uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 fileName:word2003large.doc connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} stagedSize:0 Error:
    +    [Error:9047(0x2357) DownstreamTransport::RdcGet downstreamtransport.cpp:5201 3616 C The download is redundant]
    +    [Error:9047(0x2357) RpcFinalizeContext downstreamtransport.cpp:1096 3616 C The download is redundant]
    +    [Error:9047(0x2357) Rdc::SyncClientState::Download rdc.cpp:2546 3616 C The download is redundant]
    +    [Error:9047(0x2357) Rdc::SeedFile::Initialize rdc.cpp:944 3616 C The download is redundant]
    +    [Error:9047(0x2357) Rdc::SeedFile::Initialize rdc.cpp:810 3616 C The download is redundant] ß more info that file download did not need to occur <Downstream> 20080626 11:33:58.184 3616 MEET 2032 Meet::Download Download Succeeded : false updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    <Downstream> 20080626 11:33:58.194 3616 NTFS 1257 NtfsFileSystem::SetAttributes oldFileAttributes:0x20 newFileAttributes:0x20
    <Downstream> 20080626 11:33:58.194 3616 MEET 6746 Meet::UpdateIdRecord LDB Updating ID Record: ß The database is updated to cover the new version info, regardless of the fact that file contents are unchanged
    +    fid 0x900000000A5D4
    +    usn 0x907280
    +    uidVisible 1
    +    filtered 0
    +    journalWrapped 0
    +    slowRecoverCheck 0
    +    pendingTombstone 0
    +    internalUpdate 0
    +    dirtyShutdownMismatch 0
    +    meetInstallUpdate 0
    +    meetReanimated 0
    +    recUpdateTime 16010101 00:00:00.000 GMT
    +    present 1
    +    nameConflict 0
    +    attributes 0x20
    +    ghostedHeader 0
    +    data 0
    +    gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67
    +    uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
    +    parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
    +    fence 16010101 00:00:00.000
    +    clockDecrementedInDirtyShutdown 0
    +    clock 20080626 15:33:55.524 GMT (0x1c8d7a20b5b0f15)
    +    createTime 20080626 15:30:22.912 GMT
    +    csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
    +    hash 66E49D5D-344B5F47-D192C5EA-6C30377D
    +    similarity 2C131C03-12383C0B-15071E36-131A0C27
    +    name word2003large.doc
    +    

    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

  • New Directory Services KB Articles 3/21-3/28

    New KB articles related to Directory Services for the week of 3/21-3/28.

    969100 When you log on to a Windows XP-based computer that is running version 10.200 of the Citrix ICA client, Windows XP may create a user profile instead of loading your cached profile
    969457 How to prevent profile creation on server even when an encrypted file is copied in plain text mode
    968225 Account lockout policy does not work correctly for ADAM user accounts when the password expires, and the wrong password is entered during the bind process
    969523 Installers running in Terminal Server may not copy all per-user Default settings to each user's HKCU hive.
    953152 The algorithm for the Encrypting File System (EFS) smartcard certificate implementation in Windows Vista may cause data loss
    967574 A Windows Server 2008-based or Windows Vista SP1-based computer cannot locate ADWS in a domain
    969382 Recovery process of a DFS Namespace in Windows 2003 and 2008 Server
    969511 Performance issues in W2K8 RDR cause performance delays for ADMT migrations
    959193 Two improvements are available that shorten the time that is required to manage SCEP certificates by using the Network Device Enrollment Service in Windows Server 2008
    969488 RODC logs DNS event 4015 every 3 minutes with error code 00002095
    953684 How to change the default behavior for client certificate mapping when you use forms-based authentication with Active Directory in ISA Server 2006 Service Pack 1
    967252 You may encounter a data-corruption issue on a computer that is running Windows 7 Beta
  • Understanding DFSR debug logging (Part 4: A Very Small File Added to Replicated Folder on Windows Server 2008)

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

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

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

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

    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