overhaul CP/M drive logging/debugging

1 files changed, 61 insertions, 47 deletions

diff --git a/avr/z180-serv.c b/avr/z180-serv.c
index 65ce881..f55b7a8 100644
--- a/avr/z180-serv.c
+++ b/avr/z180-serv.c
@@ -207,26 +207,31 @@ void do_msg_get_set_time(uint8_t subf, int len, uint8_t * msg)
 
 /* ---------------------------------------------------------------------------*/
 
+static uint8_t drv;
 static uint8_t disk_buffer[CONFIG_CPM_BLOCK_SIZE];
 static struct cpm_drive_s drv_table[CONFIG_CPM_MAX_DRIVE];
 static int handle_cpm_drv_to;
 
+typedef enum {SINGLE, START, MIDDLE, END} dbgmsg_t;
 
-void drv_debug(uint8_t drv, const FLASH char *const fmt, ...)		                                            \
+void drv_debug(dbgmsg_t phase, const FLASH char *const fmt, ...)		                                            \
 {
 	struct cpm_drive_s *dp = &drv_table[drv];
 
 	if (dp->opt & DRV_OPT_DEBUG) {
 
 		va_list ap;
+		va_start (ap, fmt);
 
-		printf_P(PSTR("#  %7lu  dsk%d: "), get_timer(0), drv);
+		if (phase == SINGLE || phase == START)
+			printf_P(PSTR("# %7lu dsk%d: "), get_timer(0), drv);
 
-		va_start (ap, fmt);
 		vfprintf_P (stdout, fmt, ap);
-		va_end (ap);
 
-		putc('\n', stdout);
+		if (phase == SINGLE || phase == END)
+			putc('\n', stdout);
+
+		va_end (ap);
 	}
 }
 
@@ -243,12 +248,13 @@ int drv_list(void)
 	return 0;
 }
 
