fix #278: ref counting and error handling cleanup during recycle

tjanczuk · tjanczuk · commit c4139ad7f02e · 2013-05-06T13:01:01.000-07:00
diff --git a/src/iisnode/cnodeapplication.cpp b/src/iisnode/cnodeapplication.cpp
@@ -86,7 +86,9 @@ HRESULT CNodeApplication::Dispatch(IHttpContext* context, IHttpEventProvider* pP
 	// CProtocolBridge::FinalizeResponseCore, possibly after several context switches
 	(*ctx)->IncreasePendingAsyncOperationCount(); 
 
-	CheckError(this->processManager->Dispatch(*ctx));
+	// At this point ownership of the request is handed over to Dispach below, including error handling.
+	// Therefore we don't propagate any errors up the stack.
+	this->processManager->Dispatch(*ctx);
 
 	return S_OK;
 
diff --git a/src/iisnode/cnodehttpmodule.cpp b/src/iisnode/cnodehttpmodule.cpp
@@ -14,7 +14,6 @@ REQUEST_NOTIFICATION_STATUS CNodeHttpModule::OnSendResponse(IN IHttpContext* pHt
 		if (NULL != ctx && ctx->GetIsUpgrade() && !ctx->GetOpaqueFlagSet())
 		{
 			// Set opaque mode in HTTP.SYS to enable exchanging raw bytes.
-
 			
 			pProvider->SetFlags(flags | HTTP_SEND_RESPONSE_FLAG_OPAQUE);
 			ctx->SetOpaqueFlag();
@@ -37,25 +36,64 @@ REQUEST_NOTIFICATION_STATUS CNodeHttpModule::OnExecuteRequestHandler(
 	this->applicationManager->GetEventProvider()->Log(L"iisnode received a new http request", WINEVENT_LEVEL_INFO);
 
 	CheckError(this->applicationManager->Dispatch(pHttpContext, pProvider, &ctx));
+	this->applicationManager->GetEventProvider()->Log(L"iisnode dispatched new http request", WINEVENT_LEVEL_INFO, ctx->GetActivityId());
 	ASYNC_CONTEXT* async = ctx->GetAsyncContext();
 	async->RunSynchronousContinuations();
 
+	REQUEST_NOTIFICATION_STATUS result;
 	if (0 == ctx->DecreasePendingAsyncOperationCount()) // decreases ref count set to 1 in the ctor of CNodeHttpStoredContext
 	{
-		return ctx->GetRequestNotificationStatus();
+		result = ctx->GetRequestNotificationStatus();
 	}
 	else
 	{
-		return RQ_NOTIFICATION_PENDING;
+		result = RQ_NOTIFICATION_PENDING;
 	}
 
+	switch (result) 
+	{
+	default:
+		this->applicationManager->GetEventProvider()->Log(
+			L"iisnode leaves CNodeHttpModule::OnExecuteRequestHandler", 
+			WINEVENT_LEVEL_VERBOSE, 
+			ctx->GetActivityId());
+		break;
+	case RQ_NOTIFICATION_CONTINUE:
+		this->applicationManager->GetEventProvider()->Log(
+			L"iisnode leaves CNodeHttpModule::OnExecuteRequestHandler with RQ_NOTIFICATION_CONTINUE", 
+			WINEVENT_LEVEL_VERBOSE, 
+			ctx->GetActivityId());
+		break;
+	case RQ_NOTIFICATION_FINISH_REQUEST:
+		this->applicationManager->GetEventProvider()->Log(
+			L"iisnode leaves CNodeHttpModule::OnExecuteRequestHandler with RQ_NOTIFICATION_FINISH_REQUEST", 
+			WINEVENT_LEVEL_VERBOSE, 
+			ctx->GetActivityId());
+		break;
+	case RQ_NOTIFICATION_PENDING:
+		this->applicationManager->GetEventProvider()->Log(
+			L"iisnode leaves CNodeHttpModule::OnExecuteRequestHandler with RQ_NOTIFICATION_PENDING", 
+			WINEVENT_LEVEL_VERBOSE, 
+			ctx->GetActivityId());
+		break;
+	};
+
+	return result;
+
 Error:
 
 	CNodeEventProvider* log = this->applicationManager->GetEventProvider();
 
 	if (log)
 	{
-		log->Log(L"iisnode failed to process a new http request", WINEVENT_LEVEL_INFO);
+		if (ctx)
+		{
+			log->Log(L"iisnode failed to process a new http request", WINEVENT_LEVEL_INFO, ctx->GetActivityId());
+		}
+		else
+		{
+			log->Log(L"iisnode failed to process a new http request", WINEVENT_LEVEL_INFO);
+		}
 	}
 
 	if (ERROR_NOT_ENOUGH_QUOTA == hr)
@@ -181,22 +219,39 @@ REQUEST_NOTIFICATION_STATUS CNodeHttpModule::OnAsyncCompletion(
 			async->RunSynchronousContinuations();
 		}
 
-		if (0 == ctx->DecreasePendingAsyncOperationCount()) // decreases ref count increased on entering OnAsyncCompletion
+		ctx->DecreasePendingAsyncOperationCount();
+
+		REQUEST_NOTIFICATION_STATUS result = ctx->GetRequestNotificationStatus();
+
+		switch (result) 
 		{
+		default:
 			this->applicationManager->GetEventProvider()->Log(
-				L"iisnode leaves CNodeHttpModule::OnAsyncCompletion and completes the request", 
+				L"iisnode leaves CNodeHttpModule::OnAsyncCompletion", 
 				WINEVENT_LEVEL_VERBOSE, 
 				ctx->GetActivityId());
-			return ctx->GetRequestNotificationStatus();
-		}
-		else
-		{
+			break;
+		case RQ_NOTIFICATION_CONTINUE:
 			this->applicationManager->GetEventProvider()->Log(
-				L"iisnode leaves CNodeHttpModule::OnAsyncCompletion and continues the request", 
+				L"iisnode leaves CNodeHttpModule::OnAsyncCompletion with RQ_NOTIFICATION_CONTINUE", 
 				WINEVENT_LEVEL_VERBOSE, 
 				ctx->GetActivityId());
-			return RQ_NOTIFICATION_PENDING;
-		}
+			break;
+		case RQ_NOTIFICATION_FINISH_REQUEST:
+			this->applicationManager->GetEventProvider()->Log(
+				L"iisnode leaves CNodeHttpModule::OnAsyncCompletion with RQ_NOTIFICATION_FINISH_REQUEST", 
+				WINEVENT_LEVEL_VERBOSE, 
+				ctx->GetActivityId());
+			break;
+		case RQ_NOTIFICATION_PENDING:
+			this->applicationManager->GetEventProvider()->Log(
+				L"iisnode leaves CNodeHttpModule::OnAsyncCompletion with RQ_NOTIFICATION_PENDING", 
+				WINEVENT_LEVEL_VERBOSE, 
+				ctx->GetActivityId());
+			break;
+		};
+
+		return result;
 	}
 
 	return RQ_NOTIFICATION_CONTINUE;
diff --git a/src/iisnode/cnodehttpstoredcontext.cpp b/src/iisnode/cnodehttpstoredcontext.cpp
@@ -15,16 +15,10 @@ CNodeHttpStoredContext::CNodeHttpStoredContext(CNodeApplication* nodeApplication
 	this->responseChunk.FromMemory.pBuffer = NULL;
 
 	RtlZeroMemory(&this->asyncContext, sizeof(ASYNC_CONTEXT));
-	if (NULL != (tctx = context->GetTraceContext()) && NULL != (pguid = tctx->GetTraceActivityId()))
-	{
-		memcpy(&this->activityId, pguid, sizeof GUID);
-	}
-	else
-	{
-		CoCreateGuid(&this->activityId);
-	}
+	CoCreateGuid(&this->activityId);
 	
 	this->asyncContext.data = this;
+	this->eventProvider = nodeApplication->GetApplicationManager()->GetEventProvider();
 }
 
 CNodeHttpStoredContext::~CNodeHttpStoredContext()
@@ -287,6 +281,10 @@ GUID* CNodeHttpStoredContext::GetActivityId()
 
 long CNodeHttpStoredContext::IncreasePendingAsyncOperationCount()
 {
+	this->eventProvider->Log(
+		L"iisnode increases pending async operation count", 
+		WINEVENT_LEVEL_VERBOSE, 
+		this->GetActivityId());
 	if (this->requestPumpStarted)
 	{
 		return InterlockedIncrement(&this->upgradeContext->pendingAsyncOperationCount);
@@ -299,6 +297,10 @@ long CNodeHttpStoredContext::IncreasePendingAsyncOperationCount()
 
 long CNodeHttpStoredContext::DecreasePendingAsyncOperationCount()
 {
+	this->eventProvider->Log(
+		L"iisnode decreases pending async operation count", 
+		WINEVENT_LEVEL_VERBOSE, 
+		this->GetActivityId());
 	if (this->requestPumpStarted)
 	{
 		return InterlockedDecrement(&this->upgradeContext->pendingAsyncOperationCount);
@@ -456,4 +458,4 @@ void CNodeHttpStoredContext::SetBytesCompleted(DWORD bytesCompleted)
 void CNodeHttpStoredContext::SetContinueSynchronously(BOOL continueSynchronously)
 {
 	this->asyncContext.continueSynchronously = continueSynchronously;
-}
+}
diff --git a/src/iisnode/cnodehttpstoredcontext.h b/src/iisnode/cnodehttpstoredcontext.h
@@ -24,7 +24,7 @@ class CNodeHttpStoredContext : public IHttpStoredContext
 	BOOL isChunked;
 	HRESULT result;
 	REQUEST_NOTIFICATION_STATUS requestNotificationStatus;	
-	long pendingAsyncOperationCount;
+	long volatile pendingAsyncOperationCount;
 	PCSTR targetUrl;
 	DWORD targetUrlLength;
 	IHttpContext* childContext;
@@ -39,6 +39,7 @@ class CNodeHttpStoredContext : public IHttpStoredContext
 	FILETIME startTime;
 	HTTP_DATA_CHUNK responseChunk;
 	DWORD responseChunkBufferSize;
+	CNodeEventProvider* eventProvider;
 
 public:
 
diff --git a/src/iisnode/cnodeprocessmanager.cpp b/src/iisnode/cnodeprocessmanager.cpp
@@ -145,11 +145,18 @@ HRESULT CNodeProcessManager::Dispatch(CNodeHttpStoredContext* request)
 				}
 
 				CheckError(this->processes[processToUse]->AcceptRequest(request));
+				request = NULL;
 			}
 
 			LEAVE_SRW_EXCLUSIVE(this->srwlock)
 		}
 	}
+	
+	if (request)
+	{
+		this->GetEventProvider()->Log(L"iisnode failed to accept a request beacuse the application is recycling", WINEVENT_LEVEL_ERROR, request->GetActivityId());
+		CProtocolBridge::SendEmptyResponse(request, 503, _T("Service Unavailable"), IISNODE_ERROR_APPLICATION_IS_RECYCLING);
+	}
 
 	this->DecRef(); // incremented at the beginning of this method
 
diff --git a/src/iisnode/errors.h b/src/iisnode/errors.h
@@ -10,5 +10,6 @@
 #define IISNODE_ERROR_UNABLE_TO_READ_CONFIGURATION 1031L
 #define IISNODE_ERROR_UNABLE_TO_READ_CONFIGURATION_OVERRIDE 1032L
 #define IISNODE_ERROR_UNABLE_TO_READ_CONFIGURATION_FROM_ENVIRONMENT 1033L
+#define IISNODE_ERROR_APPLICATION_IS_RECYCLING 1034L
 
 #endif

Original file line number	Diff line number	Diff line change
`@@ -145,11 +145,18 @@ HRESULT CNodeProcessManager::Dispatch(CNodeHttpStoredContext* request)`
`145`	`145`	`}`
`146`	`146`
`147`	`147`	`CheckError(this->processes[processToUse]->AcceptRequest(request));`
	`148`	`+ request = NULL;`
`148`	`149`	`}`
`149`	`150`
`150`	`151`	`LEAVE_SRW_EXCLUSIVE(this->srwlock)`
`151`	`152`	`}`
`152`	`153`	`}`
	`154`	`+`
	`155`	`+ if (request)`
	`156`	`+ {`
	`157`	`+ this->GetEventProvider()->Log(L"iisnode failed to accept a request beacuse the application is recycling", WINEVENT_LEVEL_ERROR, request->GetActivityId());`
	`158`	`+ CProtocolBridge::SendEmptyResponse(request, 503, _T("Service Unavailable"), IISNODE_ERROR_APPLICATION_IS_RECYCLING);`
	`159`	`+ }`
`153`	`160`
`154`	`161`	`this->DecRef(); // incremented at the beginning of this method`
`155`	`162`