In this scenario we will see a file created on the upstream server and attempted replication with its downstream partner. RPC traffic is being blocked between the machines by an incorrectly configured firewall. This is a common scenario and basic understanding of firewalls, TCP/IP, ports, and RPC is assumed. Debug logging severity is set to 5 in order to see more details about the problem state.

 

(rpcportsblocked - Dfsr00008 - 2008.log)

 

These are two Windows Server 2008 servers called 2008x86SRV10 and 2008x86SRV11 in the contoso.com domain. The log is from 2008x86SRV10 where the file is created (upstream). Both servers are participating in the RpcPortRG replication group for the RpcportRf replicated folder. The file is called “fveupdate.exe”.

 

<Upstream> 20080908 10:12:45.417 3372 USNC  2612 UsnConsumer::CreateNewRecord LDB Inserting ID Record: ß File added to the replicated folder on the upstream server

+       fid                             0x300000000BAAC

+       usn                             0x2633c60

+       uidVisible                      0

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               0

+       meetReanimated                  0

+       recUpdateTime                   16010101 00:00:00.000 GMT

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {5CB120DE-D2C2-452A-8280-B45FC155224F}-v28

+       uid                             {5CB120DE-D2C2-452A-8280-B45FC155224F}-v28

+       parent                          {3C47E305-FDE9-43F6-A550-791D9568C1D3}-v1

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080908 17:12:43.261 GMT (0x1c911d61b214f69)

+       createTime                      20080908 17:12:43.261 GMT

+       csId                            {3C47E305-FDE9-43F6-A550-791D9568C1D3}

+       hash                            00000000-00000000-00000000-00000000

+       similarity                      00000000-00000000-00000000-00000000

+       name                            fveupdate.exe ß file is name ‘fveupdate.exe’

+      

<Upstream> 20080908 10:12:45.417 1632 DOWN  3363 DownstreamTransport::SetupBinding Setup connId:{108028D9-F00E-4F1E-A8EF-BF60DB623231} remoteAddress:2008x86FSRV11.contoso.com  stringBinding:[5bc1ed07-f5f5-485f-9dfd-6fd0acf9a23c@ncacn_ip_tcp:2008x86FSRV11.contoso.com] ß An RPC connection setup attempt occurs over TCP (using the UUID of DFSR, which is the GUID 5bc1ed07-f5f5-485f-9dfd-6fd0acf9a23c) between upstream and downstream server

<Upstream> 20080908 10:12:45.433 3372 USNC  2615 UsnConsumer::CreateNewRecord ID record created from USN_RECORD:

+       USN_RECORD:

+       RecordLength:        88

+       MajorVersion:        2

+       MinorVersion:        0

+       FileRefNumber:       0x300000000BAAC

+       ParentFileRefNumber: 0xD00000000BA35

+       USN:                 0x2633c60

+       TimeStamp:           20080908 10:12:43.261 Pacific Standard Time

+       Reason:              Basic Info Change Close Data Extend Data Overwrite File Create

+       SourceInfo:          0x0

+       SecurityId:          0x0

+       FileAttributes:      0x20

+       FileNameLength:      26

+       FileNameOffset:      60

+       FileName:            fveupdate.exe

+      

<Upstream> 20080908 10:12:45.433 3372 LDBX  4300 Ldb::UpdateLastVersion Updating lastVersion:28

<Upstream> 20080908 10:12:45.433 3372 USNC  3459 UsnConsumer::CheckPoint Updating journalRecord: updateFlags=0

+       usnId:                              0x1c8b6df35167c8c

+       nextUsn:                            0x26360f8

+       checkpointUsn:                      0x2633c60

+       checkpointTimestamp:                20080908 17:12:43.261

+       journalWrapped:                     0

+       journalIdChanged:                   0

+       slowRecoverNotFinished:             0

+       dirtyRecoveryMode:                  0

+       dirtyShutdownRecoveryTimestamp:     16010101 00:00:00.000

+       dirtyRecoveryRecordsMarkedFinished: 0

+      

<Upstream> 20080908 10:13:04.246 2508 SETT   153 Settings::GenericDwordSetting::operator () Assigned default value. valueName:RpcContextHandleTimeoutMs value:1800000

