fix regression in enforcing log file quota

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)
+	hasProcessExited(FALSE), truncatePending(FALSE)
 {
 	RtlZeroMemory(this->namedPipe, sizeof this->namedPipe);
 	RtlZeroMemory(&this->startupInfo, sizeof this->startupInfo);
@@ -326,37 +326,55 @@ Error:
 
 void CNodeProcess::FlushStdHandles()
 {
+	const char* truncateMessage = ">>>> iisnode truncated the log file because it exceeded the configured maximum size\n";
 	LARGE_INTEGER fileSize;
 
-	// truncate the log file back to 0 if the max size is exceeded
-
-	if (GetFileSizeEx(this->startupInfo.hStdOutput, &fileSize))
-	{
-		if (fileSize.QuadPart > this->maxLogSizeInBytes)
-		{
-			fileSize.QuadPart = 0;
-			if (SetFilePointerEx(this->startupInfo.hStdOutput, fileSize, NULL, FILE_BEGIN))
-			{
-				SetEndOfFile(this->startupInfo.hStdOutput);
-			}
-		}
-	}
-
 	// flush the file
 
 	FlushFileBuffers(this->startupInfo.hStdOutput);
+
+	// truncate the log file back to 0 if the max size is exceeded
+
+	if (!this->truncatePending && GetFileSizeEx(this->startupInfo.hStdOutput, &fileSize))
+	{
+		if (fileSize.QuadPart > this->maxLogSizeInBytes)
+		{			
+			RtlZeroMemory(&this->overlapped, sizeof this->overlapped); // this also sets the Offset and OffsetHigh to 0		
+			this->overlapped.hEvent = this;
+			this->truncatePending = TRUE; // this will be reset to FALSE in the completion routine of WriteFileEx below
+			if (!WriteFileEx(
+				this->startupInfo.hStdOutput, 
+				(void*)truncateMessage, 
+				strlen(truncateMessage), 
+				&this->overlapped, 
+				CNodeProcess::TruncateLogFileCompleted)) 
+			{
+				this->truncatePending = FALSE;
+			}
+		}
+	}
+}
+
+void CALLBACK CNodeProcess::TruncateLogFileCompleted(DWORD dwErrorCode, DWORD dwNumberOfBytesTransfered, LPOVERLAPPED lpOverlapped)
+{
+	CNodeProcess* process = (CNodeProcess*)lpOverlapped->hEvent;
+	process->truncatePending = FALSE;
+	SetEndOfFile(process->startupInfo.hStdOutput);
+	FlushFileBuffers(process->startupInfo.hStdOutput);
 }
 
 unsigned int WINAPI CNodeProcess::ProcessWatcher(void* arg)
 {
 	CNodeProcess* process = (CNodeProcess*)arg;
 	DWORD exitCode;
+	DWORD waitResult;
 	CNodeEventProvider* log = process->GetProcessManager()->GetEventProvider();
 	BOOL isDebugger = process->GetProcessManager()->GetApplication()->IsDebugger();
 
 	while (!process->isClosing && process->process)
 	{
-		if (WAIT_TIMEOUT == WaitForSingleObject(process->process, process->loggingEnabled ? process->logFlushInterval : INFINITE))
+		waitResult = WaitForSingleObjectEx(process->process, process->loggingEnabled ? process->logFlushInterval : INFINITE, TRUE);
+		if (WAIT_TIMEOUT == waitResult)
 		{
 			process->FlushStdHandles();
 
@@ -498,7 +516,7 @@ HRESULT CNodeProcess::CreateStdHandles(IHttpContext* context)
 	creationDisposition = CModuleConfiguration::GetAppendToExistingLog(context) ? OPEN_ALWAYS : CREATE_ALWAYS;
 	ErrorIf(INVALID_HANDLE_VALUE == (this->startupInfo.hStdOutput = CreateFileW(
 		logName,
-		GENERIC_READ | FILE_APPEND_DATA,
+		GENERIC_READ | GENERIC_WRITE,
 		FILE_SHARE_READ | FILE_SHARE_WRITE,
 		&security,
 		creationDisposition,

src/iisnode/cnodeprocess.h

@@ -22,11 +22,14 @@ private:
 	DWORD logFlushInterval;
 	LONGLONG maxLogSizeInBytes;
 	BOOL hasProcessExited;
+	OVERLAPPED overlapped;
+	BOOL truncatePending;
 
 	static unsigned int WINAPI ProcessWatcher(void* arg);
 	void OnProcessExited();
 	HRESULT CreateStdHandles(IHttpContext* context);
 	void FlushStdHandles();	
+	static void CALLBACK TruncateLogFileCompleted(DWORD dwErrorCode, DWORD dwNumberOfBytesTransfered, LPOVERLAPPED lpOverlapped);
 
 public:
 

src/iisnode/iisnode.vcxproj

@@ -238,6 +238,7 @@ call "$(ProjectDir)\scripts\genDebuggerRc.bat" > "$(ProjectDir)\debugger_auto
     <None Include="..\..\test\functional\tests\107_filesystem.js" />
     <None Include="..\..\test\functional\tests\108_appsettings.js" />
     <None Include="..\..\test\functional\tests\109_helloworld_debug.js" />
+    <None Include="..\..\test\functional\tests\110_log_size_quota.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" />
@@ -263,6 +264,8 @@ call "$(ProjectDir)\scripts\genDebuggerRc.bat" &gt; "$(ProjectDir)\debugger_auto
     <None Include="..\..\test\functional\www\107_filesystem\web.config" />
     <None Include="..\..\test\functional\www\108_appsettings\hello.js" />
     <None Include="..\..\test\functional\www\108_appsettings\web.config" />
+    <None Include="..\..\test\functional\www\110_log_size_quota\hello.js" />
+    <None Include="..\..\test\functional\www\110_log_size_quota\web.config" />
     <None Include="..\config\iisnode_schema.xml" />
     <None Include="..\config\iisnode_schema_x64.xml" />
     <None Include="..\samples\configuration\hello.js" />

src/iisnode/iisnode.vcxproj.filters

@@ -88,6 +88,9 @@
     <Filter Include="Tests\functional\www\108_appsettings">
       <UniqueIdentifier>{f56c1f46-66cb-4585-adde-0ae7b04c5ee4}</UniqueIdentifier>
     </Filter>
+    <Filter Include="Tests\functional\www\110_log_size_quota">
+      <UniqueIdentifier>{babb03c5-c688-4393-beaa-65f34782c77c}</UniqueIdentifier>
+    </Filter>
   </ItemGroup>
   <ItemGroup>
     <ClCompile Include="main.cpp">
@@ -394,6 +397,15 @@
     <None Include="..\..\test\functional\tests\109_helloworld_debug.js">
       <Filter>Tests\functional\tests</Filter>
     </None>
+    <None Include="..\..\test\functional\www\110_log_size_quota\hello.js">
+      <Filter>Tests\functional\www\110_log_size_quota</Filter>
+    </None>
+    <None Include="..\..\test\functional\www\110_log_size_quota\web.config">
+      <Filter>Tests\functional\www\110_log_size_quota</Filter>
+    </None>
+    <None Include="..\..\test\functional\tests\110_log_size_quota.js">
+      <Filter>Tests\functional\tests</Filter>
+    </None>
   </ItemGroup>
   <ItemGroup>
     <ResourceCompile Include="debugger.rc">

test/functional/tests/110_log_size_quota.js

@@ -0,0 +1,11 @@
+/*
+Log file is truncated if it exceeds configured maximum size
+*/
+
+var iisnodeassert = require("iisnodeassert");
+
+iisnodeassert.sequence([
+    iisnodeassert.get(10000, "/110_log_size_quota/hello.js", 200, "Hello, world"),
+    iisnodeassert.wait(1000), // wait for 1 second - configured log flush interval is 500 ms
+    iisnodeassert.get(2000, "/110_log_size_quota/hello.js.logs/0.txt", 200, ">>>> iisnode truncated the log file because it exceeded the configured maximum size\n")
+]);

test/functional/www/110_log_size_quota/hello.js

@@ -0,0 +1,10 @@
+var http = require('http');
+
+var s = "01";
+for (var i = 0; i < 9; i++) s = s + s;
+
+http.createServer(function (req, res) {
+    console.log(s);
+    res.writeHead(200, { 'Content-Type': 'text/html' });
+    res.end('Hello, world');
+}).listen(process.env.PORT);  

test/functional/www/110_log_size_quota/web.config

@@ -0,0 +1,8 @@
+<configuration>
+  <system.webServer>
+    <handlers>
+      <add name="iisnode" path="hello.js" verb="*" modules="iisnode" />
+    </handlers>
+    <iisnode logFileFlushInterval="500" maxLogFileSizeInKB="1" />
+  </system.webServer>
+</configuration>