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

Article
03/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.

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.

- Ned 'Cure for Insomnia' Pyle

Comments

Anonymous
March 24, 2009
PingBack from http://www.ditii.com/2009/03/24/understanding-dfsr-debug-logging-part-1/
Anonymous
March 30, 2009
237 Microsoft Team blogs searched, 106 blogs have new articles in the past 7 days. 244 new articles found
Anonymous
July 16, 2010
The comment has been removed
Anonymous
July 16, 2010
The comment has been removed
Anonymous
August 12, 2010
Please help! I set up a new Windows 2008 R2 server and I am getting the following error every few seconds in the event logs. Users can not access the dfs share either. This is the 9th server I have installed in the past 2 months and this is the first time I have seen this. Not sure where to turn to. I have the DFSR logs available too and there are some errors in there to. I can email them or post to a share if needed. Log Name: System Source: Microsoft-Windows-DfsSvc Date: 8/12/2010 11:02:29 AM Event ID: 14530 Task Category: None Level: Error Keywords: Classic User: N/A Computer: MTP-DC01.americanchartered.com Description: DFS could not access its private data from the Active Directory. Please manually check network connectivity, security access, and/or consistency of DFS information in the Active Directory. This error occurred on root stdshares. Thanks Bob Sawyer
Anonymous
April 28, 2015
This is a collection of the top Microsoft Support solutions for the most common issues experienced when
Anonymous
May 15, 2015
This is a collection of the top Microsoft Support solutions for the most common issues experienced when
Anonymous
May 15, 2015
This is a collection of the top Microsoft Support solutions for the most common issues experienced when

Partager via

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

Logging levels

The debug log format

The common GUID fields

Comments

Ressources supplémentaires