Understanding DFSR debug logging (Part 19: File Blocked Inbound by a File Screen Filter Driver (uses debug severity 5))

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.