1. Updated Logging capability

2. Updated Windows unwindhandler() to delete HANDLE when signaled

meshcore/KVM/Windows/kvm.c

@@ -36,7 +36,7 @@ limitations under the License.
 #include <crtdbg.h>
 #endif
 
-// #define KVMDEBUGENABLED 1
+//#define KVMDEBUGENABLED 1
 ILibProcessPipe_SpawnTypes gProcessSpawnType = ILibProcessPipe_SpawnTypes_USER;
 int gProcessTSID = -1;
 extern int gRemoteMouseRenderDefault;
@@ -77,8 +77,10 @@ void KvmCriticalLog(const char* msg, const char* file, int line, int user1, int
 	if (DontDestroy == 0) CloseHandle(h);
 }
 #define KVMDEBUG(m,u) { KvmCriticalLog(m, __FILE__, __LINE__, u, GetLastError()); printf("KVMMSG: %s (%d,%d).\r\n", m, (int)u, (int)GetLastError()); }
+#define KVMDEBUG2 ILIBLOGMESSAGEX
 #else
 #define KVMDEBUG(m, u)
+#define KVMDEBUG2(...) 
 #endif
 
 int TILE_WIDTH = 0;
@@ -157,7 +159,7 @@ void kvm_setupSasPermissions()
 DWORD WINAPI kvm_ctrlaltdel(LPVOID Param)
 {
 	UNREFERENCED_PARAMETER( Param );
-	KVMDEBUG("kvm_ctrlaltdel", (int)Param);
+	KVMDEBUG("kvm_ctrlaltdel", (int)(uintptr_t)Param);
 	typedef VOID(WINAPI *SendSas)(BOOL asUser);
 	SendSas sas;
 
@@ -667,10 +669,12 @@ void kvm_pause(int pause)
 	{
 		if (pause == 0)
 		{
+			KVMDEBUG2("RESUME: KVM");
 			ILibProcessPipe_Pipe_Resume(ILibProcessPipe_Process_GetStdOut(gChildProcess));
 		}
 		else
 		{
+			KVMDEBUG2("PAUSE: KVM");
 			ILibProcessPipe_Pipe_Pause(ILibProcessPipe_Process_GetStdOut(gChildProcess));
 		}
 	}
@@ -999,16 +1003,19 @@ DWORD WINAPI kvm_server_mainloop_ex(LPVOID parm)
 					}
 					if (buf && !g_shutdown)
 					{
+						KVMDEBUG2("Writing JPEG: %llu bytes", tilesize);
 						switch (writeHandler((char*)buf, (int)tilesize, reserved))
 						{
 							case ILibTransport_DoneState_INCOMPLETE:
 								g_pause = 1;
 								ILibRemoteLogging_printf(ILibChainGetLogger(gILibChain), ILibRemoteLogging_Modules_Agent_KVM, ILibRemoteLogging_Flags_VerbosityLevel_2, "Agent KVM: KVM PAUSE");
+								KVMDEBUG2("JPEG WRITE resulted in PAUSE");
 								break;
 							case ILibTransport_DoneState_ERROR:
 								g_shutdown = 1; 
 								height = SCALED_HEIGHT; 
 								width = SCALED_WIDTH; 
+								KVMDEBUG2("JPEG WRITE resulted in ERROR");
 								break;
 						}
 						free(buf);
@@ -1125,6 +1132,10 @@ void kvm_relay_StdOutHandler(ILibProcessPipe_Process sender, char *buffer, size_
 
 	if (bufferLen > 4)
 	{
+		if (ntohs(((unsigned short*)(buffer))[0]) > 1000)
+		{
+			KVMDEBUG2("Invalid KVM Command received: %u", ntohs(((unsigned short*)(buffer))[0]));
+		}
 		if (ntohs(((unsigned short*)(buffer))[0]) == (unsigned short)MNG_JUMBO)
 		{
 			if (bufferLen > 8)
@@ -1132,20 +1143,25 @@ void kvm_relay_StdOutHandler(ILibProcessPipe_Process sender, char *buffer, size_
 				if (bufferLen >= (size_t)(8 + (int)ntohl(((unsigned int*)(buffer))[1])))
 				{
 					*bytesConsumed = 8 + (int)ntohl(((unsigned int*)(buffer))[1]);
+					KVMDEBUG2("Jumbo Packet received of size: %llu (bufferLen=%llu)", *bytesConsumed, bufferLen);
+
 					writeHandler(buffer, (int)*bytesConsumed, reserved);
 					return;
 				}
 			}
+			KVMDEBUG2("Accumulate => JUMBO: [%llu bytes] bufferLen=%llu ", (size_t)(8 + (int)ntohl(((unsigned int*)(buffer))[1])), bufferLen);
 		}
 		else
 		{
 			size = ntohs(((unsigned short*)(buffer))[1]);
 			if (size <= bufferLen)
 			{
+				KVMDEBUG2("KVM Command: [%u: %llu bytes]", ntohs(((unsigned short*)(buffer))[0]), size);
 				*bytesConsumed = size;
 				writeHandler(buffer, size, reserved);
 				return;
 			}
+			KVMDEBUG2("Accumulate => KVM Command: [%u: %d bytes] bufferLen=%llu ", ntohs(((unsigned short*)(buffer))[0]), bufferLen);
 		}
 	}
 	*bytesConsumed = 0;
@@ -1207,7 +1223,7 @@ int kvm_relay_restart(int paused, void *pipeMgr, char *exePath, ILibKVM_WriteHan
 
 	// Run the relay
 	g_shutdown = 0;
-	KVMDEBUG("kvm_relay_restart / end", (int)kvmthread);
+	KVMDEBUG("kvm_relay_restart / end", (int)(uintptr_t)kvmthread);
 
 	return 1;
 }

microscript/ILibDuktape_Polyfills.c

@@ -839,6 +839,11 @@ duk_ret_t ILibDuktape_Polyfills_Console_setInfoLevel(duk_context *ctx)
 
 	return(0);
 }
+duk_ret_t ILibDuktape_Polyfills_Console_setInfoMask(duk_context *ctx)
+{
+	ILIBLOGMESSAGEX2_SetMask(duk_require_uint(ctx, 0));
+	return(0);
+}
 duk_ret_t ILibDuktape_Polyfills_Console_rawLog(duk_context *ctx)
 {
 	char *val = (char*)duk_require_string(ctx, 0);
@@ -878,6 +883,7 @@ void ILibDuktape_Polyfills_Console(duk_context *ctx)
 	
 	ILibDuktape_CreateInstanceMethod(ctx, "setDestination", ILibDuktape_Polyfills_Console_setDestination, DUK_VARARGS);
 	ILibDuktape_CreateInstanceMethod(ctx, "setInfoLevel", ILibDuktape_Polyfills_Console_setInfoLevel, 1);
+	ILibDuktape_CreateInstanceMethod(ctx, "setInfoMask", ILibDuktape_Polyfills_Console_setInfoMask, 1);
 
 	duk_push_object(ctx);
 	duk_push_int(ctx, ILibDuktape_Console_DestinationFlags_DISABLED); duk_put_prop_string(ctx, -2, "DISABLED");

microstack/ILibParsers.c

@@ -134,6 +134,7 @@ void* gILibChain = NULL;	 // Global Chain Instance used for Remote Logging when
 
 ILibSemaphoreTrack_Handler ILibSemaphoreTrack_func = NULL;
 void* ILibSemaphoreTrack_user = NULL;
+uint32_t _g_logMessageX = 0;
 
 #define ILibChain_SIGMAX 32
 ILibLinkedList g_signalHandlers[ILibChain_SIGMAX] = { NULL };
@@ -2192,8 +2193,13 @@ int ILibChain_WindowsSelect(void *chain, fd_set *readset, fd_set *writeset, fd_s
 						// FALSE means to remove tha HANDLE
 						if (((ILibBaseChain*)chain)->currentHandle != NULL && ILibMemory_CanaryOK(info))
 						{
+							ILIBLOGMESSAGEX2(LOGEX_OVERLAPPED_IO, " * ILibChain_WindowsSelect(%p) [REMOVED]", ((ILibBaseChain*)chain)->currentHandle);
 							ILibLinkedList_Remove(info->node);
 						}
+						else
+						{
+							ILIBLOGMESSAGEX2(LOGEX_OVERLAPPED_IO, " * ILibChain_WindowsSelect(%p) [???] => %p, ", ((ILibBaseChain*)chain)->currentHandle);
+						}
 					}
 				}
 				((ILibBaseChain*)chain)->currentHandle = NULL;
@@ -3548,14 +3554,17 @@ BOOL ILibChain_ReadEx_Sink(void *chain, HANDLE h, ILibWaitHandle_ErrorStatus sta
 	DWORD bytesRead = 0;
 	DWORD err;
 
+
 	if (status == ILibWaitHandle_ErrorStatus_REMOVED)
 	{
+		ILIBLOGMESSAGEX2(LOGEX_OVERLAPPED_IO, "ILibChain_ReadEx_Sink(%p) [REMOVED]", h);
 		ILibMemory_Free(data);
 		return(FALSE);
 	}
 
 	if (GetOverlappedResult(data->fileHandle, data->p, &bytesRead, FALSE) && bytesRead > 0)
 	{
+		ILIBLOGMESSAGEX2(LOGEX_OVERLAPPED_IO, "ILibChain_ReadEx_Sink(%p) [bytesRead: %lu]", h, bytesRead);
 		if (data->handler != NULL) { data->handler(chain, data->fileHandle, ILibWaitHandle_ErrorStatus_NONE, data->buffer, bytesRead, data->user); }
 		ILibMemory_Free(data);
 		return(FALSE);
@@ -3564,12 +3573,14 @@ BOOL ILibChain_ReadEx_Sink(void *chain, HANDLE h, ILibWaitHandle_ErrorStatus sta
 	{
 		if ((err=GetLastError()) == ERROR_IO_PENDING)
 		{
+			ILIBLOGMESSAGEX2(LOGEX_OVERLAPPED_IO, "ILibChain_ReadEx_Sink(%p) [PENDING]", h);
 			// Still pending, so wait for another callback
 			return(TRUE);
 		}
 		else
 		{
 			// ERROR
+			ILIBLOGMESSAGEX2(LOGEX_OVERLAPPED_IO, "ILibChain_ReadEx_Sink(%p) [ERROR]", h);
 			if (data->handler != NULL) { data->handler(chain, data->fileHandle, ILibWaitHandle_ErrorStatus_IO_ERROR, data->buffer, 0, data->user); }
 			ILibMemory_Free(data);
 			return(FALSE);
@@ -3614,8 +3625,25 @@ ILibTransport_DoneState ILibChain_WriteEx2(void *chain, HANDLE h, OVERLAPPED *p,
 void ILibChain_ReadEx2_UnwindHandler(void *chain, void *user)
 {
 	ILibChain_ReadEx_data *state = (ILibChain_ReadEx_data*)user;
-	state->handler(chain, state->fileHandle, ILibWaitHandle_ErrorStatus_NONE, state->buffer, (int)(uintptr_t)state->p, state->user);
+	ILIBLOGMESSAGEX2(LOGEX_OVERLAPPED_IO, " + ILibChain_ReadEx2_UnwindHandler(%p)", state->reserved);
+
+	if (state->handler(chain, state->fileHandle, ILibWaitHandle_ErrorStatus_NONE, state->buffer, (int)(uintptr_t)state->p, state->user) == FALSE)
+	{
+		ILIBLOGMESSAGEX2(LOGEX_OVERLAPPED_IO, "   -> ILibChain_ReadEx2_UnwindHandler() [Try Remove: %p]", state->reserved);
+
+		// Need to remove HANDLE from list
+		void *node = ILibLinkedList_GetNode_Search(((ILibBaseChain*)chain)->auxSelectHandles, NULL, state->reserved);
+		if (node != NULL)
+		{
+			ILIBLOGMESSAGEX2(LOGEX_OVERLAPPED_IO, "   -> Removing Handle [%p]", state->reserved);
+			ILibChain_WaitHandleInfo *info = (ILibChain_WaitHandleInfo*)ILibMemory_Extra(node);
+			ILibChain_ReadEx_data *data = (ILibChain_ReadEx_data*)info->user;
+			ILibMemory_Free(data);
+			ILibLinkedList_Remove(node);
+		}
+	}
 	free(state);
+	ILIBLOGMESSAGEX2(LOGEX_OVERLAPPED_IO, "   -> ILibChain_ReadEx2_UnwindHandler() [END]");
 }
 void ILibChain_ReadEx2(void *chain, HANDLE h, OVERLAPPED *p, char *buffer, DWORD bufferLen, ILibChain_ReadEx_Handler handler, void *user, char *metadata)
 {
@@ -3654,7 +3682,7 @@ void ILibChain_ReadEx2(void *chain, HANDLE h, OVERLAPPED *p, char *buffer, DWORD
 				state->fileHandle = h;
 				state->user = user;
 				state->p = (void*)(uintptr_t)bytesRead;
-
+				state->reserved = p != NULL ? p->hEvent : NULL;
 				ILibChain_RunOnMicrostackThreadEx2(chain, ILibChain_ReadEx2_UnwindHandler, state, 1);
 			}			
 		}
@@ -3790,6 +3818,8 @@ void ILibChain_AddWaitHandleEx(void *chain, HANDLE h, int msTIMEOUT, ILibChain_W
 
 	if (((ILibBaseChain*)chain)->currentHandle != h)
 	{
+		ILIBLOGMESSAGEX2(LOGEX_OVERLAPPED_IO, "-- ILibChain_AddWaitHandlesEx(): %p", h);
+
 		void *node = ILibLinkedList_AddTailEx(((ILibBaseChain*)chain)->auxSelectHandles, h, metadata==NULL?1:1+strnlen_s(metadata, 1024));
 		info = (ILibChain_WaitHandleInfo*)ILibMemory_Extra(node);
 		info->node = node;
@@ -10745,6 +10775,25 @@ void ILIBLOGMESSAGEX(char *format, ...)
 
 	ILIBLOGMESSSAGE(dest);
 }
+void ILIBLOGMESSAGEX2(uint32_t mask, char *format, ...)
+{
+	if ((_g_logMessageX & mask) == mask)
+	{
+		char dest[4096];
+		int len = 0;
+		va_list argptr;
+
+		va_start(argptr, format);
+		len += vsnprintf(dest + len, sizeof(dest) - len, format, argptr);
+		va_end(argptr);
+
+		ILIBLOGMESSSAGE(dest);
+	}
+}
+void ILIBLOGMESSAGEX2_SetMask(uint32_t m)
+{
+	_g_logMessageX = m;
+}
 
 #if defined(__APPLE__) || defined(ILIB_NO_TIMEDJOIN)
 typedef struct ILibThread_AppleThread

microstack/ILibParsers.h

@@ -52,6 +52,10 @@ extern "C" {
 
 extern char* ILibCriticalLogFilename;
 
+#define LOGEX_OVERLAPPED_IO 0x01
+#define LOGEX_PROCESSPIPE	0x02
+
+
 #ifdef _WIN32_WCE
 #define REQUIRES_MEMORY_ALIGNMENT
 #define errno 0
@@ -1081,6 +1085,7 @@ int ILibIsRunningOnChainThread(void* chain);
 		HANDLE fileHandle;
 		OVERLAPPED *p;
 		void *user;
+		void *reserved;
 	}ILibChain_ReadEx_data;
 	typedef struct ILibChain_WriteEx_data
 	{
@@ -1592,6 +1597,8 @@ int ILibIsRunningOnChainThread(void* chain);
 #define ILIBCRITICALEXITMSG(code, msg) {printf("%s", ILibCriticalLog(msg, __FILE__, __LINE__, 0, 0)); exit(code);}
 #define ILIBLOGMESSSAGE(msg) ILibCriticalLog(msg, __FILE__, __LINE__, 0, 0)
 	void ILIBLOGMESSAGEX(char *format, ...);
+	void ILIBLOGMESSAGEX2(uint32_t m, char *format, ...);
+	void ILIBLOGMESSAGEX2_SetMask(uint32_t m);
 
 #if defined(WIN32)
 #define ILIBCRITICALERREXIT(ex) { ILibCriticalLog(NULL, __FILE__, __LINE__, GetLastError(), 0); exit(ex); }

microstack/ILibProcessPipe.c

@@ -1173,14 +1173,15 @@ void ILibProcessPipe_Pipe_ResumeEx(ILibProcessPipe_PipeObject* p)
 	ILibChain_AddWaitHandle(p->manager->ChainLink.ParentChain, p->mOverlapped->hEvent, -1, ILibProcessPipe_Process_ReadHandler, p);
 	p->PAUSED = 0;
 	return;
-#endif
-
+#else
 	ILibProcessPipe_Pipe_ResumeEx_ContinueProcessing(p);
 	if (p->PAUSED == 0)
 	{
 		ILibLifeTime_Add(ILibGetBaseTimer(p->manager->ChainLink.ParentChain), p, 0, &ILibProcessPipe_Process_StartPipeReaderWriterEx, NULL); // Need to context switch to Chain Thread
 	}
+#endif
 }
+
 #ifdef WIN32
 BOOL ILibProcessPipe_Process_Pipe_ReadExHandler(void *chain, HANDLE h, ILibWaitHandle_ErrorStatus status, char *buffer, DWORD bytesRead, void* user);
 #endif
@@ -1273,13 +1274,20 @@ BOOL ILibProcessPipe_Process_Pipe_ReadExHandler(void *chain, HANDLE h, ILibWaitH
 	size_t consumed = 0;
 	if (status == ILibWaitHandle_ErrorStatus_NONE)
 	{
+		ILIBLOGMESSAGEX2(LOGEX_PROCESSPIPE, "ReadExHandler[%p](%p) -> TotalRead: %llu, bytesRead: %llu", h, buffer, pipeObject->totalRead, bytesRead);
 		pipeObject->totalRead += bytesRead;
 		do
 		{
-			handler(pipeObject->buffer + pipeObject->readOffset, pipeObject->totalRead, &consumed, pipeObject->user1, pipeObject->user2);
-			pipeObject->readOffset += consumed;
-			pipeObject->totalRead -= consumed;
+			if (pipeObject->PAUSED == 0)
+			{
+				ILIBLOGMESSAGEX2(LOGEX_PROCESSPIPE, " ReadExHandler(%p, %llu, %llu); [%llu]", pipeObject->buffer + pipeObject->readOffset, pipeObject->totalRead, consumed, pipeObject->readOffset);
+				handler(pipeObject->buffer + pipeObject->readOffset, pipeObject->totalRead, &consumed, pipeObject->user1, pipeObject->user2);
+				pipeObject->readOffset += consumed;
+				pipeObject->totalRead -= consumed;
+				ILIBLOGMESSAGEX2(LOGEX_PROCESSPIPE, "  -> readOffset: %llu, totalRead: %llu, consumed: %llu, PAUSE: %d", pipeObject->readOffset, pipeObject->totalRead, consumed, pipeObject->PAUSED);
+			}
 		} while (pipeObject->PAUSED == 0 && consumed != 0 && pipeObject->totalRead > 0);
+
 		if (pipeObject->totalRead == 0) { pipeObject->readOffset = 0; }
 		if (pipeObject->PAUSED == 0)
 		{
@@ -1293,11 +1301,13 @@ BOOL ILibProcessPipe_Process_Pipe_ReadExHandler(void *chain, HANDLE h, ILibWaitH
 				ILibMemory_ReallocateRaw(&(pipeObject->buffer), pipeObject->bufferSize * 2);
 				pipeObject->bufferSize = pipeObject->bufferSize * 2;
 			}
+			ILIBLOGMESSAGEX2(LOGEX_PROCESSPIPE, "ILibChain_ReadEx2() => (%p, %llu, %llu)", pipeObject->buffer, pipeObject->readOffset + pipeObject->totalRead, pipeObject->bufferSize - pipeObject->totalRead);
 			ILibChain_ReadEx2(chain, h, pipeObject->mOverlapped, pipeObject->buffer + pipeObject->readOffset + pipeObject->totalRead, (DWORD)(pipeObject->bufferSize - pipeObject->totalRead), ILibProcessPipe_Process_Pipe_ReadExHandler, pipeObject, pipeObject->metadata);
 			return(TRUE);
 		}
 		else
 		{
+			ILIBLOGMESSAGEX2(LOGEX_PROCESSPIPE, "HANDLE will get removed");
 			return(FALSE);
 		}
 	}