Revert stdout logging behavior to call SetStdHandle (#907)

src/AspNetCoreModuleV2/CommonLib/FileOutputManager.cpp

@@ -5,7 +5,6 @@
 #include "sttimer.h"
 
 FileOutputManager::FileOutputManager()
-    : m_pStdOutFile(NULL)
 {
 }
 
@@ -14,16 +13,17 @@ FileOutputManager::~FileOutputManager()
     HANDLE   handle = NULL;
     WIN32_FIND_DATA fileData;
 
-    if (m_pStdOutFile != NULL)
+    if (m_hLogFileHandle != INVALID_HANDLE_VALUE)
     {
         m_Timer.CancelTimer();
-        _close(_fileno(m_pStdOutFile));
+        CloseHandle(m_hLogFileHandle);
-        m_pStdOutFile = NULL;
+        m_hLogFileHandle = INVALID_HANDLE_VALUE;
     }
 
     // delete empty log file
     handle = FindFirstFile(m_struLogFilePath.QueryStr(), &fileData);
     if (handle != INVALID_HANDLE_VALUE &&
+        handle != NULL &&
         fileData.nFileSizeHigh == 0 &&
         fileData.nFileSizeLow == 0) // skip check of nFileSizeHigh
     {
@@ -33,8 +33,15 @@ FileOutputManager::~FileOutputManager()
         DeleteFile(m_struLogFilePath.QueryStr());
     }
 
-    _dup2(m_fdStdOut, _fileno(stdout));
+    if (m_fdPreviousStdOut >= 0)
-    _dup2(m_fdStdErr, _fileno(stderr));
+    {
+        _dup2(m_fdPreviousStdOut, _fileno(stdout));
+    }
+
+    if (m_fdPreviousStdErr >= 0)
+    {
+        _dup2(m_fdPreviousStdErr, _fileno(stderr));
+    }
 }
 
 HRESULT
@@ -104,35 +111,19 @@ FileOutputManager::Start()
     SYSTEMTIME systemTime;
     SECURITY_ATTRIBUTES saAttr = { 0 };
     STRU struPath;
-
     hr = UTILITY::ConvertPathToFullPath(
         m_wsStdOutLogFileName.QueryStr(),
         m_wsApplicationPath.QueryStr(),
         &struPath);
-
     if (FAILED(hr))
     {
-        goto Finished;
+        return hr;
     }
 
     hr = UTILITY::EnsureDirectoryPathExist(struPath.QueryStr());
     if (FAILED(hr))
     {
-        goto Finished;
+        return hr;
-    }
-
-    m_fdStdOut = _dup(_fileno(stdout));
-    if (m_fdStdOut == -1)
-    {
-        hr = E_HANDLE;
-        goto Finished;
-    }
-
-    m_fdStdErr = _dup(_fileno(stderr));
-    if (m_fdStdErr == -1)
-    {
-        hr = E_HANDLE;
-        goto Finished;
     }
 
     GetSystemTime(&systemTime);
@@ -147,38 +138,55 @@ FileOutputManager::Start()
         GetCurrentProcessId());
     if (FAILED(hr))
     {
-        goto Finished;
+        return hr;
-    }
-    saAttr.nLength = sizeof(SECURITY_ATTRIBUTES);
-    saAttr.bInheritHandle = TRUE;
-    saAttr.lpSecurityDescriptor = NULL;
-
-    if (_wfreopen_s(&m_pStdOutFile, m_struLogFilePath.QueryStr(), L"w+", stdout) == 0)
-    {
-        setvbuf(m_pStdOutFile, NULL, _IONBF, 0);
-        if (_dup2(_fileno(m_pStdOutFile), _fileno(stdout)) == -1)
-        {
-            hr = E_HANDLE;
-            goto Finished;
-        }
-        if (_dup2(_fileno(m_pStdOutFile), _fileno(stderr)) == -1)
-        {
-            hr = E_HANDLE;
-            goto Finished;
-        }
     }
 
