From b84a233d39faaa86591695081b0274fbb4ef2ac4 Mon Sep 17 00:00:00 2001 From: Pavel Krymets Date: Thu, 28 Jun 2018 11:52:53 -0700 Subject: [PATCH] Add ability to print debug logs to a file (#954) --- .../AspNetCore/src/dllmain.cpp | 5 +- .../CommonLib/CommonLib.vcxproj | 2 + .../CommonLib/Environment.cpp | 32 ++++++++ .../CommonLib/Environment.h | 17 +++++ .../CommonLib/debugutil.cpp | 73 +++++++++++++++---- src/AspNetCoreModuleV2/CommonLib/debugutil.h | 4 + .../CommonLib/hostfxr_utility.cpp | 33 +-------- .../CommonLib/hostfxr_utility.h | 3 - .../InProcessRequestHandler/dllmain.cxx | 1 + .../OutOfProcessRequestHandler/dllmain.cxx | 1 + .../Inprocess/LoggingTests.cs | 28 ++++++- 11 files changed, 151 insertions(+), 48 deletions(-) create mode 100644 src/AspNetCoreModuleV2/CommonLib/Environment.cpp create mode 100644 src/AspNetCoreModuleV2/CommonLib/Environment.h diff --git a/src/AspNetCoreModuleV2/AspNetCore/src/dllmain.cpp b/src/AspNetCoreModuleV2/AspNetCore/src/dllmain.cpp index 6b8fa8cea7..34d96e45d3 100644 --- a/src/AspNetCoreModuleV2/AspNetCore/src/dllmain.cpp +++ b/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 diff --git a/src/AspNetCoreModuleV2/CommonLib/CommonLib.vcxproj b/src/AspNetCoreModuleV2/CommonLib/CommonLib.vcxproj index b40c09583c..bb34327e27 100644 --- a/src/AspNetCoreModuleV2/CommonLib/CommonLib.vcxproj +++ b/src/AspNetCoreModuleV2/CommonLib/CommonLib.vcxproj @@ -194,6 +194,7 @@ + @@ -214,6 +215,7 @@ + diff --git a/src/AspNetCoreModuleV2/CommonLib/Environment.cpp b/src/AspNetCoreModuleV2/CommonLib/Environment.cpp new file mode 100644 index 0000000000..9746fe2c9b --- /dev/null +++ b/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 + +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; +} diff --git a/src/AspNetCoreModuleV2/CommonLib/Environment.h b/src/AspNetCoreModuleV2/CommonLib/Environment.h new file mode 100644 index 0000000000..969833d842 --- /dev/null +++ b/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 + +class Environment +{ +public: + Environment() = delete; + ~Environment() = delete; + + static + std::wstring ExpandEnvironmentVariables(const std::wstring & str); +}; + diff --git a/src/AspNetCoreModuleV2/CommonLib/debugutil.cpp b/src/AspNetCoreModuleV2/CommonLib/debugutil.cpp index 293bdfb4e8..d3d6fa6b32 100644 --- a/src/AspNetCoreModuleV2/CommonLib/debugutil.cpp +++ b/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(environmentVariableValue); + const auto value = std::stoi(Environment::ExpandEnvironmentVariables(L"%ASPNETCORE_MODULE_DEBUG%")); - if (value >= 1) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_ERROR; - if (value >= 2) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_WARNING; - if (value >= 3) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_INFO; - if (value >= 4) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_CONSOLE; - } - catch (...) + if (value >= 1) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_ERROR; + if (value >= 2) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_WARNING; + if (value >= 3) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_INFO; + if (value >= 4) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_CONSOLE; + } + 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, NULL); + WriteFile(g_hStandardOutput, strOutput.QueryStr(), strOutput.QueryCB(), &nBytesWritten, nullptr); + } + + 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); } } } diff --git a/src/AspNetCoreModuleV2/CommonLib/debugutil.h b/src/AspNetCoreModuleV2/CommonLib/debugutil.h index 5b81d0130b..0a21a6d51a 100644 --- a/src/AspNetCoreModuleV2/CommonLib/debugutil.h +++ b/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 diff --git a/src/AspNetCoreModuleV2/CommonLib/hostfxr_utility.cpp b/src/AspNetCoreModuleV2/CommonLib/hostfxr_utility.cpp index 5746730507..2ebc70966e 100644 --- a/src/AspNetCoreModuleV2/CommonLib/hostfxr_utility.cpp +++ b/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); - std::wstring arguments = ExpandEnvironmentVariables(pcwzArguments); + fs::path processPath = Environment::ExpandEnvironmentVariables(pcwzProcessPath); + std::wstring arguments = Environment::ExpandEnvironmentVariables(pcwzArguments); if (processPath.is_relative()) { @@ -595,7 +596,7 @@ HOSTFXR_UTILITY::InvokeWhereToFindDotnet() std::optional 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; -} diff --git a/src/AspNetCoreModuleV2/CommonLib/hostfxr_utility.h b/src/AspNetCoreModuleV2/CommonLib/hostfxr_utility.h index b7dfcbf67c..9b9952f27a 100644 --- a/src/AspNetCoreModuleV2/CommonLib/hostfxr_utility.h +++ b/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); }; diff --git a/src/AspNetCoreModuleV2/InProcessRequestHandler/dllmain.cxx b/src/AspNetCoreModuleV2/InProcessRequestHandler/dllmain.cxx index 01a0968b0e..d0775e1ae7 100644 --- a/src/AspNetCoreModuleV2/InProcessRequestHandler/dllmain.cxx +++ b/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; } diff --git a/src/AspNetCoreModuleV2/OutOfProcessRequestHandler/dllmain.cxx b/src/AspNetCoreModuleV2/OutOfProcessRequestHandler/dllmain.cxx index 16a3f6357f..0a416a4c7b 100644 --- a/src/AspNetCoreModuleV2/OutOfProcessRequestHandler/dllmain.cxx +++ b/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; } diff --git a/test/IISIntegration.FunctionalTests/Inprocess/LoggingTests.cs b/test/IISIntegration.FunctionalTests/Inprocess/LoggingTests.cs index defdf6a8a4..611434f560 100644 --- a/test/IISIntegration.FunctionalTests/Inprocess/LoggingTests.cs +++ b/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); + } + } + } }