Understanding DFSR debug logging (Part 2: Nested Fields, Module ID's)
Ned here. Part two today covers the nested debug field format and what module ID's mean. If Part 2 makes no sense, you probably haven't read Part 1.
Nested Field Format
When examining the nested (+) entries it is important to understand all of the fields that can be displayed in the debug logs. These fields give detailed information about file and folder replication, especially regarding database entries, USN changes, and RDC data. These are implemented through LogNewLine.
Below is a table describing all of these nested fields and their data output that you will see in the debug logs. All entries marked with an asterisk (*) are Windows Server 2008 only. Otherwise they apply to both Windows Server 2003 R2 as well as 2008. There is also an example of the log entry for each table.
File information(defined in DFSR source code and GetFileAttributes) (Severity 4) |
|
Field |
Description |
Data |
|
fid |
File ID Record stored in the DFSR database |
Unique hex value |
|
usn |
The USN ID record in the journal and DFSR database |
Unique hex value |
|
uidVisible |
Has the UID file record been replicated? |
0 or 1 |
|
filtered |
Is the file filtered by an administrator to prevent replication? |
0 or 1 |
|
journalWrapped |
Is the file in USN journal wrap recovery? |
0 or 1 |
|
slowRecoverCheck |
Is the file being checked after a journal wrap recovery completed? |
0 or 1 |
|
pendingTombstone |
Is the file in the process of being tombstoned in the database? |
0 or 1 |
|
recUpdateTime |
Displays time/date of local changes to file (only on the originating server – on downstream will show garbage) |
YYYYMMDD HH:MM:SS.MS GMT |
|
present |
Is the file live or tombstoned (deleted)? |
0 or 1 |
|
nameConflict |
Was there a conflict on the file (modified on upstream and downstream servers before replication |
0 or 1 |
|
attributes |
Attributes on the file |
Hex value |
|
gvsn |
Global Version Sequence Number of the file, used to track changes and server origination |
GUID of originating server +Version # |
|
uid |
Unique ID of the file, used to identify original file |
GUID of modifying server + Version # |
|
parent |
Folder containing the file |
GUID of originating server + Version # |
|
fence |
Authoritative data flag (not used) |
N/A |
|
clock |
Time of the last change to the file on this server |
YYYYMMDD HH:MM:SS.MS |
|
createTime |
Time the file was created on the server |
YYYYMMDD HH:MM:SS.MS GMT |
|
csId |
Replicated Folder |
GUID |
|
hash |
Salted SHA1 checksum of the file and its size (not a true SHA1 of the file itself) |
Hex value |
|
similarity |
Salted SHA1 checksum information about the RDC similarity data |
Hex value |
|
Name |
Name of the file |
Text string |
|
ghostedHeader* |
<reserved for future use> |
|
|
Data* |
<reserved for future use> |
|
|
clockDecrementedInDirtyShutdown* |
<reserved for future use> |
|
+ fid 0x100000000094A
+ usn 0x0
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 20080318 20:58:37.190 GMT
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {AF8C06FD-E1B8-4044-8FE1-51A9E30F18AD}-v2353
+ uid {AF8C06FD-E1B8-4044-8FE1-51A9E30F18AD}-v2353
+ parent {5D5D914C-F585-4117-8477-7F8B37B27B01}-v1
+ fence 16010101 00:00:00.000 P
+ clockDecrementedInDirtyShutdown 0
+ clock 20080318 19:28:17.026 GMT (0x1c8892e375afac0)
+ createTime 20080318 17:36:47.960 GMT
+ csId {5D5D914C-F585-4117-8477-7F8B37B27B01}
+ hash 02F98A2C-31F58E81-E8598E22-DA9F8F95
+ similarity 00000000-00000000-00000000-00000000
+ name 0c0df164-715a-4674-bfb2-0a926eed1791
USN update Information(defined in USN_RECORD structure and GetFileAttributes) (Severity 4) |
|
Field |
Description |
Data |
|
RecordLength |
Size of file record in the USN journal in bytes |
Numeric value |
|
MajorVersion |
USN journal underlying major version |
Always 0x2 |
|
MinorVersion |
USN journal underlying major version |
Always 0x0 |
|
FileRefNumber |
USN journal internal file reference |
Unique Hex value |
|
ParentFileRefNumber |
USN journal internal folder parent reference |
Hex value |
|
TimeStamp |
USN journal timestamp of last change to file |
YYYYMMDD HH:MM:SS.MS TZ |
|
Reason |
Information about an actual change |
Text string |
|
SourceInfo |
Information about the source of the change |
Hex value |
|
SecurityId |
Unique security identifier assigned to the file |
Unique hex value |
|
FileAttributes |
Attributes on the file |
Hex value |
|
FileNameLength |
Size of file record in the USN journal in bytes |
Numeric value |
|
FileNameOffset |
The offset of the FileName member |
Numeric value |
|
FileName |
Name of the file |
Text string |
+ USN_RECORD:
+ RecordLength: 136
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x100000000B103
+ ParentFileRefNumber: 0x1000000000023
+ USN: 0xb69dd0
+ TimeStamp: 20080331 20:05:52.176 Eastern Standard Time
+ Reason: Close File Delete
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x20
+ FileNameLength: 72
+ FileNameOffset: 60
+ FileName: e7d74249-6092-475b-8e73-909516f93bdd
Content Set and Database Information(Severity 4) |
|
Field |
Description |
Data |
|
contentSetId |
Replicated Folder |
GUID |
|
memberId |
Computer referenced for this Content Set |
GUID |
|
state |
The current state of the Content Set (may be: |
May return: Normal, InitialSync(Cleanup), InitialSync(Sync), InitialBuilding, RestoreInitialSync(Cleanup), RestoreInitialSync(Sync), RestoreBuilding, Unknown |
|
startVersion |
Last version vector for chaining if the number is lost due to a problem |
Numeric value |
|
authRebuilding |
Rebuilding Content Set authoritatively |
0 or 1 |
|
stageVolumeSerialNumber |
Volume serial number for the drive containing staged data |
Unique value |
|
stageFid |
File ID of the staged data. |
Unique hex value |
|
isTombstone |
Is the Content Set tombstoned (deleted) |
0 or 1 |
|
beingDeleted |
Is the Content Set in the process of being deleted |
0 or 1 |
|
dbLossRecover |
Are we recovering from a lost database |
0 or 1 |
|
tombstoneTime* |
When was the content set tombstoned |
YYYYMMDD HH:MM:SS.MS |
|
expirationTime* |
When the tombstone will expire and the database will purge the content set info |
YYYYMMDD HH:MM:SS.MS (tombstonetime+60 days) |
|
readOnlySince* |
Date that the content set was changed from Read-Write to Read-Only (unsupported) |
YYYYMMDD HH:MM:SS.MS |
+ contentSetId: {FEB21D85-154D-4AE9-AB31-32A524F1E6F7}
+ memberId: {13828A03-E1BA-4E51-9F6F-F790671C450A}
+ state: Normal
+ startVersion: v150040
+ authRebuilding: 0
+ stageVolumeSerialNumber: ea40899d408970dd
+ stageFid: 0x2000000000031
+ isTombstone: 1
+ tombstoneTime: 20080411 13:47:07.267
+ expirationTime: 20080610 13:47:07.267
+ readOnlySince: 16010101 00:00:00.000
+ beingDeleted: 0
+ dbLossRecover: 0
RDC and XPRESS Assembler Statistics Downstream(Severity 5) |
|
Field |
Description |
Data |
|
Compression Ratio |
% of bandwidth savings over the wire (with RDC and XPRESS compression) |
0-100% |
|
Target Uncompress Size |
Total byte count of data |
Numeric value |
|
Target Compress Size |
Total byte count of data after accounting for compression with XPRESS and RDC |
Numeric value |
|
Bytes Received |
Byte count actually received (broken into signature bytes and data bytes) |
Numeric values |
|
Signature Bytes Received |
Signature bytes received |
Numeric value |
|
Number of remote calls |
RPC calls used to receive data (broken into signature, needs, and data requests) |
Numeric value |
|
RDC Need Size |
Number of bytes copied through RDC |
Numeric value |
|
Xpress Blocks |
Number of XPRESS-compressed RDC blocks copied |
Numeric value |
|
Uncompressed Xpress Blocks |
Number of non-XPRESS-compressed RDC blocks copied |
Numeric value |
|
Blocks copied to target |
RDC Blocks copied |
Numeric value |
+ TOTAL
+ Compression Ratio 49 %
+ Target Uncompress Size 480012
+ Target Compress Size 249546
+ Bytes Received 254732 Signatures: 4182 Data: 250550
+ Signature Bytes Received 4182 4182
+ Number of remote calls 15 Signatures: 1 Needs: 1 Data: 13
+ SEED
+ Rdc Need Size 0 0
+ Xpress Blocks 0 0
+ Uncompressed Xpress Blocks 0 0
+ Blocks copied to target 0 0
+ SOURCE
+ Rdc Need Size 480012 0
+ Xpress Blocks 59 0
+ Uncompressed Xpress Blocks 1 0
+ Blocks copied to target 58 0
RDC and XPRESS Needs Statistics Upstream(Severity 5) |
|
Field |
Description |
Data |
|
Compression Ratio |
% of bandwidth savings over the wire (with RDC and XPRESS compression) |
0-100% |
|
RDC Need Size |
Total bytes covered by requests |
Numeric value |
|
Bytes sent to downstream |
Actual bytes sent over the wire |
Numeric value |
|
Uncompressed XPRESS blocks |
RDC blocks from non-compressed (by XPRESS) data |
Numeric value |
|
Compressed XPRESS blocks |
RDC blocks from compressed data (by XPRESS) data |
Numeric value |
|
Copied XPRESS Blocks |
Number of compressed blocks sent |
Numeric value |
|
Bytes read using async I/Os* |
Number of bytes read in using Async I/o calls |
Numeric value |
+ TOTAL
+ Compression Ratio 47 %
+ RDC Need Size 480012
+ Bytes sent to downstream 254732
+ Uncompressed XPRESS blocks 0
+ Compressed XPRESS blocks 0
+ Copied XPRESS Blocks 59
RPC Information(Defined in RPC_EXTENDED_ERROR_INFO Structure and Extended Errors, Severity 5) |
|
Field |
Description |
Data |
|
Process ID |
PID of the DFSR service on this machine. |
Numeric value |
|
System Time |
Date-time on this machine |
YYYYMMDD HH:MM:SS.MS |
|
Generating component |
Code for component generating the error |
Numeric value |
|
Status |
Error returned to RPC |
Numeric error mapped within WINERROR.H that can be translated with NET HELPMSG <error #> |
|
Detection location |
A n entry in the Extended Error Information Detection Locations table |
Numeric value |
|
Flags |
Specifies whether SystemTime or FileTime is used. Set to zero to use SystemTime, or EEInfoUseFileTime to use FileTime. |
0 or 1 |
|
NumberOfParameters |
Parameter count to function (with nested data being passed) |
Numeric value |
+ Process ID : 1676
+ System Time : 20080318 21:49:51.310
+ Generating component : 2
+ Status : 1115
+ Detection location : 102
+ Flags : 0
+ NumberOfParameters : 1
USN Consumer Statistics(Severity 5) |
|
Field |
Description |
Data |
|
usnTotal |
Total number of USN records consumed |
Numeric value |
|
usnTotalNotFilteredByReason |
Total number of USN records (that are not filtered by USN reason attribute) |
Numeric value |
|
usnTotalDbUpdated |
Total number of USN records that caused database update |
Numeric value |
|
txTotal |
Total number of transactions |
Numeric value |
|
usnLastAverage |
Number of USN records consumed per second in last sampling period |
Numeric value |
|
usnLastAverageNotFilteredByReason |
Number of USN records per second that are not filtered by USN reason attribute in last sampling period |
Numeric value |
|
usnLastAverageDbUpdated |
Number of USN records per second that caused database update in last sampling period |
Numeric value |
|
txLastAverage |
Number of transaction per second in last sampling period |
Numeric value |
+ usnTotal 67433
+ usnTotalNotFilteredByReason 54111
+ usnTotalDbUpdated 50002
+ txTotal 11813
+ usnLastAverage 7
+ usnLastAverageNotFilteredByReason 3
+ usnLastAverageDbUpdated 0
+ txLastAverage 0
USN Recovery Information(Severity 5) |
|
Field |
Description |
Data |
|
usnId |
USN ID record in the journal |
Unique Hex value |
|
nextUsn |
Next USN record |
Unique Hex value |
|
checkpointUsn |
A special USN record to allow recovery from disk failures; used to detect whether a journal wrap or complete database rebuild will be triggered after service startup. |
Unique Hex value |
|
checkpointTimestamp |
Last time a checkpoint recovery was set |
YYYYMMDD HH:MM:SS.MS |
|
journalWrapped |
If the USN journal is wrapped |
0 or 1 |
|
journalIdChanged |
If the USN journal ID has been changed (due to recreation of journal) |
0 or 1 |
|
slowRecoverNotFinished |
Are we still doing a slow recover due to journal wrap |
0 or 1 |
|
dirtyRecoveryMode |
Are we recovering from a dirty database shutdown currently |
0 or 1 |
|
dirtyShutdownRecoveryTimestamp |
When a dirty database shutdown recovery was last done. |
YYYYMMDD HH:MM:SS.MS |
|
dirtyRecoveryRecordsMarkedFinished |
Was a dirty database recovery just performed |
0 or 1 |
+ usnId: 0x1c8893ad4b938d0
+ nextUsn: 0xbbe0
+ checkpointUsn: 0xacd8
+ checkpointTimestamp: 20080318 21:11:52.614
+ journalWrapped: 1
+ journalIdChanged: 0
+ slowRecoverNotFinished: 1
+ dirtyRecoveryMode: 1
+ dirtyShutdownRecoveryTimestamp: 20080318 21:11:52.614
+ dirtyRecoveryRecordsMarkedFinished: 0
History Information* (Severity 5) |
|
Field |
Description |
Data |
|
syncGuid* |
Synchronization GUID |
GUID |
|
State* |
Current state of replication for this Replication Group |
May return: Initialized,Connecting, In Progress, Completed, In Sync, Interrupted, In Error, UnknownSyncState |
|
initReason* |
Reason that synchronization occurred |
May return: Schedule,Force Replication, Paused, Force Until in Sync, UnknownSyncInitReason |
|
connectionGuid* |
Connection GUID |
GUID |
|
replicationGroupGuid* |
Replication group GUID |
GUID |
|
replicationGroupName* |
Replication Group friendly name |
Text string |
|
memberGuid* |
GUID of server |
GUID |
|
memberName* |
Friendly name of server |
Text string |
|
updatedNotTransferred* |
Number of updates not replicated |
Numeric value |
|
updatedTransferred* |
Number of updates replicated |
Numeric value |
|
updatedToBeTransferred* |
Number of updates to be replicated |
Numeric value |
|
byteTransferred* |
Bytes replicated |
Numeric value |
|
tombstonesGenerated* |
Number of tombstones created |
Numeric value |
|
conflictsGenerated* |
Number of conflicts that occurred |
Numeric value |
|
currentForceReplicationEndTime* |
When a forced update window (when using DFSRDIAG SYNCNOW) will close |
YYYYMMDD HH:MM:SS.MS |
|
currentForceReplicationBandwidthlevel* |
Bandwidth level is of a forced replication |
|
+ syncGuid {CE6DF7C4-5AB4-48A4-871F-344D168DA7B9}
+ state In Sync
+ initReason Schedule
+ connectionGuid {3AA17575-BA9B-43B3-B4C1-9DC4D90307A1}
+ replicationGroupGuid {4D251274-283B-46DF-81EF-570801B80D90}
+ replicationGroupName LHtest
+ memberGuid {1CEA93F6-41D7-4BF1-9AFC-7A2502308540}
+ memberName 2008SRV40
+ updatedNotTransferred 0
+ updatedTransferred 0
+ updatedToBeTransferred 0
+ byteTransferred 0
+ tombstonesGenerated 0
+ conflictsGenerated 0
+ currentForceReplicationEndTime 16010101 00:00:00.000
+ currentForceReplicationBandwidthlevel *
* Windows Server 2008 only
Understanding DFSR Module ID's
Examining the third entry in any non-nested line of the DFSR debug logs can give you quick insight into what overall type of component functionality DFSR is working on. These are referred to as "Module ID's". Note the highlighted sections below in the sample log entries:
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
20080409 11:17:21.649 3180 CFAD 8873 Config::AdReader::Peek Connection to AD is down, request full poll
The first example is in a synchronization module organized under the 'JOIN' component of DFSR. The next example is in a configuration module under the 'CFAD' component.
Below are all the module ID entries that can be mapped back to more general functional areas of DFSR. By getting to know these we can tell at a glance roughly what a given line is referencing and if it bears further attention based on what we are troubleshooting. All entries with an asterisk (*) are Windows Server 2008 only. Entries with two asterisks (**) are Windows Server 2003 R2 only.
|
Functional Area |
MODULE_ID References |
Description |
|
Configuration |
CFAD, CCTX, CPAR, CREG, CREP, CVOL, CXML, CMGR, ADWR*, HIST*, SYSM* |
Functions related to the configuration of DFSR in LDAP, the registry, WMI, and in the XML files |
|
Database |
DBCJ, DBGC, DIRW, JRWP, LDBX, PDBX, DBSR, USNC |
Functions related to the USN journal and the DFSR JET database |
|
File System |
MRSH, NTFS, FHAN,FUTL, ASYN*, OPLC* |
Functions related to NTFS, file handles, and (in Win2008) Asynchronous I/O handling. |
|
Main |
FSVC, SCFG, MAIN, VSSW, SCNT |
Functions for DFSR service control and data backup through VSS. |
|
SYSVOL Migration |
MIGM* |
Functions related to DFSRMIG.EXE for SYSVOL migration in Win2008. |
|
Performance |
PFV2* |
Functions wrapper for PerflibV2 in Win2008. |
|
Provider |
FCFG, FWMI, FWMH, PINF, PVMG, WMIC, WMIM |
Functions for DCOM and WMI providers. |
|
Synchronization |
CONF, CSMG, CRED, FREP, RDCS, INCO, ISYN, JOIN, MEET, OUTC, RDCX, RDCC, RSMG, SSYN, STAG, UPLK, UPMG, VLMG, XPRN, XPRS, XRNA, SLVS* |
Functions related to replicating files between DFSR nodes. |
|
Transport |
DOWN, RPCN, SRTR, UPST |
Functions that implement DFSR's RPC transports. |
|
Utility |
EVNT, PERF**, TASK, IMPE*, SRVC*, P2P*. SETT* |
Miscellaneous utility functions that cover event logging, performance logging in Win2003 R2, and other areas. |
* Windows Server 2008 only
** In Windows Server 2003 R2 only
Next up, we begin the various debug log real-world scenarios, with understanding new files being added to a replicated folder.
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 Pyle