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 14: A sharing violation due to a file locked upstream between two Windows Server 2008)

  • Comments 9
  • Likes

In this scenario we will see file that is locked by an application, preventing replication from occurring. The upstream replicated folder will contain a file that does not yet exist on the downstream member. This is useful to understand as one of the most common troubleshooting areas in DFSR is in the area of sharing violation events.

 

(lockedfileupstream - Dfsr00026 - 2008.log and lockedfiledownstream - Dfsr00023 - 2008.log)

 

These are two Windows Server 2008 servers called 2008MEM01 and 2008MEM02 in the fabrikam.com domain. The logs are from 2008MEM01 (upstream) and from 2008MEM02 (downstream). Both servers are participating in the NEWRG1 replication group for the NEWRF1 replicated folder.  The locked file is called “setup.exe” and the file has been exclusively write-locked with a file utility to simulate the scenario. These two debug logs have been significantly trimmed to remove extraneous entries caused by the repro requirements.

 

<Upstream> 20080627 15:50:40.249 3616 JOIN  1122 Join::SubmitUpdate LDB Updating ID Record: ß A file needs to be replicated out

+       fid                             0x500000000AC91

+       usn                             0xa9fe38

+       uidVisible                      1

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               0

+       meetReanimated                  0

+       recUpdateTime                   20080627 19:50:35.032 GMT

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95

+       uid                             {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95 ß UID/GVSN match so this is an original file creation (in DFSR terms – if a file is copied into a replicated folder it is ‘created’ in DFSR terms).

+       parent                          {05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080627 19:50:03.186 GMT (0x1c8d88efd9bd3de)

+       createTime                      20080627 19:50:02.815 GMT

+       csId                            {05631532-B65C-45AF-BB49-F237ACB6CF7C}

+       hash                            00000000-00000000-00000000-00000000

+       similarity                      00000000-00000000-00000000-00000000

+       name                            setup.exe ß the file is named setup.exe

+      

<Upstream> 20080627 15:50:40.249 3616 JOIN  1167 Join::SubmitUpdate Sent: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95 name:setup.exe connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ß the upstream server submits update to its downstream partner

<Downstream> 20080627 15:50:40.262 2424 DOWN  5186 [ERROR] DownstreamTransport::RdcGet Failed on connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} rgName:NewRG1 update: ß the downstream server attempts to initiate replication of the file through RDC but receives an error

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95

+       uid                             {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95

+       parent                          {05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080627 19:50:03.186 GMT (0x1c8d88efd9bd3de)

+       createTime                      20080627 19:50:02.815 GMT

+       csId                            {05631532-B65C-45AF-BB49-F237ACB6CF7C}

+       hash                            00000000-00000000-00000000-00000000

+       similarity                      00000000-00000000-00000000-00000000

+       name                            setup.exe

+       Error:

+       [Error:9027(0x2343) RpcFinalizeContext downstreamtransport.cpp:1096 2424 C A failure was reported by the remote partner]

+       [Error:9027(0x2343) DownstreamTransport::RdcGet downstreamtransport.cpp:5124 2424 C A failure was reported by the remote partner]

+       [Error:32(0x20) DownstreamTransport::RdcGet downstreamtransport.cpp:5124 2424 W The process cannot access the file because it is being used by another process.] ß the specific error is that the file is exclusively locked upstream

<Downstream> 20080627 15:50:40.262 2424 INCO  5599 InConnection::LogTransferActivity Failed to receive RAWGET uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95 fileName:setup.exe connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} stagedSize:0 Error: ß another error is logged for an attempted RAWGET of the same file

+       [Error:9027(0x2343) DownstreamTransport::RdcGet downstreamtransport.cpp:5201 2424 C A failure was reported by the remote partner]

+       [Error:9027(0x2343) RpcFinalizeContext downstreamtransport.cpp:1096 2424 C A failure was reported by the remote partner]

+       [Error:9027(0x2343) DownstreamTransport::RdcGet downstreamtransport.cpp:5124 2424 C A failure was reported by the remote partner]

+       [Error:32(0x20) DownstreamTransport::RdcGet downstreamtransport.cpp:5124 2424 W The process cannot access the file because it is being used by another process.] ß the file lock error is logged again

ß <snipped out repeated attempts to replicate with same in use errors, for readability>

<Upstream> 20080627 15:50:40.269 3132 SRTR  1880 SERVER_RequestVersionVector Received from connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} seqNumber:3 changeType:notify

<Upstream> 20080627 15:50:40.269 1248 MRSH  4615 Marshaller::Marshal FileAttrs in metadata : 0x20

<Upstream> 20080627 15:50:40.279 3476 SRTR  1927 SERVER_AsyncPoll Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D}

<Upstream> 20080627 15:50:40.279 2932 OUTC   784 OutConnection::OpenFile Received request for update: ß there are repeated requests from the downstream to the upstream server to replicate the file

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95

