Understanding DFSR Debug Logging (Part 1: Logging Levels, Log Format, GUID’s)
Published Apr 04 2019 01:58 PM 10.5K Views
Microsoft

First published on TechNet on Mar 23, 2009

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.

 

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 ...
Understanding DFSR debug logging (Part 4: A Very Small File Added to Replicated Folder on Windows S...
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 Se...
Understanding DFSR debug logging (Part 7: Microsoft Office Word 2007 File Modified on Windows Serve...
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 Ser...
Understanding DFSR debug logging (part 13: A New Replication Group and Replicated Folder between tw...
Understanding DFSR debug logging (Part 14: A sharing violation due to a file locked upstream betwee...
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...
Understanding DFSR debug logging (Part 17: Replication failing because of blocked RPC ports (uses d...
Understanding DFSR debug logging (Part 18: LDAP queries failing due to network (uses debug severity...
Understanding DFSR debug logging (Part 19: File Blocked Inbound by a File Screen Filter Driver (use...
Understanding DFSR debug logging (Part 20: Skipped temporary and filtered files (uses debug severit...
Understanding DFSR debug logging (Part 21: File replication performance from throttling (uses debug...

 

- Ned 'Cure for Insomnia' Pyle

Co-Authors
Version history
Last update:
‎Jun 08 2023 10:15 AM
Updated by: