Add ability to print debug logs to a file (#954)

src/AspNetCoreModuleV2/AspNetCore/src/dllmain.cpp

@@ -36,6 +36,8 @@ StaticCleanup()
         DeregisterEventSource(g_hEventLog);
         g_hEventLog = NULL;
     }
+
+    DebugStop();
 }
 
 BOOL WINAPI DllMain(HMODULE hModule,
@@ -50,6 +52,7 @@ BOOL WINAPI DllMain(HMODULE hModule,
     case DLL_PROCESS_ATTACH:
         g_hModule = hModule;
         DisableThreadLibraryCalls(hModule);
+        DebugInitialize();
         break;
     case DLL_PROCESS_DETACH:
         // IIS can cause dll detach to occur before we receive global notifications
@@ -141,8 +144,6 @@ HRESULT
         RegCloseKey(hKey);
     }
 
-    DebugInitialize();
-
     if (fDisableANCM)
     {
         // Logging

src/AspNetCoreModuleV2/CommonLib/CommonLib.vcxproj

@@ -194,6 +194,7 @@
   <ItemGroup>
     <ClInclude Include="application.h" />
     <ClInclude Include="config_utility.h" />
+    <ClInclude Include="Environment.h" />
     <ClInclude Include="exceptions.h" />
     <ClInclude Include="GlobalVersionUtility.h" />
     <ClInclude Include="fx_ver.h" />
@@ -214,6 +215,7 @@
   </ItemGroup>
   <ItemGroup>
     <ClCompile Include="debugutil.cpp" />
+    <ClCompile Include="Environment.cpp" />
     <ClCompile Include="fx_ver.cxx" />
     <ClCompile Include="GlobalVersionUtility.cpp" />
     <ClCompile Include="HandleWrapper.cpp" />

src/AspNetCoreModuleV2/CommonLib/Environment.cpp

@@ -0,0 +1,32 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+#include "Environment.h"
+
+#include <Windows.h>
+
+std::wstring
+Environment::ExpandEnvironmentVariables(const std::wstring & str)
+{
+    DWORD requestedSize = ExpandEnvironmentStringsW(str.c_str(), nullptr, 0);
+    if (requestedSize == 0)
+    {
+        throw std::system_error(GetLastError(), std::system_category(), "ExpandEnvironmentVariables");
+    }
+
+    std::wstring expandedStr;
+    do
+    {
+        expandedStr.resize(requestedSize);
+        requestedSize = ExpandEnvironmentStringsW(str.c_str(), &expandedStr[0], requestedSize);
+        if (requestedSize == 0)
+        {
+            throw std::system_error(GetLastError(), std::system_category(), "ExpandEnvironmentVariables");
+        }
+    } while (expandedStr.size() != requestedSize);
+
+    // trim null character as ExpandEnvironmentStringsW returns size including null character
+    expandedStr.resize(requestedSize - 1);
+
+    return expandedStr;
+}

src/AspNetCoreModuleV2/CommonLib/Environment.h

@@ -0,0 +1,17 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+#pragma once
+
+#include <string>
+
+class Environment
+{
+public:
+    Environment() = delete;
+    ~Environment() = delete;
+
+    static
+    std::wstring ExpandEnvironmentVariables(const std::wstring & str);
+};
+

src/AspNetCoreModuleV2/CommonLib/debugutil.cpp

@@ -7,8 +7,13 @@
 #include "dbgutil.h"
 #include "stringu.h"
 #include "stringa.h"
+#include "dbgutil.h"
+#include "Environment.h"
+#include "SRWExclusiveLock.h"
 
 inline HANDLE g_hStandardOutput;
+inline HANDLE g_logFile;
+inline SRWLOCK g_logFileLock;
 
 VOID
 DebugInitialize()
@@ -46,21 +51,55 @@ DebugInitialize()
     const size_t environmentVariableValueSize = 2;
     std::wstring environmentVariableValue(environmentVariableValueSize, '\0');
 
-    if (GetEnvironmentVariable(L"ASPNETCORE_MODULE_DEBUG", environmentVariableValue.data(), environmentVariableValueSize) == environmentVariableValueSize - 1)
+    try
     {
-        try
+        const auto value = std::stoi(Environment::ExpandEnvironmentVariables(L"%ASPNETCORE_MODULE_DEBUG%"));
-        {
-            const auto value = std::stoi(environmentVariableValue);
 
-            if (value >= 1) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_ERROR;
+        if (value >= 1) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_ERROR;
-            if (value >= 2) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_WARNING;
+        if (value >= 2) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_WARNING;
-            if (value >= 3) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_INFO;
+        if (value >= 3) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_INFO;
-            if (value >= 4) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_CONSOLE;
+        if (value >= 4) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_CONSOLE;
-        }
+    }
-        catch (...)
+    catch (...)
+    {
+        // ignore
+    }
+
+    try
+    {
+        const auto debugOutputFile = Environment::ExpandEnvironmentVariables(L"%ASPNETCORE_MODULE_DEBUG_FILE%");
+
+        if (!debugOutputFile.empty())
         {
-            // ignore
+            g_logFile = CreateFileW(debugOutputFile.c_str(),
+                FILE_GENERIC_WRITE,
+                FILE_SHARE_READ | FILE_SHARE_WRITE,
+                nullptr,
+                OPEN_ALWAYS,
+                FILE_ATTRIBUTE_NORMAL,
+                nullptr
+            );
+
+            if (g_logFile != INVALID_HANDLE_VALUE)
+            {
+                InitializeSRWLock(&g_logFileLock);
+                DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_FILE;
+            }
         }
+
+    }
+    catch (...)
+    {
+        // ignore
+    }
+}
+
+VOID
+DebugStop()
+{
+    if (IsEnabled(ASPNETCORE_DEBUG_FLAG_FILE))
+    {
+        CloseHandle(g_logFile);
     }
 }
 
@@ -93,11 +132,19 @@ DebugPrint(
         }
 
         OutputDebugStringA( strOutput.QueryStr() );
+        DWORD nBytesWritten = 0;
 
         if (IsEnabled(ASPNETCORE_DEBUG_FLAG_CONSOLE))
         {
-            DWORD nBytesWritten = 0;
+            WriteFile(g_hStandardOutput, strOutput.QueryStr(), strOutput.QueryCB(), &nBytesWritten, nullptr);
-            WriteFile(g_hStandardOutput, strOutput.QueryStr(), strOutput.QueryCB(), &nBytesWritten, NULL);
+        }
+
+        if (IsEnabled(ASPNETCORE_DEBUG_FLAG_FILE))
+        {
+            SRWExclusiveLock lock(g_logFileLock);
+
+            SetFilePointer(g_logFile, 0, nullptr, FILE_END);
+            WriteFile(g_logFile, strOutput.QueryStr(), strOutput.QueryCB(), &nBytesWritten, nullptr);
         }
     }
 }