+       uid                             {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95

+       parent                          {05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080627 19:50:03.186 GMT (0x1c8d88efd9bd3de)

+       createTime                      20080627 19:50:02.815 GMT

+       csId                            {05631532-B65C-45AF-BB49-F237ACB6CF7C}

+       hash                            00000000-00000000-00000000-00000000

+       similarity                      00000000-00000000-00000000-00000000

+       name                            setup.exe

+       rdcDesired:1 connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} rgName:NewRG1

<Upstream> 20080627 15:50:40.279 2932 STAG   987 StageWriter::AbortDownloadStage Successfully aborted staging file 95-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95-Downloading.frx. Deleted. ß after a number of attempts upstream to stage the file, the attempt is finally aborted. This is not a permanent condition, the DFSR service will try again later after waiting in the hopes that the file will unlock.

<Upstream> 20080627 15:50:40.279 2932 ASYN   510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:

<Upstream> 20080627 15:50:40.279 2932 EVNT   725 EventLog::Report Logging eventId:4304 parameterCount:8 ß a 4304 sharing violation (exclusive file lock) warning is logged in the event log.

<Upstream> 20080627 15:50:40.279 2932 EVNT   745 EventLog::Report         eventId:4304 parameter1:05631532-B65C-45AF-BB49-F237ACB6CF7C

<Upstream> 20080627 15:50:40.279 2932 EVNT   745 EventLog::Report         eventId:4304 parameter2:C:\NewRF1\setup.exe

<Upstream> 20080627 15:50:40.279 2932 EVNT   745 EventLog::Report         eventId:4304 parameter3:C:\NewRF1

<Upstream> 20080627 15:50:40.279 2932 EVNT   745 EventLog::Report         eventId:4304 parameter4:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95

<Upstream> 20080627 15:50:40.279 2932 EVNT   745 EventLog::Report         eventId:4304 parameter5:NewRF1

<Upstream> 20080627 15:50:40.279 2932 EVNT   745 EventLog::Report         eventId:4304 parameter6:NewRG1

<Upstream> 20080627 15:50:40.279 2932 EVNT   745 EventLog::Report         eventId:4304 parameter7:33DACEEE-D60C-4BF1-911C-EA5C487A78CB

<Upstream> 20080627 15:50:40.279 2932 EVNT   745 EventLog::Report         eventId:4304 parameter8:5EF77FE2-B1BF-41B4-9DA6-51F6549F523E

<Upstream> 20080627 15:50:40.300 2932 SRTR  2344 [WARN] InitializeFileTransferAsyncState::ProcessIoCompletion Failed connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} rdc:1 uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95 gsvn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95 Error:

+       [Error:32(0x20) UpstreamTransport::OpenFile upstreamtransport.cpp:1117 2932 W The process cannot access the file because it is being used by another process.]

+       [Error:32(0x20) OutConnection::OpenFile outconnection.cpp:1618 2932 W The process cannot access the file because it is being used by another process.]

+       [Error:32(0x20) OutConnection::GetReplicaReader outconnection.cpp:2289 2932 W The process cannot access the file because it is being used by another process.]

+       [Error:32(0x20) NtfsFileSystem::MakeBackupReader ntfsfilesystem.cpp:526 2932 W The process cannot access the file because it is being used by another process.]

+       [Error:32(0x20) MarshalFileReader::OpenFileId marshaller.cpp:4991 2932 W The process cannot access the file because it is being used by another process.]

+       [Error:32(0x20) Marshaller::OpenSourceFile marshaller.cpp:4334 2932 W The process cannot access the file because it is being used by another process.]

+       [Error:32(0x20) Marshaller::InitSourceFile marshaller.cpp:4205 2932 W The process cannot access the file because it is being used by another process.]

+       [Error:32(0x20) MarshalContext::OpenFileForInfo marshaller.cpp:3320 2932 W The process cannot access the file because it is being used by another process.]

+       [Error:32(0x20) MarshalContext::OpenFileForInfo marshaller.cpp:3237 2932 W The process cannot access the file because it is being used by another process.] completion:0 ptr:00E77D48

ß <snipped out repeated attempts to replicate with same in use errors, for readability>

<Downstream> 20080627 15:50:55.300 2424 MEET  1207 Meet::Install Retries:4 updateName:setup.exe uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95 connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} csName:NewRF1 updateType:remote ß the downstream server has tried to replicate the file four times by now.

<Upstream> 20080627 15:51:06.357 2932 CSMG  4844 ContentSetManager::UpdateHash LDB Updating ID Record: ß the file hash can finally be added to the DFSR database upstream as the file has been unlocked.

+       fid                             0x500000000AC91

+       usn                             0xa9fe38

+       uidVisible                      1

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               0

+       meetReanimated                  0

+       recUpdateTime                   20080627 19:50:35.032 GMT

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95

+       uid                             {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v95

+       parent                          {05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080627 19:50:03.186 GMT (0x1c8d88efd9bd3de)

+       createTime                      20080627 19:50:02.815 GMT

+       csId                            {05631532-B65C-45AF-BB49-F237ACB6CF7C}

+       hash                            324AE6CC-5F635DEF-31E86733-00737CAA

+       similarity                      1511151F-0C323F1B-0216212C-09171E20

+       name                            setup.exe

+      

ß replication will proceed normally from this point.

 

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

  • 237 Microsoft Team blogs searched, 106 blogs have new articles in the pa st 7 days. 256 new articles