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

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

  • Comments 5
  • Likes

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

  • PingBack from http://www.ditii.com/2009/03/24/understanding-dfsr-debug-logging-part-1/

  • 237 Microsoft Team blogs searched, 106 blogs have new articles in the past 7 days. 244 new articles found

  • Hello Ned!  Thank you for your DFSR postings, they are invaluable for me as a DFSR newbie taking over an existing infrastructure (previously mixed with 2k3, but now all 2k8R2).  I am trying to identify a GUID and would love your advice.  On one file server we receive repeated Event ID 6002

    The DFS Replication service detected invalid msDFSR-Subscriber object data while polling for configuration information.

    Additional Information:

    Object DN: CN=b66f5a04-7959-4137-b62a-abd47b83cbd9,CN=DFSR-LocalSettings,CN=[file server],OU=[ou1],OU=[ou2],OU=[ou3],DC=[dc1],DC=[dc2]

    Attribute Name: msDFSR-MemberReference

    Domain Controller: [domain controller]

    Polling Cycle: 60 minutes

    When viewing with ADSI edit, I see that the msDFSR-Subscription record is missing completely for b66f5a04-7959-4137-b62a-abd47b83cbd9, I was hoping to identify this with dfsrdiag.exe guid2name /GUID:, but it needs the replication group name (which is what I'm trying to identify)

    Basically I want to find out if this is orphaned and can be deleted - any suggestions?

    Thanks in advance!

  • Hi,

    You can use the WORKAROUND section here to walk through the deletion (and yes, you will need to delete it):

    953527 An event ID 6002 that references Distributed File System replication is logged several times a day on a Windows Server 2003 R2-based computer

    support.microsoft.com/default.aspx

    You don't need to walk the GUID to the RG, it's already gone. Hence the issue. :)

    - Ned

  • 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