fix #55: support friendly HTTP 200 errors with node.exe log capture i…

…n dev scenarios
Azure · Jan 12, 2012 · aba0c73 · aba0c73
1 parent 6e68c03
commit aba0c73
Show file tree

Hide file tree

Showing 9 changed files with 284 additions and 15 deletions.
diff --git a/src/iisnode/cnodeprocess.cpp b/src/iisnode/cnodeprocess.cpp
@@ -2,7 +2,7 @@
 
 CNodeProcess::CNodeProcess(CNodeProcessManager* processManager, IHttpContext* context, DWORD ordinal)
 	: processManager(processManager), process(NULL), processWatcher(NULL), isClosing(FALSE), ordinal(ordinal),
-	hasProcessExited(FALSE), truncatePending(FALSE)
+	hasProcessExited(FALSE), truncatePending(FALSE), logName(NULL)
 {
 	RtlZeroMemory(this->namedPipe, sizeof this->namedPipe);
 	RtlZeroMemory(&this->startupInfo, sizeof this->startupInfo);
@@ -45,6 +45,12 @@ CNodeProcess::~CNodeProcess()
 		CloseHandle(this->startupInfo.hStdError);
 		this->startupInfo.hStdError = INVALID_HANDLE_VALUE;
 	}	
+
+	if (NULL != this->logName)
+	{
+		delete [] this->logName;
+		this->logName = NULL;
+	}
 }
 
 HRESULT CNodeProcess::Initialize(IHttpContext* context)
@@ -468,7 +474,6 @@ HRESULT CNodeProcess::CreateStdHandles(IHttpContext* context)
 	this->startupInfo.dwFlags = STARTF_USESTDHANDLES;
 
 	HRESULT hr;
-	WCHAR* logName = NULL;
 	SECURITY_ATTRIBUTES security;
 	DWORD creationDisposition;
 
@@ -539,21 +544,9 @@ HRESULT CNodeProcess::CreateStdHandles(IHttpContext* context)
 		DUPLICATE_SAME_ACCESS),
 		GetLastError());
 
-	if (NULL != logName)
-	{
-		delete [] logName;
-		logName = NULL;
-	}
-
 	return S_OK;
 Error:
 
-	if (NULL != logName)
-	{
-		delete [] logName;
-		logName = NULL;
-	}
-
 	if (INVALID_HANDLE_VALUE != this->startupInfo.hStdOutput)
 	{
 		CloseHandle(this->startupInfo.hStdOutput);
@@ -573,3 +566,54 @@ CConnectionPool* CNodeProcess::GetConnectionPool()
 {
 	return &this->connectionPool;
 }
+
+char* CNodeProcess::TryGetLog(IHttpContext* context, DWORD* size)
+{
+	HRESULT hr;
+	HANDLE file = INVALID_HANDLE_VALUE;
+	char* log = NULL;
+	*size = 0;
+
+	if (this->logName)
+	{
+		ErrorIf(INVALID_HANDLE_VALUE == (file = CreateFileW(
+			this->logName,
+			GENERIC_READ,
+			FILE_SHARE_READ | FILE_SHARE_WRITE, 
+			NULL,
+			OPEN_EXISTING,
+			0,
+			NULL)), GetLastError());
+
+		ErrorIf(INVALID_FILE_SIZE == (*size = GetFileSize(file, NULL)), GetLastError());
+
+		if (*size > 65536)
+		{
+			// if log is larger than 64k, return only the last 64k
+
+			*size = 65536;
+			ErrorIf(INVALID_SET_FILE_POINTER == SetFilePointer(file, *size, NULL, FILE_END), GetLastError());
+		}
+
+		ErrorIf(NULL == (log = (char*)context->AllocateRequestMemory(*size)), ERROR_NOT_ENOUGH_MEMORY);
+		ErrorIf(0 == ReadFile(file, log, *size, size, NULL), GetLastError());
+
+		CloseHandle(file);
+		file = INVALID_HANDLE_VALUE;
+	}
+
+	return log;
+Error:
+
+	if (INVALID_HANDLE_VALUE != file)
+	{
+		CloseHandle(file);
+		file = INVALID_HANDLE_VALUE;
+	}
+
+	// log does not need to be freed - IIS will take care of it when IHttpContext is disposed
+
+	*size = 0;
+
+	return NULL;
+}
diff --git a/src/iisnode/cnodeprocess.h b/src/iisnode/cnodeprocess.h
@@ -25,6 +25,7 @@ class CNodeProcess
 	OVERLAPPED overlapped;
 	BOOL truncatePending;
 	CConnectionPool connectionPool;
+	WCHAR* logName;
 
 	static unsigned int WINAPI ProcessWatcher(void* arg);
 	void OnProcessExited();
@@ -44,6 +45,7 @@ class CNodeProcess
 	HRESULT AcceptRequest(CNodeHttpStoredContext* context);
 	void OnRequestCompleted(CNodeHttpStoredContext* context);	
 	void SignalWhenDrained(HANDLE handle);
+	char* TryGetLog(IHttpContext* context, DWORD* size);
 };
 
 #endif
