Microsoft's official enterprise support blog for AD DS and more
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.
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 SeverityDefault: 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 FilesDefault: 100 Range: 1 to 10000 WMIC syntax:
wmic /namespace:\\root\microsoftdfs path dfsrmachineconfig set maxdebuglogfiles=200
SETTING: Debug Log File PathDefault: %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
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
Write informational events and all others above
5
LogLevelTrace
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 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
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'.
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.com20080403 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
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
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.com20080403 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