src: dll: FspDebugLogRequest, FspDebugLogResponse

build/VStudio/version.properties

@@ -7,7 +7,7 @@
         <MyCopyright>2015-2016 Bill Zissimopoulos</MyCopyright>
         <!-- build number: concat 2-digit year with 3-digit day of the year (16-bits until 2066) -->
         <MyBuildNumber>$([System.DateTime]::Now.ToString(`yy`))$([System.DateTime]::Now.DayOfYear.ToString(`000`))</MyBuildNumber>
-        <MyVersion>0.11.$(MyBuildNumber)</MyVersion>
+        <MyVersion>0.12.$(MyBuildNumber)</MyVersion>
         <MyVersionWithCommas>$(MyVersion.Replace('.',',')),0</MyVersionWithCommas>
     </PropertyGroup>
 </Project>

build/VStudio/winfsp_dll.vcxproj

@@ -37,6 +37,7 @@
     <ClCompile Include="..\..\src\dll\ntstatus.c" />
     <ClCompile Include="..\..\src\dll\path.c" />
     <ClCompile Include="..\..\src\dll\service.c" />
+    <ClCompile Include="..\..\src\dll\util.c" />
   </ItemGroup>
   <ItemGroup>
     <None Include="..\..\src\dll\library.def" />

build/VStudio/winfsp_dll.vcxproj.filters

@@ -64,6 +64,9 @@
     <ClCompile Include="..\..\src\dll\eventlog.c">
       <Filter>Source</Filter>
     </ClCompile>
+    <ClCompile Include="..\..\src\dll\util.c">
+      <Filter>Source</Filter>
+    </ClCompile>
   </ItemGroup>
   <ItemGroup>
     <None Include="..\..\src\dll\ntstatus.i">

inc/winfsp/winfsp.h

@@ -591,6 +591,7 @@ typedef struct _FSP_FILE_SYSTEM
     NTSTATUS DispatcherResult;
     PWSTR MountPoint;
     LIST_ENTRY MountEntry;
