Understanding DFSR debug logging (Part 2: Nested Fields, Module ID's)

Understanding DFSR debug logging (Part 2: Nested Fields, Module ID's)

  • Comments 2
  • Likes

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

SHA-1 checksum of the marshaled file,
to include its data stream, alternate data stream, and security

Hex value

similarity

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 IDentries 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