Cleaned up logging code, added log timestamps (using GetTickCount) and changed calls in router code to prevent it from generating extra log messages.

Makefile

@@ -17,7 +17,7 @@
 CFLAGS := -Wall
 CXXFLAGS := -Wall
 
-IPXWRAPPER_DEPS := src/ipxwrapper.o src/winsock.o src/ipxwrapper_stubs.o src/ipxwrapper.def
+IPXWRAPPER_DEPS := src/ipxwrapper.o src/winsock.o src/ipxwrapper_stubs.o src/log.o src/ipxwrapper.def
 
 all: ipxwrapper.dll wsock32.dll mswsock.dll ipxconfig.exe
 
@@ -46,7 +46,7 @@ src/wsock32_stubs.s: src/wsock32_stubs.txt
 src/mswsock_stubs.s: src/mswsock_stubs.txt
 	perl mkstubs.pl src/mswsock_stubs.txt src/mswsock_stubs.s mswsock.dll
 
-%.dll: src/stubdll.o src/%_stubs.o src/%.def
+%.dll: src/stubdll.o src/%_stubs.o src/log.o src/%.def
 	$(CC) $(CFLAGS) -Wl,--enable-stdcall-fixup,-s -shared -o $@ $^
 
 src/%_stubs.o: src/%_stubs.s

changes.txt

@@ -14,6 +14,11 @@ Version 0.2.1:
 	Bugfix: Store correct DLL name in stub DLLs.
 	
 	Cleanup: Replace assert calls with proper error checks in ipxconfig.
+	
+	Cleanup: Cleaned up logging code and added timestamps using GetTickCount.
+	
+	Cleanup: Call r_ winsock calls directly in router code to prevent it from
+	generating extra log messages.
 
 Version 0.2:
 	Implemented ioctlsocket() function with support for FIONREAD.

src/ipxwrapper.c

@@ -45,7 +45,6 @@ HMODULE winsock2_dll = NULL;
 HMODULE mswsock_dll = NULL;
 HMODULE wsock32_dll = NULL;
 
-static FILE *debug_fh = NULL;
 static HANDLE mutex = NULL;
 static HANDLE router_thread = NULL;
 static DWORD router_tid = 0;
