refactor: switch debug log to a more convenient printf-like API

8 files changed, 318 insertions, 390 deletions

diff --git a/dlog.h b/dlog.h
index 68439e3..ebeb01c 100644
--- a/dlog.h
+++ b/dlog.h
@@ -21,6 +21,9 @@
 #define DLOG_H
 
 #include <conio.h>
+#include <stdarg.h>
+#include <stdbool.h>
+#include <limits.h>
 
 // Customizable defines
 /** If 0, these routines become nops */
@@ -40,7 +43,7 @@
 static void dlog_init();
 
 /** Logs a single character to the debug message IO port. */
-static inline void dlog_putc(char c);
+static inline void dputc(char c);
 
 #if DLOG_TARGET_SERIAL
 
@@ -56,7 +59,7 @@ static void dlog_init()
 	outp(DLOG_TARGET_PORT + 4, 0x03);    // RTS/DSR set, IRQs disabled
 }
 
-static inline void dlog_putc(char c)
+static inline void dputc(char c)
 {
 	while (!(inp(DLOG_TARGET_PORT + 5) & 0x20));
 	outp(DLOG_TARGET_PORT, c);
@@ -64,64 +67,68 @@ static inline void dlog_putc(char c)
 
 #else /* DLOG_TARGET_SERIAL */
 
-static void dlog_init()
+static inline void dlog_init()
 {
+	// No initialization required
 }
 
-static inline void dlog_putc(char c)
+static inline void dputc(char c)
 {
 	outp(DLOG_TARGET_PORT, c);
 }
 
 #endif /* DLOG_TARGET_SERIAL */
 
-static void dlog_endline(void)
+static void d_utoa(unsigned num, unsigned base)
 {
-	dlog_putc('\n');
-}
+	char buf[6];
+	int i = 0;
 
-/** Print string to log */
-static void dlog_print(const char *s)
-{
-	char c;
-	while (c = *s++) {
-		dlog_putc(c);
-	}
-}
+	do {
+		unsigned digit = num % base;
 
-/** Print (far) string to log */
-static void dlog_fprint(const char __far *s)
-{
-	char c;
-	while (c = *s++) {
-		dlog_putc(c);
-	}
-}
+		if (digit < 10) {
+			buf[i] = '0' + digit;
+		} else {
+			buf[i] = 'a' + (digit - 10);
+		}
 
-/** Print (far) string of fixed length to log */
-static void dlog_fnprint(const char __far *s, unsigned l)
-{
-	while (l > 0) {
-		dlog_putc(*s++);
-		l--;
-	}
-}
+		i++;
+		num /= base;
+	} while (num > 0 && i < sizeof(buf));
 
-/** Print + newline */
-static void dlog_puts(const char *s)
-{
-	dlog_print(s);
-	dlog_endline();
+	while (i--) {
+		dputc(buf[i]);
+	}
 }
 
-/** Print unsigned number with base */
-static void dlog_printub(unsigned int num, int base)
+static void d_ultoa(unsigned long num, unsigned base)
 {
-	char buf[8];
+	char buf[12];
 	int i = 0;
 
 	do {
-		int digit = num % base;
+		unsigned digit = 0;
+
+		static inline void uldiv(void);
+#pragma aux uldiv = \
+			"push eax" \
+			"push ecx" \
+			"push edx" \
+			"mov eax, [num]" \
+			"movzx ecx, [base]" \
+			"xor edx, edx" \
+			\
+			"div ecx" \
+			\
+			"mov [num], eax" \
+			"mov [digit], dx" \
+			\
+			"pop edx" \
+			"pop ecx" \
+			"pop eax" \
+			__modify __exact [];
+		uldiv();
 
 		if (digit < 10) {
 			buf[i] = '0' + digit;
@@ -130,63 +137,178 @@ static void dlog_printub(unsigned int num, int base)
 		}
 
 		i++;
-		num /= base;
 	} while (num > 0 && i < sizeof(buf));
 
 	while (i--) {
-		dlog_putc(buf[i]);
+		dputc(buf[i]);
 	}
 }
 
-/** Print signed number with base */
-static void dlog_printdb(int num, int base)
+static void d_itoa(int num, unsigned base)
 {
-	unsigned int unum;
+	unsigned unum;
 
 	// TODO
 	if (num < 0) {
-		dlog_putc('-');
+		dputc('-');
 		unum = -num;
 	} else {
 		unum = num;
 	}
 
-	dlog_printub(unum, base);
+	d_utoa(unum, base);
+}
+
+static void d_ltoa(long num, unsigned base)
+{
+	unsigned long unum;
+
+	// TODO
+	if (num < 0) {
+		dputc('-');
+		unum = -num;
+	} else {
+		unum = num;
+	}
+
+	d_ultoa(unum, base);
+}
+
+static unsigned d_strtou(const char * __far *str)
+{
+	unsigned i = 0;
+	const char *s = *str;
+	char c = *s;
+	while (c >= '0' && c <= '9') {
+		i = (i * 10) + (c - '0');
+		c = *(++s);
+	}
+	*str = s;
+	return i;
 }
 
-/** Print unsigned number in base 16. */
-static void dlog_printu(unsigned int num)
+static void d_printstr(const char __far *s, unsigned l)
 {
-	dlog_printub(num, 10);
+	while (l > 0 && *s) {
+		dputc(*s++);
+		l--;
+	}
 }
 
-/** Print unsigned number in base 10. */
-static void dlog_printx(unsigned int num)
+static void dprintf(const char *fmt, ...)
 {
-	dlog_printub(num, 16);
+	va_list va;
+	char c;
+
+	va_start(va, fmt);
+
+	while ((c = *(fmt++))) {
+		if (c == '%') {
+			unsigned width, precision, size;
+			bool is_far = false;
+
+			width = d_strtou(&fmt);
+
+			if ((c = *fmt) == '.') {
+				fmt++;
+				precision = d_strtou(&fmt);
+			} else {
+				precision = UINT_MAX;
+			}
+
+			switch ((c = *fmt)) {
+			case 'l':
+				size = sizeof(long);
+				fmt++;
+				break;
+			case 'h':
+				size = sizeof(short);
+				fmt++;
+				break;
+			case 'F':
+				is_far = true;
+				fmt++;
+				break;
+			default:
+				size = sizeof(int);
+				break;
+			}
+
+			switch ((c = *fmt)) {
+			case 'd':
+				switch (size) {
+				case sizeof(int):
+					d_itoa(va_arg(va, int), 10);
+					break;
+				case sizeof(long):
+					d_ltoa(va_arg(va, long), 10);
+					break;
+				}
+				break;
+			case 'u':
+				switch (size) {
+				case sizeof(int):
+					d_utoa(va_arg(va, int), 10);
+					break;
+				case sizeof(long):
+					d_ultoa(va_arg(va, long), 10);
+					break;
+				}
+				break;
+			case 'x':
+				switch (size) {
+				case sizeof(int):
+					d_utoa(va_arg(va, int), 16);
+					break;
+				case sizeof(long):
+					d_ultoa(va_arg(va, long), 16);
+					break;
+				}
+				break;
+			case 'p':
+				if (is_far) {
+					void __far *p = va_arg(va, void __far *);
+					d_utoa(FP_SEG(p), 16);
+					dputc(':');
+					d_utoa(FP_OFF(p), 16);
+				} else {
+					d_utoa(va_arg(va, unsigned), 16);
+				}
+				break;
+			case 's':
+				d_printstr(is_far ? va_arg(va, const char __far *)
+				                  : va_arg(va, const char *),
+				           precision);
+				break;
+			case '%':
+				dputc('%');
+				break;
+			}
+			fmt++;
+		} else {
+			dputc(c);
+		}
+	}
+
+	va_end(va);
 }
 
-/** Print signed number in base 10. */
-static void dlog_printd(int num)
+static void dputs(const char *s)
 {
-	dlog_printdb(num, 10);
+	char c;
+	while ((c = *(s++))) {
+		dputc(c);
+	}
+	dputc('\n');
 }
 
 #else /* ENABLE_DLOG */
 
-#define dlog_nop()          do { } while(0)
-#define dlog_init()         dlog_nop()
-#define dlog_putc(c)        dlog_nop()
-#define dlog_endline()      dlog_nop()
-#define dlog_print(s)       dlog_nop()
-#define dlog_fprint(s)      dlog_nop()
-#define dlog_fnprint(s,n)   dlog_nop()
-#define dlog_puts(s)        dlog_nop()
-#define dlog_printub(n,b)   dlog_nop()
-#define dlog_printdb(n,b)   dlog_nop()
-#define dlog_printx(n)      dlog_nop()
-#define dlog_printu(n)      dlog_nop()
-#define dlog_printd(n)      dlog_nop()
+#define dlog_nop()       do { } while(0)
+#define dlog_init()      dlog_nop()
+#define dputc(c)         dlog_nop()
+#define dputs(s)         dlog_nop()
+#define dprintf(...)     dlog_nop()
 
 
 #endif /* ENABLE_DLOG */
diff --git a/int15ps2.h b/int15ps2.h
index 438dfd8..dfc5b3a 100644
--- a/int15ps2.h
+++ b/int15ps2.h
@@ -227,9 +227,7 @@ static bool ps2m_detect_wheel(void)
 
 	if (device_id != PS2M_DEVICE_ID_PLAIN) {
 		// TODO: Likely we have to accept more device IDs here
-		dlog_print("Unknown initial mouse device_id=");
-		dlog_printx(device_id);
-		dlog_endline();
+		dprintf("Unknown initial mouse device_id=0x%x\n", device_id);
 		return false;
 	}
 
diff --git a/mousetsr.c b/mousetsr.c
index a03da07..ff03499 100644
--- a/mousetsr.c
+++ b/mousetsr.c
@@ -460,12 +460,12 @@ static void load_cursor(void)
 			}
 		}
 
-		dlog_puts("Loading cursor to VBox");
+		dputs("Loading cursor to VBox");
 
 		vbox_send_request(data.vb.iobase, data.vb.dds.physicalAddress);
 
 		if (req->header.rc != 0) {
-			dlog_puts("Could not send cursor to VirtualBox");
+			dputs("Could not send cursor to VirtualBox");
 			return;
 		}
 
@@ -504,13 +504,8 @@ static void reload_video_info(void)
 		data.screen_granularity.y = 8;
 	}
 
-	dlog_print("Current video mode=");
-	dlog_printx(data.video_mode.mode);
-	dlog_print(" screen_max=");
-	dlog_printd(data.screen_max.x);
-	dlog_putc(',');
-	dlog_printd(data.screen_max.y);
-	dlog_endline();
+	dprintf("Current video mode=%x screen_max=%d,%d\n",
+	        data.video_mode.mode, data.screen_max.x, data.screen_max.y);
 }
 
 /** True if the current video is different from what we have stored
@@ -558,19 +553,8 @@ static void call_event_handler(void (__far *handler)(), uint16_t events,
                                int16_t delta_x, int16_t delta_y)
 {
 #if TRACE_EVENTS
-	dlog_print("calling event handler events=");
-	dlog_printx(events);
-	dlog_print(" buttons=");
-	dlog_printx(buttons);
-	dlog_print(" x=");
-	dlog_printd(x);
-	dlog_print(" y=");
-	dlog_printd(y);
-	dlog_print(" dx=");
-	dlog_printd(delta_x);
-	dlog_print(" dy=");
-	dlog_printd(delta_y);
-	dlog_endline();
+	dprintf("calling event handler events=0x%x buttons=0x%x x=%d y=%d dx=%d dy=%d\n",
+	        events, buttons, x, y, delta_x, delta_y);
 #endif
 
 	__asm {
@@ -598,17 +582,8 @@ static void handle_mouse_event(uint16_t buttons, bool absolute, int x, int y, in
 	int i;
 
 #if TRACE_EVENTS
-	dlog_print("handle mouse event");
-	if (absolute) dlog_print(" absolute");
-	dlog_print(" buttons=");
-	dlog_printx(buttons);
-	dlog_print(" x=");
-	dlog_printd(x);
-	dlog_print(" y=");
-	dlog_printd(y);
-	dlog_print(" z=");
-	dlog_printd(z);
-	dlog_endline();
+	dprintf("handle mouse event %s buttons=0x%x x=%d y=%d z=%d\n",
+	        absolute ? "absolute" : "relative", buttons, x, y, z);
 #endif
 
 	if (absolute) {
@@ -752,15 +727,7 @@ static void handle_ps2_packet(void)
 	y = -(status & PS2M_STATUS_Y_NEG ? 0xFF00 | y : y);
 
 #if TRACE_EVENTS
-	dlog_print("ps2 packet ");
-	dlog_printx(status);
-	dlog_putc(' ');
-	dlog_printd(x);
-	dlog_putc(' ');
-	dlog_printd(y);
-	dlog_putc(' ');
-	dlog_printd(z);
-	dlog_endline();
+	dprintf("ps2 packet %x %d %d %d\n", status, x, y, z);
 #endif /* TRACE_EVENTS */
 
 #if USE_VIRTUALBOX
@@ -789,11 +756,7 @@ static void handle_ps2_packet(void)
 		uint16_t data_avail = vmwstatus & VMWARE_ABSPOINTER_STATUS_MASK_DATA;
 
 #if TRACE_EVENTS