<Upstream> 20080908 10:13:04.246 2508 SETT   153 Settings::GenericDwordSetting::operator () Assigned default value. valueName:MinRateCounterUpdateIntervalSec value:29

<Upstream> 20080908 10:13:06.433 1632 DOWN  3868 [WARN] DownstreamTransport::EstablishConnection Failed. Try flat name. ß RPC connection has failed

+       [Error:9027(0x2343) DownstreamTransport::EstablishConnection downstreamtransport.cpp:3853 1632 C A failure was reported by the remote partner] ß returns error 9027

+       [Error:1722(0x6ba) DownstreamTransport::EstablishConnection downstreamtransport.cpp:3853 1632 W The RPC server is unavailable.] ß returns extended error 1722 (“The RPC server is unavailable”)

<Upstream> 20080908 10:13:06.433 1632 DOWN  3099 DownstreamTransport::SetupBinding Entering SetupBinding

<Upstream> 20080908 10:13:06.433 1632 DOWN  3181 DownstreamTransport::SetupBinding Setting authentication information for partner: CONTOSO\2008X86FSRV11$ ß the partner that was being connected to

<Upstream> 20080908 10:13:06.433 1632 DOWN  3363 DownstreamTransport::SetupBinding Setup connId:{108028D9-F00E-4F1E-A8EF-BF60DB623231} remoteAddress:2008x86FSRV11.contoso.com  stringBinding:[5bc1ed07-f5f5-485f-9dfd-6fd0acf9a23c@ncacn_ip_tcp:2008x86FSRV11]

<Upstream> 20080908 10:13:27.434 1632 DOWN   383 LogExtendedErrorInformation Extended error information: ß various extended error information is logged for troubleshooting purposes. All are from WINERROR.H and can be translated with err.exe

+       Process ID           : 3148 ß process ID of DFSR.EXE

+       System Time          : 20080908 17:13:27.434

+       Generating component : 2

+       Status               : 1722

+       Detection location   : 501

+       Flags                : 0

+       NumberOfParameters   : 4

+               0 Unicode string: [ncacn_ip_tcp]

+               1 Unicode string: [2008x86FSRV11]

+               2 Long          : -1988219297

+               3 Long          : 1722

<Upstream> 20080908 10:13:27.434 1632 DOWN   383 LogExtendedErrorInformation Extended error information:

+       Process ID           : 3148

+       System Time          : 20080908 17:13:27.434

+       Generating component : 8

+       Status               : 1722 ß Error “The RPC server is unavailable”

+       Detection location   : 1442

+       Flags                : 0

+       NumberOfParameters   : 1

+               0 Unicode string: [2008x86FSRV11]

<Upstream> 20080908 10:13:27.434 1632 DOWN   383 LogExtendedErrorInformation Extended error information:

+       Process ID           : 3148

+       System Time          : 20080908 17:13:27.434

+       Generating component : 8

+       Status               : 1237 ß error “The operation could not be completed. A retry should be performed.”

+       Detection location   : 313

+       Flags                : 0

+       NumberOfParameters   : 0

<Upstream> 20080908 10:13:27.434 1632 DOWN   383 LogExtendedErrorInformation Extended error information:

+       Process ID           : 3148

+       System Time          : 20080908 17:13:27.434

+       Generating component : 8

+       Status               : 10060 ß error “A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.”

+       Detection location   : 311

+       Flags                : 0

+       NumberOfParameters   : 3

+               0 Long          : 135

+               1 Pointer       : 00000000

+               2 Pointer       : 6F000A0A00000000

<Upstream> 20080908 10:13:27.434 1632 DOWN   383 LogExtendedErrorInformation Extended error information:

+       Process ID           : 3148

+       System Time          : 20080908 17:13:27.434

+       Generating component : 8

+       Status               : 10060

+       Detection location   : 318

+       Flags                : 0

+       NumberOfParameters   : 0

<Upstream> 20080908 10:13:27.434 1632 DOWN   373 LogExtendedErrorInformation Done enumerating extended error information

 

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