In this scenario we will see an attempted file replication. The downstream partner is running the File Server Resource Manager role with file screens configured and these screens are not matched to the DFSR file filters.  The debug log has been set to severity 5 for deeper details than usual.

 

(filescreenupstream - Dfsr00008 - 2008.log  and filescreendownstream - Dfsr00009 - 2008.log)

 

These are two Windows Server 2008 servers called 2008x86SRV10 and 2008x86SRV11 in the contoso.com domain. The logs are from 2008x86SRV10 where the file is created (upstream) and from 2008x86SRV11 where it is replicated (downstream). Both servers are participating in the FsrmRg replication group for the FsrmRf replicated folder. The file is called “spoolsv.exe”.  FSRM is configured with the default “block executable files” file screen.

 

<Upstream> 20080908 13:21:16.113 3264 USNC  2612 UsnConsumer::CreateNewRecord LDB Inserting ID Record: ß File created upstream

+       fid                             0x300000000BACF

+       usn                             0x2685058

+       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}-v39

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

+       parent                          {9D619939-CA99-497B-90F1-D667B4D76F05}-v1

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080908 20:21:16.113 GMT (0x1c911f0721d8af3)

+       createTime                      20080908 20:21:16.113 GMT

+       csId                            {9D619939-CA99-497B-90F1-D667B4D76F05}

+       hash                            00000000-00000000-00000000-00000000

+       similarity                      00000000-00000000-00000000-00000000

+       name                            spoolsv.exe ß file named ‘spoolsv.exe’

+      

<Upstream> 20080908 13:21:16.113 3264 USNC  2615 UsnConsumer::CreateNewRecord ID record created from USN_RECORD:

+       USN_RECORD:

+       RecordLength:        88

+       MajorVersion:        2

+       MinorVersion:        0

+       FileRefNumber:       0x300000000BACF

+       ParentFileRefNumber: 0x60000000000B3

+       USN:                 0x2685058

+       TimeStamp:           20080908 13:21:16.113 Pacific Standard Time

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

+       SourceInfo:          0x0

+       SecurityId:          0x0

+       FileAttributes:      0x20

+       FileNameLength:      22

+       FileNameOffset:      60

+       FileName:            spoolsv.exe

+      

<Upstream> 20080908 13:21:16.113 3264 LDBX  4300 Ldb::UpdateLastVersion Updating lastVersion:39

<Upstream> 20080908 13:21:16.113 3264 LDBX  3340 LdbManager::WakeUpSleepers Wake up callback 008753C0

<Upstream> 20080908 13:21:16.113 3460 UPST  1399 UpstreamTransport::FlushVvUp 00201800

<Upstream> 20080908 13:21:16.113 3460 UPST  1417 UpstreamTransport::FlushVvUp send connId:{4373FD61-670B-4687-846B-C8D8A71E0044} csId:{9D619939-CA99-497B-90F1-D667B4D76F05} seqNumber:10 status:0 vvGeneration:5 vvUp:

<Upstream> 20080908 13:21:16.128 2748 SRTR  1880 SERVER_RequestVersionVector Received from connId:{4373FD61-670B-4687-846B-C8D8A71E0044} csId:{9D619939-CA99-497B-90F1-D667B4D76F05} seqNumber:11 changeType:all

<Upstream> 20080908 13:21:16.128 2748 SRTR  1927 SERVER_AsyncPoll Received from connId:{4373FD61-670B-4687-846B-C8D8A71E0044}

<Upstream> 20080908 13:21:16.128 2748 UPST  1297 UpstreamTransport::AddAsyncPoll Inserted new async request rpcStatePtr:00201800

<snipped out operations covered in detail in earlier sections>

<Downstream> 20080908 13:21:16.525 2036 MEET  2822 Meet::InstallRename Moving contents from Installing to final destination. Attributes:0x20 updateName:spoolsv.exe uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 connId:{4373FD61-670B-4687-846B-C8D8A71E0044} csName:fsrmrf ß file has been RDC-reconstructed on the downstream partner

<Downstream> 20080908 13:21:16.525 2036 MEET  1638 Meet::InstallStep Done installing file updateName:spoolsv.exe uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 connId:{4373FD61-670B-4687-846B-C8D8A71E0044} csName:fsrmrf ß downstream server will now copy the file into replicated folder.

<Downstream> 20080908 13:21:16.525 2036 MEET  1641 Meet::InstallStep Deleting fid in installing updateName:spoolsv.exe uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 connId:{4373FD61-670B-4687-846B-C8D8A71E0044} csName:fsrmrf

<Downstream> 20080908 13:21:16.525 2036 MEET  1263 Meet::Install -> WAIT Error processing update. updateName:spoolsv.exe uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 connId:{4373FD61-670B-4687-846B-C8D8A71E0044} csName:fsrmrf csId:{9D619939-CA99-497B-90F1-D667B4D76F05} code:5 Error: ß the FSRM datascrn filter driver now blocks the write operation from occurring on the downstream server, as remotely added EXE files are not allowed. The error is unfortunately bubbled as ‘access denied’, but security is not related here at all, it’s just the error returned by the filter driver.

+       [Error:5(0x5) Meet::InstallStep meet.cpp:1657 2036 W Access is denied.]

+       [Error:5(0x5) Meet::InstallRename meet.cpp:2960 2036 W Access is denied.]

+       [Error:5(0x5) NtfsFileSystem::Move ntfsfilesystem.cpp:1188 2036 W Access is denied.]

+       [Error:5(0x5) NtfsFileSystem::Move ntfsfilesystem.cpp:999 2036 W Access is denied.]

+       [Error:5(0x5) FileUtil::RenameByHandle fileutil.cpp:386 2036 W Access is denied.]

+       [Error:5(0x5) FileUtil::RenameByHandle fileutil.cpp:383 2036 W Access is denied.]

<Upstream> 20080908 13:21:16.535 2748 SRTR  1772 SERVER_RdcClose uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 csId:{9D619939-CA99-497B-90F1-D667B4D76F05} connId:{4373FD61-670B-4687-846B-C8D8A71E0044}

<Upstream> 20080908 13:21:16.535 2748 ASYN  1291 AsyncUnbufferedFileReader::Close Async READ Statistics:

 

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