-    m_hLogFileHandle = (HANDLE)_get_osfhandle(_fileno(m_pStdOutFile));
+    m_fdPreviousStdOut = _dup(_fileno(stdout));
+    m_fdPreviousStdErr = _dup(_fileno(stderr));
+
+    m_hLogFileHandle = CreateFileW(m_struLogFilePath.QueryStr(),
+        FILE_READ_DATA | FILE_WRITE_DATA,
+        FILE_SHARE_READ,
+        &saAttr,
+        CREATE_ALWAYS,
+        FILE_ATTRIBUTE_NORMAL,
+        NULL);
+
     if (m_hLogFileHandle == INVALID_HANDLE_VALUE)
     {
-        hr = E_HANDLE;
+        hr = HRESULT_FROM_WIN32(GetLastError());
-        goto Finished;
+        return hr;
     }
 
-    // Periodically flush the log content to file
+    // There are a few options for redirecting stdout/stderr,
-    m_Timer.InitializeTimer(STTIMER::TimerCallback, &m_struLogFilePath, FILE_FLUSH_TIMEOUT, FILE_FLUSH_TIMEOUT);
+    // but there are issues with most of them.
+    // AllocConsole() 
+    // *stdout = *m_pStdFile; 
+    // *stderr = *m_pStdFile;
+    // Calling _dup2 on stderr fails on IIS. IIS sets stderr to -2
+    // _dup2(_fileno(m_pStdFile), _fileno(stdout));
+    // _dup2(_fileno(m_pStdFile), _fileno(stderr));
+    // If we were okay setting stdout and stderr to separate files, we could use:
+    // _wfreopen_s(&m_pStdFile, struLogFileName.QueryStr(), L"w+", stdout);
+    // _wfreopen_s(&m_pStdFile, struLogFileName.QueryStr(), L"w+", stderr);
+    // Calling SetStdHandle works for redirecting managed logs, however you cannot
+    // capture native logs (including hostfxr failures).
 
-Finished:
+    if (!SetStdHandle(STD_OUTPUT_HANDLE, m_hLogFileHandle))
+    {
+        hr = HRESULT_FROM_WIN32(GetLastError());
+        return hr;
+    }
+
+    if (!SetStdHandle(STD_ERROR_HANDLE, m_hLogFileHandle))
+    {
+        hr = HRESULT_FROM_WIN32(GetLastError());
+        return hr;
+    }
+
+
+    // Periodically flush the log content to file
+    m_Timer.InitializeTimer(STTIMER::TimerCallback, &m_struLogFilePath, 3000, 3000);
 
     return hr;
 }

src/AspNetCoreModuleV2/CommonLib/FileOutputManager.h

@@ -25,8 +25,7 @@ private:
     STRU m_wsStdOutLogFileName;
     STRU m_wsApplicationPath;
     STRU m_struLogFilePath;
-    int m_fdStdOut;
+    int m_fdPreviousStdOut;
-    int m_fdStdErr;
+    int m_fdPreviousStdErr;
-    FILE* m_pStdOutFile;
 };
 

src/AspNetCoreModuleV2/CommonLib/PipeOutputManager.cpp

