Query event logs when verifying event log messages. (#1323)

src/AspNetCoreModuleV1/AspNetCore/aspnetcoremodule.rc

@@ -10,7 +10,7 @@
 #if !defined(AFX_RESOURCE_DLL) || defined(AFX_TARG_ENU)
 LANGUAGE LANG_ENGLISH, SUBLANG_ENGLISH_US
 
-#define FileDescription "IIS AspNetCore Module. Commit: " CommitHash
+#define FileDescription "IIS ASP.NET Core Module. Commit: " CommitHash
 
 /////////////////////////////////////////////////////////////////////////////
 //

src/AspNetCoreModuleV2/AspNetCore/aspnetcoremodule.rc

@@ -10,7 +10,7 @@
 #if !defined(AFX_RESOURCE_DLL) || defined(AFX_TARG_ENU)
 LANGUAGE LANG_ENGLISH, SUBLANG_ENGLISH_US
 
-#define FileDescription "IIS AspNetCore Module V2. Commit: " CommitHash
+#define FileDescription "IIS ASP.NET Core Module V2. Commit: " CommitHash
 
 /////////////////////////////////////////////////////////////////////////////
 //

src/AspNetCoreModuleV2/CommonLib/EventLog.cpp

@@ -1,8 +1,10 @@
 // Copyright (c) .NET Foundation. All rights reserved.
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
+#include <array>
 #include "EventLog.h"
 #include "debugutil.h"
+#include "StringHelpers.h"
 
 extern HANDLE       g_hEventLog;
 
@@ -13,6 +15,19 @@ EventLog::LogEvent(
     _In_ LPCWSTR pstrMsg
 )
 {
+    // Static locals to avoid getting the process ID and string multiple times.
+    // Effectively have the same semantics as global variables, except initialized
+    // on first occurence.
+    static const auto processIdString = GetProcessIdString();
+    static const auto versionInfoString = GetVersionInfoString();
+
+    std::array<LPCWSTR, 3> eventLogDataStrings
+    {
+        pstrMsg,
+        processIdString.c_str(),
+        versionInfoString.c_str()
+    };
+
     if (g_hEventLog != NULL)
     {
         ReportEventW(g_hEventLog,
@@ -20,9 +35,9 @@ EventLog::LogEvent(
             0,        // wCategory
             dwEventId,
             NULL,     // lpUserSid
-            1,        // wNumStrings
+            3,        // wNumStrings
             0,        // dwDataSize,
-            &pstrMsg,
+            eventLogDataStrings.data(),
             NULL      // lpRawData
         );
     }

src/AspNetCoreModuleV2/CommonLib/debugutil.cpp

@@ -13,6 +13,7 @@
 #include "exceptions.h"
 #include "atlbase.h"
 #include "config_utility.h"
+#include "StringHelpers.h"
 
 inline HANDLE g_logFile = INVALID_HANDLE_VALUE;
 inline HMODULE g_hModule;
@@ -21,43 +22,72 @@ inline SRWLOCK g_logFileLock;
 HRESULT
 PrintDebugHeader()
 {
-    DWORD  verHandle = 0;
+    // Major, minor are stored in dwFileVersionMS field and patch, build in dwFileVersionLS field as pair of 32 bit numbers
-    UINT   size      = 0;
+    DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, "Initializing logs for %S. %S. %S.",
-    LPVOID lpBuffer  = NULL;
+        GetModuleName().c_str(),
+        GetProcessIdString().c_str(),
+        GetVersionInfoString().c_str()
+    );
 
-    WCHAR path[MAX_PATH];
+    return S_OK;
-    RETURN_LAST_ERROR_IF(!GetModuleFileName(g_hModule, path, sizeof(path)));
+}
 
-    DWORD verSize = GetFileVersionInfoSize(path, &verHandle);
+std::wstring
-    RETURN_LAST_ERROR_IF(verSize == 0);
+GetProcessIdString()
+{
+    return format(L"Process Id: %u.", GetCurrentProcessId());
+}
 
-    // Allocate memory to hold data structure returned by GetFileVersionInfo
+std::wstring
-    std::vector<BYTE> verData(verSize);
+GetVersionInfoString()
-
+{
-    RETURN_LAST_ERROR_IF(!GetFileVersionInfo(path, verHandle, verSize, verData.data()));
+    auto func = [](std::wstring& res)
-    RETURN_LAST_ERROR_IF(!VerQueryValue(verData.data(), L"\\", &lpBuffer, &size));
-
-    auto verInfo = reinterpret_cast<VS_FIXEDFILEINFO *>(lpBuffer);
-    // Check result signature
-    if (verInfo->dwSignature == VS_FFI_SIGNATURE)
     {
+        DWORD  verHandle = 0;
+        UINT   size = 0;
+        LPVOID lpBuffer = NULL;
+
+        auto path = GetModuleName();
+
+        DWORD verSize = GetFileVersionInfoSize(path.c_str(), &verHandle);
+        RETURN_LAST_ERROR_IF(verSize == 0);
+
+        // Allocate memory to hold data structure returned by GetFileVersionInfo
+        std::vector<BYTE> verData(verSize);
+
+        RETURN_LAST_ERROR_IF(!GetFileVersionInfo(path.c_str(), verHandle, verSize, verData.data()));
+        RETURN_LAST_ERROR_IF(!VerQueryValue(verData.data(), L"\\", &lpBuffer, &size));
+
+        auto verInfo = reinterpret_cast<VS_FIXEDFILEINFO *>(lpBuffer);
+        if (verInfo->dwSignature != VS_FFI_SIGNATURE)
+        {
+            RETURN_IF_FAILED(E_FAIL);
+        }
+
         LPVOID pvProductName = NULL;
         unsigned int iProductNameLen = 0;
         RETURN_LAST_ERROR_IF(!VerQueryValue(verData.data(), _T("\\StringFileInfo\\040904b0\\FileDescription"), &pvProductName, &iProductNameLen));
 
-        // Major, minor are stored in dwFileVersionMS field and patch, build in dwFileVersionLS field as pair of 32 bit numbers
+        res = format(L"File Version: %d.%d.%d.%d. Description: %s",
-        DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, "Initializing logs for %S. ProcessId: %d. File Version: %d.%d.%d.%d. Description: %S",
+            (verInfo->dwFileVersionMS >> 16) & 0xffff,
-            path,
+            (verInfo->dwFileVersionMS >> 0) & 0xffff,
-            GetCurrentProcessId(),
+            (verInfo->dwFileVersionLS >> 16) & 0xffff,
-            ( verInfo->dwFileVersionMS >> 16 ) & 0xffff,
+            (verInfo->dwFileVersionLS >> 0) & 0xffff,
-            ( verInfo->dwFileVersionMS >>  0 ) & 0xffff,
+            pvProductName);
-            ( verInfo->dwFileVersionLS >> 16 ) & 0xffff,
+        return S_OK;
-            ( verInfo->dwFileVersionLS >>  0 ) & 0xffff,
+    };
-            pvProductName
-        );
-    }
 
-    return S_OK;
+    std::wstring versionInfoString;
+
+    return func(versionInfoString) == S_OK ? versionInfoString : L"";
+}
+
+std::wstring
+GetModuleName()
+{
+    WCHAR path[MAX_PATH];
+    LOG_LAST_ERROR_IF(GetModuleFileName(g_hModule, path, sizeof(path)));
+    return path;
 }
 
 void SetDebugFlags(const std::wstring &debugValue)