@@ -59,9 +58,7 @@ static BOOL load_nics(void);
 
 BOOL WINAPI DllMain(HINSTANCE me, DWORD why, LPVOID res) {
 	if(why == DLL_PROCESS_ATTACH) {
-		#ifdef DEBUG
+		log_open();
-		debug_fh = fopen(DEBUG, "w");
-		#endif
 		
 		winsock2_dll = load_sysdll("ws2_32.dll");
 		mswsock_dll = load_sysdll("mswsock.dll");
@@ -81,7 +78,7 @@ BOOL WINAPI DllMain(HINSTANCE me, DWORD why, LPVOID res) {
 		
 		if(reg_err != ERROR_SUCCESS) {
 			regkey = NULL;
-			debug("Could not open registry: %s", w32_error(reg_err));
+			log_printf("Could not open registry: %s", w32_error(reg_err));
 		}
 		
 		DWORD gsize = sizeof(global_conf);
@@ -99,14 +96,14 @@ BOOL WINAPI DllMain(HINSTANCE me, DWORD why, LPVOID res) {
 		
 		mutex = CreateMutex(NULL, FALSE, NULL);
 		if(!mutex) {
-			debug("Failed to create mutex");
+			log_printf("Failed to create mutex");
 			return FALSE;
 		}
 		
 		WSADATA wsdata;
 		int err = WSAStartup(MAKEWORD(1,1), &wsdata);
 		if(err) {
-			debug("Failed to initialize winsock: %s", w32_error(err));
+			log_printf("Failed to initialize winsock: %s", w32_error(err));
 			return FALSE;
 		}
 		
@@ -142,6 +139,8 @@ BOOL WINAPI DllMain(HINSTANCE me, DWORD why, LPVOID res) {
 		DLL_UNLOAD(winsock2_dll);
 		DLL_UNLOAD(mswsock_dll);
 		DLL_UNLOAD(wsock32_dll);
+		
+		log_close();
 	}
 	
 	return TRUE;
@@ -158,27 +157,13 @@ void __stdcall *find_sym(char const *symbol) {
 	}
 	
 	if(!addr) {
-		debug("Unknown symbol: %s", symbol);
+		log_printf("Unknown symbol: %s", symbol);
 		abort();
 	}
 	
 	return addr;
 }
 
-void debug(char const *fmt, ...) {
-	char msg[1024];
-	va_list argv;
-	
-	if(debug_fh) {
-		va_start(argv, fmt);
-		vsnprintf(msg, 1024, fmt, argv);
-		va_end(argv);
-		
-		fprintf(debug_fh, "%s\n", msg);
-		fflush(debug_fh);
-	}
-}
-
 /* Lock the mutex and search the sockets list for an ipx_socket structure with
  * the requested fd, if no matching fd is found, unlock the mutex
  *
@@ -251,7 +236,7 @@ static HMODULE load_sysdll(char const *name) {
 	
 	ret = LoadLibrary(path);
 	if(!ret) {
-		debug("Error loading %s: %s", path, w32_error(GetLastError()));
+		log_printf("Error loading %s: %s", path, w32_error(GetLastError()));
 	}
 	
 	return ret;
@@ -259,9 +244,9 @@ static HMODULE load_sysdll(char const *name) {
 
 /* Initialize and start the router thread */
 static int init_router(void) {
-	net_fd = socket(AF_INET, SOCK_DGRAM, 0);
+	net_fd = r_socket(AF_INET, SOCK_DGRAM, 0);
 	if(net_fd == -1) {
-		debug("Failed to create network socket: %s", w32_error(WSAGetLastError()));
+		log_printf("Failed to create network socket: %s", w32_error(WSAGetLastError()));
 		return 0;
 	}
 	
@@ -270,27 +255,27 @@ static int init_router(void) {
 	bind_addr.sin_addr.s_addr = INADDR_ANY;
 	bind_addr.sin_port = htons(global_conf.udp_port);
 	
-	if(bind(net_fd, (struct sockaddr*)&bind_addr, sizeof(bind_addr)) == -1) {
+	if(r_bind(net_fd, (struct sockaddr*)&bind_addr, sizeof(bind_addr)) == -1) {
-		debug("Failed to bind network socket: %s", w32_error(WSAGetLastError()));
+		log_printf("Failed to bind network socket: %s", w32_error(WSAGetLastError()));
 		return 0;
 	}
 	
 	BOOL broadcast = TRUE;
 	int bufsize = 524288;	/* 512KiB */
 	
-	setsockopt(net_fd, SOL_SOCKET, SO_BROADCAST, (char*)&broadcast, sizeof(BOOL));
+	r_setsockopt(net_fd, SOL_SOCKET, SO_BROADCAST, (char*)&broadcast, sizeof(BOOL));
-	setsockopt(net_fd, SOL_SOCKET, SO_RCVBUF, (char*)&bufsize, sizeof(int));
+	r_setsockopt(net_fd, SOL_SOCKET, SO_RCVBUF, (char*)&bufsize, sizeof(int));
-	setsockopt(net_fd, SOL_SOCKET, SO_SNDBUF, (char*)&bufsize, sizeof(int));
+	r_setsockopt(net_fd, SOL_SOCKET, SO_SNDBUF, (char*)&bufsize, sizeof(int));
 	
 	router_buf = malloc(PACKET_BUF_SIZE);
 	if(!router_buf) {
-		debug("Not enough memory for router buffer (64KiB)");
+		log_printf("Not enough memory for router buffer (64KiB)");
 		return 0;
 	}
 	
 	router_thread = CreateThread(NULL, 0, &router_main, NULL, 0, &router_tid);
 	if(!router_thread) {
-		debug("Failed to create router thread");
+		log_printf("Failed to create router thread");
 		return 0;
 	}
 	
@@ -311,9 +296,9 @@ static DWORD WINAPI router_main(LPVOID notused) {
 	
 	while(1) {
 		addrlen = sizeof(addr);
-		rval = recvfrom(net_fd, (char*)packet, PACKET_BUF_SIZE, 0, (struct sockaddr*)&addr, &addrlen);
+		rval = r_recvfrom(net_fd, (char*)packet, PACKET_BUF_SIZE, 0, (struct sockaddr*)&addr, &addrlen);
 		if(rval <= 0) {
-			debug("Error recieving packet: %s", w32_error(WSAGetLastError()));
+			log_printf("Error recieving packet: %s", w32_error(WSAGetLastError()));
 			continue;
 		}
 		
@@ -337,7 +322,7 @@ static DWORD WINAPI router_main(LPVOID notused) {
 		packet->size = ntohs(packet->size);
 		
 		if(packet->size > MAX_PACKET_SIZE || packet->size+sizeof(ipx_packet)-1 != rval) {
-			debug("Recieved packet with incorrect size field, discarding");
+			log_printf("Recieved packet with incorrect size field, discarding");
 			continue;
 		}
 		
@@ -374,7 +359,7 @@ static DWORD WINAPI router_main(LPVOID notused) {
 				
 				sval = r_sendto(sockptr->fd, (char*)packet, rval, 0, (struct sockaddr*)&addr, addrlen);
 				if(sval == -1) {
-					debug("Error relaying packet: %s", w32_error(WSAGetLastError()));
+					log_printf("Error relaying packet: %s", w32_error(WSAGetLastError()));
 				}
 			}
 		}
@@ -411,7 +396,7 @@ static void add_host(const unsigned char *net, const unsigned char *node, uint32
 	
 	hptr = malloc(sizeof(ipx_host));
 	if(!hptr) {
-		debug("No memory for hosts list entry");
+		log_printf("No memory for hosts list entry");
 		return;
 	}
 	
@@ -461,7 +446,7 @@ static BOOL load_nics(void) {
 	ipx_nic *enic = NULL;
 	
 	if(!ifptr) {
-		debug("No NICs: %s", w32_error(WSAGetLastError()));
+		log_printf("No NICs: %s", w32_error(WSAGetLastError()));
 	}
 	
 	while(ifptr) {

src/ipxwrapper.h

@@ -25,8 +25,6 @@
 
 #include "config.h"
 
-#define DEBUG "ipxwrapper.log"
-
 /* Maximum UDP data size is 65467, we use a smaller value to ensure we have
  * plenty of space to play with for headers, etc
 */
@@ -141,7 +139,6 @@ extern HMODULE mswsock_dll;
 extern HMODULE wsock32_dll;
 
 void __stdcall *find_sym(char const *sym);
-void debug(char const *fmt, ...);
 ipx_socket *get_socket(SOCKET fd);
 void lock_mutex(void);
 void unlock_mutex(void);
@@ -149,6 +146,10 @@ IP_ADAPTER_INFO *get_nics(void);
 char const *w32_error(DWORD errnum);
 ipx_host *find_host(const unsigned char *net, const unsigned char *node);
 
+void log_open();
+void log_close();
+void log_printf(const char *fmt, ...);
+
 INT APIENTRY r_EnumProtocolsA(LPINT,LPVOID,LPDWORD);
 INT APIENTRY r_EnumProtocolsW(LPINT,LPVOID,LPDWORD);
 int PASCAL FAR r_WSARecvEx(SOCKET,char*,int,int*);

src/log.c

@@ -0,0 +1,100 @@
+/* ipxwrapper - Logging functions
+ * Copyright (C) 2011 Daniel Collins <solemnwarning@solemnwarning.net>
+ *
+ * This program is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 as published by
+ * the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License for
+ * more details.
+ *
+ * You should have received a copy of the GNU General Public License along with
+ * this program; if not, write to the Free Software Foundation, Inc., 51
+ * Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.
+*/
+
+#include <windows.h>
+#include <stdlib.h>
+#include <stdio.h>
+#include <stdarg.h>
+
+#include "ipxwrapper.h"
+
+static HANDLE log_fh = NULL;
+static HANDLE log_mutex = NULL;
+
+void log_open() {
+	if(!(log_mutex = CreateMutex(NULL, FALSE, NULL))) {
+		abort();
+	}
+	
+	log_fh = CreateFile(
+		"ipxwrapper.log",
+		GENERIC_READ | GENERIC_WRITE,
+		FILE_SHARE_DELETE | FILE_SHARE_READ | FILE_SHARE_WRITE,
+		NULL,
+		OPEN_ALWAYS,
+		FILE_ATTRIBUTE_NORMAL,
+		NULL
+	);
+	
+	if(log_fh == INVALID_HANDLE_VALUE) {
+		log_fh = NULL;
+	}
+}
+
+void log_close() {
+	if(log_fh) {
+		CloseHandle(log_fh);
+		log_fh = NULL;
+	}
+	
+	CloseHandle(log_mutex);
+	log_mutex = NULL;
+}
+
+void log_printf(const char *fmt, ...) {
+	DWORD called = GetTickCount();
+	
+	WaitForSingleObject(log_mutex, INFINITE);
+	
+	if(!log_fh) {
+		ReleaseMutex(log_mutex);
+		return;
+	}
+	
+	va_list argv;
+	char msg[1024], tstr[32];
+	
+	va_start(argv, fmt);
+	vsnprintf(msg, 1024, fmt, argv);
+	va_end(argv);
+	
+	snprintf(tstr, 32, "[%u.%u] ", (unsigned int)(called/1000), (unsigned int)((called % 1000) / 10));
+	
+	OVERLAPPED off;
+	off.Offset = 0;
+	off.OffsetHigh = 0;
+	off.hEvent = 0;
+	
+	if(!LockFileEx(log_fh, LOCKFILE_EXCLUSIVE_LOCK, 0, 1, 0, &off)) {
+		ReleaseMutex(log_mutex);
+		return;
+	}
+	
+	if(SetFilePointer(log_fh, 0, NULL, FILE_END) != INVALID_SET_FILE_POINTER) {
+		DWORD written;
+		
+		WriteFile(log_fh, tstr, strlen(tstr), &written, NULL);
+		WriteFile(log_fh, msg, strlen(msg), &written, NULL);
+		WriteFile(log_fh, "\r\n", 2, &written, NULL);
+		
+		FlushFileBuffers(log_fh);
+	}
+	
+	UnlockFile(log_fh, 0, 0, 1, 0);
+	
+	ReleaseMutex(log_mutex);
+}

src/stubdll.c

@@ -25,8 +25,9 @@ extern char const *dllname;
 
 FILE *call_log = NULL;
 
-void __stdcall *find_sym(char const *symbol);
+void log_open();
-void debug(char const *fmt, ...);
+void log_close();
+void log_printf(const char *fmt, ...);
 
 static void load_dlls() {
 	char sysdir[1024], path[1024];
@@ -47,6 +48,8 @@ static void load_dlls() {
 
 BOOL WINAPI DllMain(HINSTANCE me, DWORD why, LPVOID res) {
 	if(why == DLL_PROCESS_ATTACH) {
+		log_open();
+		
 		HKEY key;
 		
 		if(RegOpenKeyEx(HKEY_CURRENT_USER, "Software\\IPXWrapper", 0, KEY_QUERY_VALUE, &key) == ERROR_SUCCESS) {
@@ -62,9 +65,7 @@ BOOL WINAPI DllMain(HINSTANCE me, DWORD why, LPVOID res) {
 			
 			RegCloseKey(key);
 		}
-	}
+	}else if(why == DLL_PROCESS_DETACH) {
-	
-	if(why == DLL_PROCESS_DETACH) {
 		if(sysdll) {
 			FreeLibrary(sysdll);
 			sysdll = NULL;
@@ -79,6 +80,8 @@ BOOL WINAPI DllMain(HINSTANCE me, DWORD why, LPVOID res) {
 			fclose(call_log);
 			call_log = NULL;
 		}
+		
+		log_close();
 	}
 	
 	return TRUE;
@@ -96,26 +99,9 @@ void __stdcall *find_sym(char const *symbol) {
 	}
 	
 	if(!ptr) {
-		debug("Missing symbol in %s: %s", dllname, symbol);
+		log_printf("Missing symbol in %s: %s", dllname, symbol);
 		abort();
 	}
 	
 	return ptr;
 }
-
-void debug(char const *fmt, ...) {
-	static void (*real_debug)(char const*,...) = NULL;
-	char msgbuf[1024];
-	va_list argv;
-	
-	if(ipxdll && !real_debug) {
-		real_debug = (void*)GetProcAddress(ipxdll, "debug");
-	}
-	if(real_debug) {
-		va_start(argv, fmt);
-		vsnprintf(msgbuf, 1024, fmt, argv);
-		va_end(argv);
-		
-		real_debug("%s", msgbuf);
-	}
-}

src/winsock.c

@@ -128,7 +128,7 @@ INT APIENTRY EnumProtocolsW(LPINT protocols, LPVOID buf, LPDWORD bsptr) {
 }
 
 SOCKET WSAAPI socket(int af, int type, int protocol) {
-	debug("socket(%d, %d, %d)", af, type, protocol);
+	log_printf("socket(%d, %d, %d)", af, type, protocol);
 	
 	if(af == AF_IPX) {
 		ipx_socket *nsock = malloc(sizeof(ipx_socket));
@@ -138,7 +138,7 @@ SOCKET WSAAPI socket(int af, int type, int protocol) {
 		
 		nsock->fd = r_socket(AF_INET, SOCK_DGRAM, 0);
 		if(nsock->fd == -1) {
-			debug("Creating fake socket failed: %s", w32_error(WSAGetLastError()));
+			log_printf("Creating fake socket failed: %s", w32_error(WSAGetLastError()));
 			
 			free(nsock);
 			RETURN(-1);
@@ -152,7 +152,7 @@ SOCKET WSAAPI socket(int af, int type, int protocol) {
 		nsock->next = sockets;
 		sockets = nsock;
 		
-		debug("IPX socket created (fd = %d)", nsock->fd);
+		log_printf("IPX socket created (fd = %d)", nsock->fd);
 		
 		RETURN(nsock->fd);
 	}else{
@@ -172,11 +172,11 @@ int WSAAPI closesocket(SOCKET fd) {
 	}
 	
 	if(ret == SOCKET_ERROR) {
-		debug("closesocket(%d) failed: %s", fd, w32_error(WSAGetLastError()));
+		log_printf("closesocket(%d) failed: %s", fd, w32_error(WSAGetLastError()));
 		RETURN(SOCKET_ERROR);
 	}
 	
-	debug("IPX socket closed (fd = %d)", fd);
+	log_printf("IPX socket closed (fd = %d)", fd);
 	
 	if(ptr == sockets) {
 		sockets = ptr->next;
@@ -205,10 +205,10 @@ int WSAAPI bind(SOCKET fd, const struct sockaddr *addr, int addrlen) {
 		NET_TO_STRING(net_s, ipxaddr->sa_netnum);
 		NODE_TO_STRING(node_s, ipxaddr->sa_nodenum);
 		
-		debug("bind(%d, net=%s node=%s socket=%hu)", fd, net_s, node_s, ntohs(ipxaddr->sa_socket));
+		log_printf("bind(%d, net=%s node=%s socket=%hu)", fd, net_s, node_s, ntohs(ipxaddr->sa_socket));
 		
 		if(ptr->flags & IPX_BOUND) {
-			debug("bind failed: socket already bound");
+			log_printf("bind failed: socket already bound");
 			RETURN_WSA(WSAEINVAL, -1);
 		}
 		
@@ -240,7 +240,7 @@ int WSAAPI bind(SOCKET fd, const struct sockaddr *addr, int addrlen) {
 		}
 		
 		if(!nic) {
-			debug("bind failed: no such address");
+			log_printf("bind failed: no such address");
 			RETURN_WSA(WSAEADDRNOTAVAIL, -1);
 		}
 		
@@ -258,7 +258,7 @@ int WSAAPI bind(SOCKET fd, const struct sockaddr *addr, int addrlen) {
 			while(socket) {
 				if(ntohs(socket->socket) == s && socket->flags & IPX_BOUND) {
 					if(s == 65535) {
-						debug("bind failed: out of sockets?!");
+						log_printf("bind failed: out of sockets?!");
 						RETURN_WSA(WSAEADDRNOTAVAIL, -1);
 					}
 					
@@ -279,7 +279,7 @@ int WSAAPI bind(SOCKET fd, const struct sockaddr *addr, int addrlen) {
 			
 			while(socket) {
 				if(socket->socket == ipxaddr->sa_socket && socket->flags & IPX_BOUND) {
-					debug("bind failed: requested socket in use");
+					log_printf("bind failed: requested socket in use");
 					RETURN_WSA(WSAEADDRINUSE, -1);
 				}
 				
@@ -292,7 +292,7 @@ int WSAAPI bind(SOCKET fd, const struct sockaddr *addr, int addrlen) {
 		NET_TO_STRING(net_s, nic->ipx_net);
 		NODE_TO_STRING(node_s, nic->ipx_node);
 		
-		debug("bind address: net=%s node=%s socket=%hu", net_s, node_s, ntohs(ptr->socket));
+		log_printf("bind address: net=%s node=%s socket=%hu", net_s, node_s, ntohs(ptr->socket));
 		
 		/* TODO: Bind fake socket in socket() call rather than here?
 		 *
@@ -311,7 +311,7 @@ int WSAAPI bind(SOCKET fd, const struct sockaddr *addr, int addrlen) {
 		if(rval == 0) {
 			ptr->flags |= IPX_BOUND;
 		}else{
-			debug("Binding fake socket failed: %s", w32_error(WSAGetLastError()));
+			log_printf("Binding fake socket failed: %s", w32_error(WSAGetLastError()));
 		}
 		
 		RETURN(rval);
@@ -612,7 +612,7 @@ int WSAAPI sendto(SOCKET fd, const char *buf, int len, int flags, const struct s
 		}
 		
 		if(!(sockptr->flags & IPX_BOUND)) {
-			debug("sendto() on unbound socket, attempting implicit bind");
+			log_printf("sendto() on unbound socket, attempting implicit bind");
 			
 			struct sockaddr_ipx bind_addr;