@@ -39,6 +39,7 @@ PipeOutputManager::StopOutputRedirection()
     }
 
     if (m_hErrThread != NULL &&
+        m_hErrThread != INVALID_HANDLE_VALUE &&
         GetExitCodeThread(m_hErrThread, &dwThreadStatus) != 0 &&
         dwThreadStatus == STILL_ACTIVE)
     {
@@ -64,14 +65,14 @@ PipeOutputManager::StopOutputRedirection()
 
     // Restore the original stdout and stderr handles of the process,
     // as the application has either finished startup or has exited.
-    if (_dup2(m_fdStdOut, _fileno(stdout)) == -1)
+    if (m_fdPreviousStdOut != -1)
     {
-        return;
+        _dup2(m_fdPreviousStdOut, _fileno(stdout));
     }
 
-    if (_dup2(m_fdStdErr, _fileno(stderr)) == -1)
+    if (m_fdPreviousStdErr != -1)
     {
-        return;
+        _dup2(m_fdPreviousStdErr, _fileno(stderr));
     }
 
     if (GetStdOutContent(&straStdOutput))
@@ -89,18 +90,8 @@ HRESULT PipeOutputManager::Start()
     HANDLE                  hStdErrReadPipe;
     HANDLE                  hStdErrWritePipe;
 
-    m_fdStdOut = _dup(_fileno(stdout));
+    m_fdPreviousStdOut = _dup(_fileno(stdout));
-    if (m_fdStdOut == -1)
+    m_fdPreviousStdErr = _dup(_fileno(stderr));
-    {
-        hr = E_HANDLE;
-        goto Finished;
-    }
-    m_fdStdErr = _dup(_fileno(stderr));
-    if (m_fdStdErr == -1)
-    {
-        hr = E_HANDLE;
-        goto Finished;
-    }
 
     if (!CreatePipe(&hStdErrReadPipe, &hStdErrWritePipe, &saAttr, 0 /*nSize*/))
     {

src/AspNetCoreModuleV2/CommonLib/PipeOutputManager.h

@@ -32,7 +32,7 @@ private:
     CHAR                            m_pzFileContents[MAX_PIPE_READ_SIZE] = { 0 };
     BOOL                            m_fDisposed;
     DWORD                           m_dwStdErrReadTotal;
-    int                             m_fdStdOut;
+    int                             m_fdPreviousStdOut;
-    int                             m_fdStdErr;
+    int                             m_fdPreviousStdErr;
 };
 

src/AspNetCoreModuleV2/InProcessRequestHandler/inprocessapplication.cpp

@@ -403,7 +403,10 @@ IN_PROCESS_APPLICATION::LoadManagedApplication
                 goto Finished;
             }
 
-            m_pLoggerProvider->Start();
+            if (FAILED(hr = m_pLoggerProvider->Start()))
+            {
+                goto Finished;
+            }
         }
       
         if (m_status != APPLICATION_STATUS::STARTING)

test/CommonLibTests/FileOutputManagerTests.cpp

@@ -54,13 +54,13 @@ namespace FileOutManagerStartupTests
         }
     };
 
-    TEST_F(FileOutputManagerTest, WriteToFileCheckContentsWritten)
+    TEST_F(FileOutputManagerTest, DISABLED_WriteToFileCheckContentsWritten)
     {
         Test(L"", stdout);
         Test(L"log", stdout);
     }
 
-    TEST_F(FileOutputManagerTest, WriteToFileCheckContentsWrittenErr)
+    TEST_F(FileOutputManagerTest, DISABLED_WriteToFileCheckContentsWrittenErr)
     {
         Test(L"", stderr);
         Test(L"log", stderr);
@@ -70,7 +70,7 @@ namespace FileOutManagerStartupTests
 namespace FileOutManagerOutputTests
 {
 
-    TEST(FileOutManagerOutputTest, StdErr)
+    TEST(FileOutManagerOutputTest, DISABLED_StdErr)
     {
         PCSTR expected = "test";
 
@@ -91,7 +91,7 @@ namespace FileOutManagerOutputTests
         Helpers::DeleteDirectory(tempDirectory);
     }
 
-    TEST(FileOutManagerOutputTest, CheckFileOutput)
+    TEST(FileOutManagerOutputTest, DISABLED_CheckFileOutput)
     {
         PCSTR expected = "test";
 
@@ -112,7 +112,7 @@ namespace FileOutManagerOutputTests
         Helpers::DeleteDirectory(tempDirectory);
     }
 
-    TEST(FileOutManagerOutputTest, CapAt4KB)
+    TEST(FileOutManagerOutputTest, DISABLED_CapAt4KB)
     {
         PCSTR expected = "test";