-		dlog_print("vmware status=0x");
-		dlog_printx(vmwstatus >> 16);
-		dlog_print(" ");
-		dlog_printx(vmwstatus & 0xFFFF);
-		dlog_endline();
+		dprintf("vmware status=0x%lx\n", vmwstatus);
 #endif
 
 		if (data_avail >= VMWARE_ABSPOINTER_DATA_PACKET_SIZE) {
@@ -801,19 +764,14 @@ static void handle_ps2_packet(void)
 			vmware_abspointer_data(VMWARE_ABSPOINTER_DATA_PACKET_SIZE, &vmw);
 
 #if TRACE_EVENTS
-			dlog_print("vmware pstatus=0x");
-			dlog_printx(status);
-			dlog_print(" x=0x");
-			dlog_printx(vmw.x);
-			dlog_print(" z=");
-			dlog_printd((int8_t) (uint8_t) vmw.z);
-			dlog_endline();
+			dprintf("vmware pstatus=0x%x x=%d y=%d z=%d\n",
+			        status, vmw.x, vmw.y, (int) (uint8_t) vmw.z);
 #endif
 
 			if (vmw.status & VMWARE_ABSPOINTER_STATUS_RELATIVE) {
 				x = (int16_t) vmw.x;
 				y = (int16_t) vmw.y;
-				z = (int8_t) (uint8_t) vmw.z;
+				z = (uint8_t) vmw.z;
 			} else {
 				abs = true;
 				// Scale to screen coordinates
@@ -822,7 +780,7 @@ static void handle_ps2_packet(void)
 				           MAX(data.max.x, data.screen_max.x));
 				y = scaleu(vmw.y & 0xFFFFU, 0xFFFFU,
 				           MAX(data.max.y, data.screen_max.y));
-				z = (int8_t) (uint8_t) vmw.z;
+				z = (uint8_t) vmw.z;
 			}
 
 			if (vmw.status & VMWARE_ABSPOINTER_STATUS_BUTTON_LEFT) {
@@ -868,23 +826,15 @@ static void ps2_mouse_handler(uint16_t word0, uint16_t word1, uint16_t word2, ui
 	// We have to compute synchronization ourselves.
 
 #if TRACE_EVENTS
-	dlog_print("ps2 callback byte ");
-	dlog_printd(1 + data.cur_packet_bytes);
-	dlog_putc('/');
-	dlog_printd(data.packet_size);
-	dlog_putc('=');
-	dlog_printx(word0 & 0xFF);
-	dlog_endline();
+	dprintf("ps2 callback byte %d/%d = %x\n",
+	        1 + data.cur_packet_bytes, data.packet_size, word0 & 0xFF);
 #endif /* TRACE_EVENTS */
 
 	if (data.cur_packet_bytes &&
 	        ticks >= data.cur_packet_ticks + MAX_PS2_PACKET_DELAY) {
 		// Assume the start of a new packet
-		dlog_print("dropping packet! prev ticks=");
-		dlog_printu(data.cur_packet_ticks);
-		dlog_print(" new_ticks=");
-		dlog_printu(ticks);
-		dlog_endline();
+		dprintf("dropping packet! prev_ticks=%u new_ticks=%u\n",
+		        data.cur_packet_ticks, ticks);
 		data.cur_packet_bytes = 0;
 	}
 	if (data.cur_packet_bytes == 0) {
@@ -943,10 +893,10 @@ static void set_absolute(bool enable)
 	if (data.vbavail) {
 		int err = vbox_set_mouse(&data.vb, enable, false);
 		if (enable && !err) {
-			dlog_puts("VBox absolute mouse enabled");
+			dputs("VBox absolute mouse enabled");
 			data.vbhaveabs = true;
 		} else if (!enable) {
-			dlog_puts("VBox absolute mouse disabled");
+			dputs("VBox absolute mouse disabled");
 		}
 	}
 #endif /* USE_VIRTUALBOX */
@@ -960,12 +910,12 @@ static void set_absolute(bool enable)
 			vmware_abspointer_data_clear();
 			vmware_abspointer_cmd(VMWARE_ABSPOINTER_CMD_REQUEST_ABSOLUTE);
 
-			dlog_puts("VMware absolute mouse enabled");
+			dputs("VMware absolute mouse enabled");
 		} else {
 			vmware_abspointer_cmd(VMWARE_ABSPOINTER_CMD_REQUEST_RELATIVE);
 			vmware_abspointer_cmd(VMWARE_ABSPOINTER_CMD_DISABLE);
 
-			dlog_puts("VMware absolute mouse disabled");
+			dputs("VMware absolute mouse disabled");
 		}
 	}
 #endif /* USE_VMWARE */
@@ -992,7 +942,7 @@ static void reset_mouse_hardware()
 		err = ps2m_get_device_id(&device_id);
 		if (err || device_id != PS2M_DEVICE_ID_IMPS2) {
 			// Our special driver is not running...
-			dlog_puts("Windows running, using plain packet size");
+			dputs("Windows running, using plain packet size");
 			data.bios_packet_size = PS2M_PACKET_SIZE_PLAIN;
 		}
 	}
@@ -1004,23 +954,23 @@ static void reset_mouse_hardware()
 	if (err && data.bios_packet_size != PS2M_PACKET_SIZE_PLAIN) {
 		// However, if there is an error, drop down to plain packet size
 		// Emulators like DOSBox don't support anything but plain packet size
-		dlog_puts("BIOS didn't support streaming mode, using plain packet size");
+		dputs("BIOS didn't support streaming mode, using plain packet size");
 		data.bios_packet_size = PS2M_PACKET_SIZE_PLAIN;
 		err = ps2m_init(data.bios_packet_size);
 	}
 	if (err) {
-		dlog_puts("error on ps2m_init during reset, ignoring");
+		dputs("error on ps2m_init during reset, ignoring");
 	}
 
 #if USE_WHEEL
 	if (data.usewheel
 	        && data.bios_packet_size == PS2M_PACKET_SIZE_STREAMING
 	        && ps2m_detect_wheel()) {
-		dlog_puts("PS/2 wheel detected");
+		dputs("PS/2 wheel detected");
 		data.haswheel = true;
 		data.packet_size = PS2M_PACKET_SIZE_EXT;
 	} else {
-		if (data.usewheel) dlog_puts("PS/2 wheel NOT detected");
+		if (data.usewheel) dputs("PS/2 wheel NOT detected");
 		data.haswheel = false;
 	}
 #if USE_VMWARE
