From dac012a84b1fec9f2a5003e8cf45a7bdb8cb004a Mon Sep 17 00:00:00 2001 From: Peter Scott Date: Sat, 29 Oct 2011 13:29:55 -0400 Subject: [PATCH] Windows: additional trace logging for afsredirlib A large number of addition trace log entries were added to assist in diagnosing problems in the dir entry processing. Change-Id: I85cab4d66680eb5b9c00843c49c33a81acb18bc2 Reviewed-on: http://gerrit.openafs.org/5739 Reviewed-by: Rod Widdowson Tested-by: BuildBot Tested-by: Jeffrey Altman Reviewed-by: Jeffrey Altman --- .../afsrdr/kernel/lib/AFSBTreeSupport.cpp | 16 ++-- src/WINNT/afsrdr/kernel/lib/AFSCleanup.cpp | 6 ++ .../afsrdr/kernel/lib/AFSCommSupport.cpp | 73 ++++++++++++++++--- src/WINNT/afsrdr/kernel/lib/AFSCreate.cpp | 7 ++ src/WINNT/afsrdr/kernel/lib/AFSFileInfo.cpp | 20 ++++- src/WINNT/afsrdr/kernel/lib/AFSGeneric.cpp | 13 ++++ .../afsrdr/kernel/lib/AFSNameSupport.cpp | 8 +- 7 files changed, 123 insertions(+), 20 deletions(-) diff --git a/src/WINNT/afsrdr/kernel/lib/AFSBTreeSupport.cpp b/src/WINNT/afsrdr/kernel/lib/AFSBTreeSupport.cpp index a87004582..5320e7e09 100644 --- a/src/WINNT/afsrdr/kernel/lib/AFSBTreeSupport.cpp +++ b/src/WINNT/afsrdr/kernel/lib/AFSBTreeSupport.cpp @@ -368,11 +368,10 @@ AFSInsertCaseSensitiveDirEntry( IN AFSDirectoryCB *RootNode, { AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, - AFS_TRACE_LEVEL_WARNING, - "AFSInsertCaseSensitiveDirEntry Attempt to re-insert a CRC %I64X\n", - DirEntry->CaseSensitiveTreeEntry.HashIndex); - - ASSERT( FALSE); + AFS_TRACE_LEVEL_VERBOSE, + "AFSInsertCaseSensitiveDirEntry Collision with DE %p for %wZ\n", + pCurrentEntry, + &pCurrentEntry->NameInformation.FileName); ntStatus = STATUS_UNSUCCESSFUL; @@ -1084,6 +1083,13 @@ AFSInsertShortNameDirEntry( IN AFSDirectoryCB *RootNode, else { + AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, + AFS_TRACE_LEVEL_VERBOSE, + "AFSInsertShortNameDirEntry Collision with DE %p for shortname %S and %wZ\n", + pCurrentEntry, + pCurrentEntry->NameInformation.ShortName, + &pCurrentEntry->NameInformation.FileName); + break; } } diff --git a/src/WINNT/afsrdr/kernel/lib/AFSCleanup.cpp b/src/WINNT/afsrdr/kernel/lib/AFSCleanup.cpp index 554b1aaeb..c56faf4db 100644 --- a/src/WINNT/afsrdr/kernel/lib/AFSCleanup.cpp +++ b/src/WINNT/afsrdr/kernel/lib/AFSCleanup.cpp @@ -417,6 +417,12 @@ AFSCleanup( IN PDEVICE_OBJECT LibDeviceObject, AFSAcquireExcl( pObjectInfo->ParentObjectInformation->Specific.Directory.DirectoryNodeHdr.TreeLock, TRUE); + AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, + AFS_TRACE_LEVEL_VERBOSE, + "AFSCleanup DE %p for %wZ removing entry\n", + pCcb->DirectoryCB, + &pCcb->DirectoryCB->NameInformation.FileName); + AFSRemoveNameEntry( pObjectInfo->ParentObjectInformation, pCcb->DirectoryCB); diff --git a/src/WINNT/afsrdr/kernel/lib/AFSCommSupport.cpp b/src/WINNT/afsrdr/kernel/lib/AFSCommSupport.cpp index 98049c54d..c5d380c38 100644 --- a/src/WINNT/afsrdr/kernel/lib/AFSCommSupport.cpp +++ b/src/WINNT/afsrdr/kernel/lib/AFSCommSupport.cpp @@ -717,6 +717,46 @@ AFSVerifyDirectoryContent( IN AFSObjectInfoCB *ObjectInfoCB, SetFlag( pDirNode->Flags, AFS_DIR_ENTRY_VALID); + if( pCurrentDirEntry->ShortNameLength > 0 && + pDirNode->NameInformation.ShortNameLength > 0) + { + AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, + AFS_TRACE_LEVEL_VERBOSE, + "AFSVerifyDirectoryContent Verified entry %wZ (%wZ) old short name %S New short name %S\n", + &uniDirName, + &pDirNode->NameInformation.FileName, + pDirNode->NameInformation.ShortName, + pCurrentDirEntry->ShortName); + } + else if( pCurrentDirEntry->ShortNameLength == 0 && + pDirNode->NameInformation.ShortNameLength > 0) + { + AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, + AFS_TRACE_LEVEL_VERBOSE, + "AFSVerifyDirectoryContent Verified entry %wZ (%wZ) old short name %S New short name NULL\n", + &uniDirName, + &pDirNode->NameInformation.FileName, + pDirNode->NameInformation.ShortName); + } + else if( pCurrentDirEntry->ShortNameLength > 0 && + pDirNode->NameInformation.ShortNameLength == 0) + { + AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, + AFS_TRACE_LEVEL_VERBOSE, + "AFSVerifyDirectoryContent Verified entry %wZ (%wZ) old short name NULL New short name %S\n", + &uniDirName, + &pDirNode->NameInformation.FileName, + pCurrentDirEntry->ShortName); + } + else + { + AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, + AFS_TRACE_LEVEL_VERBOSE, + "AFSVerifyDirectoryContent Verified entry %wZ (%wZ) old short name NULL New short name NULL\n", + &uniDirName, + &pDirNode->NameInformation.FileName); + } + AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, AFS_TRACE_LEVEL_VERBOSE, "AFSVerifyDirectoryContent Verified entry %wZ for parent FID %08lX-%08lX-%08lX-%08lX\n", @@ -777,7 +817,8 @@ AFSVerifyDirectoryContent( IN AFSObjectInfoCB *ObjectInfoCB, AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, AFS_TRACE_LEVEL_VERBOSE, - "AFSVerifyDirectoryContent Processing dir entry %wZ with different FID, same name in parent FID %08lX-%08lX-%08lX-%08lX\n", + "AFSVerifyDirectoryContent Processing dir entry %p %wZ with different FID, same name in parent FID %08lX-%08lX-%08lX-%08lX\n", + pDirNode, &pDirNode->NameInformation.FileName, ObjectInfoCB->FileId.Cell, ObjectInfoCB->FileId.Volume, @@ -793,12 +834,17 @@ AFSVerifyDirectoryContent( IN AFSObjectInfoCB *ObjectInfoCB, AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, AFS_TRACE_LEVEL_VERBOSE, - "AFSVerifyDirectoryContent Deleting dir entry %wZ from parent FID %08lX-%08lX-%08lX-%08lX\n", + "AFSVerifyDirectoryContent Different FIDs - Deleting DE %p for %wZ Old FID %08lX-%08lX-%08lX-%08lX New FID %08lX-%08lX-%08lX-%08lX\n", + pDirNode, &pDirNode->NameInformation.FileName, ObjectInfoCB->FileId.Cell, ObjectInfoCB->FileId.Volume, ObjectInfoCB->FileId.Vnode, - ObjectInfoCB->FileId.Unique); + ObjectInfoCB->FileId.Unique, + pCurrentDirEntry->FileId.Cell, + pCurrentDirEntry->FileId.Volume, + pCurrentDirEntry->FileId.Vnode, + pCurrentDirEntry->FileId.Unique); AFSDeleteDirEntry( ObjectInfoCB, pDirNode); @@ -806,17 +852,21 @@ AFSVerifyDirectoryContent( IN AFSObjectInfoCB *ObjectInfoCB, else { + SetFlag( pDirNode->Flags, AFS_DIR_ENTRY_DELETED); + AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, AFS_TRACE_LEVEL_VERBOSE, - "AFSVerifyDirectoryContent Setting dir entry %p name %wZ DELETED in parent FID %08lX-%08lX-%08lX-%08lX\n", + "AFSVerifyDirectoryContent Different FIDs - removing DE %p for %wZ Old FID %08lX-%08lX-%08lX-%08lX New FID %08lX-%08lX-%08lX-%08lX\n", pDirNode, &pDirNode->NameInformation.FileName, ObjectInfoCB->FileId.Cell, ObjectInfoCB->FileId.Volume, ObjectInfoCB->FileId.Vnode, - ObjectInfoCB->FileId.Unique); - - SetFlag( pDirNode->Flags, AFS_DIR_ENTRY_DELETED); + ObjectInfoCB->FileId.Unique, + pCurrentDirEntry->FileId.Cell, + pCurrentDirEntry->FileId.Volume, + pCurrentDirEntry->FileId.Vnode, + pCurrentDirEntry->FileId.Unique); AFSRemoveNameEntry( ObjectInfoCB, pDirNode); @@ -864,10 +914,13 @@ AFSVerifyDirectoryContent( IN AFSObjectInfoCB *ObjectInfoCB, AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, AFS_TRACE_LEVEL_VERBOSE, - "AFSVerifyDirectoryContent Initialized short name %wZ for DE %p for %wZ\n", - &uniShortName, + "AFSVerifyDirectoryContent NO short name for DE %p for %wZ FID %08lX-%08lX-%08lX-%08lX\n", pDirNode, - &pDirNode->NameInformation.FileName); + &pDirNode->NameInformation.FileName, + pCurrentDirEntry->FileId.Cell, + pCurrentDirEntry->FileId.Volume, + pCurrentDirEntry->FileId.Vnode, + pCurrentDirEntry->FileId.Unique); } // diff --git a/src/WINNT/afsrdr/kernel/lib/AFSCreate.cpp b/src/WINNT/afsrdr/kernel/lib/AFSCreate.cpp index 6340ebbf2..e9412e4eb 100644 --- a/src/WINNT/afsrdr/kernel/lib/AFSCreate.cpp +++ b/src/WINNT/afsrdr/kernel/lib/AFSCreate.cpp @@ -2016,6 +2016,13 @@ try_exit: if( bFileCreated) { + AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, + AFS_TRACE_LEVEL_VERBOSE, + "AFSProcessCreate Create failed, removing DE %p from aprent object %p Status %08lX\n", + pDirEntry, + pParentObjectInfo, + ntStatus); + // // Remove the dir entry from the parent // diff --git a/src/WINNT/afsrdr/kernel/lib/AFSFileInfo.cpp b/src/WINNT/afsrdr/kernel/lib/AFSFileInfo.cpp index fe93a6f19..bc7967c81 100644 --- a/src/WINNT/afsrdr/kernel/lib/AFSFileInfo.cpp +++ b/src/WINNT/afsrdr/kernel/lib/AFSFileInfo.cpp @@ -1946,6 +1946,13 @@ AFSSetRenameInfo( IN PIRP Irp) try_return( ntStatus = STATUS_OBJECT_NAME_COLLISION); } + AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, + AFS_TRACE_LEVEL_ERROR, + "AFSSetRenameInfo Target %wZ exists DE %p Count %08lX, performing delete of target\n", + &pTargetDirEntry->NameInformation.FileName, + pTargetDirEntry, + pTargetDirEntry->OpenReferenceCount); + bTargetEntryExists = TRUE; } @@ -2292,6 +2299,12 @@ AFSSetRenameInfo( IN PIRP Irp) pSrcCcb->DirectoryCB->Type.Data.ShortNameTreeEntry.HashIndex = AFSGenerateCRC( &uniShortName, TRUE); + + AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, + AFS_TRACE_LEVEL_VERBOSE, + "AFSSetRenameInfo Initialized short name hash for %wZ longname %wZ\n", + &uniShortName, + &pSrcCcb->DirectoryCB->NameInformation.FileName); } else { @@ -2401,10 +2414,9 @@ AFSSetRenameInfo( IN PIRP Irp) AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, AFS_TRACE_LEVEL_VERBOSE, - "AFSSetRenameInfo Setting DELETE flag in dir entry %p name %wZ to tmp %wZ\n", + "AFSSetRenameInfo Setting DELETE flag in dir entry %p name %wZ\n", pTargetDirEntry, - &pTargetDirEntry->NameInformation.FileName, - &uniTmpTargetName); + &pTargetDirEntry->NameInformation.FileName); SetFlag( pTargetDirEntry->Flags, AFS_DIR_ENTRY_DELETED); @@ -2432,7 +2444,7 @@ AFSSetRenameInfo( IN PIRP Irp) AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, AFS_TRACE_LEVEL_ERROR, - "AFSSetRenameInfo Failed to flush section for deleted temp file %wZ\n", + "AFSSetRenameInfo Failed to delete section for target file %wZ\n", &pTargetDirEntry->NameInformation.FileName); } diff --git a/src/WINNT/afsrdr/kernel/lib/AFSGeneric.cpp b/src/WINNT/afsrdr/kernel/lib/AFSGeneric.cpp index 797f3f2a8..4251e7407 100644 --- a/src/WINNT/afsrdr/kernel/lib/AFSGeneric.cpp +++ b/src/WINNT/afsrdr/kernel/lib/AFSGeneric.cpp @@ -3250,6 +3250,13 @@ AFSValidateDirectoryCache( IN AFSObjectInfoCB *ObjectInfo, { ClearFlag( pCurrentDirEntry->Flags, AFS_DIR_ENTRY_VALID); + + AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, + AFS_TRACE_LEVEL_VERBOSE, + "AFSValidateDirectoryCache Clear VALID flag on DE %p Reference count %08lX\n", + pCurrentDirEntry, + pCurrentDirEntry->OpenReferenceCount); + } pCurrentDirEntry = (AFSDirectoryCB *)pCurrentDirEntry->ListEntry.fLink; @@ -3281,6 +3288,12 @@ AFSValidateDirectoryCache( IN AFSObjectInfoCB *ObjectInfo, continue; } + AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, + AFS_TRACE_LEVEL_VERBOSE, + "AFSValidateDirectoryCache Processing INVALID DE %p Reference count %08lX\n", + pCurrentDirEntry, + pCurrentDirEntry->OpenReferenceCount); + if( pCurrentDirEntry->OpenReferenceCount == 0) { diff --git a/src/WINNT/afsrdr/kernel/lib/AFSNameSupport.cpp b/src/WINNT/afsrdr/kernel/lib/AFSNameSupport.cpp index a2aa32dcf..f4fad0731 100644 --- a/src/WINNT/afsrdr/kernel/lib/AFSNameSupport.cpp +++ b/src/WINNT/afsrdr/kernel/lib/AFSNameSupport.cpp @@ -2106,7 +2106,7 @@ AFSInsertDirectoryNode( IN AFSObjectInfoCB *ParentObjectInfo, AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, AFS_TRACE_LEVEL_VERBOSE, - "AFSInsertDirectoryNode Insert DE %p to case sensitive tree for %wZ\n", + "AFSInsertDirectoryNode Insert DE %p to case insensitive tree for %wZ\n", DirEntry, &DirEntry->NameInformation.FileName); } @@ -2293,6 +2293,12 @@ AFSRemoveDirNodeFromParent( IN AFSObjectInfoCB *ParentObjectInfo, if( !BooleanFlagOn( DirEntry->Flags, AFS_DIR_ENTRY_NOT_IN_PARENT_TREE)) { + AFSDbgLogMsg( AFS_SUBSYSTEM_FILE_PROCESSING, + AFS_TRACE_LEVEL_VERBOSE, + "AFSRemoveDirNodeFromParent Removing DirEntry %08lX name %wZ\n", + DirEntry, + &DirEntry->NameInformation.FileName); + AFSRemoveNameEntry( ParentObjectInfo, DirEntry); } -- 2.39.5