src/AspNetCoreModuleV2/CommonLib/debugutil.h

@@ -49,3 +49,12 @@ DebugPrintf(
     LPCSTR  szFormat,
     ...
     );
+
+std::wstring
+GetProcessIdString();
+
+std::wstring
+GetVersionInfoString();
+
+std::wstring
+GetModuleName();

src/AspNetCoreModuleV2/InProcessRequestHandler/inprocessrequesthandler.rc

@@ -9,7 +9,7 @@
 #if !defined(AFX_RESOURCE_DLL) || defined(AFX_TARG_ENU)
 LANGUAGE LANG_ENGLISH, SUBLANG_ENGLISH_US
 
-#define FileDescription "IIS ASP.NET Core Module Request Handler. Commit: " CommitHash
+#define FileDescription "IIS ASP.NET Core Module V2 Request Handler. Commit: " CommitHash
 
 /////////////////////////////////////////////////////////////////////////////
 //

src/AspNetCoreModuleV2/OutOfProcessRequestHandler/outofprocessrequesthandler.rc

@@ -9,7 +9,7 @@
 #if !defined(AFX_RESOURCE_DLL) || defined(AFX_TARG_ENU)
 LANGUAGE LANG_ENGLISH, SUBLANG_ENGLISH_US
 
-#define FileDescription "IIS ASP.NET Core Module Request Handler. Commit: " CommitHash
+#define FileDescription "IIS ASP.NET Core Module V2 Request Handler. Commit: " CommitHash
 
 /////////////////////////////////////////////////////////////////////////////
 //