@@ -1129,7 +1079,7 @@ static void int33_handler(union INTPACK r)
 {
 	switch (r.w.ax) {
 	case INT33_RESET_MOUSE:
-		dlog_puts("Mouse reset");
+		dputs("Mouse reset");
 		reload_video_info();
 		reset_mouse_settings();
 		reset_mouse_hardware();
@@ -1139,21 +1089,21 @@ static void int33_handler(union INTPACK r)
 		break;
 	case INT33_SHOW_CURSOR:
 #if TRACE_EVENTS
-		dlog_puts("Mouse show cursor");
+		dputs("Mouse show cursor");
 #endif
 		data.visible_count++;
 		refresh_cursor();
 		break;
 	case INT33_HIDE_CURSOR:
 #if TRACE_EVENTS
-		dlog_puts("Mouse hide cursor");
+		dputs("Mouse hide cursor");
 #endif
 		data.visible_count--;
 		refresh_cursor();
 		break;
 	case INT33_GET_MOUSE_POSITION:
 #if TRACE_EVENTS
-		dlog_puts("Mouse get position");
+		dputs("Mouse get position");
 #endif
 		r.w.cx = snap_to_grid(data.pos.x, data.screen_granularity.x);
 		r.w.dx = snap_to_grid(data.pos.y, data.screen_granularity.y);
@@ -1167,7 +1117,7 @@ static void int33_handler(union INTPACK r)
 		break;
 	case INT33_SET_MOUSE_POSITION:
 #if TRACE_EVENTS
-		dlog_puts("Mouse set position");
+		dputs("Mouse set position");
 #endif
 		data.pos.x = r.w.cx;
 		data.pos.y = r.w.dx;
@@ -1181,7 +1131,7 @@ static void int33_handler(union INTPACK r)
 		break;
 	case INT33_GET_BUTTON_PRESSED_COUNTER:
 #if TRACE_EVENTS
-		dlog_puts("Mouse get button pressed counter");
+		dputs("Mouse get button pressed counter");
 #endif
 		r.w.ax = data.buttons;
 #if USE_WHEEL
@@ -1200,7 +1150,7 @@ static void int33_handler(union INTPACK r)
 		break;
 	case INT33_GET_BUTTON_RELEASED_COUNTER:
 #if TRACE_EVENTS
-		dlog_puts("Mouse get button released counter");
+		dputs("Mouse get button released counter");
 #endif
 		r.w.ax = data.buttons;
 #if USE_WHEEL
@@ -1217,11 +1167,7 @@ static void int33_handler(union INTPACK r)
 		    &data.button[MIN(r.w.bx, NUM_BUTTONS - 1)].released);
 		break;
 	case INT33_SET_HORIZONTAL_WINDOW:
-		dlog_print("Mouse set horizontal window [");
-		dlog_printd(r.w.cx);
-		dlog_putc(',');
-		dlog_printd(r.w.dx);
-		dlog_puts("]");
+		dprintf("Mouse set horizontal window [%d,%d]\n", r.w.cx, r.w.dx);
 		// Recheck in case someone changed the video mode
 		refresh_video_info();
 		data.min.x = r.w.cx;
@@ -1229,18 +1175,14 @@ static void int33_handler(union INTPACK r)
 		bound_position_to_window();
 		break;
 	case INT33_SET_VERTICAL_WINDOW:
-		dlog_print("Mouse set vertical window [");
-		dlog_printd(r.w.cx);
-		dlog_putc(',');
-		dlog_printd(r.w.dx);
-		dlog_puts("]");
+		dprintf("Mouse set vertical window [%d,%d]\n", r.w.cx, r.w.dx);
 		refresh_video_info();
 		data.min.y = r.w.cx;
 		data.max.y = r.w.dx;
 		bound_position_to_window();
 		break;
 	case INT33_SET_GRAPHICS_CURSOR:
-		dlog_puts("Mouse set graphics cursor");
+		dputs("Mouse set graphics cursor");
 		hide_cursor();
 		data.cursor_hotspot.x = r.w.bx;
 		data.cursor_hotspot.y = r.w.cx;
@@ -1249,9 +1191,7 @@ static void int33_handler(union INTPACK r)
 		refresh_cursor();
 		break;
 	case INT33_SET_TEXT_CURSOR:
-		dlog_print("Mouse set text cursor ");
-		dlog_printd(r.w.bx);
-		dlog_endline();
+		dprintf("Mouse set text cursor type=%d\n", r.w.bx);
 		hide_cursor();
 		data.cursor_text_type = r.w.bx;
 		data.cursor_text_and_mask = r.w.cx;
@@ -1260,7 +1200,7 @@ static void int33_handler(union INTPACK r)
 		break;
 	case INT33_GET_MOUSE_MOTION:
 #if TRACE_EVENTS
-		dlog_puts("Mouse get motion");
+		dputs("Mouse get motion");
 #endif
 		r.w.cx = data.delta.x;
 		r.w.dx = data.delta.y;
@@ -1268,27 +1208,21 @@ static void int33_handler(union INTPACK r)
 		data.delta.y = 0;
 		break;
 	case INT33_SET_EVENT_HANDLER:
-		dlog_puts("Mouse set event handler");
+		dputs("Mouse set event handler");
 		data.event_mask = r.w.cx;
 		data.event_handler = MK_FP(r.w.es, r.w.dx);
 		break;
 	case INT33_SET_MOUSE_SPEED:
-		dlog_print("Mouse set speed x=");
-		dlog_printd(r.w.cx);
-		dlog_print(" y=");
-		dlog_printd(r.w.dx);
-		dlog_endline();
+		dprintf("Mouse set speed x=%d y=%d\n", r.w.cx, r.w.dx);
 		data.mickeysPerLine.x = r.w.cx;
 		data.mickeysPerLine.y = r.w.dx;
 		break;
 	case INT33_SET_SPEED_DOUBLE_THRESHOLD:
-		dlog_print("Mouse set speed double threshold=");
-		dlog_printd(r.w.dx);
-		dlog_endline();
+		dprintf("Mouse set speed double threshold=%d\n", r.w.dx);
 		data.doubleSpeedThreshold = r.w.dx;
 		break;
 	case INT33_EXCHANGE_EVENT_HANDLER:
-		dlog_puts("Mouse exchange event handler");
+		dputs("Mouse exchange event handler");
 		data.event_mask = r.w.cx;
 	    {
 		    void (__far *prev_event_handler)() = data.event_handler;
@@ -1298,25 +1232,20 @@ static void int33_handler(union INTPACK r)
 	    }
 		break;
 	case INT33_GET_MOUSE_STATUS_SIZE:
-		dlog_puts("Mouse get status size");
+		dputs("Mouse get status size");
 		r.w.bx = sizeof(TSRDATA);
 		break;
 	case INT33_SAVE_MOUSE_STATUS:
-		dlog_puts("Mouse save status");
+		dputs("Mouse save status");
 		_fmemcpy(MK_FP(r.w.es, r.w.dx), &data, sizeof(TSRDATA));
 		break;
 	case INT33_LOAD_MOUSE_STATUS:
-		dlog_puts("Mouse load status");
+		dputs("Mouse load status");
 		_fmemcpy(&data, MK_FP(r.w.es, r.w.dx), sizeof(TSRDATA));
 		break;
 	case INT33_SET_MOUSE_SENSITIVITY:
-		dlog_print("Mouse set sensitivity x=");
-		dlog_printd(r.w.bx);
-		dlog_print(" y=");
-		dlog_printd(r.w.cx);
-		dlog_print(" threshold=");
-		dlog_printd(r.w.dx);
-		dlog_endline();
+		dprintf("Mouse set sensitivity x=%d y=%d threshold=%d\n",
+		        r.w.bx, r.w.cx, r.w.dx);
 		// TODO According to cutemouse, sensitivity != mickeysPerLine
 		data.mickeysPerLine.x = r.w.bx;
 		data.mickeysPerLine.y = r.w.cx;
@@ -1328,7 +1257,7 @@ static void int33_handler(union INTPACK r)
 		r.w.dx = data.doubleSpeedThreshold;
 		break;
 	case INT33_RESET_SETTINGS:
-		dlog_puts("Mouse reset settings");
+		dputs("Mouse reset settings");
 		reload_video_info();
 		reset_mouse_settings();
 		if (!data.bios_packet_size || !data.packet_size) {
@@ -1343,7 +1272,7 @@ static void int33_handler(union INTPACK r)
 		r.w.bx = 0;
 		break;
 	case INT33_GET_DRIVER_INFO:
-		dlog_puts("Mouse get driver info");
+		dputs("Mouse get driver info");
 		r.h.bh = REPORTED_VERSION_MAJOR;
 		r.h.bl = REPORTED_VERSION_MINOR;
 		r.h.ch = INT33_MOUSE_TYPE_PS2;
@@ -1363,7 +1292,7 @@ static void int33_handler(union INTPACK r)
 #if USE_WHEEL
 	// Wheel API extensions:
 	case INT33_GET_CAPABILITIES:
-		dlog_puts("Mouse get capabitilies");
+		dputs("Mouse get capabitilies");
 		r.w.ax = INT33_WHEEL_API_MAGIC; // Driver supports wheel API
 		r.w.bx = 0;
 		r.w.cx = data.haswheel ? INT33_CAPABILITY_MOUSE_API : 0;
@@ -1372,14 +1301,12 @@ static void int33_handler(union INTPACK r)
 #endif
 	// Our internal API extensions:
 	case INT33_GET_TSR_DATA:
-		dlog_puts("Get TSR data");
+		dputs("Get TSR data");
 		r.w.es = FP_SEG(&data);
 		r.w.di = FP_OFF(&data);
 		break;
 	default:
-		dlog_print("Unknown mouse function ax=");
-		dlog_printx(r.w.ax);
-		dlog_endline();
+		dprintf("Unknown mouse function ax=%x\n", r.w.ax);
 		break;
 	}
 }