+    UINT32 DebugLog;
 } FSP_FILE_SYSTEM;
 /**
  * Create a file system object.
@@ -737,6 +738,12 @@ VOID FspFileSystemSetDispatcherResult(FSP_FILE_SYSTEM *FileSystem,
         return;
     InterlockedCompareExchange(&FileSystem->DispatcherResult, DispatcherResult, 0);
 }
+static inline
+VOID FspFileSystemSetDebugLog(FSP_FILE_SYSTEM *FileSystem,
+    UINT32 DebugLog)
+{
+    FileSystem->DebugLog = DebugLog;
+}
 
 /*
  * Operations
@@ -1034,6 +1041,8 @@ FSP_API VOID FspEventLogV(ULONG Type, PWSTR Format, va_list ap);
 FSP_API VOID FspDebugLog(const char *format, ...);
 FSP_API VOID FspDebugLogSD(const char *format, PSECURITY_DESCRIPTOR SecurityDescriptor);
 FSP_API VOID FspDebugLogFT(const char *format, PFILETIME FileTime);
+FSP_API VOID FspDebugLogRequest(FSP_FSCTL_TRANSACT_REQ *Request);
+FSP_API VOID FspDebugLogResponse(FSP_FSCTL_TRANSACT_RSP *Response);
 FSP_API NTSTATUS FspCallNamedPipeSecurely(PWSTR PipeName,
     PVOID InBuffer, ULONG InBufferSize, PVOID OutBuffer, ULONG OutBufferSize,
     PULONG PBytesTransferred, ULONG Timeout,

src/dll/debug.c

@@ -37,7 +37,8 @@ FSP_API VOID FspDebugLogSD(const char *format, PSECURITY_DESCRIPTOR SecurityDesc
 
     if (0 == SecurityDescriptor)
         FspDebugLog(format, "null security descriptor");
-    else if (ConvertSecurityDescriptorToStringSecurityDescriptorA(SecurityDescriptor, SDDL_REVISION_1,
+    else if (ConvertSecurityDescriptorToStringSecurityDescriptorA(SecurityDescriptor,
+        SDDL_REVISION_1,
         OWNER_SECURITY_INFORMATION | GROUP_SECURITY_INFORMATION |
         DACL_SECURITY_INFORMATION | SACL_SECURITY_INFORMATION,
         &Sddl, 0))
@@ -65,3 +66,560 @@ FSP_API VOID FspDebugLogFT(const char *format, PFILETIME FileTime)
     else
         FspDebugLog(format, "invalid file time");
 }
+
+#define MAKE_UINT32_PAIR(v)             (((v) >> 32) & 0xffffffff), ((v) & 0xffffffff)
+
+static inline const char *FspDebugLogDispositionString(UINT32 CreateOptions)
+{
+    switch ((CreateOptions >> 24) & 0xff)
+    {
+    case FILE_CREATE:
+        return "FILE_CREATE";
+    case FILE_OPEN:
+        return "FILE_OPEN";
+    case FILE_OPEN_IF:
+        return "FILE_OPEN_IF";
+    case FILE_OVERWRITE:
+        return "FILE_OVERWRITE";
+    case FILE_SUPERSEDE:
+        return "FILE_SUPERSEDE";
+    case FILE_OVERWRITE_IF:
+        return "FILE_OVERWRITE_IF";
+    default:
+        return "INVALID";
+    }
+}
+
+static const char *FspDebugLogFileTimeString(UINT64 FileTime, char *Buf)
+{
+    SYSTEMTIME SystemTime;
+
+    if (0 == FileTime)
+        lstrcpyA(Buf, "0");
+    else if (FileTimeToSystemTime((PFILETIME)&FileTime, &SystemTime))
+    {
+        wsprintfA(Buf, "%04hu-%02hu-%02huT%02hu:%02hu:%02hu.%03huZ",
+            SystemTime.wYear, SystemTime.wMonth, SystemTime.wDay,
+            SystemTime.wHour, SystemTime.wMinute, SystemTime.wSecond,
+            SystemTime.wMilliseconds);
+    }
+    else
+        lstrcpyA(Buf, "INVALID");
+
+    return Buf;
+}
+
+static const char *FspDebugLogFileInfoString(FSP_FSCTL_FILE_INFO *FileInfo, char *Buf)
+{
+    char CreationTimeBuf[32], LastAccessTimeBuf[32], LastWriteTimeBuf[32], ChangeTimeBuf[32];
+
+    wsprintfA(Buf,
+        "{"
+        "FileAttributes=%lx, "
+        "ReparseTag=%lx, "
+        "AllocationSize=%lx:%lx, "
+        "FileSize=%lx:%lx, "
+        "CreationTime=%s, "
+        "LastAccessTime=%s, "
+        "LastWriteTime=%s, "
+        "ChangeTime=%s, "
+        "IndexNumber=%lx:%lx"
+        "}",
+        FileInfo->FileAttributes,
+        FileInfo->ReparseTag,
+        MAKE_UINT32_PAIR(FileInfo->AllocationSize),
+        MAKE_UINT32_PAIR(FileInfo->FileSize),
+        FspDebugLogFileTimeString(FileInfo->CreationTime, CreationTimeBuf),
+        FspDebugLogFileTimeString(FileInfo->LastAccessTime, LastAccessTimeBuf),
+        FspDebugLogFileTimeString(FileInfo->LastWriteTime, LastWriteTimeBuf),
+        FspDebugLogFileTimeString(FileInfo->ChangeTime, ChangeTimeBuf),
+        MAKE_UINT32_PAIR(FileInfo->IndexNumber));
+
+    return Buf;
+}
+
+static const char *FspDebugLogVolumeInfoString(FSP_FSCTL_VOLUME_INFO *VolumeInfo, char *Buf)
+{
+    wsprintfA(Buf,
+        "{"
+        "TotalSize=%lx:%lx, "
+        "FreeSize=%lx:%lx, "
+        "VolumeLabel=\"%.32S\""
+        "}",
+        MAKE_UINT32_PAIR(VolumeInfo->TotalSize),
+        MAKE_UINT32_PAIR(VolumeInfo->FreeSize),
+        &VolumeInfo->VolumeLabel);
+
+    return Buf;
+}
+
+static inline VOID FspDebugLogRequestVoid(FSP_FSCTL_TRANSACT_REQ *Request, const char *Name)
+{
+    FspDebugLog("%S[TID=%ld]: %p: >>%s\n",
+        FspDiagIdent(), GetCurrentThreadId(), Request->Hint, Name);
+}
+
+static inline VOID FspDebugLogResponseStatus(FSP_FSCTL_TRANSACT_RSP *Response, const char *Name)
+{
+    FspDebugLog("%S[TID=%ld]: %p: <<%s IoStatus=%lx[%ld]\n",
+        FspDiagIdent(), GetCurrentThreadId(), Response->Hint, Name,
+        Response->IoStatus.Status, Response->IoStatus.Information);
+}
+
+FSP_API VOID FspDebugLogRequest(FSP_FSCTL_TRANSACT_REQ *Request)
+{
+    char CreationTimeBuf[32], LastAccessTimeBuf[32], LastWriteTimeBuf[32];
+    char *Sddl = 0;
+
+    switch (Request->Kind)
+    {
+    case FspFsctlTransactReservedKind:
+        FspDebugLogRequestVoid(Request, "RESERVED");
+        break;
+    case FspFsctlTransactCreateKind:
+        if (0 != Request->Req.Create.SecurityDescriptor.Offset)
+            ConvertSecurityDescriptorToStringSecurityDescriptorA(
+                Request->Buffer + Request->Req.Create.SecurityDescriptor.Offset,
+                SDDL_REVISION_1,
+                OWNER_SECURITY_INFORMATION | GROUP_SECURITY_INFORMATION |
+                DACL_SECURITY_INFORMATION | SACL_SECURITY_INFORMATION,
+                &Sddl, 0);
+        FspDebugLog("%S[TID=%ld]: %p: >>Create[%c%c%c%c] \"%S\", "
+            "%s, CreateOptions=%lx, FileAttributes=%lx, Security=%s%s%s, "
+            "AllocationSize=%lx:%lx, AccessToken=%lx, DesiredAccess=%lx, ShareAccess=%lx\n",
+            FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+            Request->Req.Create.UserMode ? 'U' : 'K',
+            Request->Req.Create.HasTraversePrivilege ? 'T' : '-',
+            Request->Req.Create.OpenTargetDirectory ? 'D' : '-',
+            Request->Req.Create.CaseSensitive ? 'C' : '-',
+            (PWSTR)Request->Buffer,
+            FspDebugLogDispositionString(Request->Req.Create.CreateOptions),
+            Request->Req.Create.CreateOptions & 0xffffff,
+            Request->Req.Create.FileAttributes,
+            Sddl ? "\"" : "",
+            Sddl ? Sddl : "NULL",
+            Sddl ? "\"" : "",
+            MAKE_UINT32_PAIR(Request->Req.Create.AllocationSize),
+            Request->Req.Create.AccessToken,
+            Request->Req.Create.DesiredAccess,
+            Request->Req.Create.ShareAccess);
+        LocalFree(Sddl);
+        break;
+    case FspFsctlTransactOverwriteKind:
+        FspDebugLog("%S[TID=%ld]: %p: >>Overwrite%s %s%S%s%p, %p, "
+            "FileAttributes=%lx\n",
+            FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+            Request->Req.Overwrite.Supersede ? " [Supersede]" : "",
+            Request->FileName.Size ? "\"" : "",
+            Request->FileName.Size ? (PWSTR)Request->Buffer : L"",
+            Request->FileName.Size ? "\", " : "",
+            (PVOID)Request->Req.Overwrite.UserContext,
+            (PVOID)Request->Req.Overwrite.UserContext2,
+            Request->Req.Overwrite.FileAttributes);
+        break;
+    case FspFsctlTransactCleanupKind:
+        FspDebugLog("%S[TID=%ld]: %p: >>Cleanup%s %s%S%s%p, %p\n",
+            FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+            Request->Req.Cleanup.Delete ? " [Delete]" : "",
+            Request->FileName.Size ? "\"" : "",
+            Request->FileName.Size ? (PWSTR)Request->Buffer : L"",
+            Request->FileName.Size ? "\", " : "",
+            (PVOID)Request->Req.Cleanup.UserContext,
+            (PVOID)Request->Req.Cleanup.UserContext2);
+        break;
+    case FspFsctlTransactCloseKind:
+        FspDebugLog("%S[TID=%ld]: %p: >>Close %s%S%s%p, %p\n",
+            FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+            Request->FileName.Size ? "\"" : "",
+            Request->FileName.Size ? (PWSTR)Request->Buffer : L"",
+            Request->FileName.Size ? "\", " : "",
+            (PVOID)Request->Req.Close.UserContext,
+            (PVOID)Request->Req.Close.UserContext2);
+        break;
+    case FspFsctlTransactReadKind:
+        FspDebugLog("%S[TID=%ld]: %p: >>Read %s%S%s%p, %p, "
+            "Address=%p, Offset=%lx:%lx, Length=%ld, Key=%lx\n",
+            FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+            Request->FileName.Size ? "\"" : "",
+            Request->FileName.Size ? (PWSTR)Request->Buffer : L"",
+            Request->FileName.Size ? "\", " : "",
+            (PVOID)Request->Req.Read.UserContext,
+            (PVOID)Request->Req.Read.UserContext2,
+            Request->Req.Read.Address,
+            MAKE_UINT32_PAIR(Request->Req.Read.Offset),
+            Request->Req.Read.Length,
+            Request->Req.Read.Key);
+        break;
+    case FspFsctlTransactWriteKind:
+        FspDebugLog("%S[TID=%ld]: %p: >>Write%s %s%S%s%p, %p, "
+            "Address=%p, Offset=%lx:%lx, Length=%ld, Key=%lx\n",
+            FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+            Request->Req.Write.ConstrainedIo ? " [C]" : "",
+            Request->FileName.Size ? "\"" : "",
+            Request->FileName.Size ? (PWSTR)Request->Buffer : L"",
+            Request->FileName.Size ? "\", " : "",
+            (PVOID)Request->Req.Write.UserContext,
+            (PVOID)Request->Req.Write.UserContext2,
+            Request->Req.Write.Address,
+            MAKE_UINT32_PAIR(Request->Req.Write.Offset),
+            Request->Req.Write.Length,
+            Request->Req.Write.Key);
+        break;
+    case FspFsctlTransactQueryInformationKind:
+        FspDebugLog("%S[TID=%ld]: %p: >>QueryInformation %s%S%s%p, %p\n",
+            FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+            Request->FileName.Size ? "\"" : "",
+            Request->FileName.Size ? (PWSTR)Request->Buffer : L"",
+            Request->FileName.Size ? "\", " : "",
+            (PVOID)Request->Req.QueryInformation.UserContext,
+            (PVOID)Request->Req.QueryInformation.UserContext2);
+        break;
+    case FspFsctlTransactSetInformationKind:
+        switch (Request->Req.SetInformation.FileInformationClass)
+        {
+        case 4/*FileBasicInformation*/:
+            FspDebugLog("%S[TID=%ld]: %p: >>SetInformation [Basic] %s%S%s%p, %p, "
+                "FileAttributes=%lx, CreationTime=%s, LastAccessTime=%s, LastWriteTime=%s\n",
+                FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+                Request->FileName.Size ? "\"" : "",
+                Request->FileName.Size ? (PWSTR)Request->Buffer : L"",
+                Request->FileName.Size ? "\", " : "",
+                (PVOID)Request->Req.SetInformation.UserContext,
+                (PVOID)Request->Req.SetInformation.UserContext2,
+                Request->Req.SetInformation.Info.Basic.FileAttributes,
+                FspDebugLogFileTimeString(Request->Req.SetInformation.Info.Basic.CreationTime,
+                    CreationTimeBuf),
+                FspDebugLogFileTimeString(Request->Req.SetInformation.Info.Basic.LastAccessTime,
+                    LastAccessTimeBuf),
+                FspDebugLogFileTimeString(Request->Req.SetInformation.Info.Basic.LastWriteTime,
+                    LastWriteTimeBuf));
+            break;
+        case 19/*FileAllocationInformation*/:
+            FspDebugLog("%S[TID=%ld]: %p: >>SetInformation [Allocation] %s%S%s%p, %p, "
+                "AllocationSize=%lx:%lx\n",
+                FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+                Request->FileName.Size ? "\"" : "",
+                Request->FileName.Size ? (PWSTR)Request->Buffer : L"",
+                Request->FileName.Size ? "\", " : "",
+                (PVOID)Request->Req.SetInformation.UserContext,
+                (PVOID)Request->Req.SetInformation.UserContext2,
+                MAKE_UINT32_PAIR(Request->Req.SetInformation.Info.Allocation.AllocationSize));
+            break;
+        case 20/*FileEndOfFileInformation*/:
+            FspDebugLog("%S[TID=%ld]: %p: >>SetInformation [EndOfFile] %s%S%s%p, %p, "
+                "FileSize = %lx:%lx\n",
+                FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+                Request->FileName.Size ? "\"" : "",
+                Request->FileName.Size ? (PWSTR)Request->Buffer : L"",
+                Request->FileName.Size ? "\", " : "",
+                (PVOID)Request->Req.SetInformation.UserContext,
+                (PVOID)Request->Req.SetInformation.UserContext2,
+                MAKE_UINT32_PAIR(Request->Req.SetInformation.Info.EndOfFile.FileSize));
+            break;
+        case 13/*FileDispositionInformation*/:
+            FspDebugLog("%S[TID=%ld]: %p: >>SetInformation [Disposition] %s%S%s%p, %p, "
+                "%s\n",
+                FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+                Request->FileName.Size ? "\"" : "",
+                Request->FileName.Size ? (PWSTR)Request->Buffer : L"",
+                Request->FileName.Size ? "\", " : "",
+                (PVOID)Request->Req.SetInformation.UserContext,
+                (PVOID)Request->Req.SetInformation.UserContext2,
+                Request->Req.SetInformation.Info.Disposition.Delete ? "Delete" : "Undelete");
+            break;
+        case 10/*FileRenameInformation*/:
+            FspDebugLog("%S[TID=%ld]: %p: >>SetInformation [Rename] %s%S%s%p, %p, "
+                "NewFileName=\"%S\"%s\n",
+                FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+                Request->FileName.Size ? "\"" : "",
+                Request->FileName.Size ? (PWSTR)Request->Buffer : L"",
+                Request->FileName.Size ? "\", " : "",
+                (PVOID)Request->Req.SetInformation.UserContext,
+                (PVOID)Request->Req.SetInformation.UserContext2,
+                (PWSTR)(Request->Buffer + Request->Req.SetInformation.Info.Rename.NewFileName.Offset),
+                Request->Req.SetInformation.Info.Rename.ReplaceIfExists ? " ReplaceIfExists" : "");
+            break;
+        default:
+            FspDebugLog("%S[TID=%ld]: %p: >>SetInformation [INVALID] %s%S%s%p, %p\n",
+                FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+                Request->FileName.Size ? "\"" : "",
+                Request->FileName.Size ? (PWSTR)Request->Buffer : L"",
+                Request->FileName.Size ? "\", " : "",
+                (PVOID)Request->Req.SetInformation.UserContext,
+                (PVOID)Request->Req.SetInformation.UserContext2);
+        }
+        break;
+    case FspFsctlTransactQueryEaKind:
+        FspDebugLogRequestVoid(Request, "QUERYEA");
+        break;
+    case FspFsctlTransactSetEaKind:
+        FspDebugLogRequestVoid(Request, "SETEA");
+        break;
+    case FspFsctlTransactFlushBuffersKind:
+        FspDebugLog("%S[TID=%ld]: %p: >>FlushBuffers %s%S%s%p, %p\n",
+            FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+            Request->FileName.Size ? "\"" : "",
+            Request->FileName.Size ? (PWSTR)Request->Buffer : L"",
+            Request->FileName.Size ? "\", " : "",
+            (PVOID)Request->Req.FlushBuffers.UserContext,
+            (PVOID)Request->Req.FlushBuffers.UserContext2);
+        break;
+    case FspFsctlTransactQueryVolumeInformationKind:
+        FspDebugLogRequestVoid(Request, "QueryVolumeInformation");
+        break;
+    case FspFsctlTransactSetVolumeInformationKind:
+        switch (Request->Req.SetVolumeInformation.FsInformationClass)
+        {
+        case 2/*FileFsLabelInformation*/:
+            FspDebugLog("%S[TID=%ld]: %p: >>SetVolumeInformation [FsLabel] "
+                "Label=\"%S\"\n",
+                FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+                (PWSTR)Request->Buffer);
+            break;
+        default:
+            FspDebugLog("%S[TID=%ld]: %p: >>SetVolumeInformation [INVALID]\n",
+                FspDiagIdent(), GetCurrentThreadId(), Request->Hint);
+            break;
+        }
+        break;
+    case FspFsctlTransactQueryDirectoryKind:
+        FspDebugLog("%S[TID=%ld]: %p: >>QueryDirectory %s%S%s%p, %p, "
+            "Address=%p, Offset=%lx:%lx, Length=%ld, Pattern=%s%S%s\n",
+            FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+            Request->FileName.Size ? "\"" : "",
+            Request->FileName.Size ? (PWSTR)Request->Buffer : L"",
+            Request->FileName.Size ? "\", " : "",
+            (PVOID)Request->Req.QueryDirectory.UserContext,
+            (PVOID)Request->Req.QueryDirectory.UserContext2,
+            Request->Req.QueryDirectory.Address,
+            MAKE_UINT32_PAIR(Request->Req.QueryDirectory.Offset),
+            Request->Req.QueryDirectory.Length,
+            Request->Req.QueryDirectory.Pattern.Size ? "\"" : "",
+            Request->Req.QueryDirectory.Pattern.Size ?
+                (PWSTR)(Request->Buffer + Request->Req.QueryDirectory.Pattern.Offset) : L"NULL",
+            Request->Req.QueryDirectory.Pattern.Size ? "\"" : "");
+        break;
+    case FspFsctlTransactFileSystemControlKind:
+        FspDebugLogRequestVoid(Request, "FILESYSTEMCONTROL");
+        break;
+    case FspFsctlTransactDeviceControlKind:
+        FspDebugLogRequestVoid(Request, "DEVICECONTROL");
+        break;
+    case FspFsctlTransactShutdownKind:
+        FspDebugLogRequestVoid(Request, "SHUTDOWN");
+        break;
+    case FspFsctlTransactLockControlKind:
+        FspDebugLogRequestVoid(Request, "LOCKCONTROL");
+        break;
+    case FspFsctlTransactQuerySecurityKind:
+        FspDebugLog("%S[TID=%ld]: %p: >>QuerySecurity %s%S%s%p, %p\n",
+            FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+            Request->FileName.Size ? "\"" : "",
+            Request->FileName.Size ? (PWSTR)Request->Buffer : L"",
+            Request->FileName.Size ? "\", " : "",
+            (PVOID)Request->Req.QuerySecurity.UserContext,
+            (PVOID)Request->Req.QuerySecurity.UserContext2);
+        break;
+    case FspFsctlTransactSetSecurityKind:
+        if (0 != Request->Req.SetSecurity.SecurityDescriptor.Size)
+            ConvertSecurityDescriptorToStringSecurityDescriptorA(
+                Request->Buffer + Request->Req.SetSecurity.SecurityDescriptor.Offset,
+                SDDL_REVISION_1,
+                OWNER_SECURITY_INFORMATION | GROUP_SECURITY_INFORMATION |
+                DACL_SECURITY_INFORMATION | SACL_SECURITY_INFORMATION,
+                &Sddl, 0);
+        FspDebugLog("%S[TID=%ld]: %p: >>SetSecurity %s%S%s%p, %p, "
+            "SecurityInformation=%lx, AccessToken=%lx, Security=%s%s%s\n",
+            FspDiagIdent(), GetCurrentThreadId(), Request->Hint,
+            Request->FileName.Size ? "\"" : "",
+            Request->FileName.Size ? (PWSTR)Request->Buffer : L"",
+            Request->FileName.Size ? "\", " : "",
+            (PVOID)Request->Req.SetSecurity.UserContext,
+            (PVOID)Request->Req.SetSecurity.UserContext2,
+            Request->Req.SetSecurity.SecurityInformation,
+            Request->Req.SetSecurity.AccessToken,
+            Sddl ? "\"" : "",
+            Sddl ? Sddl : "NULL",
+            Sddl ? "\"" : "");
+        LocalFree(Sddl);
+        break;
+    default:
+        FspDebugLogRequestVoid(Request, "INVALID");
+        break;
+    }
+}
+
+FSP_API VOID FspDebugLogResponse(FSP_FSCTL_TRANSACT_RSP *Response)
+{
+    if (STATUS_PENDING == Response->IoStatus.Status)
+        return;
+
+    char InfoBuf[256];
+    char *Sddl = 0;
+
+    switch (Response->Kind)
+    {
+    case FspFsctlTransactReservedKind:
+        FspDebugLogResponseStatus(Response, "RESERVED");
+        break;
+    case FspFsctlTransactCreateKind:
+        if (!NT_SUCCESS(Response->IoStatus.Status))
+            FspDebugLogResponseStatus(Response, "Create");
+        else if (STATUS_REPARSE == Response->IoStatus.Status)
+            FspDebugLog("%S[TID=%ld]: %p: <<Create IoStatus=%lx[%ld] "
+                "Reparse.FileName=\"%S\"\n",
+                FspDiagIdent(), GetCurrentThreadId(), Response->Hint,
+                Response->IoStatus.Status, Response->IoStatus.Information,
+                (PWSTR)(Response->Buffer + Response->Rsp.Create.Reparse.FileName.Offset));
+        else
+            FspDebugLog("%S[TID=%ld]: %p: <<Create IoStatus=%lx[%ld] "
+                "%p, %p, GrantedAccess=%lx, FileInfo=%s\n",
+                FspDiagIdent(), GetCurrentThreadId(), Response->Hint,
+                Response->IoStatus.Status, Response->IoStatus.Information,
+                (PVOID)Response->Rsp.Create.Opened.UserContext,
+                (PVOID)Response->Rsp.Create.Opened.UserContext2,
+                Response->Rsp.Create.Opened.GrantedAccess,
+                FspDebugLogFileInfoString(&Response->Rsp.Create.Opened.FileInfo, InfoBuf));
+        break;
+    case FspFsctlTransactOverwriteKind:
+        if (!NT_SUCCESS(Response->IoStatus.Status))
+            FspDebugLogResponseStatus(Response, "Overwrite");
+        else
+            FspDebugLog("%S[TID=%ld]: %p: <<Overwrite IoStatus=%lx[%ld] "
+                "FileInfo=%s\n",
+                FspDiagIdent(), GetCurrentThreadId(), Response->Hint,
+                Response->IoStatus.Status, Response->IoStatus.Information,
+                FspDebugLogFileInfoString(&Response->Rsp.Overwrite.FileInfo, InfoBuf));
+        break;
+    case FspFsctlTransactCleanupKind:
+        FspDebugLogResponseStatus(Response, "Cleanup");
+        break;
+    case FspFsctlTransactCloseKind:
+        FspDebugLogResponseStatus(Response, "Close");
+        break;
+    case FspFsctlTransactReadKind:
+        FspDebugLogResponseStatus(Response, "Read");
+        break;
+    case FspFsctlTransactWriteKind:
+        if (!NT_SUCCESS(Response->IoStatus.Status))
+            FspDebugLogResponseStatus(Response, "Write");
+        else
+            FspDebugLog("%S[TID=%ld]: %p: <<Write IoStatus=%lx[%ld] "
+                "FileInfo=%s\n",
+                FspDiagIdent(), GetCurrentThreadId(), Response->Hint,
+                Response->IoStatus.Status, Response->IoStatus.Information,
+                FspDebugLogFileInfoString(&Response->Rsp.Write.FileInfo, InfoBuf));
+        break;
+    case FspFsctlTransactQueryInformationKind:
+        if (!NT_SUCCESS(Response->IoStatus.Status))
+            FspDebugLogResponseStatus(Response, "QueryInformation");
+        else
+            FspDebugLog("%S[TID=%ld]: %p: <<QueryInformation IoStatus=%lx[%ld] "
+                "FileInfo=%s\n",
+                FspDiagIdent(), GetCurrentThreadId(), Response->Hint,
+                Response->IoStatus.Status, Response->IoStatus.Information,
+                FspDebugLogFileInfoString(&Response->Rsp.QueryInformation.FileInfo, InfoBuf));
+        break;
+    case FspFsctlTransactSetInformationKind:
+        if (!NT_SUCCESS(Response->IoStatus.Status))
+            FspDebugLogResponseStatus(Response, "SetInformation");
+        else
+            FspDebugLog("%S[TID=%ld]: %p: <<SetInformation IoStatus=%lx[%ld] "
+                "FileInfo=%s\n",
+                FspDiagIdent(), GetCurrentThreadId(), Response->Hint,
+                Response->IoStatus.Status, Response->IoStatus.Information,
+                FspDebugLogFileInfoString(&Response->Rsp.SetInformation.FileInfo, InfoBuf));
+        break;
+    case FspFsctlTransactQueryEaKind:
+        FspDebugLogResponseStatus(Response, "QUERYEA");
+        break;
+    case FspFsctlTransactSetEaKind:
+        FspDebugLogResponseStatus(Response, "SETEA");
+        break;
+    case FspFsctlTransactFlushBuffersKind:
+        FspDebugLogResponseStatus(Response, "FlushBuffers");
+        break;
+    case FspFsctlTransactQueryVolumeInformationKind:
+        if (!NT_SUCCESS(Response->IoStatus.Status))
+            FspDebugLogResponseStatus(Response, "QueryVolumeInformation");
+        else
+            FspDebugLog("%S[TID=%ld]: %p: <<QueryVolumeInformation IoStatus=%lx[%ld] "
+                "VolumeInfo=%s\n",
+                FspDiagIdent(), GetCurrentThreadId(), Response->Hint,
+                Response->IoStatus.Status, Response->IoStatus.Information,
+                FspDebugLogVolumeInfoString(&Response->Rsp.QueryVolumeInformation.VolumeInfo, InfoBuf));
+        break;
+    case FspFsctlTransactSetVolumeInformationKind:
+        if (!NT_SUCCESS(Response->IoStatus.Status))
+            FspDebugLogResponseStatus(Response, "SetVolumeInformation");
+        else
+            FspDebugLog("%S[TID=%ld]: %p: <<SetVolumeInformation IoStatus=%lx[%ld] "
+                "VolumeInfo=%s\n",
+                FspDiagIdent(), GetCurrentThreadId(), Response->Hint,
+                Response->IoStatus.Status, Response->IoStatus.Information,
+                FspDebugLogVolumeInfoString(&Response->Rsp.SetVolumeInformation.VolumeInfo, InfoBuf));
+        break;
+    case FspFsctlTransactQueryDirectoryKind:
+        FspDebugLogResponseStatus(Response, "QueryDirectory");
+        break;
+    case FspFsctlTransactFileSystemControlKind:
+        FspDebugLogResponseStatus(Response, "FILESYSTEMCONTROL");
+        break;
+    case FspFsctlTransactDeviceControlKind:
+        FspDebugLogResponseStatus(Response, "DEVICECONTROL");
+        break;
+    case FspFsctlTransactShutdownKind:
+        FspDebugLogResponseStatus(Response, "SHUTDOWN");
+        break;
+    case FspFsctlTransactLockControlKind:
+        FspDebugLogResponseStatus(Response, "LOCKCONTROL");
+        break;
+    case FspFsctlTransactQuerySecurityKind:
+        if (!NT_SUCCESS(Response->IoStatus.Status))
+            FspDebugLogResponseStatus(Response, "QuerySecurity");
+        else
+        {
+            if (0 != Response->Rsp.QuerySecurity.SecurityDescriptor.Size)
+                ConvertSecurityDescriptorToStringSecurityDescriptorA(
+                    Response->Buffer + Response->Rsp.QuerySecurity.SecurityDescriptor.Offset,
+                    SDDL_REVISION_1,
+                    OWNER_SECURITY_INFORMATION | GROUP_SECURITY_INFORMATION |
+                    DACL_SECURITY_INFORMATION | SACL_SECURITY_INFORMATION,
+                    &Sddl, 0);
+            FspDebugLog("%S[TID=%ld]: %p: <<QuerySecurity IoStatus=%lx[%ld] "
+                "Security=%s%s%s\n",
+                FspDiagIdent(), GetCurrentThreadId(), Response->Hint,
+                Response->IoStatus.Status, Response->IoStatus.Information,
+                Sddl ? "\"" : "",
+                Sddl ? Sddl : "NULL",
+                Sddl ? "\"" : "");
+            LocalFree(Sddl);
+        }
+        break;
+    case FspFsctlTransactSetSecurityKind:
+        if (!NT_SUCCESS(Response->IoStatus.Status))
+            FspDebugLogResponseStatus(Response, "SetSecurity");
+        else
+        {
+            if (0 != Response->Rsp.SetSecurity.SecurityDescriptor.Size)
+                ConvertSecurityDescriptorToStringSecurityDescriptorA(
+                    Response->Buffer + Response->Rsp.SetSecurity.SecurityDescriptor.Offset,
+                    SDDL_REVISION_1,
+                    OWNER_SECURITY_INFORMATION | GROUP_SECURITY_INFORMATION |
+                    DACL_SECURITY_INFORMATION | SACL_SECURITY_INFORMATION,
+                    &Sddl, 0);
+            FspDebugLog("%S[TID=%ld]: %p: <<SetSecurity IoStatus=%lx[%ld] "
+                "Security=%s%s%s\n",
+                FspDiagIdent(), GetCurrentThreadId(), Response->Hint,
+                Response->IoStatus.Status, Response->IoStatus.Information,
+                Sddl ? "\"" : "",
+                Sddl ? Sddl : "NULL",
+                Sddl ? "\"" : "");
+            LocalFree(Sddl);
+        }
+        break;
+    default:
+        FspDebugLogResponseStatus(Response, "INVALID");
+        break;
+    }
+}

