From 9b81c03ccc7e7991a69e41efc72a5813fd7bd43e Mon Sep 17 00:00:00 2001 From: Bill Zissimopoulos Date: Sun, 10 Apr 2016 23:45:09 -0700 Subject: [PATCH] sys: fsp_debug: greatly simplify debugging support --- src/sys/create.c | 4 +- src/sys/debug.c | 15 ++++++ src/sys/dirctl.c | 4 +- src/sys/driver.c | 4 +- src/sys/driver.h | 116 ++++++++++++++++++++++----------------------- src/sys/file.c | 2 +- src/sys/fileinfo.c | 2 +- src/sys/lockctl.c | 2 +- src/sys/read.c | 6 +-- src/sys/security.c | 2 +- src/sys/util.c | 4 +- src/sys/write.c | 6 +-- 12 files changed, 90 insertions(+), 77 deletions(-) diff --git a/src/sys/create.c b/src/sys/create.c index 7cf4dfc3..fcd46951 100644 --- a/src/sys/create.c +++ b/src/sys/create.c @@ -429,7 +429,7 @@ NTSTATUS FspFsvolCreatePrepare( FileObject = FspIopRequestContext(Request, RequestFileObject); /* lock the FileNode for overwriting */ - Success = DEBUGTEST(90, TRUE) && FspFileNodeTryAcquireExclusive(FileNode, Full); + Success = DEBUGTEST(90) && FspFileNodeTryAcquireExclusive(FileNode, Full); if (!Success) { FspIopRetryPrepareIrp(Irp, &Result); @@ -706,7 +706,7 @@ static NTSTATUS FspFsvolCreateTryOpen(PIRP Irp, const FSP_FSCTL_TRANSACT_RSP *Re FSP_FSCTL_TRANSACT_REQ *Request = FspIrpRequest(Irp); BOOLEAN Success; - Success = DEBUGTEST(90, TRUE) && FspFileNodeTryAcquireExclusive(FileNode, Main); + Success = DEBUGTEST(90) && FspFileNodeTryAcquireExclusive(FileNode, Main); if (!Success) { /* repost the IRP to retry later */ diff --git a/src/sys/debug.c b/src/sys/debug.c index c2f031b7..506172e1 100644 --- a/src/sys/debug.c +++ b/src/sys/debug.c @@ -296,4 +296,19 @@ ULONG DebugRandom(VOID) return Result; } + +VOID FspDebugLogIrp(const char *func, PIRP Irp, NTSTATUS Result) +{ + PIO_STACK_LOCATION IrpSp = IoGetCurrentIrpStackLocation(Irp); + DbgPrint("[%d] " DRIVER_NAME "!%s: IRP=%p, %s%c, %s%s, IoStatus=%s[%lld]\n", + KeGetCurrentIrql(), + func, + Irp, + DeviceExtensionKindSym(FspDeviceExtension(IrpSp->DeviceObject)->Kind), + Irp->RequestorMode == KernelMode ? 'K' : 'U', + IrpMajorFunctionSym(IrpSp->MajorFunction), + IrpMinorFunctionSym(IrpSp->MajorFunction, IrpSp->MinorFunction), + NtStatusSym(Result), + (LONGLONG)Irp->IoStatus.Information); +} #endif diff --git a/src/sys/dirctl.c b/src/sys/dirctl.c index 47f24fa9..9a113b10 100644 --- a/src/sys/dirctl.c +++ b/src/sys/dirctl.c @@ -395,7 +395,7 @@ static NTSTATUS FspFsvolQueryDirectoryRetry( (ULONG)(UINT_PTR)FspIopRequestContext(Request, RequestSystemBufferLength) : 0; /* try to acquire the FileNode exclusive; Full because we may need to send a Request */ - Success = DEBUGTEST(90, TRUE) && + Success = DEBUGTEST(90) && FspFileNodeTryAcquireExclusiveF(FileNode, FspFileNodeAcquireFull, CanWait); if (!Success) { @@ -798,7 +798,7 @@ NTSTATUS FspFsvolDirectoryControlComplete( (ULONG)(UINT_PTR)FspIopRequestContext(Request, RequestDirInfoChangeNumber); /* acquire FileNode exclusive Full (because we may need to go back to user-mode) */ - Success = DEBUGTEST(90, TRUE) && FspFileNodeTryAcquireExclusive(FileNode, Full); + Success = DEBUGTEST(90) && FspFileNodeTryAcquireExclusive(FileNode, Full); if (!Success) { FspIopRetryCompleteIrp(Irp, Response, &Result); diff --git a/src/sys/driver.c b/src/sys/driver.c index 92147591..32419248 100644 --- a/src/sys/driver.c +++ b/src/sys/driver.c @@ -31,7 +31,7 @@ DRIVER_UNLOAD FspUnload; NTSTATUS DriverEntry( PDRIVER_OBJECT DriverObject, PUNICODE_STRING RegistryPath) { - FSP_ENTER(); + FSP_ENTER_DRV(); FspDriverMultiVersionInitialize(); @@ -158,7 +158,7 @@ NTSTATUS DriverEntry( IoRegisterFileSystem(FspFsctlDiskDeviceObject); #pragma prefast(suppress:28175, "We are in DriverEntry: ok to access DriverName") - FSP_LEAVE("DriverName=\"%wZ\", RegistryPath=\"%wZ\"", + FSP_LEAVE_DRV("DriverName=\"%wZ\", RegistryPath=\"%wZ\"", &DriverObject->DriverName, RegistryPath); } diff --git a/src/sys/driver.h b/src/sys/driver.h index 6fdbf663..8f034e88 100644 --- a/src/sys/driver.h +++ b/src/sys/driver.h @@ -35,63 +35,84 @@ #define FSP_ALLOC_EXTERNAL_TAG 'XpsF' #define FSP_IO_INCREMENT IO_NETWORK_INCREMENT +/* debug */ +#if DBG +enum +{ + fsp_debug_bp_generic = 0x00000001, /* generic breakpoint switch */ + fsp_debug_bp_drvrld = 0x00000002, /* DriverEntry/Unload breakpoint switch */ + fsp_debug_bp_ioentr = 0x00000004, /* I/O entry breakpoint switch */ + fsp_debug_bp_ioprep = 0x00000008, /* I/O prepare breakpoint switch */ + fsp_debug_bp_iocmpl = 0x00000010, /* I/O complete breakpoint switch */ + fsp_debug_bp_iocall = 0x00000020, /* I/O callback breakpoint switch */ + fsp_debug_bp_iorecu = 0x00000040, /* I/O recursive breakpoint switch */ + fsp_debug_dt = 0x01000000, /* DEBUGTEST switch */ + fsp_debug_dp = 0x10000000, /* DbgPrint switch */ +}; +extern __declspec(selectany) int fsp_debug = + fsp_debug_bp_drvrld | fsp_debug_dt; +const char *NtStatusSym(NTSTATUS Status); +const char *IrpMajorFunctionSym(UCHAR MajorFunction); +const char *IrpMinorFunctionSym(UCHAR MajorFunction, UCHAR MinorFunction); +const char *IoctlCodeSym(ULONG ControlCode); +const char *FileInformationClassSym(FILE_INFORMATION_CLASS FileInformationClass); +const char *FsInformationClassSym(FS_INFORMATION_CLASS FsInformationClass); +const char *DeviceExtensionKindSym(UINT32 Kind); +ULONG DebugRandom(VOID); +VOID FspDebugLogIrp(const char *func, PIRP Irp, NTSTATUS Result); +#endif + /* DbgPrint */ #if DBG -extern __declspec(selectany) int fsp_dp = 1; -#define DbgPrint(...) ((void)(fsp_dp ? DbgPrint(__VA_ARGS__) : 0)) -#else +#define DbgPrint(...) \ + ((void)((fsp_debug & fsp_debug_dp) ? DbgPrint(__VA_ARGS__) : 0)) #endif /* DEBUGLOG */ #if DBG #define DEBUGLOG(fmt, ...) \ DbgPrint("[%d] " DRIVER_NAME "!" __FUNCTION__ ": " fmt "\n", KeGetCurrentIrql(), __VA_ARGS__) -#else -#define DEBUGLOG(fmt, ...) ((void)0) -#endif - -/* DEBUGLOGIRP */ -#if DBG #define DEBUGLOGIRP(Irp, Result) FspDebugLogIrp(__FUNCTION__, Irp, Result) #else +#define DEBUGLOG(fmt, ...) ((void)0) #define DEBUGLOGIRP(Irp, Result) ((void)0) #endif /* DEBUGBREAK */ #if DBG -extern __declspec(selectany) int fsp_bp = 1; /* generic breakpoint switch */ -extern __declspec(selectany) int fsp_bp_crit = 1; /* critical error breakpoint */ -extern __declspec(selectany) int fsp_bp_ioentr = 1; /* I/O entry breakpoint switch */ -extern __declspec(selectany) int fsp_bp_ioprep = 1; /* I/O prepare breakpoint switch */ -extern __declspec(selectany) int fsp_bp_iocmpl = 1; /* I/O complete breakpoint switch */ -extern __declspec(selectany) int fsp_bp_iocall = 1; /* I/O callback breakpoint switch */ -extern __declspec(selectany) int fsp_bp_iorecu = 1; /* I/O recursive breakpoint switch */ +#define DEBUGBREAK_CRIT() \ + do \ + { \ + static int bp = 1; \ + if (bp && !KD_DEBUGGER_NOT_PRESENT)\ + DbgBreakPoint(); \ + } while (0,0) #define DEBUGBREAK() \ do \ { \ static int bp = 1; \ - if (bp && fsp_bp && !KD_DEBUGGER_NOT_PRESENT)\ + if (bp && (fsp_debug & fsp_debug_bp_generic) && !KD_DEBUGGER_NOT_PRESENT)\ DbgBreakPoint(); \ } while (0,0) #define DEBUGBREAK_EX(category) \ do \ { \ static int bp = 1; \ - if (bp && fsp_bp && fsp_bp_ ## category && !KD_DEBUGGER_NOT_PRESENT)\ + if (bp && (fsp_debug & fsp_debug_bp_ ## category) && !KD_DEBUGGER_NOT_PRESENT)\ DbgBreakPoint(); \ } while (0,0) #else +#define DEBUGBREAK_CRIT() do {} while (0,0) #define DEBUGBREAK() do {} while (0,0) #define DEBUGBREAK_EX(category) do {} while (0,0) #endif /* DEBUGTEST */ #if DBG -extern __declspec(selectany) int fsp_dt = 1; -#define DEBUGTEST(Percent, Default) \ - (!fsp_dt || DebugRandom() <= (Percent) * 0x7fff / 100 ? (Default) : !(Default)) +#define DEBUGTEST(Percent) \ + (0 == (fsp_debug & fsp_debug_dt) || DebugRandom() <= (Percent) * 0x7fff / 100) #else -#define DEBUGTEST(Percent, Default) (Default) +#define DEBUGTEST(Percent) (TRUE) #endif /* FSP_ENTER/FSP_LEAVE */ @@ -137,6 +158,10 @@ extern __declspec(selectany) int fsp_dt = 1; NTSTATUS Result = STATUS_SUCCESS; FSP_ENTER_(iocall, __VA_ARGS__) #define FSP_LEAVE(fmt, ...) \ FSP_LEAVE_(FSP_DEBUGLOG_(fmt, " = %s", __VA_ARGS__, NtStatusSym(Result))); return Result +#define FSP_ENTER_DRV(...) \ + NTSTATUS Result = STATUS_SUCCESS; FSP_ENTER_(drvrld, __VA_ARGS__) +#define FSP_LEAVE_DRV(fmt, ...) \ + FSP_LEAVE_(FSP_DEBUGLOG_(fmt, " = %s", __VA_ARGS__, NtStatusSym(Result))); return Result #define FSP_ENTER_MJ(...) \ NTSTATUS Result = STATUS_SUCCESS; \ PIO_STACK_LOCATION IrpSp = IoGetCurrentIrpStackLocation(Irp);\ @@ -973,43 +998,6 @@ NTSTATUS FspFileDescResetDirectoryPattern(FSP_FILE_DESC *FileDesc, #define FspFileNodeDereferenceDirInfo(P) FspMetaCacheDereferenceItemBuffer(P) #define FspFileNodeUnlockAll(N,F,P) FsRtlFastUnlockAll(&(N)->FileLock, F, P, N) -/* debug */ -#if DBG -const char *NtStatusSym(NTSTATUS Status); -const char *IrpMajorFunctionSym(UCHAR MajorFunction); -const char *IrpMinorFunctionSym(UCHAR MajorFunction, UCHAR MinorFunction); -const char *IoctlCodeSym(ULONG ControlCode); -const char *FileInformationClassSym(FILE_INFORMATION_CLASS FileInformationClass); -const char *FsInformationClassSym(FS_INFORMATION_CLASS FsInformationClass); -const char *DeviceExtensionKindSym(UINT32 Kind); -ULONG DebugRandom(VOID); -static inline -VOID FspDebugLogIrp(const char *func, PIRP Irp, NTSTATUS Result) -{ - PIO_STACK_LOCATION IrpSp = IoGetCurrentIrpStackLocation(Irp); - DbgPrint("[%d] " DRIVER_NAME "!%s: IRP=%p, %s%c, %s%s, IoStatus=%s[%lld]\n", - KeGetCurrentIrql(), - func, - Irp, - DeviceExtensionKindSym(FspDeviceExtension(IrpSp->DeviceObject)->Kind), - Irp->RequestorMode == KernelMode ? 'K' : 'U', - IrpMajorFunctionSym(IrpSp->MajorFunction), - IrpMinorFunctionSym(IrpSp->MajorFunction, IrpSp->MinorFunction), - NtStatusSym(Result), - (LONGLONG)Irp->IoStatus.Information); -} -#endif - -/* extern */ -extern PDRIVER_OBJECT FspDriverObject; -extern PDEVICE_OBJECT FspFsctlDiskDeviceObject; -extern PDEVICE_OBJECT FspFsctlNetDeviceObject; -extern FAST_IO_DISPATCH FspFastIoDispatch; -extern CACHE_MANAGER_CALLBACKS FspCacheManagerCallbacks; -extern FSP_IOPREP_DISPATCH *FspIopPrepareFunction[]; -extern FSP_IOCMPL_DISPATCH *FspIopCompleteFunction[]; -extern WCHAR FspFileDescDirectoryPatternMatchAll[]; - /* multiversion support */ typedef NTKERNELAPI @@ -1021,6 +1009,16 @@ FSP_MV_CcCoherencyFlushAndPurgeCache( _Out_ PIO_STATUS_BLOCK IoStatus, _In_opt_ ULONG Flags ); + +/* extern */ +extern PDRIVER_OBJECT FspDriverObject; +extern PDEVICE_OBJECT FspFsctlDiskDeviceObject; +extern PDEVICE_OBJECT FspFsctlNetDeviceObject; +extern FAST_IO_DISPATCH FspFastIoDispatch; +extern CACHE_MANAGER_CALLBACKS FspCacheManagerCallbacks; +extern FSP_IOPREP_DISPATCH *FspIopPrepareFunction[]; +extern FSP_IOCMPL_DISPATCH *FspIopCompleteFunction[]; +extern WCHAR FspFileDescDirectoryPatternMatchAll[]; extern FSP_MV_CcCoherencyFlushAndPurgeCache *FspMvCcCoherencyFlushAndPurgeCache; #endif diff --git a/src/sys/file.c b/src/sys/file.c index ea0fcb79..3fac5ff7 100644 --- a/src/sys/file.c +++ b/src/sys/file.c @@ -774,7 +774,7 @@ VOID FspFileNodeSetFileInfo(FSP_FILE_NODE *FileNode, PFILE_OBJECT CcFileObject, if (!NT_SUCCESS(Result)) { DEBUGLOG("FspCcSetFileSizes error: %s", NtStatusSym(Result)); - DEBUGBREAK_EX(crit); + DEBUGBREAK_CRIT(); CcUninitializeCacheMap(CcFileObject, 0, 0); } } diff --git a/src/sys/fileinfo.c b/src/sys/fileinfo.c index 416a7264..2a195ad9 100644 --- a/src/sys/fileinfo.c +++ b/src/sys/fileinfo.c @@ -497,7 +497,7 @@ NTSTATUS FspFsvolQueryInformationComplete( FspFileNodeReleaseOwner(FileNode, Full, Request); } - Success = DEBUGTEST(90, TRUE) && FspFileNodeTryAcquireExclusive(FileNode, Main); + Success = DEBUGTEST(90) && FspFileNodeTryAcquireExclusive(FileNode, Main); if (!Success) { FspIopRetryCompleteIrp(Irp, Response, &Result); diff --git a/src/sys/lockctl.c b/src/sys/lockctl.c index f17a1e34..5775385a 100644 --- a/src/sys/lockctl.c +++ b/src/sys/lockctl.c @@ -33,7 +33,7 @@ static NTSTATUS FspFsvolLockControlRetry( BOOLEAN Success; /* try to acquire the FileNode shared Main */ - Success = DEBUGTEST(90, TRUE) && + Success = DEBUGTEST(90) && FspFileNodeTryAcquireSharedF(FileNode, FspFileNodeAcquireMain, CanWait); if (!Success) return FspWqRepostIrpWorkItem(Irp, FspFsvolLockControlRetry, 0); diff --git a/src/sys/read.c b/src/sys/read.c index 0fd5c185..1e7e8ad4 100644 --- a/src/sys/read.c +++ b/src/sys/read.c @@ -103,7 +103,7 @@ static NTSTATUS FspFsvolReadCached( BOOLEAN Success; /* try to acquire the FileNode Main shared */ - Success = DEBUGTEST(90, TRUE) && + Success = DEBUGTEST(90) && FspFileNodeTryAcquireSharedF(FileNode, FspFileNodeAcquireMain, CanWait); if (!Success) return FspWqRepostIrpWorkItem(Irp, FspFsvolReadCached, 0); @@ -232,7 +232,7 @@ static NTSTATUS FspFsvolReadNonCached( return Result; /* acquire FileNode exclusive Full */ - Success = DEBUGTEST(90, TRUE) && + Success = DEBUGTEST(90) && FspFileNodeTryAcquireExclusiveF(FileNode, FspFileNodeAcquireFull, CanWait); if (!Success) return FspWqRepostIrpWorkItem(Irp, FspFsvolReadNonCached, 0); @@ -371,7 +371,7 @@ NTSTATUS FspFsvolReadComplete( InfoChangeNumber = (ULONG)(UINT_PTR)FspIopRequestContext(Request, RequestInfoChangeNumber); - Success = DEBUGTEST(90, TRUE) && FspFileNodeTryAcquireExclusive(FileNode, Main); + Success = DEBUGTEST(90) && FspFileNodeTryAcquireExclusive(FileNode, Main); if (!Success) { FspIopRetryCompleteIrp(Irp, Response, &Result); diff --git a/src/sys/security.c b/src/sys/security.c index 682fa48d..b01397b8 100644 --- a/src/sys/security.c +++ b/src/sys/security.c @@ -141,7 +141,7 @@ NTSTATUS FspFsvolQuerySecurityComplete( FspFileNodeReleaseOwner(FileNode, Full, Request); } - Success = DEBUGTEST(90, TRUE) && FspFileNodeTryAcquireExclusive(FileNode, Main); + Success = DEBUGTEST(90) && FspFileNodeTryAcquireExclusive(FileNode, Main); if (!Success) { FspIopRetryCompleteIrp(Irp, Response, &Result); diff --git a/src/sys/util.c b/src/sys/util.c index dc2259b9..16dc173e 100644 --- a/src/sys/util.c +++ b/src/sys/util.c @@ -128,7 +128,7 @@ PVOID FspAllocatePoolMustSucceed(POOL_TYPE PoolType, SIZE_T Size, ULONG Tag) for (ULONG i = 0, n = sizeof(Delays) / sizeof(Delays[0]);; i++) { - Result = DEBUGTEST(95, TRUE) ? ExAllocatePoolWithTag(PoolType, Size, Tag) : 0; + Result = DEBUGTEST(95) ? ExAllocatePoolWithTag(PoolType, Size, Tag) : 0; if (0 != Result) return Result; @@ -146,7 +146,7 @@ PVOID FspAllocateIrpMustSucceed(CCHAR StackSize) for (ULONG i = 0, n = sizeof(Delays) / sizeof(Delays[0]);; i++) { - Result = DEBUGTEST(95, TRUE) ? IoAllocateIrp(StackSize, FALSE) : 0; + Result = DEBUGTEST(95) ? IoAllocateIrp(StackSize, FALSE) : 0; if (0 != Result) return Result; diff --git a/src/sys/write.c b/src/sys/write.c index e72b1769..ea611ba1 100644 --- a/src/sys/write.c +++ b/src/sys/write.c @@ -109,7 +109,7 @@ static NTSTATUS FspFsvolWriteCached( BOOLEAN Success; /* should we defer the write? */ - Success = DEBUGTEST(90, TRUE) && CcCanIWrite(FileObject, WriteLength, CanWait, Retrying); + Success = DEBUGTEST(90) && CcCanIWrite(FileObject, WriteLength, CanWait, Retrying); if (!Success) { Result = FspWqCreateIrpWorkItem(Irp, FspFsvolWriteCached, 0); @@ -125,7 +125,7 @@ static NTSTATUS FspFsvolWriteCached( } /* try to acquire the FileNode Main exclusive */ - Success = DEBUGTEST(90, TRUE) && + Success = DEBUGTEST(90) && FspFileNodeTryAcquireExclusiveF(FileNode, FspFileNodeAcquireMain, CanWait); if (!Success) return FspWqRepostIrpWorkItem(Irp, FspFsvolWriteCached, 0); @@ -298,7 +298,7 @@ static NTSTATUS FspFsvolWriteNonCached( return Result; /* acquire FileNode exclusive Full */ - Success = DEBUGTEST(90, TRUE) && + Success = DEBUGTEST(90) && FspFileNodeTryAcquireExclusiveF(FileNode, FspFileNodeAcquireFull, CanWait); if (!Success) return FspWqRepostIrpWorkItem(Irp, FspFsvolWriteNonCached, 0);