@@ -1421,12 +1348,12 @@ static void windows_mouse_handler(int action, int x, int y, int buttons, int eve
 		handle_mouse_event(buttons, true, x, y, 0);
 		break;
 	case VMD_ACTION_HIDE_CURSOR:
-		dlog_puts("VMD_ACTION_HIDE_CURSOR");
+		dputs("VMD_ACTION_HIDE_CURSOR");
 		data.w386cursor = true;
 		refresh_cursor();
 		break;
 	case VMD_ACTION_SHOW_CURSOR:
-		dlog_puts("VMD_ACTION_SHOW_CURSOR");
+		dputs("VMD_ACTION_SHOW_CURSOR");
 		data.w386cursor = false;
 		refresh_cursor();
 		break;
@@ -1463,9 +1390,7 @@ static void int2f_handler(union INTPACK r)
 {
 	switch (r.w.ax) {
 	case INT2F_NOTIFY_WIN386_STARTUP:
-		dlog_print("Windows is starting, version=");
-		dlog_printx(r.w.di);
-		dlog_endline();
+		dprintf("Windows is starting, version=0x%x\n", r.w.di);
 		data.w386_startup.version = 3;
 		data.w386_startup.next = MK_FP(r.w.es, r.w.bx);
 		data.w386_startup.device_driver = 0;
@@ -1480,7 +1405,7 @@ static void int2f_handler(union INTPACK r)
 		data.haswin386 = true;
 		break;
 	case INT2F_NOTIFY_WIN386_SHUTDOWN:
-		dlog_puts("Windows is stopping");
+		dputs("Windows is stopping");
 		data.haswin386 = false;
 		data.w386cursor = false;
 		break;
diff --git a/mousew16.c b/mousew16.c
index dc16833..dcfb82e 100644
--- a/mousew16.c
+++ b/mousew16.c
@@ -102,9 +102,7 @@ static void send_wheel_movement(int8_t z)
 	WPARAM wParam;
 
 #if TRACE_EVENTS
-	dlog_print("w16mouse: wheel=");
-	dlog_printd(z);
-	dlog_endline();
+	dprintf("w16mouse: wheel=%d\n", z);
 #endif
 
 	// TODO It's highly unlikely that we can call this many functions from
@@ -156,19 +154,8 @@ static void FAR int33_mouse_callback(uint16_t events, uint16_t buttons, int16_t
 	int status = 0;
 
 #if TRACE_EVENTS
-	dlog_print("w16mouse: events=");
-	dlog_printx(events);
-	dlog_print(" buttons=");
-	dlog_printx(buttons);
-	dlog_print(" x=");
-	dlog_printd(x);
-	dlog_print(" y=");
-	dlog_printd(y);
-	dlog_print(" dx=");
-	dlog_printd(delta_x);
-	dlog_print(" dy=");
-	dlog_printd(delta_y);
-	dlog_endline();
+	dprintf("w16mouse: events=0x%x buttons=0x%x x=%d y=%d dx=%d dy=%d\n",
+	        events, buttons, x, y, delta_x, delta_y);
 #endif
 
 	if (events & INT33_EVENT_MASK_LEFT_BUTTON_PRESSED)   status |= SF_B1_DOWN;
@@ -214,15 +201,12 @@ static void FAR int33_mouse_callback(uint16_t events, uint16_t buttons, int16_t
 	(void) buttons;
 
 #if TRACE_EVENTS
-	dlog_print("w16mouse: post status=");
-	dlog_printx(status);
-	dlog_print(" x=");
-	if (status & SF_ABSOLUTE) dlog_printu(x);
-	                     else dlog_printd(x);
-	dlog_print(" y=");
-	if (status & SF_ABSOLUTE) dlog_printu(y);
-	                     else dlog_printd(y);
-	dlog_endline();
+	dprintf("w16mouse: post status=0x%x ", status);
+	if (status & SF_ABSOLUTE) {
+		dprintf("x=%u y=%u\n", x, y);
+	} else {
+		dprintf("x=%d y=%d\n", x, y);
+	}
 #endif
 
 	send_event(status, x, y, MOUSE_NUM_BUTTONS, 0, 0);
diff --git a/sfmain.c b/sfmain.c
index 3cd9a03..c0f292f 100644
--- a/sfmain.c
+++ b/sfmain.c
@@ -349,6 +349,9 @@ static int configure_driver(LPTSRDATA data)
 		data->files[i].handle = SHFL_HANDLE_NIL;
 	}
 
+	// Configure the debug logging port
+	dlog_init();
+
 	// Initialize TSR data
 	data->dossda = dos_get_swappable_dos_area();
 
diff --git a/sftsr.c b/sftsr.c
index 4e47109..97471ae 100644
--- a/sftsr.c
+++ b/sftsr.c
@@ -141,15 +141,13 @@ static bool is_call_for_mounted_drive(union INTPACK __far *r)
 
 static void clear_dos_err(union INTPACK __far *r)
 {
-	dlog_puts("->ok");
+	dputs("->ok");
 	r->w.flags &= ~INTR_CF;
 }
 
 static void set_dos_err(union INTPACK __far *r, int err)
 {
-	dlog_print("->dos error ");
-	dlog_printd(err);
-	dlog_endline();
+	dprintf("->dos error %d\n", err);
 	r->w.flags |= INTR_CF;
 	r->w.ax = err;
 }
@@ -190,15 +188,7 @@ static int vbox_err_to_dos(vboxerr err)
 
 static void set_vbox_err(union INTPACK __far *r, vboxerr err)
 {
-	dlog_print("->vbox error ");
-	if (err < INT16_MIN || err > INT16_MAX) {
-		dlog_printx(err >> 16);
-		dlog_print(":");
-		dlog_printx(err & 0xFFFF);
-	} else {
-		dlog_printd(err);
-	}
-	dlog_endline();
+	dprintf("->vbox error %ld\n", err);
 	set_dos_err(r, vbox_err_to_dos(err));
 }
 
@@ -308,7 +298,10 @@ static bool copy_to_8_3_filename(char __far *dst, const SHFLSTRING *str)
 		extlen = 0;
 	}
 
-	if (namelen > 8) {
+	if (namelen == 0) {
+		// Skip files with extension but no name (e.g. ".hid")
+		valid_8_3 = false;
+	} else if (namelen > 8) {
 		namelen = 8;
 		valid_8_3 = false;
 	}
@@ -393,21 +386,19 @@ static inline void clear_sdb_openfile_index(DOSSDB __far *sdb)
 }
 
 /** Closes an openfile entry by index, and marks it as free. */
-static vboxerr close_openfile(unsigned index)
+static vboxerr close_openfile(unsigned openfile)
 {
 	vboxerr err;
 
-	dlog_print("close openfile=");
-	dlog_printu(index);
-	dlog_endline();
+	dprintf("close openfile=%u\n", openfile);
 
 	err = vbox_shfl_close(&data.vb, data.hgcm_client_id,
-	                      data.files[index].root, data.files[index].handle);
+	                      data.files[openfile].root, data.files[openfile].handle);
 
 	// Even if we have an error on close,
 	// assume the file is lost and leak the handle
-	data.files[index].root = SHFL_ROOT_NIL;
-	data.files[index].handle = SHFL_HANDLE_NIL;
+	data.files[openfile].root = SHFL_ROOT_NIL;
+	data.files[openfile].handle = SHFL_HANDLE_NIL;
 
 	return err;
 }
@@ -423,12 +414,7 @@ static void flush_sft_metadata(DOSSFT __far *sft)
 	if (sft->dev_info & DOS_SFT_FLAG_TIME_SET) {
 		unsigned buf_size = sizeof(SHFLFSOBJINFO);
 
-		dlog_puts("setting modified date/time");
-		dlog_print("time=");
-		dlog_printx(sft->f_time);
-		dlog_print("date=");
-		dlog_printx(sft->f_date);
-		dlog_endline();
+		dputs("setting modified date/time");
 
 		memset(&parms.objinfo, 0, sizeof(SHFLFSOBJINFO));
 
@@ -478,13 +464,7 @@ static void handle_create_open_ex(union INTPACK __far *r)
 		break;
 	}
 
-	dlog_print("handle_open for ");
-	dlog_fprint(path);
-	dlog_print(" act=");
-	dlog_printx(action);
-	dlog_print(" mode=");
-	dlog_printx(mode);
-	dlog_endline();
+	dprintf("handle_open for %Fs act=%x mode=%x\n", path, action, mode);
 
 	openfile = find_free_openfile();
 	if (openfile == INVALID_OPENFILE) {
@@ -530,9 +510,7 @@ static void handle_create_open_ex(union INTPACK __far *r)
 		parms.create.CreateFlags |= SHFL_CF_ACT_FAIL_IF_NEW;
 	}
 
-	dlog_print("vbox create flags=");
-	dlog_printx(parms.create.CreateFlags);
-	dlog_endline();
+	dprintf("vbox create flags=%lx\n", parms.create.CreateFlags);
 
 	err = vbox_shfl_open(&data.vb, data.hgcm_client_id, root, &shflstr.shflstr, &parms.create);
 	if (err) {
@@ -540,11 +518,7 @@ static void handle_create_open_ex(union INTPACK __far *r)
 		return;
 	}
 
-	dlog_print("vbox success result=");
-	dlog_printd(parms.create.Result);
-	dlog_print(" openfile=");
-	dlog_printu(openfile);
-	dlog_endline();
+	dprintf("vbox success result=%ld openfile=%u\n", parms.create.Result, openfile);
 
 	switch (parms.create.Result) {
 	case SHFL_PATH_NOT_FOUND:
@@ -587,9 +561,7 @@ static void handle_close(union INTPACK __far *r)
 	DOSSFT __far *sft = MK_FP(r->w.es, r->w.di);
 	unsigned openfile = get_sft_openfile_index(sft);
 
-	dlog_print("handle_close openfile=");
-	dlog_printu(openfile);
-	dlog_endline();
+	dprintf("handle_close openfile=%u\n", openfile);
 
 	if (!is_valid_openfile_index(openfile)) {
 		set_dos_err(r, DOS_ERROR_INVALID_HANDLE);
@@ -624,11 +596,7 @@ static void handle_read(union INTPACK __far *r)
 	unsigned bytes = r->w.cx;
 	vboxerr err;
 
-	dlog_print("handle_read openfile=");
-	dlog_printu(openfile);
-	dlog_print(" bytes=");
-	dlog_printu(bytes);
-	dlog_endline();
+	dprintf("handle_read openfile=%u bytes=%u\n", openfile, bytes);
 
 	if (!is_valid_openfile_index(openfile)) {
 		set_dos_err(r, DOS_ERROR_INVALID_HANDLE);
@@ -643,9 +611,7 @@ static void handle_read(union INTPACK __far *r)
 		return;
 	}
 
-	dlog_print("handle_read bytes_read=");
-	dlog_printu(bytes);
-	dlog_endline();
+	dprintf("handle_read bytes_read=%u\n", bytes);
 
 	// Advance the file position
 	sft->f_pos += bytes;
@@ -663,11 +629,7 @@ static void handle_write(union INTPACK __far *r)
 	unsigned bytes = r->w.cx;
 	vboxerr err;
 
-	dlog_print("handle_write openfile=");
-	dlog_printu(openfile);
-	dlog_print(" bytes=");
-	dlog_printu(bytes);
-	dlog_endline();
+	dprintf("handle_write openfile=%u bytes=%u\n", openfile, bytes);
 
 	if (!is_valid_openfile_index(openfile)) {
 		set_dos_err(r, DOS_ERROR_INVALID_HANDLE);
@@ -682,9 +644,7 @@ static void handle_write(union INTPACK __far *r)
 		return;
 	}
 
-	dlog_print("handle_write bytes_written=");
-	dlog_printu(bytes);
-	dlog_endline();
+	dprintf("handle_write bytes_written=%u\n", bytes);
 
 	// Advance the file position
 	sft->f_pos += bytes;
@@ -705,9 +665,7 @@ static void handle_commit(union INTPACK __far *r)
 	unsigned openfile = get_sft_openfile_index(sft);
 	vboxerr err;
 
-	dlog_print("handle_commit openfile=");
-	dlog_printu(openfile);
-	dlog_endline();
+	dprintf("handle_commit openfile=%u\n", openfile);
 
 	if (!is_valid_openfile_index(openfile)) {
 		set_dos_err(r, DOS_ERROR_INVALID_HANDLE);
@@ -737,11 +695,7 @@ static void handle_lock(union INTPACK __far *r)
 	DOSLOCK __far *ops = MK_FP(r->w.ds, r->w.dx);
 	vboxerr err;
 
-	dlog_print("handle_lock ");
-	if (unlock) dlog_print("unlock");
-	dlog_print(" numops=");
-	dlog_printu(numops);
-	dlog_endline();
+	dprintf("handle_lock %s numops=%u\n", unlock ? "unlock" : "lock", numops);
 
 	for (i = 0; i < numops; i++) {
 		err = vbox_shfl_lock(&data.vb, data.hgcm_client_id,
@@ -765,9 +719,7 @@ static void handle_seek_end(union INTPACK __far *r)
 	unsigned buf_size = sizeof(SHFLFSOBJINFO);
 	vboxerr err;
 
-	dlog_print("handle_seek_end offset=");
-	dlog_printd(offset);
-	dlog_endline();
+	dprintf("handle_seek_end openfile=%u offset=%ld\n", openfile, offset);
 
 	memset(&parms.objinfo, 0, sizeof(SHFLFSOBJINFO));
 
@@ -789,9 +741,7 @@ static void handle_seek_end(union INTPACK __far *r)
 	// Update current file size
 	sft->f_size = parms.objinfo.cbObject;
 
-	dlog_print("seek_end filesize=");
-	dlog_printd(sft->f_size);
-	dlog_endline();
+	dprintf("seek_end filesize=%lu\n", sft->f_size);
 
 	// Update the current offset pointer
 	if (offset < 0 && sft->f_size < -offset ) {
@@ -799,7 +749,7 @@ static void handle_seek_end(union INTPACK __far *r)
 		set_dos_err(r, DOS_ERROR_SEEK);
 		return;
 	} else if (offset > 0) {
-		dlog_puts("seek_end enlarge");
+		dputs("seek_end enlarge");
 		// Seeking past the end of the file, enlarge
 		err = vbox_shfl_set_file_size(&data.vb, data.hgcm_client_id,
 		                              data.files[openfile].root, data.files[openfile].handle,
@@ -817,9 +767,7 @@ static void handle_seek_end(union INTPACK __far *r)
 		sft->f_pos = sft->f_size + offset;
 	}
 
-	dlog_print("seek_end new pos=");
-	dlog_printd(sft->f_pos);
-	dlog_endline();
+	dprintf("seek_end new pos=%lu\n", sft->f_pos);
 
 	// Return new file position in dx:ax
 	r->w.dx = sft->f_pos >> 16;
@@ -832,7 +780,7 @@ static void handle_close_all(union INTPACK __far *r)
 {
 	unsigned i;
 
-	dlog_puts("handle_close_all");
+	dputs("handle_close_all");
 
 	for (i = 0; i < NUM_FILES; ++i) {
 		if (data.files[i].root != SHFL_ROOT_NIL) {
@@ -850,9 +798,7 @@ static void handle_delete(union INTPACK __far *r)
 	SHFLROOT root = data.drives[drive].root;
 	vboxerr err;
 
-	dlog_print("handle_delete ");
-	dlog_fprint(path);
-	dlog_endline();
+	dprintf("handle_delete %Fs\n", path);
 
 	copy_drive_relative_filename(&shflstr.shflstr, path);
 	translate_filename_to_host(&shflstr.shflstr);
@@ -876,11 +822,7 @@ static void handle_rename(union INTPACK __far *r)
 	SHFLROOT root = data.drives[srcdrive].root;
 	vboxerr err;
 
-	dlog_print("handle_rename ");
-	dlog_fprint(src);
-	dlog_print(" to ");
-	dlog_fprint(dst);
-	dlog_endline();
+	dprintf("handle_rename %Fs to %Fs\n", src, dst);
 
 	if (srcdrive != dstdrive) {
 		set_dos_err(r, DOS_ERROR_NOT_SAME_DEVICE);
@@ -912,9 +854,7 @@ static void handle_getattr(union INTPACK __far *r)
 	SHFLROOT root = data.drives[drive].root;
 	vboxerr err;
 
-	dlog_print("handle_getattr ");
-	dlog_fprint(path);
-	dlog_endline();
+	dprintf("handle_getattr %Fs\n", path);
 
 	copy_drive_relative_filename(&shflstr.shflstr, path);
 	translate_filename_to_host(&shflstr.shflstr);
@@ -957,11 +897,7 @@ static vboxerr open_search_dir(unsigned openfile, SHFLROOT root, const char __fa
 {
 	vboxerr err;
 
-	dlog_print("open_search_dir openfile=");
-	dlog_printu(openfile);
-	dlog_print(" path=");
-	dlog_fprint(path);
-	dlog_endline();
+	dprintf("open_search_dir openfile=%u path=%Fs\n", openfile, path);
 
 	copy_drive_relative_dirname(&shflstr.shflstr, path);
 	translate_filename_to_host(&shflstr.shflstr);
@@ -974,7 +910,7 @@ static vboxerr open_search_dir(unsigned openfile, SHFLROOT root, const char __fa
 	err = vbox_shfl_open(&data.vb, data.hgcm_client_id, root,
 	                     &shflstr.shflstr, &parms.create);
 	if (err) {
-		dlog_puts("open search dir failed");
+		dputs("open search dir failed");
 		return err;
 	}
 
@@ -988,7 +924,7 @@ static vboxerr open_search_dir(unsigned openfile, SHFLROOT root, const char __fa
 	}
 
 	if (parms.create.Handle == SHFL_HANDLE_NIL) {
-		dlog_puts("open search dir returned no handle...");
+		dputs("open search dir returned no handle...");
 		return VERR_INVALID_HANDLE;
 	}
 
@@ -1011,9 +947,7 @@ static vboxerr find_volume_label(SHFLROOT root)
 
 	translate_filename_from_host(&shflstr.shflstr);
 
-	dlog_print("label: ");
-	dlog_fprint(shflstr.buf);
-	dlog_endline();
+	dprintf("label: %s\n", shflstr.buf);
 
 	found_file->attr = _A_VOLID;
 	copy_to_8_3_filename(found_file->filename, &shflstr.shflstr);
@@ -1044,9 +978,7 @@ static vboxerr find_next_from_vbox(unsigned openfile, const char __far *path)
 		translate_filename_to_host(&shflstr.shflstr);
 		fix_wildcards(&shflstr.shflstr);
 
-		dlog_print("fixed path=");
-		dlog_print(shflstr.buf);
-		dlog_endline();
+		dprintf("fixed path=%s\n", shflstr.buf);
 
 		if (shflstr.shflstr.ach[shflstr.shflstr.u16Length-1] == '\\') {
 			// No wildcard?
@@ -1079,14 +1011,10 @@ static vboxerr find_next_from_vbox(unsigned openfile, const char __far *path)
 			return VERR_IO_BAD_LENGTH;
 		}
 
-		dlog_print("got diritem name=");
-		dlog_fprint(shfldirinfo.dirinfo.name.ach);
-		dlog_print(" sfnLen=");
-		dlog_printu(shfldirinfo.dirinfo.cucShortName);
-		dlog_endline();
+		dprintf("got diritem name=%s\n", shfldirinfo.dirinfo.name.ach);
 
 		if (!is_valid_dos_file(&shfldirinfo.dirinfo.Info)) {
-			dlog_puts("hiding file with invalid info");
+			dputs("hiding file with invalid info");
 			continue;
 		}
 
@@ -1098,7 +1026,7 @@ static vboxerr find_next_from_vbox(unsigned openfile, const char __far *path)
 		// than the ones in search_attr .
 		// Except for the ARCH and RDONLY attributes, which are always accepted.
 		if (found_file->attr & search_mask) {
-			dlog_puts("hiding file with unwanted attrs");
+			dputs("hiding file with unwanted attrs");
 			continue; // Skip this one
 		}
 
@@ -1109,12 +1037,12 @@ static vboxerr find_next_from_vbox(unsigned openfile, const char __far *path)
 		translate_filename_from_host(&shfldirinfo.dirinfo.name);
 
 		if (!copy_to_8_3_filename(found_file->filename, &shfldirinfo.dirinfo.name)) {
-			dlog_puts("hiding file with long filename");
+			dputs("hiding file with long filename");
 			continue;
 		}
 
 		if (!matches_8_3_wildcard(found_file->filename, sdb->search_templ)) {
-			dlog_puts("hiding file with unwanted filename");
+			dputs("hiding file with unwanted filename");
 			continue;
 		}
 
@@ -1122,13 +1050,7 @@ static vboxerr find_next_from_vbox(unsigned openfile, const char __far *path)
 		break;
 	};
 
-	dlog_print("accepted file name='");
-	dlog_fnprint(&found_file->filename[0], 8);
-	dlog_putc(' ');
-	dlog_fnprint(&found_file->filename[8], 3);
-	dlog_print("' attr=");
-	dlog_printx(found_file->attr);
-	dlog_endline();
+	dprintf("accepted file name='%.11Fs' attr=0x%x\n", found_file->filename, found_file->attr);
 
 	return 0;
 }
@@ -1149,13 +1071,7 @@ static void handle_find_first(union INTPACK __far *r)
 	unsigned openfile;
 	vboxerr err;
 
-	dlog_print("find_first path=");
-	dlog_fprint(path);
-	dlog_print(" mask=");
-	dlog_fnprint(search_mask, 8+3);
-	dlog_print(" attr=");
-	dlog_printx(search_attr);
-	dlog_endline();
+	dprintf("find_first path=%Fs mask='%.11Fs' attr=0x%x\n", path, search_mask, search_attr);
 
 	// Initialize the search data block; we'll use it on future calls
 	// Even DOS seems to look and check that we did initialize it;
@@ -1171,14 +1087,14 @@ static void handle_find_first(union INTPACK __far *r)
 		// Simulate an initial entry with the volume label
 		// if we are searching for it.
 		// DOS actually expects to always find it first, and nothing else.
-		dlog_puts("search volid");
+		dputs("search volid");
 		err = find_volume_label(root);
 		if (err) {
-			dlog_puts("search volid err");
+			dputs("search volid err");
 			set_vbox_err(r, err);
 			return;
 		}
-		dlog_puts("search volid OK");
+		dputs("search volid OK");
 		clear_dos_err(r);
 		return;
 	} else if (search_attr == 0) {
@@ -1239,7 +1155,7 @@ static void handle_find_first(union INTPACK __far *r)
 	// never to call findnext again.
 	// Cue hack to avoid leaking one dirfd for each mkdir...
 	if (_fmemcmp(data.dossda->found_file.filename, "TESTDIR TMP", 8+3) == 0) {
-		dlog_puts("win3.x testdir detected");
+		dputs("win3.x testdir detected");
 		close_openfile(openfile);
 		clear_sdb_openfile_index(&data.dossda->sdb);
 	}
@@ -1252,9 +1168,7 @@ static void handle_find_next(union INTPACK __far *r)
 	unsigned openfile = get_sdb_openfile_index(&data.dossda->sdb);
 	vboxerr err;
 
-	dlog_print("find_next openfile=");
-	dlog_printu(openfile);
-	dlog_endline();
+	dprintf("find_next openfile=%u\n", openfile);
 
 	if (!is_valid_openfile_index(openfile)) {
 		set_dos_err(r, DOS_ERROR_NO_MORE_FILES);
@@ -1279,9 +1193,7 @@ static void handle_chdir(union INTPACK __far *r)
 	SHFLROOT root = data.drives[drive].root;
 	vboxerr err;
 
-	dlog_print("handle_chdir to ");
-	dlog_fprint(path);
-	dlog_endline();
+	dprintf("handle_chdir %Fs\n", path);
 
 	// Just have to check if the directory exists
 	copy_drive_relative_filename(&shflstr.shflstr, path);
@@ -1322,9 +1234,7 @@ static void handle_mkdir(union INTPACK __far *r)
 	SHFLROOT root = data.drives[drive].root;
 	vboxerr err;
 
-	dlog_print("handle_mkdir ");
-	dlog_fprint(path);
-	dlog_endline();
+	dprintf("handle_mkdir %Fs\n", path);
 
 	copy_drive_relative_filename(&shflstr.shflstr, path);
 	translate_filename_to_host(&shflstr.shflstr);
@@ -1362,9 +1272,7 @@ static void handle_rmdir(union INTPACK __far *r)
 	SHFLROOT root = data.drives[drive].root;
 	vboxerr err;
 
-	dlog_print("handle_rmdir ");
-	dlog_fprint(path);
-	dlog_endline();
+	dprintf("handle_rmdir %Fs\n", path);
 
 	copy_drive_relative_filename(&shflstr.shflstr, path);
 	translate_filename_to_host(&shflstr.shflstr);
@@ -1406,7 +1314,7 @@ static void handle_get_disk_free(union INTPACK __far *r)
 	unsigned buf_size = sizeof(SHFLVOLINFO);
 	vboxerr err;
 
-	dlog_puts("handle disk free");
+	dputs("handle disk free");
 
 	memset(&parms.volinfo, 0, sizeof(SHFLVOLINFO));
 
@@ -1433,7 +1341,7 @@ static bool int2f_11_handler(union INTPACK r)
 	if (r.h.ah != 0x11) return false; // Only interested in network redirector functions
 	if (r.h.al == 0xff && r.w.bx == 0x5742 && r.w.cx == 0x5346) {
 		// These are the magic numbers to our private "Get TSR data" function
-		dlog_puts("Get TSR data");
+		dputs("Get TSR data");
 		r.w.es = get_ds();
 		r.w.di = FP_OFF(&data);
 		r.w.bx = 0x5444;
@@ -1442,9 +1350,7 @@ static bool int2f_11_handler(union INTPACK r)
 	}
 
 #if TRACE_CALLS
-	dlog_print("2f al=");
-	dlog_printx(r.h.al);
-	dlog_endline();
+	dprintf("2f al=%hx\n", r.h.al);
 #endif
 
 	// Handle special functions that target all redirectors first
diff --git a/unixtime.h b/unixtime.h
index 57846b7..3a2a7f0 100644
--- a/unixtime.h
+++ b/unixtime.h
@@ -140,7 +140,7 @@ static void timestampns_to_dos_time(uint16_t __far *dos_time, uint16_t __far *do
 	day = 1 + days_since_epoch; // (day is 1-based)
 
 	if (year < DOS_EPOCH_YEAR) {
-		dlog_puts("Year is too old, will show as 0");
+		dputs("Year is too old, will show as 0");
 		year = 0;
 	} else {
 		year -= DOS_EPOCH_YEAR;
@@ -179,12 +179,6 @@ static void timestampns_from_dos_time(int64_t *timestampns, uint16_t dos_time, u
 
 	seconds2_since_day = seconds2 + (minutes * 60U/2) + (hours * 3600U/2);
 
-	dlog_print("days_since_epoch=");
-	dlog_printd(days_since_epoch);
-	dlog_print(" seconds2_since_day=");
-	dlog_printd(seconds2_since_day);
-	dlog_endline();
-
 	__asm {
 		push eax
 		push ecx
diff --git a/vbox.c b/vbox.c
index 9fd0aa4..7640b13 100644
--- a/vbox.c
+++ b/vbox.c
@@ -94,9 +94,7 @@ int vbox_init_buffer(LPVBOXCOMM vb, unsigned size)
 		if (err) {
 			// As far as I have seen, most VDS providers always keep low memory contiguous,
 			// so I'm not handling VDS_REGION_NOT_CONTIGUOUS here.
-			dlog_print("Error while VDS locking, err=");
-			dlog_printd(err);
-			dlog_endline();
+			dprintf("Error while VDS locking, err=%d\n", err);
 			return err;
 		}
 
@@ -115,9 +113,7 @@ int vbox_release_buffer(LPVBOXCOMM vb)
 	if (vb->vds && vds_available()) {
 		int err = vds_unlock_dma_buffer_region(&vb->dds, 0);
 		if (err) {
-			dlog_print("Error while VDS unlocking, err=");
-			dlog_printd(err);
-			dlog_endline();
+			dprintf("Error while VDS unlocking, err=%d\n", err);
 			// Ignore the error, it's not like we can do anything
 		}
 	}