src/dll/fs.c

@@ -267,10 +267,12 @@ static DWORD WINAPI FspFileSystemDispatcherThread(PVOID FileSystem0)
         if (0 == RequestSize)
             continue;
 
-#if 0
+        if (FileSystem->DebugLog)
-        FspDebugLog("FspFileSystemDispatcherThread: TID=%ld, Request={Kind=%d, Hint=%p}\n",
+        {
-            GetCurrentThreadId(), Request->Kind, (PVOID)Request->Hint);
+            if (FspFsctlTransactKindCount <= Request->Kind ||
-#endif
+                (FileSystem->DebugLog & (1 << Request->Kind)))
+                FspDebugLogRequest(Request);
+        }
 
         Response->Size = sizeof *Response;
         Response->Kind = Request->Kind;
@@ -285,6 +287,13 @@ static DWORD WINAPI FspFileSystemDispatcherThread(PVOID FileSystem0)
         else
             Response->IoStatus.Status = STATUS_INVALID_DEVICE_REQUEST;
 
+        if (FileSystem->DebugLog)
+        {
+            if (FspFsctlTransactKindCount <= Response->Kind ||
+                (FileSystem->DebugLog & (1 << Response->Kind)))
+                FspDebugLogResponse(Response);
+        }
+
         ResponseSize = FSP_FSCTL_DEFAULT_ALIGN_UP(Response->Size);
         if (FSP_FSCTL_TRANSACT_RSP_SIZEMAX < ResponseSize/* should NOT happen */)
         {
@@ -364,6 +373,13 @@ FSP_API VOID FspFileSystemSendResponse(FSP_FILE_SYSTEM *FileSystem,
 {
     NTSTATUS Result;
 
+    if (FileSystem->DebugLog)
+    {
+        if (FspFsctlTransactKindCount <= Response->Kind ||
+            (FileSystem->DebugLog & (1 << Response->Kind)))
+            FspDebugLogResponse(Response);
+    }
+
     Result = FspFsctlTransact(FileSystem->VolumeHandle,
         Response, Response->Size, 0, 0, FALSE);
     if (!NT_SUCCESS(Result))

src/dll/fsop.c

@@ -617,6 +617,7 @@ FSP_API NTSTATUS FspFileSystemOpSetVolumeInformation(FSP_FILE_SYSTEM *FileSystem
             Result = FileSystem->Interface->SetVolumeLabel(FileSystem, Request,
                 (PWSTR)Request->Buffer,
                 &VolumeInfo);
+        break;
     }
 
     if (!NT_SUCCESS(Result))

src/dll/library.h

@@ -52,4 +52,6 @@ NTSTATUS FspNpUnregister(VOID);
 NTSTATUS FspEventLogRegister(VOID);
 NTSTATUS FspEventLogUnregister(VOID);
 
+PWSTR FspDiagIdent(VOID);
+
 #endif

src/dll/np.c

@@ -17,117 +17,11 @@
 
 #include <dll/library.h>
 #include <launcher/launcher.h>
-#include <aclapi.h>
 #include <npapi.h>
 
 #define FSP_NP_NAME                     LIBRARY_NAME ".Np"
 #define FSP_NP_TYPE                     ' spF'  /* pick a value hopefully not in use */
 
-FSP_API NTSTATUS FspCallNamedPipeSecurely(PWSTR PipeName,
-    PVOID InBuffer, ULONG InBufferSize, PVOID OutBuffer, ULONG OutBufferSize,
-    PULONG PBytesTransferred, ULONG Timeout,
-    PSID Sid)
-{
-    NTSTATUS Result;
-    HANDLE Pipe = INVALID_HANDLE_VALUE;
-    DWORD PipeMode;
-
-    Pipe = CreateFileW(PipeName,
-        GENERIC_READ | FILE_WRITE_DATA | FILE_WRITE_ATTRIBUTES,
-        FILE_SHARE_READ | FILE_SHARE_WRITE, 0, OPEN_EXISTING,
-        SECURITY_SQOS_PRESENT | SECURITY_IDENTIFICATION, 0);
-    if (INVALID_HANDLE_VALUE == Pipe)
-    {
-        if (ERROR_PIPE_BUSY != GetLastError())
-        {
-            Result = FspNtStatusFromWin32(GetLastError());
-            goto exit;
-        }
-
-        WaitNamedPipeW(PipeName, Timeout);
-
-        Pipe = CreateFileW(PipeName,
-            GENERIC_READ | FILE_WRITE_DATA | FILE_WRITE_ATTRIBUTES,
-            FILE_SHARE_READ | FILE_SHARE_WRITE, 0, OPEN_EXISTING,
-            SECURITY_SQOS_PRESENT | SECURITY_IDENTIFICATION, 0);
-        if (INVALID_HANDLE_VALUE == Pipe)
-        {
-            Result = FspNtStatusFromWin32(GetLastError());
-            goto exit;
-        }
-    }
-
-    if (0 != Sid)
-    {
-        PSECURITY_DESCRIPTOR SecurityDescriptor = 0;
-        PSID OwnerSid, WellKnownSid = 0;
-        DWORD SidSize, LastError;
-
-        /* if it is a small number treat it like a well known SID */
-        if (1024 > (INT_PTR)Sid)
-        {
-            SidSize = SECURITY_MAX_SID_SIZE;
-            WellKnownSid = MemAlloc(SidSize);
-            if (0 == WellKnownSid)
-            {
-                Result = STATUS_INSUFFICIENT_RESOURCES;
-                goto sid_exit;
-            }
-
-            if (!CreateWellKnownSid((INT_PTR)Sid, 0, WellKnownSid, &SidSize))
-            {
-                Result = FspNtStatusFromWin32(GetLastError());
-                goto sid_exit;
-            }
-        }
-
-        LastError = GetSecurityInfo(Pipe, SE_FILE_OBJECT,
-            OWNER_SECURITY_INFORMATION, &OwnerSid, 0, 0, 0, &SecurityDescriptor);
-        if (0 != LastError)
-        {
-            Result = FspNtStatusFromWin32(GetLastError());
-            goto sid_exit;
-        }
-
-        if (!EqualSid(OwnerSid, WellKnownSid ? WellKnownSid : Sid))
-        {
-            Result = STATUS_ACCESS_DENIED;
-            goto sid_exit;
-        }
-
-        Result = STATUS_SUCCESS;
-
-    sid_exit:
-        MemFree(WellKnownSid);
-        LocalFree(SecurityDescriptor);
-
-        if (!NT_SUCCESS(Result))
-            goto exit;
-    }
-
-    PipeMode = PIPE_READMODE_MESSAGE | PIPE_WAIT;
-    if (!SetNamedPipeHandleState(Pipe, &PipeMode, 0, 0))
-    {
-        Result = FspNtStatusFromWin32(GetLastError());
-        goto exit;
-    }
-
-    if (!TransactNamedPipe(Pipe, InBuffer, InBufferSize, OutBuffer, OutBufferSize,
-        PBytesTransferred, 0))
-    {
-        Result = FspNtStatusFromWin32(GetLastError());
-        goto exit;
-    }
-
-    Result = STATUS_SUCCESS;
-
-exit:
-    if (INVALID_HANDLE_VALUE != Pipe)
-        CloseHandle(Pipe);
-
-    return Result;
-}
-
 DWORD APIENTRY NPGetCaps(DWORD Index)
 {
     switch (Index)

src/dll/util.c

@@ -0,0 +1,165 @@
+/**
+ * @file dll/util.c
+ *
+ * @copyright 2015-2016 Bill Zissimopoulos
+ */
+/*
+ * This file is part of WinFsp.
+ *
+ * You can redistribute it and/or modify it under the terms of the
+ * GNU Affero General Public License version 3 as published by the
+ * Free Software Foundation.
+ *
+ * Licensees holding a valid commercial license may use this file in
+ * accordance with the commercial license agreement provided with the
+ * software.
+ */
+
+#include <dll/library.h>
+#include <aclapi.h>
+
+static INIT_ONCE FspDiagIdentInitOnce = INIT_ONCE_STATIC_INIT;
+static WCHAR FspDiagIdentBuf[16] = L"UNKNOWN";
+
+static BOOL WINAPI FspDiagIdentInit(
+    PINIT_ONCE InitOnce, PVOID Parameter, PVOID *Context)
+{
+    WCHAR ModuleFileName[MAX_PATH];
+    WCHAR Root[2] = L"\\";
+    PWSTR Parent, ModuleBaseName;
+
+    if (0 != GetModuleFileNameW(0, ModuleFileName, sizeof ModuleFileName / sizeof(WCHAR)))
+        FspPathSuffix(ModuleFileName, &Parent, &ModuleBaseName, Root);
+    else
+        lstrcpyW(ModuleBaseName = ModuleFileName, L"UNKNOWN");
+
+    for (PWSTR P = ModuleBaseName, Dot = 0;; P++)
+    {
+        if (L'\0' == *P)
+        {
+            if (0 != Dot)
+                *Dot = L'\0';
+            break;
+        }
+        if (L'.' == *P)
+            Dot = P;
+    }
+
+    memcpy(FspDiagIdentBuf, ModuleBaseName, sizeof FspDiagIdentBuf);
+    FspDiagIdentBuf[(sizeof FspDiagIdentBuf / sizeof(WCHAR)) - 1] = L'\0';
+
+    return TRUE;
+}
+
+PWSTR FspDiagIdent(VOID)
+{
+    /* internal only: get a diagnostic identifier (eventlog, debug) */
+
+    InitOnceExecuteOnce(&FspDiagIdentInitOnce, FspDiagIdentInit, 0, 0);
+    return FspDiagIdentBuf;
+}
+
+FSP_API NTSTATUS FspCallNamedPipeSecurely(PWSTR PipeName,
+    PVOID InBuffer, ULONG InBufferSize, PVOID OutBuffer, ULONG OutBufferSize,
+    PULONG PBytesTransferred, ULONG Timeout,
+    PSID Sid)
+{
+    NTSTATUS Result;
+    HANDLE Pipe = INVALID_HANDLE_VALUE;
+    DWORD PipeMode;
+
+    Pipe = CreateFileW(PipeName,
+        GENERIC_READ | FILE_WRITE_DATA | FILE_WRITE_ATTRIBUTES,
+        FILE_SHARE_READ | FILE_SHARE_WRITE, 0, OPEN_EXISTING,
+        SECURITY_SQOS_PRESENT | SECURITY_IDENTIFICATION, 0);
+    if (INVALID_HANDLE_VALUE == Pipe)
+    {
+        if (ERROR_PIPE_BUSY != GetLastError())
+        {
+            Result = FspNtStatusFromWin32(GetLastError());
+            goto exit;
+        }
+
+        WaitNamedPipeW(PipeName, Timeout);
+
+        Pipe = CreateFileW(PipeName,
+            GENERIC_READ | FILE_WRITE_DATA | FILE_WRITE_ATTRIBUTES,
+            FILE_SHARE_READ | FILE_SHARE_WRITE, 0, OPEN_EXISTING,
+            SECURITY_SQOS_PRESENT | SECURITY_IDENTIFICATION, 0);
+        if (INVALID_HANDLE_VALUE == Pipe)
+        {
+            Result = FspNtStatusFromWin32(GetLastError());
+            goto exit;
+        }
+    }
+
+    if (0 != Sid)
+    {
+        PSECURITY_DESCRIPTOR SecurityDescriptor = 0;
+        PSID OwnerSid, WellKnownSid = 0;
+        DWORD SidSize, LastError;
+
+        /* if it is a small number treat it like a well known SID */
+        if (1024 > (INT_PTR)Sid)
+        {
+            SidSize = SECURITY_MAX_SID_SIZE;
+            WellKnownSid = MemAlloc(SidSize);
+            if (0 == WellKnownSid)
+            {
+                Result = STATUS_INSUFFICIENT_RESOURCES;
+                goto sid_exit;
+            }
+
+            if (!CreateWellKnownSid((INT_PTR)Sid, 0, WellKnownSid, &SidSize))
+            {
+                Result = FspNtStatusFromWin32(GetLastError());
+                goto sid_exit;
+            }
+        }
+
+        LastError = GetSecurityInfo(Pipe, SE_FILE_OBJECT,
+            OWNER_SECURITY_INFORMATION, &OwnerSid, 0, 0, 0, &SecurityDescriptor);
+        if (0 != LastError)
+        {
+            Result = FspNtStatusFromWin32(GetLastError());
+            goto sid_exit;
+        }
+
+        if (!EqualSid(OwnerSid, WellKnownSid ? WellKnownSid : Sid))
+        {
+            Result = STATUS_ACCESS_DENIED;
+            goto sid_exit;
+        }
+
+        Result = STATUS_SUCCESS;
+
+    sid_exit:
+        MemFree(WellKnownSid);
+        LocalFree(SecurityDescriptor);
+
+        if (!NT_SUCCESS(Result))
+            goto exit;
+    }
+
+    PipeMode = PIPE_READMODE_MESSAGE | PIPE_WAIT;
+    if (!SetNamedPipeHandleState(Pipe, &PipeMode, 0, 0))
+    {
+        Result = FspNtStatusFromWin32(GetLastError());
+        goto exit;
+    }
+
+    if (!TransactNamedPipe(Pipe, InBuffer, InBufferSize, OutBuffer, OutBufferSize,
+        PBytesTransferred, 0))
+    {
+        Result = FspNtStatusFromWin32(GetLastError());
+        goto exit;
+    }
+
+    Result = STATUS_SUCCESS;
+
+exit:
+    if (INVALID_HANDLE_VALUE != Pipe)
+        CloseHandle(Pipe);
+
+    return Result;
+}