From: short <> Date: Mon, 4 Aug 2003 17:25:51 +0000 (+0000) Subject: Synchronize all Cc*() calls for proper debugging info chronology. X-Git-Tag: bp_captive~101 X-Git-Url: https://git.jankratochvil.net/?a=commitdiff_plain;h=a563f768ab4e0fc3a81a6c186c12e7fb72973792;hp=933a6d391780eee0e14fe8778ceeee93a9e149f0;p=captive.git Synchronize all Cc*() calls for proper debugging info chronology. Additional debug info for 'SharedCacheMap' tracking. --- diff --git a/src/TraceFS/TraceFS-W32/TraceFS.c b/src/TraceFS/TraceFS-W32/TraceFS.c index 3bdd145..1064f4b 100644 --- a/src/TraceFS/TraceFS-W32/TraceFS.c +++ b/src/TraceFS/TraceFS-W32/TraceFS.c @@ -30,21 +30,56 @@ NTSTATUS DriverEntry(IN PDRIVER_OBJECT DriverObject,IN PUNICODE_STRING RegistryP #pragma alloc_text (INIT, DriverEntry) #endif -static FAST_MUTEX lock_mutex; +/* Ke*Mutex() would be reentrant but it looked too unclear for me. + * Never ExAcquireFastMutex() two FAST_MUTEX once or one FAST_MUTEX twice. + * Use Ex*ResourceLite instead of Ex*FastMutex() as it would set IRQL to DPC + * and we cannot pass the execution to Cc*() in DPC. + * Ex*FastMutex() problem: IRP_MJ_SHUTDOWN: Assertion failure. + */ +static ERESOURCE lock_resource; +static int lock_resource_count; +static PETHREAD lock_resource_CurrentThread; static void lock_init(void) { - ExInitializeFastMutex(&lock_mutex); + if (ExInitializeResourceLite(&lock_resource)) + KeBugCheck(0); + lock_resource_count=0; + lock_resource_CurrentThread=NULL; } static void lock(void) { - ExAcquireFastMutex(&lock_mutex); + if (lock_resource_CurrentThread==PsGetCurrentThread()) { + if (lock_resource_count<=0) + KeBugCheck(0); + lock_resource_count++; + return; + } + KeEnterCriticalRegion(); + if (!ExAcquireResourceExclusiveLite(&lock_resource,TRUE)) + KeBugCheck(0); + KeLeaveCriticalRegion(); + if (lock_resource_CurrentThread) + KeBugCheck(0); + if (lock_resource_count!=0) + KeBugCheck(0); + lock_resource_CurrentThread=PsGetCurrentThread(); + lock_resource_count++; } static void unlock(void) { - ExReleaseFastMutex(&lock_mutex); + if (lock_resource_CurrentThread!=PsGetCurrentThread()) + KeBugCheck(0); + if (lock_resource_count<=0) + KeBugCheck(0); + if (--lock_resource_count) + return; + lock_resource_CurrentThread=NULL; + KeEnterCriticalRegion(); + ExReleaseResourceLite(&lock_resource); + KeLeaveCriticalRegion(); } #define DBGPREFIX "TraceFS(0x%08lX/0x%08lX): " @@ -52,6 +87,11 @@ static void unlock(void) static int dbgindent=0; +/* DBGSINGLEENTER*() / DBGSINGLELEAVE*() are protected by lock()/unlock() + * to serialize the Cc*() function calls as otherwise the debug dumps + * chronology may not match the real core execution chronology inside. + */ + /* lock() will protect dbg_unicode_string() static buffer. */ #define DBGSINGLE6(fmt,arg1,arg2,arg3,arg4,arg5,arg6) \ do { lock(); DbgPrint("%*s" DBGPREFIX fmt "\n",dbgindent,"",DBGARG,arg1,arg2,arg3,arg4,arg5,arg6); unlock(); } while (0) @@ -62,7 +102,7 @@ static int dbgindent=0; #define DBGSINGLE1(fmt,arg1) DBGSINGLE2(fmt,arg1,0) #define DBGSINGLE0(fmt) DBGSINGLE1(fmt,0) #define DBGSINGLEENTER6(fmt,arg1,arg2,arg3,arg4,arg5,arg6) \ - do { DBGSINGLE6("enter: " fmt,arg1,arg2,arg3,arg4,arg5,arg6); dbgindent++; } while (0) + do { lock(); DBGSINGLE6("enter: " fmt,arg1,arg2,arg3,arg4,arg5,arg6); dbgindent++; } while (0) #define DBGSINGLEENTER5(fmt,arg1,arg2,arg3,arg4,arg5) DBGSINGLEENTER6(fmt,arg1,arg2,arg3,arg4,arg5,0) #define DBGSINGLEENTER4(fmt,arg1,arg2,arg3,arg4) DBGSINGLEENTER5(fmt,arg1,arg2,arg3,arg4,0) #define DBGSINGLEENTER3(fmt,arg1,arg2,arg3) DBGSINGLEENTER4(fmt,arg1,arg2,arg3,0) @@ -70,7 +110,7 @@ static int dbgindent=0; #define DBGSINGLEENTER1(fmt,arg1) DBGSINGLEENTER2(fmt,arg1,0) #define DBGSINGLEENTER0(fmt) DBGSINGLEENTER1(fmt,0) #define DBGSINGLELEAVE3(fmt,arg1,arg2,arg3) \ - do { dbgindent--; DBGSINGLE3("leave: " fmt,arg1,arg2,arg3); } while (0) + do { dbgindent--; DBGSINGLE3("leave: " fmt,arg1,arg2,arg3); unlock(); } while (0) #define DBGSINGLELEAVE2(fmt,arg1,arg2) DBGSINGLELEAVE3(fmt,arg1,arg2,0) #define DBGSINGLELEAVE1(fmt,arg1) DBGSINGLELEAVE2(fmt,arg1,0) #define DBGSINGLELEAVE0(fmt) DBGSINGLELEAVE1(fmt,0) @@ -120,7 +160,7 @@ DEVICE_OBJECT *device_object; return r; } -static const char *const irp_mj_dump_FILE_SYSTEM_CONTROL_MinorFunction_names[]={ +static const char *const dump_irp_mj_FILE_SYSTEM_CONTROL_MinorFunction_names[]={ "IRP_MN_USER_FS_REQUEST", "IRP_MN_MOUNT_VOLUME", "IRP_MN_VERIFY_VOLUME", @@ -156,10 +196,66 @@ static const char *const irp_mj_dump_FILE_SYSTEM_CONTROL_MinorFunction_names[]={ #define FSCTL_FILE_PREFETCH CTL_CODE(FILE_DEVICE_FILE_SYSTEM,72,METHOD_BUFFERED,FILE_SPECIAL_ACCESS) #endif -static void irp_mj_dump(struct _DEVICE_OBJECT *DeviceObject,struct _IRP *Irp) +static struct SectionObjectPointer { + FILE_OBJECT *FileObject; + PVOID SharedCacheMap; + } SectionObjectPointer_cache[CACHE_SIZE]; +static int SectionObjectPointer_cache_used=0; + +static struct SectionObjectPointer *SectionObjectPointer_set(FILE_OBJECT *FileObject) +{ +struct SectionObjectPointer *sopp; +PVOID SharedCacheMap; + + if (!FileObject->SectionObjectPointer) + return NULL; + if (!(SharedCacheMap=FileObject->SectionObjectPointer->SharedCacheMap)) + return NULL; + for (sopp=SectionObjectPointer_cache;soppFileObject==FileObject || sopp->SharedCacheMap==SharedCacheMap) + break; + } + if (sopp>=SectionObjectPointer_cache+G_N_ELEMENTS(SectionObjectPointer_cache)) + return NULL; + if (sopp==SectionObjectPointer_cache+SectionObjectPointer_cache_used) + SectionObjectPointer_cache_used++; + sopp->FileObject=FileObject; + sopp->SharedCacheMap=SharedCacheMap; + return sopp; +} + +static FILE_OBJECT *SectionObjectPointer_find(SECTION_OBJECT_POINTERS *SectionObjectPointer) +{ +struct SectionObjectPointer *sopp; +PVOID SharedCacheMap; + + if (!SectionObjectPointer) + return NULL; + if (!(SharedCacheMap=SectionObjectPointer->SharedCacheMap)) + return NULL; + for (sopp=SectionObjectPointer_cache;soppSharedCacheMap==SharedCacheMap) + return sopp->FileObject; + } + return NULL; +} + +static void dump_FileObject(FILE_OBJECT *FileObject) +{ + if (!FileObject) { + DBGSINGLE0("FileObject=NULL"); + return; + } + DBGSINGLE4("FileObject=0x%lX: FileName=%s,Flags=0x%lX,SectionObjectPointer->SharedCacheMap=0x%lX", + (long)FileObject, + dbg_unicode_string(&FileObject->FileName),FileObject->Flags, + (!FileObject->SectionObjectPointer ? -1 : (long)FileObject->SectionObjectPointer->SharedCacheMap)); + SectionObjectPointer_set(FileObject); +} + +static void dump_irp_mj(struct _DEVICE_OBJECT *DeviceObject,struct _IRP *Irp) { IO_STACK_LOCATION *IoStackLocation; -FILE_OBJECT *FileObject; if (!Irp) { DBGSINGLE0("Irp==NULL"); @@ -170,14 +266,8 @@ FILE_OBJECT *FileObject; DBGSINGLE0("IoStackLocation==NULL"); return; } - if (!(FileObject=IoStackLocation->FileObject)) - DBGSINGLE0("FileObject=NULL"); - else - DBGSINGLE5("FileObject=0x%lX: FileName=%s,Flags=0x%lX,SectionObjectPointer=0x%lX,->SharedCacheMap=0x%lX", - (long)FileObject, - dbg_unicode_string(&FileObject->FileName),FileObject->Flags, - (long)FileObject->SectionObjectPointer, - (!FileObject->SectionObjectPointer ? -1 : (long)FileObject->SectionObjectPointer->SharedCacheMap)); + dump_FileObject(IoStackLocation->FileObject); + switch (IoStackLocation->MajorFunction) { case IRP_MJ_READ: DBGSINGLE2("READ: ByteOffset=0x%lX,Length=0x%lX", @@ -193,8 +283,8 @@ FILE_OBJECT *FileObject; DBGSINGLE2("FILE_SYSTEM_CONTROL: MinorFunction=%s (%d)", ((1 && IoStackLocation->MinorFunction>=0 - && IoStackLocation->MinorFunctionMinorFunction] : "???"), + && IoStackLocation->MinorFunctionMinorFunction] : "???"), IoStackLocation->MinorFunction); switch (IoStackLocation->MinorFunction) { case IRP_MN_USER_FS_REQUEST: { @@ -255,7 +345,7 @@ static NTSTATUS tracefs_major_##irp_mj_name(IN struct _DEVICE_OBJECT *DeviceObje NTSTATUS r; \ \ DBGSINGLEENTER0( #irp_mj_name ); \ - irp_mj_dump(DeviceObject,Irp); \ + dump_irp_mj(DeviceObject,Irp); \ r=(*tracefs_major_##irp_mj_name##_orig)(DeviceObject,Irp); \ DBGSINGLELEAVE1( #irp_mj_name ": r=0x%lX",(long)r); \ return r; \ @@ -339,6 +429,7 @@ BOOLEAN r; DBGSINGLEENTER4("CcCanIWrite: FileObject=0x%lX,BytesToWrite=0x%lX,Wait=%d,Retrying=%d", (long)FileObject,BytesToWrite,Wait,Retrying); + dump_FileObject(FileObject); r=CcCanIWrite ( FileObject, BytesToWrite, @@ -372,6 +463,7 @@ BOOLEAN r; DBGSINGLEENTER5("CcCopyRead: FileObject=0x%lX,FileOffset=0x%lX,Length=0x%lX,Wait=%d,Buffer=0x%lX", (long)FileObject,(!FileOffset ? -1 : (long)FileOffset->QuadPart),Length,Wait,(long)Buffer); + dump_FileObject(FileObject); r=CcCopyRead ( FileObject, FileOffset, @@ -406,6 +498,7 @@ BOOLEAN r; DBGSINGLEENTER5("CcCopyWrite: FileObject=0x%lX,FileOffset=0x%lX,Length=0x%lX,Wait=%d,Buffer=0x%lX", (long)FileObject,(!FileOffset ? -1 : (long)FileOffset->QuadPart),Length,Wait,(long)Buffer); + dump_FileObject(FileObject); r=CcCopyWrite ( FileObject, FileOffset, @@ -444,6 +537,7 @@ TcDeferWrite ( "BytesToWrite=0x%lX,Retrying=%d", (long)FileObject,(long)PostRoutine,(long)Context1,(long)Context2, BytesToWrite,Retrying); + dump_FileObject(FileObject); CcDeferWrite ( FileObject, PostRoutine, @@ -476,6 +570,7 @@ TcFastCopyRead ( { DBGSINGLEENTER5("CcFastCopyRead: FileObject=0x%lX,FileOffset=0x%lX,Length=0x%lX,PageCount=0x%lX,Buffer=0x%lX", (long)FileObject,FileOffset,Length,PageCount,(long)Buffer); + dump_FileObject(FileObject); CcFastCopyRead ( FileObject, FileOffset, @@ -505,6 +600,7 @@ TcFastCopyWrite ( { DBGSINGLEENTER4("CcFastCopyWrite: FileObject=0x%lX,FileOffset=0x%lX,Length=0x%lX,Buffer=0x%lX", (long)FileObject,FileOffset,Length,(long)Buffer); + dump_FileObject(FileObject); CcFastCopyWrite ( FileObject, FileOffset, @@ -533,12 +629,14 @@ TcFlushCache ( (long)SectionObjectPointer, (!SectionObjectPointer ? -1 : (long)SectionObjectPointer->SharedCacheMap), (!FileOffset ? -1 : (long)FileOffset->QuadPart),Length); + dump_FileObject(SectionObjectPointer_find(SectionObjectPointer)); CcFlushCache ( SectionObjectPointer, FileOffset, Length, IoStatus ); + dump_FileObject(SectionObjectPointer_find(SectionObjectPointer)); DBGSINGLELEAVE2("CcFlushCache: IoStatus->Status=0x%lX,IoStatus->Information=0x%lX", (!IoStatus ? -1 : (long)IoStatus->Status),(!IoStatus ? -1 : (long)IoStatus->Information)); } @@ -564,6 +662,7 @@ static VOID TcGetDirtyPages_DirtyPageRoutine(IN PFILE_OBJECT FileObject,IN PLARG "OldestLsn=0x%lX,NewestLsn=0x%lX,Context1,Context2", (long)FileObject,(!FileOffset ? -1 : (long)FileOffset->QuadPart),Length, (!OldestLsn ? -1 : (long)OldestLsn->QuadPart),(!NewestLsn ? -1 : (long)NewestLsn->QuadPart)); + dump_FileObject(FileObject); (*TcGetDirtyPages_DirtyPageRoutine_orig)(FileObject,FileOffset,Length,OldestLsn,NewestLsn,Context1,Context2); DBGSINGLELEAVE0("DirtyPageRoutine"); } @@ -649,6 +748,7 @@ BOOLEAN r; DBGSINGLEENTER3("AcquireForLazyWrite: FileObject=0x%lX,Context=0x%lX,Wait=%d", (long)callbacksp->FileObject,(long)callbacksp->LazyWriteContext,Wait); + dump_FileObject(callbacksp->FileObject); r=(*callbacksp->Callbacks.AcquireForLazyWrite)(callbacksp->LazyWriteContext,Wait); DBGSINGLELEAVE1("AcquireForLazyWrite: r=%d",r); return r; @@ -660,6 +760,7 @@ struct Callbacks *callbacksp=Context; DBGSINGLEENTER2("ReleaseFromLazyWrite: FileObject=0x%lX,Context=0x%lX", (long)callbacksp->FileObject,(long)callbacksp->LazyWriteContext); + dump_FileObject(callbacksp->FileObject); (*callbacksp->Callbacks.ReleaseFromLazyWrite)(callbacksp->LazyWriteContext); DBGSINGLELEAVE0("ReleaseFromLazyWrite"); } @@ -671,6 +772,7 @@ BOOLEAN r; DBGSINGLEENTER3("AcquireForReadAhead: FileObject=0x%lX,Context=0x%lX,Wait=%d", (long)callbacksp->FileObject,(long)callbacksp->LazyWriteContext,Wait); + dump_FileObject(callbacksp->FileObject); r=(*callbacksp->Callbacks.AcquireForReadAhead)(callbacksp->LazyWriteContext,Wait); DBGSINGLELEAVE1("AcquireForReadAhead: r=%d",r); return r; @@ -682,6 +784,7 @@ struct Callbacks *callbacksp=Context; DBGSINGLEENTER2("ReleaseFromReadAhead: FileObject=0x%lX,Context=0x%lX", (long)callbacksp->FileObject,(long)callbacksp->LazyWriteContext); + dump_FileObject(callbacksp->FileObject); (*callbacksp->Callbacks.ReleaseFromReadAhead)(callbacksp->LazyWriteContext); DBGSINGLELEAVE0("ReleaseFromReadAhead"); } @@ -726,6 +829,7 @@ struct Callbacks *callbacksp; (!FileSizes ? -1 : (long)FileSizes->FileSize.QuadPart), (!FileSizes ? -1 : (long)FileSizes->ValidDataLength.QuadPart), PinAccess); + dump_FileObject(FileObject); if ((callbacksp=Callbacks_set(FileObject,Callbacks,LazyWriteContext))) { Callbacks=&TcInitializeCacheMap_Callbacks; LazyWriteContext=callbacksp; @@ -745,6 +849,7 @@ PinAccess, Callbacks, LazyWriteContext ); + dump_FileObject(FileObject); DBGSINGLELEAVE0("CcInitializeCacheMap"); } @@ -771,6 +876,7 @@ BOOLEAN r; DBGSINGLEENTER4("CcMapData: FileObject=0x%lX,FileOffset=0x%lX,Length=0x%lX,Flags=0x%lX", (long)FileObject,(!FileOffset ? -1 : (long)FileOffset->QuadPart),Length,Flags); + dump_FileObject(FileObject); r=CcMapData ( FileObject, FileOffset, @@ -803,6 +909,7 @@ TcMdlRead ( { DBGSINGLEENTER3("CcMdlRead: FileObject=0x%lX,FileOffset=0x%lX,Length=0x%lX", (long)FileObject,(!FileOffset ? -1 : (long)FileOffset->QuadPart),Length); + dump_FileObject(FileObject); CcMdlRead ( FileObject, FileOffset, @@ -828,6 +935,7 @@ TcMdlReadComplete ( { DBGSINGLEENTER2("CcMdlReadComplete: FileObject=0x%lX,MdlChain=0x%lX", (long)FileObject,(long)MdlChain); + dump_FileObject(FileObject); CcMdlReadComplete ( FileObject, MdlChain @@ -848,6 +956,7 @@ TcMdlWriteAbort ( { DBGSINGLEENTER2("CcMdlWriteAbort: FileObject=0x%lX,MdlChain=0x%lX", (long)FileObject,(long)MdlChain); + dump_FileObject(FileObject); CcMdlWriteAbort ( FileObject, MdlChain @@ -870,6 +979,7 @@ TcMdlWriteComplete ( { DBGSINGLEENTER3("CcMdlWriteComplete: FileObject=0x%lX,FileOffset=0x%lX,MdlChain=0x%lX", (long)FileObject,(!FileOffset ? -1 : (long)FileOffset->QuadPart),(long)MdlChain); + dump_FileObject(FileObject); CcMdlWriteComplete ( FileObject, FileOffset, @@ -899,6 +1009,7 @@ BOOLEAN r; DBGSINGLEENTER4("CcPinMappedData: FileObject=0x%lX,FileOffset=0x%lX,Length=0x%lX,Flags=0x%lX", (long)FileObject,(!FileOffset ? -1 : (long)FileOffset->QuadPart),Length,Flags); + dump_FileObject(FileObject); r=CcPinMappedData ( FileObject, FileOffset, @@ -934,6 +1045,7 @@ BOOLEAN r; DBGSINGLEENTER4("CcPinRead: FileObject=0x%lX,FileOffset=0x%lX,Length=0x%lX,Flags=0x%lX", (long)FileObject,(!FileOffset ? -1 : (long)FileOffset->QuadPart),Length,Flags); + dump_FileObject(FileObject); r=CcPinRead ( FileObject, FileOffset, @@ -966,6 +1078,7 @@ TcPrepareMdlWrite ( { DBGSINGLEENTER3("CcPrepareMdlWrite: FileObject=0x%lX,FileOffset=0x%lX,Length=0x%lX", (long)FileObject,(!FileOffset ? -1 : (long)FileOffset->QuadPart),Length); + dump_FileObject(FileObject); CcPrepareMdlWrite ( FileObject, FileOffset, @@ -1003,6 +1116,7 @@ BOOLEAN r; DBGSINGLEENTER5("CcPreparePinWrite: FileObject=0x%lX,FileOffset=0x%lX,Length=0x%lX,Zero=%d,Flags=0x%lX", (long)FileObject,(!FileOffset ? -1 : (long)FileOffset->QuadPart),Length,Zero,Flags); + dump_FileObject(FileObject); r=CcPreparePinWrite ( FileObject, FileOffset, @@ -1040,12 +1154,14 @@ BOOLEAN r; (!SectionObjectPointer ? -1 : (long)SectionObjectPointer->SharedCacheMap), (!FileOffset ? -1 : (long)FileOffset->QuadPart),Length, UninitializeCacheMaps); + dump_FileObject(SectionObjectPointer_find(SectionObjectPointer)); r=CcPurgeCacheSection ( SectionObjectPointer, FileOffset, Length, UninitializeCacheMaps ); + dump_FileObject(SectionObjectPointer_find(SectionObjectPointer)); DBGSINGLELEAVE1("CcPurgeCacheSection: r=%d",r); return r; } @@ -1084,6 +1200,7 @@ TcSetAdditionalCacheAttributes ( { DBGSINGLEENTER3("CcSetAdditionalCacheAttributes: FileObject=0x%lX,DisableReadAhead=%d,DisableWriteBehind=%d", (long)FileObject,DisableReadAhead,DisableWriteBehind); + dump_FileObject(FileObject); CcSetAdditionalCacheAttributes ( FileObject, DisableReadAhead, @@ -1149,6 +1266,7 @@ TcSetFileSizes ( (!FileSizes ? -1 : (long)FileSizes->AllocationSize.QuadPart), (!FileSizes ? -1 : (long)FileSizes->FileSize.QuadPart), (!FileSizes ? -1 : (long)FileSizes->ValidDataLength.QuadPart)); + dump_FileObject(FileObject); CcSetFileSizes ( FileObject, FileSizes @@ -1218,6 +1336,7 @@ TcSetLogHandleForFile ( { DBGSINGLEENTER3("CcSetLogHandleForFile: FileObject=0x%lX,LogHandle=0x%lX,FlushToLsnRoutine=0x%lX", (long)FileObject,(long)LogHandle,(long)FlushToLsnRoutine); + dump_FileObject(FileObject); if (LogHandle_set(LogHandle,FlushToLsnRoutine)) FlushToLsnRoutine=TcSetLogHandleForFile_FlushToLsnRoutine; CcSetLogHandleForFile ( @@ -1241,6 +1360,7 @@ TcSetReadAheadGranularity ( { DBGSINGLEENTER2("CcSetReadAheadGranularity: FileObject=0x%lX,Granularity=0x%lX", (long)FileObject,Granularity); + dump_FileObject(FileObject); CcSetReadAheadGranularity ( FileObject, Granularity @@ -1270,11 +1390,13 @@ BOOLEAN r; DBGSINGLEENTER3("CcUninitializeCacheMap: FileObject=0x%lX,TruncateSize=0x%lX,UninitializeCompleteEvent=0x%lX", (long)FileObject,(!TruncateSize ? -1 : (long)TruncateSize->QuadPart),(long)UninitializeCompleteEvent); + dump_FileObject(FileObject); r=CcUninitializeCacheMap ( FileObject, TruncateSize, UninitializeCompleteEvent ); + dump_FileObject(FileObject); DBGSINGLELEAVE1("CcUninitializeCacheMap: r=%d",r); return r; } @@ -1355,6 +1477,7 @@ BOOLEAN r; (!StartOffset ? -1 : (long)StartOffset->QuadPart), (!EndOffset ? -1 : (long)EndOffset->QuadPart), Wait); + dump_FileObject(FileObject); r=CcZeroData ( FileObject, StartOffset, diff --git a/src/TraceFS/TraceFS-W32/TraceFS.sys b/src/TraceFS/TraceFS-W32/TraceFS.sys index 157824c..bb27942 100644 Binary files a/src/TraceFS/TraceFS-W32/TraceFS.sys and b/src/TraceFS/TraceFS-W32/TraceFS.sys differ