Ask the Directory Services Team

9 MIN READ

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

Microsoft

Apr 04, 2019

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

LogLevelNone

N/A

Write nothing

LogLevelAlways

N/A

Write log header information only

LogLevelError

[ERROR]

Write error events and all others above

LogLevelWarn

[WARN]

Write warning events and all others above

LogLevelInfo

N/A

Write informational events and all others above

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