Don't stop redirect stdout/stderr after startup is done. (#1067)

This commit is contained in:
Justin Kotalik 2018-07-29 23:25:32 -07:00 committed by GitHub
parent b7e26fed99
commit 41493f01e3
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
14 changed files with 144 additions and 147 deletions

View File

@ -237,6 +237,13 @@ Language=English
%1
.
Messageid=1035
SymbolicName=ASPNETCORE_EVENT_INPROCESS_THREAD_EXIT_STDOUT
Language=English
%1
.
;
;#endif // _ASPNETCORE_MODULE_MSG_H_
;

View File

@ -7,10 +7,10 @@
#include "requesthandler_config.h"
#include "environmentvariablehelpers.h"
#include "utility.h"
#include "EventLog.h"
#include "SRWExclusiveLock.h"
#include "exceptions.h"
#include "LoggingHelpers.h"
#include "resources.h"
const LPCSTR IN_PROCESS_APPLICATION::s_exeLocationParameterName = "InProcessExeLocation";
@ -220,7 +220,6 @@ IN_PROCESS_APPLICATION::SetCallbackHandles(
m_ShutdownHandlerContext = pvShutdownHandlerContext;
m_AsyncCompletionHandler = async_completion_handler;
m_pLoggerProvider->NotifyStartupComplete();
// Can't check the std err handle as it isn't a critical error
// Initialization complete
UTILITY::LogEventF(g_hEventLog,
@ -498,11 +497,10 @@ Finished:
m_status = APPLICATION_STATUS::SHUTDOWN;
m_fShutdownCalledFromManaged = TRUE;
FreeLibrary(hModule);
m_pLoggerProvider->Stop();
if (!m_fShutdownCalledFromNative)
{
m_pLoggerProvider->NotifyStartupComplete();
LogErrorsOnMainExit(hr);
if (m_fInitialized)
{
@ -533,7 +531,7 @@ IN_PROCESS_APPLICATION::LogErrorsOnMainExit(
if (SUCCEEDED(struStdMsg.CopyA(straStdErrOutput.QueryStr()))) {
UTILITY::LogEventF(g_hEventLog,
EVENTLOG_ERROR_TYPE,
ASPNETCORE_EVENT_INPROCESS_THREAD_EXIT,
ASPNETCORE_EVENT_INPROCESS_THREAD_EXIT_STDOUT,
ASPNETCORE_EVENT_INPROCESS_THREAD_EXIT_STDOUT_MSG,
m_pConfig->QueryApplicationPath()->QueryStr(),
m_pConfig->QueryApplicationPhysicalPath()->QueryStr(),

View File

@ -18,8 +18,7 @@ register_callbacks(
_In_ PFN_SHUTDOWN_HANDLER shutdown_handler,
_In_ PFN_ASYNC_COMPLETION_HANDLER async_completion_handler,
_In_ VOID* pvRequstHandlerContext,
_In_ VOID* pvShutdownHandlerContext,
_Out_ BOOL* pfResetStandardStreams
_In_ VOID* pvShutdownHandlerContext
)
{
if (pInProcessApplication == NULL)
@ -34,7 +33,6 @@ register_callbacks(
pvRequstHandlerContext,
pvShutdownHandlerContext
);
*pfResetStandardStreams = !pInProcessApplication->QueryConfig()->QueryStdoutLogEnabled();
return S_OK;
}

View File

@ -7,48 +7,20 @@
#include "utility.h"
#include "exceptions.h"
#include "debugutil.h"
#include "SRWExclusiveLock.h"
FileOutputManager::FileOutputManager() :
m_hLogFileHandle(INVALID_HANDLE_VALUE),
m_fdPreviousStdOut(-1),
m_fdPreviousStdErr(-1)
m_fdPreviousStdErr(-1),
m_disposed(false)
{
InitializeSRWLock(&m_srwLock);
}
FileOutputManager::~FileOutputManager()
{
HANDLE handle = NULL;
WIN32_FIND_DATA fileData;
if (m_hLogFileHandle != INVALID_HANDLE_VALUE)
{
m_Timer.CancelTimer();
}
// 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
{
FindClose(handle);
// no need to check whether the deletion succeeds
// as nothing can be done
DeleteFile(m_struLogFilePath.QueryStr());
}
if (m_fdPreviousStdOut >= 0)
{
LOG_LAST_ERROR_IF(SetStdHandle(STD_OUTPUT_HANDLE, (HANDLE)_get_osfhandle(m_fdPreviousStdOut)));
LOG_INFOF("Restoring original stdout: %d", m_fdPreviousStdOut);
}
if (m_fdPreviousStdErr >= 0)
{
LOG_LAST_ERROR_IF(SetStdHandle(STD_ERROR_HANDLE, (HANDLE)_get_osfhandle(m_fdPreviousStdErr)));
LOG_INFOF("Restoring original stderr: %d", m_fdPreviousStdOut);
}
Stop();
}
HRESULT
@ -100,8 +72,6 @@ bool FileOutputManager::GetStdOutContent(STRA* struStdOutput)
}
}
LOG_INFOF("First 4KB captured by stdout: %s", pzFileContents);
return fLogged;
}
@ -174,3 +144,52 @@ FileOutputManager::Start()
return S_OK;
}
HRESULT
FileOutputManager::Stop()
{
if (m_disposed)
{
return S_OK;
}
SRWExclusiveLock lock(m_srwLock);
if (m_disposed)
{
return S_OK;
}
m_disposed = true;
HANDLE handle = NULL;
WIN32_FIND_DATA fileData;
if (m_hLogFileHandle != INVALID_HANDLE_VALUE)
{
m_Timer.CancelTimer();
}
// 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
{
FindClose(handle);
LOG_LAST_ERROR_IF(!DeleteFile(m_struLogFilePath.QueryStr()));
}
if (m_fdPreviousStdOut >= 0)
{
LOG_LAST_ERROR_IF(!SetStdHandle(STD_OUTPUT_HANDLE, (HANDLE)_get_osfhandle(m_fdPreviousStdOut)));
LOG_INFOF("Restoring original stdout: %d", m_fdPreviousStdOut);
}
if (m_fdPreviousStdErr >= 0)
{
LOG_LAST_ERROR_IF(!SetStdHandle(STD_ERROR_HANDLE, (HANDLE)_get_osfhandle(m_fdPreviousStdErr)));
LOG_INFOF("Restoring original stderr: %d", m_fdPreviousStdOut);
}
return S_OK;
}

View File

@ -19,7 +19,7 @@ public:
virtual bool GetStdOutContent(STRA* struStdOutput) override;
virtual HRESULT Start() override;
virtual void NotifyStartupComplete() override {};
virtual HRESULT Stop() override;
private:
HandleWrapper<InvalidHandleTraits> m_hLogFileHandle;
@ -29,5 +29,7 @@ private:
STRU m_struLogFilePath;
int m_fdPreviousStdOut;
int m_fdPreviousStdErr;
BOOL m_disposed;
SRWLOCK m_srwLock;
};

View File

@ -14,12 +14,12 @@ public:
virtual
~IOutputManager() {};
virtual
void
NotifyStartupComplete() = 0;
virtual
bool
GetStdOutContent(STRA* struStdOutput) = 0;
virtual
HRESULT
Stop() = 0;
};

View File

@ -15,12 +15,12 @@ public:
HRESULT Start()
{
// The process has console, e.g., IIS Express scenario
return S_OK;
}
void NotifyStartupComplete()
HRESULT Stop()
{
return S_OK;
}
bool GetStdOutContent(STRA*)

View File

@ -14,7 +14,7 @@ PipeOutputManager::PipeOutputManager() :
m_hErrReadPipe(INVALID_HANDLE_VALUE),
m_hErrWritePipe(INVALID_HANDLE_VALUE),
m_hErrThread(NULL),
m_fDisposed(FALSE),
m_disposed(FALSE),
m_fdPreviousStdOut(-1),
m_fdPreviousStdErr(-1)
{
@ -23,26 +23,61 @@ PipeOutputManager::PipeOutputManager() :
PipeOutputManager::~PipeOutputManager()
{
StopOutputRedirection();
Stop();
}
VOID
PipeOutputManager::StopOutputRedirection()
HRESULT PipeOutputManager::Start()
{
SECURITY_ATTRIBUTES saAttr = { 0 };
HANDLE hStdErrReadPipe;
HANDLE hStdErrWritePipe;
m_fdPreviousStdOut = _dup(_fileno(stdout));
LOG_IF_DUPFAIL(m_fdPreviousStdOut);
m_fdPreviousStdErr = _dup(_fileno(stderr));
LOG_IF_DUPFAIL(m_fdPreviousStdErr);
RETURN_LAST_ERROR_IF(!CreatePipe(&hStdErrReadPipe, &hStdErrWritePipe, &saAttr, 0 /*nSize*/));
// TODO this still doesn't redirect calls in native, like wprintf
RETURN_LAST_ERROR_IF(!SetStdHandle(STD_ERROR_HANDLE, hStdErrWritePipe));
RETURN_LAST_ERROR_IF(!SetStdHandle(STD_OUTPUT_HANDLE, hStdErrWritePipe));
m_hErrReadPipe = hStdErrReadPipe;
m_hErrWritePipe = hStdErrWritePipe;
// Read the stderr handle on a separate thread until we get 4096 bytes.
m_hErrThread = CreateThread(
NULL, // default security attributes
0, // default stack size
(LPTHREAD_START_ROUTINE)ReadStdErrHandle,
this, // thread function arguments
0, // default creation flags
NULL); // receive thread identifier
RETURN_LAST_ERROR_IF_NULL(m_hErrThread);
return S_OK;
}
HRESULT PipeOutputManager::Stop()
{
DWORD dwThreadStatus = 0;
STRA straStdOutput;
if (m_fDisposed)
if (m_disposed)
{
return;
return S_OK;
}
SRWExclusiveLock lock(m_srwLock);
if (m_fDisposed)
if (m_disposed)
{
return;
return S_OK;
}
m_fDisposed = true;
m_disposed = true;
fflush(stdout);
fflush(stderr);
@ -115,40 +150,6 @@ PipeOutputManager::StopOutputRedirection()
// Need to flush contents for the new stdout and stderr
_flushall();
}
}
HRESULT PipeOutputManager::Start()
{
SECURITY_ATTRIBUTES saAttr = { 0 };
HANDLE hStdErrReadPipe;
HANDLE hStdErrWritePipe;
m_fdPreviousStdOut = _dup(_fileno(stdout));
LOG_IF_DUPFAIL(m_fdPreviousStdOut);
m_fdPreviousStdErr = _dup(_fileno(stderr));
LOG_IF_DUPFAIL(m_fdPreviousStdErr);
RETURN_LAST_ERROR_IF(!CreatePipe(&hStdErrReadPipe, &hStdErrWritePipe, &saAttr, 0 /*nSize*/));
// TODO this still doesn't redirect calls in native, like wprintf
RETURN_LAST_ERROR_IF(!SetStdHandle(STD_ERROR_HANDLE, hStdErrWritePipe));
RETURN_LAST_ERROR_IF(!SetStdHandle(STD_OUTPUT_HANDLE, hStdErrWritePipe));
m_hErrReadPipe = hStdErrReadPipe;
m_hErrWritePipe = hStdErrWritePipe;
// Read the stderr handle on a separate thread until we get 4096 bytes.
m_hErrThread = CreateThread(
NULL, // default security attributes
0, // default stack size
(LPTHREAD_START_ROUTINE)ReadStdErrHandle,
this, // thread function arguments
0, // default creation flags
NULL); // receive thread identifier
RETURN_LAST_ERROR_IF_NULL(m_hErrThread);
return S_OK;
}
@ -163,16 +164,17 @@ PipeOutputManager::ReadStdErrHandle(
pLoggingProvider->ReadStdErrHandleInternal();
}
bool PipeOutputManager::GetStdOutContent(STRA* struStdOutput)
bool PipeOutputManager::GetStdOutContent(STRA* straStdOutput)
{
bool fLogged = false;
if (m_dwStdErrReadTotal > 0)
{
if (SUCCEEDED(struStdOutput->Copy(m_pzFileContents, m_dwStdErrReadTotal)))
if (SUCCEEDED(straStdOutput->Copy(m_pzFileContents, m_dwStdErrReadTotal)))
{
fLogged = TRUE;
}
}
return fLogged;
}
@ -194,13 +196,19 @@ PipeOutputManager::ReadStdErrHandleInternal(
}
else if (GetLastError() == ERROR_BROKEN_PIPE)
{
break;
return;
}
}
char tempBuffer[MAX_PIPE_READ_SIZE];
while (true)
{
if (ReadFile(m_hErrReadPipe, tempBuffer, MAX_PIPE_READ_SIZE, &dwNumBytesRead, NULL))
{
}
else if (GetLastError() == ERROR_BROKEN_PIPE)
{
return;
}
}
}
VOID
PipeOutputManager::NotifyStartupComplete()
{
StopOutputRedirection();
}