src/AspNetCoreModuleV2/CommonLib/debugutil.h

@@ -10,6 +10,7 @@
 #define ASPNETCORE_DEBUG_FLAG_WARNING       DEBUG_FLAG_WARN
 #define ASPNETCORE_DEBUG_FLAG_ERROR         DEBUG_FLAG_ERROR
 #define ASPNETCORE_DEBUG_FLAG_CONSOLE       0x00000008
+#define ASPNETCORE_DEBUG_FLAG_FILE          0x00000008
 
 #define LOG_INFO(...) DebugPrint(ASPNETCORE_DEBUG_FLAG_INFO, __VA_ARGS__)
 #define LOG_INFOF(...) DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, __VA_ARGS__)
@@ -26,6 +27,9 @@
 VOID
 DebugInitialize();
 
+VOID
+DebugStop();
+
 BOOL
 IsEnabled(
     DWORD   dwFlag

src/AspNetCoreModuleV2/CommonLib/hostfxr_utility.cpp

@@ -11,6 +11,7 @@
 #include "debugutil.h"
 #include "exceptions.h"
 #include "HandleWrapper.h"
+#include "Environment.h"
 
 namespace fs = std::experimental::filesystem;
 
@@ -124,8 +125,8 @@ HOSTFXR_UTILITY::GetHostFxrParameters(
         pcwzApplicationPhysicalPath);
 
     const fs::path applicationPhysicalPath = pcwzApplicationPhysicalPath;
-    fs::path processPath = ExpandEnvironmentVariables(pcwzProcessPath);
+    fs::path processPath = Environment::ExpandEnvironmentVariables(pcwzProcessPath);
-    std::wstring arguments = ExpandEnvironmentVariables(pcwzArguments);
+    std::wstring arguments = Environment::ExpandEnvironmentVariables(pcwzArguments);
 
     if (processPath.is_relative())
     {
@@ -595,7 +596,7 @@ HOSTFXR_UTILITY::InvokeWhereToFindDotnet()
 std::optional<fs::path>
 HOSTFXR_UTILITY::GetAbsolutePathToDotnetFromProgramFiles()
 {
-    const auto programFilesDotnet = fs::path(ExpandEnvironmentVariables(L"%ProgramFiles%")) / "dotnet" / "dotnet.exe";
+    const auto programFilesDotnet = fs::path(Environment::ExpandEnvironmentVariables(L"%ProgramFiles%")) / "dotnet" / "dotnet.exe";
     return is_regular_file(programFilesDotnet) ? std::make_optional(programFilesDotnet) : std::nullopt;
 }
 
@@ -640,29 +641,3 @@ HOSTFXR_UTILITY::FindDotNetFolders(
 
     FindClose(handle);
 }
-
-std::wstring
-HOSTFXR_UTILITY::ExpandEnvironmentVariables(const std::wstring & str)
-{
-    DWORD requestedSize = ExpandEnvironmentStringsW(str.c_str(), nullptr, 0);
-    if (requestedSize == 0)
-    {
-        throw std::system_error(GetLastError(), std::system_category(), "ExpandEnvironmentVariables");
-    }
-
-    std::wstring expandedStr;
-    do
-    {
-        expandedStr.resize(requestedSize);
-        requestedSize = ExpandEnvironmentStringsW(str.c_str(), &expandedStr[0], requestedSize);
-        if (requestedSize == 0)
-        {
-            throw std::system_error(GetLastError(), std::system_category(), "ExpandEnvironmentVariables");
-        }
-    } while (expandedStr.size() != requestedSize);
-
-    // trim null character as ExpandEnvironmentStringsW returns size including null character
-    expandedStr.resize(requestedSize - 1);
-
-    return expandedStr;
-}

src/AspNetCoreModuleV2/CommonLib/hostfxr_utility.h

@@ -93,8 +93,5 @@ public:
     GetAbsolutePathToDotnet(
         _In_ const std::experimental::filesystem::path & requestedPath
     );
-
-    static
-    std::wstring ExpandEnvironmentVariables(const std::wstring & str);
 };
 

src/AspNetCoreModuleV2/InProcessRequestHandler/dllmain.cxx

@@ -72,6 +72,7 @@ BOOL APIENTRY DllMain(HMODULE hModule,
         break;
     case DLL_PROCESS_DETACH:
         g_fProcessDetach = TRUE;
+        DebugStop();
     default:
         break;
     }

src/AspNetCoreModuleV2/OutOfProcessRequestHandler/dllmain.cxx

@@ -260,6 +260,7 @@ BOOL APIENTRY DllMain(HMODULE hModule,
         break;
     case DLL_PROCESS_DETACH:
         g_fProcessDetach = TRUE;
+        DebugStop();
     default:
         break;
     }

test/IISIntegration.FunctionalTests/Inprocess/LoggingTests.cs

@@ -1,6 +1,7 @@
 // Copyright (c) .NET Foundation. All rights reserved.
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
+using System;
 using System.IO;
 using System.Linq;
 using System.Threading.Tasks;
@@ -20,7 +21,7 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
         {
             var deploymentParameters = Helpers.GetBaseDeploymentParameters();
             deploymentParameters.PublishApplicationBeforeDeployment = true;
-            deploymentParameters.PreservePublishedApplicationForDebugging = true; // workaround for keeping 
+            deploymentParameters.PreservePublishedApplicationForDebugging = true; // workaround for keeping
 
             var deploymentResult = await DeployAsync(deploymentParameters);
 
@@ -64,5 +65,30 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
                     retryDelayMilliseconds: 100);
             }
         }
+
+        [Fact]
+        public async Task StartupMessagesAreLoggedIntoDebugLogFile()
+        {
+            var tempFile = Path.GetTempFileName();
+            try
+            {
+                var deploymentParameters = Helpers.GetBaseDeploymentParameters();
+                deploymentParameters.EnvironmentVariables["ASPNETCORE_MODULE_DEBUG_FILE"] = tempFile;
+
+                var deploymentResult = await DeployAsync(deploymentParameters);
+                var response = await deploymentResult.RetryingHttpClient.GetAsync("/");
+
+                StopServer();
+
+                var logContents = File.ReadAllText(tempFile);
+                Assert.Contains("[aspnetcore.dll]", logContents);
+                Assert.Contains("[aspnetcorev2_inprocess.dll]", logContents);
+            }
+            finally
+            {
+                File.Delete(tempFile);
+            }
+        }
+
     }
 }