diff --git a/src/iisnode/cprotocolbridge.cpp b/src/iisnode/cprotocolbridge.cpp
@@ -214,6 +214,189 @@ BOOL CProtocolBridge::SendIisnodeError(CNodeHttpStoredContext* ctx, HRESULT hr)
 	return FALSE;
 }
 
+BOOL CProtocolBridge::SendDevError(CNodeHttpStoredContext* context, USHORT status, PCTSTR reason, HRESULT hresult, BOOL disableCache)
+{
+	HRESULT hr;
+	DWORD rawLogSize, htmlLogSize, htmlTotalSize;
+	IHttpContext* ctx;
+	char* rawLog;
+	char* templ1;
+	char* html;
+	char* current;
+
+	if (500 <= status && CModuleConfiguration::GetDevErrorsEnabled(context->GetHttpContext()) && NULL != context->GetNodeProcess())
+	{
+		// return a friendly HTTP 200 response with HTML entity body that contains error details 
+		// and the content of node.exe stdout/err, if available
+
+		ctx = context->GetHttpContext();		
+		rawLog = context->GetNodeProcess()->TryGetLog(ctx, &rawLogSize);
+		templ1 = 
+			"<p>iisnode encountered an error when processing the request.</p><pre style=\"background-color: eeeeee\">"
+			"HRESULT: 0x%x\n"
+			"HTTP status: %d\n"
+			"HTTP reason: %s</pre>"
+			"<p>You are receiving this HTTP 200 response because <a href=""https://github.com/tjanczuk/iisnode/blob/master/src/samples/configuration/web.config"">"
+			"system.webServer/iisnode/@devErrorsEnabled</a> configuration setting is 'true'.</p>"
+			"<p>In addition to the log of stdout and stderr of the node.exe process, consider using "
+			"<a href=""http://tomasz.janczuk.org/2011/11/debug-nodejs-applications-on-windows.html"">debugging</a> "
+			"and <a href=""http://tomasz.janczuk.org/2011/09/using-event-tracing-for-windows-to.html"">ETW traces</a> to further diagnose the problem.</p>";
+
+		// calculate HTML encoded size of the log
+
+		htmlLogSize = 0;
+		for (int i = 0; i < rawLogSize; i++)
+		{
+			if (rawLog[i] >= 0 && rawLog[i] <= 0x8
+				|| rawLog[i] >= 0xb && rawLog[i] <= 0xc
+				|| rawLog[i] >= 0xe && rawLog[i] <= 0x1f
+				|| rawLog[i] >= 0x80 && rawLog[i] <= 0x9f)
+			{
+				// characters disallowed in HTML will be converted to [xAB] notation, thus taking 5 bytes
+				htmlLogSize += 5;
+			}
+			else
+			{
+				switch (rawLog[i]) 
+				{
+				default:
+					htmlLogSize++; 
+					break;
+				case '&':
+					htmlLogSize += 5; // &amp;
+					break;
+				case '<':
+				case '>':
+					htmlLogSize += 4; // &lt; &gt;
+					break;
+				case '"':
+				case '\'':
+					htmlLogSize += 6; // &quot; &apos;
+					break;
+				};
+			}
+		}
+
+		// calculate total size of HTML and allocate memory
+
+		htmlTotalSize = strlen(templ1) + 20 /* hresult */ + 20 /* status code */ + strlen(reason) + 300 /* log content heading */ + htmlLogSize;
+		ErrorIf(NULL == (html = (char*)ctx->AllocateRequestMemory(htmlTotalSize)), ERROR_NOT_ENOUGH_MEMORY);
+		RtlZeroMemory(html, htmlTotalSize);
+
+		// construct the HTML
+
+		sprintf(html, templ1, hresult, status, reason);
+
+		if (0 == rawLogSize)
+		{
+			if (CModuleConfiguration::GetLoggingEnabled(ctx))
+			{
+				strcat(html, "<p>The node.exe process has not written any information to the stdout or stderr.</p>");
+			}
+			else
+			{
+				strcat(html, "<p>You may get additional information about this error condition by logging stdout and stderr of the node.exe process."
+					"To enable logging, set the <a href=""https://github.com/tjanczuk/iisnode/blob/master/src/samples/configuration/web.config"">"
+					"system.webServer/iisnode/@loggingEnabled</a> configuration setting to 'true' (current value is 'false').</p>");
+			}
+		}
+		else
+		{
+			strcat(html, "<p>The last 64k of the output generated by the node.exe process to stdout and stderr is shown below:</p><pre style=\"background-color: eeeeee\">");
+
+			current = html + strlen(html);
+
+			if (htmlLogSize == rawLogSize)
+			{
+				// no HTML encoding is necessary
+
+				memcpy(current, rawLog, rawLogSize);
+			}
+			else
+			{
+				// HTML encode the log
+
+				for (int i = 0; i < rawLogSize; i++)
+				{
+					if (rawLog[i] >= 0 && rawLog[i] <= 0x8
+						|| rawLog[i] >= 0xb && rawLog[i] <= 0xc
+						|| rawLog[i] >= 0xe && rawLog[i] <= 0x1f
+						|| rawLog[i] >= 0x80 && rawLog[i] <= 0x9f)
+					{
+						// characters disallowed in HTML are converted to [xAB] notation
+						*current++ = '[';
+						*current++ = 'x';
+						*current = rawLog[i] >> 4;
+						*current++ += *current > 9 ? 'A' - 10 : '0';
+						*current = rawLog[i] & 15;
+						*current++ += *current > 9 ? 'A' - 10 : '0';
+						*current++ = ']';
+					}
+					else
+					{
+						switch (rawLog[i]) 
+						{
+						default:
+							*current++ = rawLog[i];
+							break;
+						case '&':
+							*current++ = '&';
+							*current++ = 'a';
+							*current++ = 'm';
+							*current++ = 'p';
+							*current++ = ';';
+							break;
+						case '<':
+							*current++ = '&';
+							*current++ = 'l';
+							*current++ = 't';
+							*current++ = ';';
+							break;
+						case '>':
+							*current++ = '&';
+							*current++ = 'g';
+							*current++ = 't';
+							*current++ = ';';
+							break;
+						case '"':
+							*current++ = '&';
+							*current++ = 'q';
+							*current++ = 'u';
+							*current++ = 'o';
+							*current++ = 't';
+							*current++ = ';';
+							break;
+						case '\'':
+							*current++ = '&';
+							*current++ = 'a';
+							*current++ = 'p';
+							*current++ = 'o';
+							*current++ = 's';
+							*current++ = ';';
+							break;
+						};
+					}
+				}
+			}
+		}
+
+		// send the response
+
+		CheckError(CProtocolBridge::SendSyncResponse(
+			ctx,
+			200,
+			"OK",
+			hresult,
+			TRUE,
+			html));
+
+		return true;
+	}
+
+Error:
+	return false;
+}
+
 HRESULT CProtocolBridge::SendEmptyResponse(CNodeHttpStoredContext* context, USHORT status, PCTSTR reason, HRESULT hresult, BOOL disableCache)
 {
 	context->GetNodeApplication()->GetApplicationManager()->GetEventProvider()->Log(
@@ -225,7 +408,12 @@ HRESULT CProtocolBridge::SendEmptyResponse(CNodeHttpStoredContext* context, USHO
 		context->SetPipe(INVALID_HANDLE_VALUE);
 	}
 
-	CProtocolBridge::SendEmptyResponse(context->GetHttpContext(), status, reason, hresult, disableCache);	
+	if (!CProtocolBridge::SendDevError(context, status, reason, hresult, disableCache))
+	{
+		// return default IIS response
+
+		CProtocolBridge::SendEmptyResponse(context->GetHttpContext(), status, reason, hresult, disableCache);	
+	}
 
 	CProtocolBridge::FinalizeResponseCore(
 		context, 

diff --git a/src/iisnode/cprotocolbridge.h b/src/iisnode/cprotocolbridge.h
@@ -13,6 +13,7 @@ class CProtocolBridge
 	static HRESULT EnsureBuffer(CNodeHttpStoredContext* context);
 	static HRESULT FinalizeResponseCore(CNodeHttpStoredContext * context, REQUEST_NOTIFICATION_STATUS status, HRESULT error, CNodeEventProvider* log, PCWSTR etw, UCHAR level);
 	static BOOL IsLocalCall(IHttpContext* ctx);
+	static BOOL SendDevError(CNodeHttpStoredContext* context, USHORT status, PCTSTR reason, HRESULT hresult, BOOL disableCache = FALSE);
 
 	// processing stages
 	static void WINAPI ChildContextCompleted(DWORD error, DWORD bytesTransfered, LPOVERLAPPED overlapped);

diff --git a/src/iisnode/iisnode.vcxproj b/src/iisnode/iisnode.vcxproj
@@ -253,6 +253,7 @@ copy /y $(ProjectDir)\..\config\* $(ProjectDir)\..\..\build\$(Configuration)\$(P
     <None Include="..\..\test\functional\tests\117_autoupdate_dependency.bat" />
     <None Include="..\..\test\functional\tests\118_xff.js" />
     <None Include="..\..\test\functional\tests\119_servervars.js" />
+    <None Include="..\..\test\functional\tests\120_dev_errors_exception.js" />
     <None Include="..\..\test\functional\tests\200_samples.bat" />
     <None Include="..\..\test\functional\tests\node_modules\iisnodeassert.js" />
     <None Include="..\..\test\functional\tests\parts\106_autoupdate_first.js" />
@@ -304,6 +305,8 @@ copy /y $(ProjectDir)\..\config\* $(ProjectDir)\..\..\build\$(Configuration)\$(P
     <None Include="..\..\test\functional\www\118_xff\web.config" />
     <None Include="..\..\test\functional\www\119_servervars\hello.js" />
     <None Include="..\..\test\functional\www\119_servervars\web.config" />
+    <None Include="..\..\test\functional\www\120_dev_errors_exception\hello.js" />
+    <None Include="..\..\test\functional\www\120_dev_errors_exception\web.config" />
     <None Include="..\..\test\performance\client.bat" />
     <None Include="..\..\test\performance\localRun.bat" />
     <None Include="..\..\test\performance\readme.txt" />

diff --git a/src/iisnode/iisnode.vcxproj.filters b/src/iisnode/iisnode.vcxproj.filters
@@ -126,6 +126,9 @@
     <Filter Include="Tests\functional\www\119_servervars">
       <UniqueIdentifier>{4595469d-4085-4631-836b-08584244a9e7}</UniqueIdentifier>
     </Filter>
+    <Filter Include="Tests\functional\www\120_dev_errors_exception">
+      <UniqueIdentifier>{39ff35f2-9b08-4689-8185-a10773c03ab0}</UniqueIdentifier>
+    </Filter>
   </ItemGroup>
   <ItemGroup>
     <ClCompile Include="main.cpp">
@@ -552,6 +555,15 @@
     <None Include="..\..\test\functional\www\119_servervars\web.config">
       <Filter>Tests\functional\www\119_servervars</Filter>
     </None>
+    <None Include="..\..\test\functional\tests\120_dev_errors_exception.js">
+      <Filter>Tests\functional\tests</Filter>
+    </None>
+    <None Include="..\..\test\functional\www\120_dev_errors_exception\hello.js">
+      <Filter>Tests\functional\www\120_dev_errors_exception</Filter>
+    </None>
+    <None Include="..\..\test\functional\www\120_dev_errors_exception\web.config">
+      <Filter>Tests\functional\www\120_dev_errors_exception</Filter>
+    </None>
   </ItemGroup>
   <ItemGroup>
     <ResourceCompile Include="iisnode.rc" />

diff --git a/test/functional/tests/120_dev_errors_exception.js b/test/functional/tests/120_dev_errors_exception.js
@@ -0,0 +1,9 @@
+/*
+When devErrorsEnabled="true", iisnode returns a friendly HTTP 200 response if unhandled exceptions are thrown in the application
+*/
+
+var iisnodeassert = require("iisnodeassert");
+
+iisnodeassert.sequence([
+    iisnodeassert.get(10000, "/120_dev_errors_exception/hello.js", 200)
+]);
diff --git a/test/functional/www/120_dev_errors_exception/hello.js b/test/functional/www/120_dev_errors_exception/hello.js
@@ -0,0 +1,3 @@
+console.log('This will have to be HTML encoded: "&<>\'';
+
+var http = require('idonotexist'); // this will throw an unhandled exception when node.exe starts