test/Common.FunctionalTests/Inprocess/EventLogTests.cs

@@ -1,7 +1,6 @@
 // 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.Net;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Server.IIS.FunctionalTests.Utilities;
 using Microsoft.AspNetCore.Testing.xunit;

test/Common.FunctionalTests/Inprocess/LoggingTests.cs

@@ -200,8 +200,8 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
                 var logContents = streamReader.ReadToEnd();
                 Assert.Contains("[aspnetcorev2.dll]", logContents);
                 Assert.Contains("[aspnetcorev2_inprocess.dll]", logContents);
-                Assert.Contains("Description: IIS AspNetCore Module V2. Commit:", logContents);
+                Assert.Contains("Description: IIS ASP.NET Core Module V2. Commit:", logContents);
-                Assert.Contains("Description: IIS ASP.NET Core Module Request Handler. Commit:", logContents);
+                Assert.Contains("Description: IIS ASP.NET Core Module V2 Request Handler. Commit:", logContents);
             }
         }
     }

test/Common.FunctionalTests/Utilities/EventLogHelpers.cs

@@ -1,17 +1,24 @@
 // 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.Collections.Generic;
+using System.Diagnostics;
+using System.Linq;
 using System.Text;
 using System.Text.RegularExpressions;
+using Microsoft.AspNetCore.Server.IntegrationTesting;
 using Microsoft.AspNetCore.Server.IntegrationTesting.IIS;
 using Microsoft.Extensions.Logging.Testing;
 using Xunit;
+using Xunit.Sdk;
 
 namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
 {
     public class EventLogHelpers
     {
         private static readonly Regex EventLogRegex = new Regex("Event Log: (?<EventLogMessage>.+?)End Event Log Message.", RegexOptions.Singleline | RegexOptions.Compiled);
+
         public static void VerifyEventLogEvent(IISDeploymentResult deploymentResult, ITestSink testSink, string expectedRegexMatchString)
         {
             Assert.True(deploymentResult.HostProcess.HasExited);
@@ -36,6 +43,43 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
 
             Assert.True(count > 0, $"'{expectedRegexMatchString}' didn't match any event log messaged");
             Assert.True(count < 2, $"'{expectedRegexMatchString}' matched more then one event log message");
+
+            var eventLog = new EventLog("Application");
+
+            // Perf: only get the last 20 events from the event log.
+            // Eventlog is already sorted based on time of event in ascending time.
+            // Add results in reverse order.
+            var expectedRegexEventLog = new Regex(expectedRegexMatchString);
+            var processIdString = $"Process Id: {deploymentResult.HostProcess.Id}.";
+
+            for (var i = eventLog.Entries.Count - 1; i >= eventLog.Entries.Count - 20; i--)
+            {
+                var eventLogEntry = eventLog.Entries[i];
+                if (eventLogEntry.ReplacementStrings == null ||
+                    eventLogEntry.ReplacementStrings.Length < 3)
+                {
+                    continue;
+                }
+
+                // ReplacementStings == EventData collection in EventLog
+                // This is unaffected if event providers are not registered correctly
+                if (eventLogEntry.Source == AncmVersionToMatch(deploymentResult) &&
+                    processIdString == eventLogEntry.ReplacementStrings[1] &&
+                    expectedRegex.IsMatch(eventLogEntry.ReplacementStrings[0]))
+                {
+                    return;
+                }
+            }
+
+            Assert.True(false, $"'{expectedRegexMatchString}' didn't match any event log messaged.");
+        }
+
+        private static string AncmVersionToMatch(IISDeploymentResult deploymentResult)
+        {
+            return "IIS " +
+                (deploymentResult.DeploymentParameters.ServerType == ServerType.IISExpress ? "Express " : "") +
+                "AspNetCore Module" +
+                (deploymentResult.DeploymentParameters.AncmVersion == AncmVersion.AspNetCoreModuleV2 ? " V2" : "");
         }
     }
 }