View File

@ -13,30 +13,26 @@ public:
PipeOutputManager();
~PipeOutputManager();
// Inherited via ILoggerProvider
virtual HRESULT Start() override;
virtual void NotifyStartupComplete() override;
// Inherited via IOutputManager
virtual HRESULT Stop() override;
virtual bool GetStdOutContent(STRA* struStdOutput) override;
// Thread functions
VOID ReadStdErrHandleInternal(VOID);
static
VOID ReadStdErrHandle(LPVOID pContext);
private:
VOID StopOutputRedirection();
HANDLE m_hErrReadPipe;
HANDLE m_hErrWritePipe;
STRU m_struLogFilePath;
HANDLE m_hErrThread;
CHAR m_pzFileContents[MAX_PIPE_READ_SIZE] = { 0 };
DWORD m_dwStdErrReadTotal;
BOOL m_fDisposed;
SRWLOCK m_srwLock;
int m_fdPreviousStdOut;
int m_fdPreviousStdErr;
BOOL m_disposed;
};

View File

@ -38,33 +38,7 @@ namespace Microsoft.AspNetCore.Server.IIS.Core
shutdownHandler,
onAsyncCompletion,
requestContext,
shutdownContext,
out var resetStandardStreams);
if (resetStandardStreams)
{
ResetStdOutHandles();
}
}
private static void ResetStdOutHandles()
{
// By using the PipeOutputRedirection, after calling RegisterCallbacks,
// stdout and stderr will be redirected to NULL. However, if something wrote
// to stdout before redirecting, (like a Console.WriteLine during startup),
// we need to call Console.Set* to pick up the modified consoles outputs.
Console.SetOut(CreateStreamWriter(Console.OpenStandardOutput()));
Console.SetError(CreateStreamWriter(Console.OpenStandardError()));
}
private static StreamWriter CreateStreamWriter(Stream stdStream)
{
return new StreamWriter(
stdStream,
encoding: Console.OutputEncoding,
bufferSize: 256,
leaveOpen: true)
{ AutoFlush = true };
shutdownContext);
}
public void Dispose()