-int drv_detach(uint8_t drv)
+int drv_detach(uint8_t unit)
 {
+	drv = unit;
 	if (drv < CONFIG_CPM_MAX_DRIVE) {
 		struct cpm_drive_s *p = &drv_table[drv];
 
-		drv_debug(drv, PSTR("detach from '%s'"), p->img_name ? p->img_name : "-");
+		drv_debug(SINGLE, PSTR("detach from '%s'"), p->img_name ? p->img_name : "-");
 
 		if (p->img_name) {
 			f_close(&p->fd);
@@ -279,10 +285,11 @@ static int drv_find_file_attached(const char *fn)
 	return -1;
 }
 
-int drv_attach(uint8_t drv, const char *filename, drv_opt_t options)
+int drv_attach(uint8_t unit, const char *filename, drv_opt_t options)
 {
 	int res;
 
+	drv = unit;
 	if (drv >= CONFIG_CPM_MAX_DRIVE)
 		return AT_RANGE;
 
@@ -340,7 +347,7 @@ int drv_attach(uint8_t drv, const char *filename, drv_opt_t options)
 				bg_setstat(handle_cpm_drv_to, 1);
 			}
 #else
-			drv_debug(drv, PSTR("wrong image file size: %ld, should be %ld"),
+			drv_debug(SINGLE, PSTR("wrong image file size: %ld, should be %ld"),
 					f_size(&p->fd), CONFIG_CPM_DISKSIZE);
 			res = 64;
 #endif
@@ -374,7 +381,8 @@ int cpm_drv_to(int state)
 				if (drv_table[i].flags & DRV_FLG_DIRTY) {
 					drv_table[i].flags &= ~DRV_FLG_DIRTY;
 					f_sync(&drv_table[i].fd);
-					drv_debug(i, PSTR("f_sync"));
+					drv = i;
+					drv_debug(SINGLE, PSTR("f_sync"));
 				}
 			}
 			state = 0;
@@ -383,6 +391,15 @@ int cpm_drv_to(int state)
 	return state;
 }
 
+static const FLASH char * const FLASH rc_messages[] = {
+			FSTR("OK"),
+			FSTR("Internal error: wrong message len"),	/* 01 */
+			FSTR("Invalid relative drive #"),			/* 02 */
+			FSTR("Bus timeout"),						/* 03 */
+			FSTR("Access byond disk size"),				/* 04 */
+			FSTR("Write protect"),						/* 05 */
+			FSTR("No media"),							/* 06 */
+		};
 
 void msg_cpm_result(uint8_t subf, uint8_t rc, int res)
 {
@@ -395,11 +412,14 @@ void msg_cpm_result(uint8_t subf, uint8_t rc, int res)
 	result_msg[1] = res;
 	result_msg[2] = res >> 8;
 
-	if (rc) {
-		debug_cpmsd("###%7lu  error rc: %.02x, res: %d\n", get_timer(0), rc, res);
-	}
-
 	msg_xmit(2, subf, sizeof(result_msg), result_msg);
+
+	if (rc)
+		drv_debug(END, PSTR(" rc: %.02x/%d, '%S'"),
+					rc, res, rc_messages[rc & 0x7f]);
+	else
+		drv_debug(END, PSTR(""));
+
 }
 
 /*
@@ -412,34 +432,31 @@ void msg_cpm_result(uint8_t subf, uint8_t rc, int res)
 
 void do_msg_cpm_login(uint8_t subf, int len, uint8_t * msg)
 {
-	uint8_t drv;
 	struct cpm_drive_s *dp;
 	FRESULT res = 0;
 
 	(void)subf;
 
+	/* Get relative drive number */
+	drv = msg[1];
+	drv_debug(START, PSTR("login"));
+
 	if (len != 5) {
 		return msg_cpm_result(subf, 0x01, res);
 	}
 
-	/* Get relative drive number */
-	drv = msg[1];
 	if ( drv >= CONFIG_CPM_MAX_DRIVE) {
-		debug_cpmsd("##           login failed: invalid relative drive number '%d'\n", drv);
+		/* invalid relative drive number */
 		return msg_cpm_result(subf, 0x02, res);
 	}
 
-	drv_debug(drv, PSTR("login"));
-
 	dp = &drv_table[drv];
 	dp->flags &= ~DRV_FLG_OPEN;
 	dp->dph = ((uint32_t)msg[4] << 16) + ((uint16_t)msg[3] << 8) + msg[2];
 
-
 	if (dp->img_name == NULL) {
 		/* no file attached */
-		drv_debug(drv, PSTR("login failed: no file attached"));
-		return msg_cpm_result(subf, 0x03, res);
+		return msg_cpm_result(subf, 0x06, res);
 	}
 
 	f_close(&dp->fd);
@@ -473,7 +490,6 @@ void do_msg_cpm_login(uint8_t subf, int len, uint8_t * msg)
 
 void do_msg_cpm_rw(uint8_t subf, int len, uint8_t * msg)
 {
-	uint8_t drv;
 	struct cpm_drive_s *dp;
 	uint32_t addr;
 	uint32_t pos;
@@ -485,46 +501,43 @@ void do_msg_cpm_rw(uint8_t subf, int len, uint8_t * msg)
 	uint8_t rc = 0;
 	bool buserr = 0;
 
+	drv = msg[RDRV];
+	dowrite = (subf == 2);
+
+	drv_debug(START, PSTR("%2S"), dowrite ? PSTR("W ") : PSTR(" R"));
+
 	if (len != 10) {
 		return msg_cpm_result(subf, 0x01, res);
 	}
-
-	drv = msg[RDRV];
 	if ( drv>= CONFIG_CPM_MAX_DRIVE) {
 		return msg_cpm_result(subf, 0x02, res);
 	}
 
 	dp = &drv_table[drv];
-
-	if (dp->img_name == NULL) {
-		/* no media */
-		return msg_cpm_result(subf, 0x06, res);
-	}
-
-	if (subf == 2) {
-		dowrite = true;
-		if (dp->opt & DRV_OPT_RO) {
-			return msg_cpm_result(subf, 0x05, res);
-		}
-	} else {
-		dowrite = false;
-	}
-
 	track = (uint16_t)(msg[TRK+1] << 8) + msg[TRK];
 	sec  = (uint16_t)(msg[SEC+1] << 8) + msg[SEC];
 	secs = msg[CNT];
 	addr = ((uint32_t)msg[ADDR+2] << 16) + ((uint16_t)msg[ADDR+1] << 8) + msg[ADDR];
 
+	if (dp->img_name == NULL) {
+		/* no media */
+		return msg_cpm_result(subf, 0x06, res);
+	}
 
 	/* TODO: tracks per sector from dpb */
 	pos = (track * 8UL + sec) * CONFIG_CPM_BLOCK_SIZE;
 
-	drv_debug(drv, PSTR("%5s trk:%4d, sec: %d, pos: %.8lx, secs: %2d, addr: %.5lx"),
-			dowrite ? "write" : " read", track, sec, pos, secs, addr);
+	drv_debug(MIDDLE, PSTR(" T:%4d, S:%2d, cnt:%2d, lba: %.8lx, addr: %.5lx"),
+				track, sec, secs, pos, addr);
+
+	if (dowrite && dp->opt & DRV_OPT_RO) {
+		return msg_cpm_result(subf, 0x05, res);
+	}
+
 
 	if (pos + secs * CONFIG_CPM_BLOCK_SIZE > CONFIG_CPM_DISKSIZE) {
-		drv_debug(drv, PSTR("access > DISKSIZE (%.8lx > %.8lx) aborted!"),
-						pos + secs * CONFIG_CPM_BLOCK_SIZE, CONFIG_CPM_DISKSIZE);
+		drv_debug(MIDDLE, PSTR(" access > DISKSIZE:%.8lx!"),
+						CONFIG_CPM_DISKSIZE);
 		return msg_cpm_result(subf, 0x04, res);
 	}
 
@@ -554,7 +567,8 @@ void do_msg_cpm_rw(uint8_t subf, int len, uint8_t * msg)
 			}
 		}
 		if (brw != CONFIG_CPM_BLOCK_SIZE) {
-			drv_debug(drv, PSTR("short read or write: res: %d, bytes rd/wr: %u"), res, brw);
+			drv_debug(MIDDLE, PSTR(" short rd/wr: res: %d, brw: %u"),
+						res, brw);
 			res = 64;
 		}
 		addr += CONFIG_CPM_BLOCK_SIZE;
@@ -566,7 +580,7 @@ void do_msg_cpm_rw(uint8_t subf, int len, uint8_t * msg)
 	}
 
 	if (buserr) {
-		drv_debug(drv, PSTR("Bus timeout"));
+		/* Bus timeout. how can this happen? */
 		rc = 0x03;
 	}