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

Ned Pyle · ‎Apr 04 2019

First published on TechNet on Apr 09, 2009

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:

Products (50)

Special Topics (27)

Video Hub (462)

Most Active Hubs

Most Active Hubs

Video Hub

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