View File

@ -59,8 +59,7 @@ namespace Microsoft.AspNetCore.Server.IIS
PFN_SHUTDOWN_HANDLER shutdownCallback,
PFN_ASYNC_COMPLETION asyncCallback,
IntPtr pvRequestContext,
IntPtr pvShutdownContext,
out bool resetStandardStreams);
IntPtr pvShutdownContext);
[DllImport(AspNetCoreModuleDll)]
private static extern unsafe int http_write_response_bytes(IntPtr pInProcessHandler, HttpApiTypes.HTTP_DATA_CHUNK* pDataChunks, int nChunks, out bool fCompletionExpected);
@ -147,10 +146,9 @@ namespace Microsoft.AspNetCore.Server.IIS
PFN_SHUTDOWN_HANDLER shutdownCallback,
PFN_ASYNC_COMPLETION asyncCallback,
IntPtr pvRequestContext,
IntPtr pvShutdownContext,
out bool resetStandardStreams)
IntPtr pvShutdownContext)
{
Validate(register_callbacks(pInProcessApplication, requestCallback, shutdownCallback, asyncCallback, pvRequestContext, pvShutdownContext, out resetStandardStreams));
Validate(register_callbacks(pInProcessApplication, requestCallback, shutdownCallback, asyncCallback, pvRequestContext, pvShutdownContext));
}
public static unsafe int HttpWriteResponseBytes(IntPtr pInProcessHandler, HttpApiTypes.HTTP_DATA_CHUNK* pDataChunks, int nChunks, out bool fCompletionExpected)

View File

@ -108,6 +108,7 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
public async Task CheckStdoutLoggingToPipe_DoesNotCrashProcess(string path)
{
var deploymentParameters = Helpers.GetBaseDeploymentParameters(publish: true);
deploymentParameters.GracefulShutdown = true;
var deploymentResult = await DeployAsync(deploymentParameters);
await Helpers.AssertStarts(deploymentResult, path);
@ -126,6 +127,8 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
public async Task CheckStdoutLoggingToPipeWithFirstWrite(string path)
{
var deploymentParameters = Helpers.GetBaseDeploymentParameters(publish: true);
deploymentParameters.GracefulShutdown = true;
var firstWriteString = path + path;
deploymentParameters.WebConfigBasedEnvironmentVariables["ASPNETCORE_INPROCESS_INITIAL_WRITE"] = firstWriteString;

View File

@ -29,9 +29,6 @@ namespace PipeOutputManagerTests
PipeOutputManager* pManager = new PipeOutputManager();
ASSERT_EQ(S_OK, pManager->Start());
pManager->NotifyStartupComplete();
}
TEST(PipeManagerOutputTest, SetInvalidHandlesForErrAndOut)
@ -47,8 +44,6 @@ namespace PipeOutputManagerTests
PipeOutputManager* pManager = new PipeOutputManager();
ASSERT_EQ(S_OK, pManager->Start());
pManager->NotifyStartupComplete();
_dup2(m_fdPreviousStdOut, _fileno(stdout));
_dup2(m_fdPreviousStdErr, _fileno(stderr));

View File

@ -30,7 +30,6 @@
<None Include="$(MSBuildThisFileDirectory)..\..\src\AspNetCoreModuleV2\AspNetCore\bin\$(Configuration)\x64\aspnetcorev2.pdb" CopyToOutputDirectory="PreserveNewest" Visible="true" Link="%(FileName)%(Extension)" />
</ItemGroup>
<ItemGroup>
<PackageReference Include="Microsoft.AspNetCore.Server.IntegrationTesting" Version="$(MicrosoftAspNetCoreServerIntegrationTestingPackageVersion)" />
<PackageReference Include="Microsoft.AspNetCore.Hosting" Version="$(MicrosoftAspNetCoreHostingPackageVersion)" />