mboxd: Introduce a new DEBUG log level

Currently there is no output on the console unless -v is specified on
the command line which enables error output. A second -v will provide
info output.

We probably want error output irrespective of whether a -v was given
on the command line because people generally want to know why their
program stopped working.

Make error output unconditional.

A single -v will give minimal informational output which is a good
level to see what the daemon is doing without barfing all over the
console.

A second -v will enable debug output which will print highly verbose
information which will be useful for debugging. Probably don't enable
this under normal circumstances.

Signed-off-by: Suraj Jitindar Singh <sjitindarsingh@gmail.com>
Change-Id: I3da25f7e4e9e976c17389fcceb1d85ef98de7e0a

7 files changed, 121 insertions, 41 deletions

diff --git a/common.h b/common.h
index 55b7b1e..581cd0c 100644
--- a/common.h
+++ b/common.h
@@ -27,16 +27,20 @@
 
 enum {
    MBOX_LOG_NONE = 0,
-   MBOX_LOG_VERBOSE = 1,
+   MBOX_LOG_INFO = 1,
    MBOX_LOG_DEBUG = 2
 } verbosity;
 
-#define MSG_OUT(f_, ...)	do { if (verbosity >= MBOX_LOG_DEBUG) { \
+/* Error Messages */
+#define MSG_ERR(f_, ...)	mbox_log(LOG_ERR, f_, ##__VA_ARGS__)
+/* Informational Messages */
+#define MSG_INFO(f_, ...)	do { if (verbosity >= MBOX_LOG_INFO) { \
 					mbox_log(LOG_INFO, f_, ##__VA_ARGS__); \
 				} } while (0)
-#define MSG_ERR(f_, ...)	do { if (verbosity >= MBOX_LOG_VERBOSE) { \
-					mbox_log(LOG_ERR, f_, ##__VA_ARGS__); \
-				} } while (0)
+/* Debug Messages */
+#define MSG_DBG(f_, ...)	do { if (verbosity >= MBOX_LOG_DEBUG) { \
+					mbox_log(LOG_DEBUG, f_, ##__VA_ARGS__); \
+				} } while(0)
 
 void (*mbox_vlog)(int p, const char *fmt, va_list args);
 
diff --git a/mboxd.c b/mboxd.c
index 1307fe6..e5b6fe8 100644
--- a/mboxd.c
+++ b/mboxd.c
@@ -92,10 +92,11 @@ static int poll_loop(struct mbox_context *context)
 					strerror(errno));
 			}
 
+			MSG_DBG("Received signal: %d\n", info.ssi_signo);
 			switch (info.ssi_signo) {
 			case SIGINT:
 			case SIGTERM:
-				MSG_OUT("Caught Signal - Exiting...\n");
+				MSG_INFO("Caught Signal - Exiting...\n");
 				context->terminate = true;
 				break;
 			case SIGHUP:
@@ -116,7 +117,9 @@ static int poll_loop(struct mbox_context *context)
 			}
 		}
 		if (context->fds[DBUS_FD].revents & POLLIN) { /* DBUS */
-			while ((rc = sd_bus_process(context->bus, NULL)) > 0);
+			while ((rc = sd_bus_process(context->bus, NULL)) > 0) {
+				MSG_DBG("DBUS Event\n");
+			}
 			if (rc < 0) {
 				MSG_ERR("Error handling DBUS event: %s\n",
 						strerror(-rc));
@@ -126,6 +129,7 @@ static int poll_loop(struct mbox_context *context)
 			break; /* This should mean we clean up nicely */
 		}
 		if (context->fds[MBOX_FD].revents & POLLIN) { /* MBOX */
+			MSG_DBG("MBOX Event\n");
 			rc = dispatch_mbox(context);
 			if (rc < 0) {
 				MSG_ERR("Error handling MBOX event\n");
@@ -272,10 +276,10 @@ static bool parse_cmdline(int argc, char **argv,
 		return false;
 	}
 
-	MSG_OUT("Flash size: 0x%.8x\n", context->flash_size);
+	MSG_INFO("Flash size: 0x%.8x\n", context->flash_size);
 
 	if (verbosity) {
-		MSG_OUT("%s logging\n", verbosity == MBOX_LOG_DEBUG ? "Debug" :
+		MSG_INFO("%s logging\n", verbosity == MBOX_LOG_DEBUG ? "Debug" :
 					"Verbose");
 	}
 
@@ -305,7 +309,7 @@ int main(int argc, char **argv)
 		context->fds[i].fd = -1;
 	}
 
-	MSG_OUT("Starting Daemon\n");
+	MSG_INFO("Starting Daemon\n");
 
 	rc = init_signals(context, &set);
 	if (rc) {
@@ -349,13 +353,13 @@ int main(int argc, char **argv)
 		goto finish;
 	}
 
-	MSG_OUT("Entering Polling Loop\n");
+	MSG_INFO("Entering Polling Loop\n");
 	rc = poll_loop(context);
 
-	MSG_OUT("Exiting Poll Loop: %d\n", rc);
+	MSG_INFO("Exiting Poll Loop: %d\n", rc);
 
 finish:
-	MSG_OUT("Daemon Exiting...\n");
+	MSG_INFO("Daemon Exiting...\n");
 	clr_bmc_events(context, BMC_EVENT_DAEMON_READY, SET_BMC_EVENT);
 
 	free_mboxd_dbus(context);
diff --git a/mboxd_dbus.c b/mboxd_dbus.c
index a72e48b..6673ca6 100644
--- a/mboxd_dbus.c
+++ b/mboxd_dbus.c
@@ -159,7 +159,7 @@ static int dbus_handle_kill(struct mbox_context *context,
 {
 	context->terminate = 1;
 
-	MSG_OUT("DBUS Kill - Exiting...\n");
+	MSG_INFO("DBUS Kill - Exiting...\n");
 
 	return 0;
 }
@@ -276,7 +276,7 @@ static int method_cmd(sd_bus_message *m, void *userdata,
 	struct mbox_dbus_msg req = { 0 }, resp = { 0 };
 	struct mbox_context *context;
 	sd_bus_message *n;
-	int rc;
+	int rc, i;
 
 	context = (struct mbox_context *) userdata;
 	if (!context) {
@@ -292,6 +292,7 @@ static int method_cmd(sd_bus_message *m, void *userdata,
 		rc = -E_DBUS_INTERNAL;
 		goto out;
 	}
+	MSG_DBG("DBUS request: %u\n", req.cmd);
 
 	/* Read the args */
 	rc = sd_bus_message_read_array(m, 'y', (const void **) &req.args,
@@ -301,6 +302,10 @@ static int method_cmd(sd_bus_message *m, void *userdata,
 		rc = -E_DBUS_INTERNAL;
 		goto out;
 	}
+	MSG_DBG("DBUS num_args: %u\n", (unsigned) req.num_args);
+	for (i = 0; i < req.num_args; i++) {
+		MSG_DBG("DBUS arg[%d]: %u\n", i, req.args[i]);
+	}
 
 	/* Handle the command */
 	if (req.cmd >= NUM_DBUS_CMDS) {
@@ -332,6 +337,12 @@ out:
 		goto cleanup;
 	}
 
+	MSG_DBG("DBUS response: %u\n", resp.cmd);
+	MSG_DBG("DBUS num_args: %u\n", (unsigned) resp.num_args);
+	for (i = 0; i < resp.num_args; i++) {
+		MSG_DBG("DBUS arg[%d]: %u\n", i, resp.args[i]);
+	}
+
 	rc = sd_bus_send(NULL, n, NULL); /* Send response */
 	if (rc < 0)
 		MSG_ERR("sd_bus_send failed: %d\n", rc);
diff --git a/mboxd_flash.c b/mboxd_flash.c
index 7ef834a..1e1b7a0 100644
--- a/mboxd_flash.c
+++ b/mboxd_flash.c
@@ -55,7 +55,7 @@ int init_flash_dev(struct mbox_context *context)
 		return -1;
 	}
 
-	MSG_OUT("Opening %s\n", filename);
+	MSG_DBG("Opening %s\n", filename);
 
 	/* Open Flash Device */
 	fd = open(filename, O_RDWR);
@@ -105,6 +105,7 @@ int init_flash_dev(struct mbox_context *context)
 	context->flash_bmap = calloc(context->flash_size >>
 				     context->erase_size_shift,
 				     sizeof(*context->flash_bmap));
+	MSG_DBG("Flash erase size: 0x%.8x\n", context->mtd_info.erasesize);
 
 out:
 	free(filename);
@@ -135,8 +136,8 @@ int copy_flash(struct mbox_context *context, uint32_t offset, void *mem,
 {
 	int32_t size_read;
 
-	MSG_OUT("Loading flash at %p for 0x%08x bytes from offset 0x%.8x\n",
-							mem, size, offset);
+	MSG_DBG("Copy flash to %p for size 0x%.8x from offset 0x%.8x\n",
+		mem, size, offset);
 	if (lseek(context->fds[MTD_FD].fd, offset, SEEK_SET) != offset) {
 		MSG_ERR("Couldn't seek flash at pos: %u %s\n", offset,
 			strerror(errno));
@@ -192,6 +193,8 @@ int set_flash_bytemap(struct mbox_context *context, uint32_t offset,
 		return -MBOX_R_PARAM_ERROR;
 	}
 
+	MSG_DBG("Set flash bytemap @ 0x%.8x for 0x%.8x to %s\n",
+		offset, count, val ? "ERASED" : "DIRTY");
 	memset(context->flash_bmap + (offset >> context->erase_size_shift),
 	       val,
 	       align_up(count, 1 << context->erase_size_shift) >>
@@ -214,7 +217,7 @@ int erase_flash(struct mbox_context *context, uint32_t offset, uint32_t count)
 	struct erase_info_user erase_info = { 0 };
 	int rc;
 
-	MSG_OUT("Erasing 0x%.8x for 0x%.8x\n", offset, count);
+	MSG_DBG("Erase flash @ 0x%.8x for 0x%.8x\n", offset, count);
 
 	/*
 	 * We have an erased_bytemap for the flash so we want to avoid erasing
@@ -231,6 +234,8 @@ int erase_flash(struct mbox_context *context, uint32_t offset, uint32_t count)
 			erase_info.length += erase_size;
 		} else if (erase_info.length) { /* Already erased|end of run? */
 			/* Erase the previous run which just ended */
+			MSG_DBG("Erase flash @ 0x%.8x for 0x%.8x\n",
+				erase_info.start, erase_info.length);
 			rc = ioctl(context->fds[MTD_FD].fd, MEMERASE,
 				   &erase_info);
 			if (rc < 0) {
@@ -250,6 +255,8 @@ int erase_flash(struct mbox_context *context, uint32_t offset, uint32_t count)
 	}
 
 	if (erase_info.length) {
+		MSG_DBG("Erase flash @ 0x%.8x for 0x%.8x\n",
+			erase_info.start, erase_info.length);
 		rc = ioctl(context->fds[MTD_FD].fd, MEMERASE, &erase_info);
 		if (rc < 0) {
 			MSG_ERR("Couldn't erase flash at 0x%.8x\n",
@@ -279,7 +286,7 @@ int write_flash(struct mbox_context *context, uint32_t offset, void *buf,
 	uint32_t buf_offset = 0;
 	int rc;
 
-	MSG_OUT("Writing 0x%.8x for 0x%.8x from %p\n", offset, count, buf);
+	MSG_DBG("Write flash @ 0x%.8x for 0x%.8x from %p\n", offset, count, buf);
 
 	if (lseek(context->fds[MTD_FD].fd, offset, SEEK_SET) != offset) {
 		MSG_ERR("Couldn't seek flash at pos: %u %s\n", offset,
diff --git a/mboxd_lpc.c b/mboxd_lpc.c
index c8f69b6..0529b14 100644
--- a/mboxd_lpc.c
+++ b/mboxd_lpc.c
@@ -61,7 +61,7 @@ int __init_lpc_dev(struct mbox_context *context, const char *path)
 	int fd;
 
 	/* Open LPC Device */
-	MSG_OUT("Opening %s\n", path);
+	MSG_DBG("Opening %s\n", path);
 	fd = open(path, O_RDWR | O_SYNC);
 	if (fd < 0) {
 		MSG_ERR("Couldn't open %s with flags O_RDWR: %s\n",
@@ -72,7 +72,7 @@ int __init_lpc_dev(struct mbox_context *context, const char *path)
 	context->fds[LPC_CTRL_FD].fd = fd;
 
 	/* Find Size of Reserved Memory Region */
-	MSG_OUT("Getting buffer size...\n");
+	MSG_DBG("Getting buffer size...\n");
 	if (ioctl(fd, ASPEED_LPC_CTRL_IOCTL_GET_SIZE, &map) < 0) {
 		MSG_ERR("Couldn't get lpc control buffer size: %s\n",
 			strerror(errno));
@@ -82,9 +82,9 @@ int __init_lpc_dev(struct mbox_context *context, const char *path)
 	context->mem_size = map.size;
 	/* Map at the top of the 28-bit LPC firmware address space-0 */
 	context->lpc_base = 0x0FFFFFFF & -context->mem_size;
-	
+
 	/* mmap the Reserved Memory Region */
-	MSG_OUT("Mapping in %u bytes of %s\n", context->mem_size, path);
+	MSG_DBG("Mapping in 0x%.8x bytes of %s\n", context->mem_size, path);
 	context->mem = mmap(NULL, context->mem_size, PROT_READ | PROT_WRITE,
 				MAP_SHARED, fd, 0);
 	if (context->mem == MAP_FAILED) {
@@ -138,8 +138,8 @@ int point_to_flash(struct mbox_context *context)
 		return -MBOX_R_PARAM_ERROR;
 	}
 
-	MSG_OUT("Pointing HOST LPC bus at the actual flash\n");
-	MSG_OUT("Assuming %dMB of flash: HOST LPC 0x%08x\n",
+	MSG_INFO("Pointing HOST LPC bus at the flash\n");
+	MSG_INFO("Assuming %dMB of flash: HOST LPC 0x%08x\n",
 		context->flash_size >> 20, map.addr);
 
 	if (ioctl(context->fds[LPC_CTRL_FD].fd, ASPEED_LPC_CTRL_IOCTL_MAP, &map)
@@ -178,9 +178,9 @@ int point_to_memory(struct mbox_context *context)
 		return 0; /* LPC Bus already points to reserved memory area */
 	}
 
-	MSG_OUT("Pointing HOST LPC bus at memory region %p of size 0x%.8x\n",
+	MSG_INFO("Pointing HOST LPC bus at memory region %p of size 0x%.8x\n",
 			context->mem, context->mem_size);
-	MSG_OUT("LPC address 0x%.8x\n", map.addr);
+	MSG_INFO("LPC address 0x%.8x\n", map.addr);
 
 	if (ioctl(context->fds[LPC_CTRL_FD].fd, ASPEED_LPC_CTRL_IOCTL_MAP,
 		  &map)) {
diff --git a/mboxd_msg.c b/mboxd_msg.c
index 0cc1cd2..65946e8 100644
--- a/mboxd_msg.c
+++ b/mboxd_msg.c
@@ -112,6 +112,7 @@ int set_bmc_events(struct mbox_context *context, uint8_t bmc_event,
 	}
 
 	context->bmc_events |= (bmc_event & mask);
+	MSG_DBG("BMC Events set to: 0x%.2x\n", context->bmc_events);
 
 	return write_back ? write_bmc_event_reg(context) : 0;
 }
@@ -128,6 +129,7 @@ int clr_bmc_events(struct mbox_context *context, uint8_t bmc_event,
 		   bool write_back)
 {
 	context->bmc_events &= ~bmc_event;
+	MSG_DBG("BMC Events clear to: 0x%.2x\n", context->bmc_events);
 
 	return write_back ? write_bmc_event_reg(context) : 0;
 }
@@ -156,8 +158,13 @@ static uint16_t get_suggested_timeout(struct mbox_context *context)
 {
 	struct window_context *window = find_largest_window(context);
 	uint32_t max_size_mb = window ? (window->size >> 20) : 0;
+	uint8_t ret;
 
-	return align_up(max_size_mb * FLASH_ACCESS_MS_PER_MB, 1000) / 1000;
+	ret = align_up(max_size_mb * FLASH_ACCESS_MS_PER_MB, 1000) / 1000;
+
+	MSG_DBG("Suggested Timeout: %us, max window size: %uMB, for %dms/MB\n",
+		ret, max_size_mb, FLASH_ACCESS_MS_PER_MB);
+	return ret;
 }
 
 /*
@@ -197,7 +204,7 @@ static int mbox_handle_mbox_info(struct mbox_context *context,
 		mbox_api_version = API_MAX_VERSION;
 
 	context->version = mbox_api_version;
-	MSG_OUT("Using Protocol Version: %d\n", context->version);
+	MSG_INFO("Using Protocol Version: %d\n", context->version);
 
 	/*
 	 * The reset state is currently to have the LPC bus point directly to
@@ -218,7 +225,8 @@ static int mbox_handle_mbox_info(struct mbox_context *context,
 		context->block_size_shift = log_2(context->mtd_info.erasesize);
 		break;
 	}
-	MSG_OUT("Block Size Shift: %d\n", context->block_size_shift);
+	MSG_INFO("Block Size: 0x%.8x (shift: %u)\n",
+		 1 << context->block_size_shift, context->block_size_shift);
 
 	/* Now we know the blocksize we can allocate the window dirty_bytemap */
 	if (mbox_api_version != old_api_version) {
@@ -300,6 +308,8 @@ static inline uint16_t get_lpc_addr_shifted(struct mbox_context *context)
 	/* Total LPC Address */
 	lpc_addr = context->lpc_base + mem_offset;
 
+	MSG_DBG("LPC address of current window: 0x%.8x\n", lpc_addr);
+
 	return lpc_addr >> context->block_size_shift;
 }
 
@@ -343,12 +353,13 @@ static int mbox_handle_read_window(struct mbox_context *context,
 
 	/* Offset the host has requested */
 	flash_offset = get_u16(&req->msg.args[0]) << context->block_size_shift;
-	MSG_OUT("Host Requested Flash @ 0x%.8x\n", flash_offset);
+	MSG_INFO("Host requested flash @ 0x%.8x\n", flash_offset);
 	/* Check if we have an existing window */
 	context->current = search_windows(context, flash_offset,
 					  context->version == API_VERSION_1);
 
 	if (!context->current) { /* No existing window */
+		MSG_DBG("No existing window which maps that flash offset\n");
 		rc = create_map_window(context, &context->current, flash_offset,
 				       context->version == API_VERSION_1);
 		if (rc < 0) { /* Unable to map offset */
@@ -358,6 +369,10 @@ static int mbox_handle_read_window(struct mbox_context *context,
 		}
 	}
 
+	MSG_INFO("Window @ %p for size 0x%.8x maps flash offset 0x%.8x\n",
+		 context->current->mem, context->current->size,
+		 context->current->flash_offset);
+
 	put_u16(&resp->args[0], get_lpc_addr_shifted(context));
 	if (context->version >= API_VERSION_2) {
 		put_u16(&resp->args[2], context->current->size >>
@@ -462,6 +477,10 @@ static int mbox_handle_dirty_window(struct mbox_context *context,
 		size >>= context->block_size_shift;
 	}
 
+	MSG_INFO("Dirty window @ 0x%.8x for 0x%.8x\n",
+		 offset << context->block_size_shift,
+		 size << context->block_size_shift);
+
 	return set_window_bytemap(context, context->current, offset, size,
 				  WINDOW_DIRTY);
 }
@@ -498,6 +517,10 @@ static int mbox_handle_erase_window(struct mbox_context *context,
 	offset = get_u16(&req->msg.args[0]);
 	size = get_u16(&req->msg.args[2]);
 
+	MSG_INFO("Erase window @ 0x%.8x for 0x%.8x\n",
+		 offset << context->block_size_shift,
+		 size << context->block_size_shift);
+
 	rc = set_window_bytemap(context, context->current, offset, size,
 				WINDOW_ERASED);
 	if (rc < 0) {
@@ -558,6 +581,10 @@ static int mbox_handle_flush_window(struct mbox_context *context,
 	count = 0;
 	prev = WINDOW_CLEAN;
 
+	MSG_INFO("Flush window @ %p for size 0x%.8x which maps flash @ 0x%.8x\n",
+		 context->current->mem, context->current->size,
+		 context->current->flash_offset);
+
 	/*
 	 * We look for streaks of the same type and keep a count, when the type
 	 * (dirty/erased) changes we perform the required action on the backing
@@ -681,7 +708,8 @@ static int check_req_valid(struct mbox_context *context, union mbox_regs *req)
 	}
 
 	if (seq == context->prev_seq && cmd != MBOX_C_GET_MBOX_INFO) {
-		MSG_ERR("Invalid sequence number: %d\n", seq);
+		MSG_ERR("Invalid sequence number: %d, previous: %d\n", seq,
+			context->prev_seq);
 		return -MBOX_R_SEQ_ERROR;
 	}
 
@@ -733,9 +761,9 @@ static int handle_mbox_req(struct mbox_context *context, union mbox_regs *req)
 		.args = { 0 },
 		.response = MBOX_R_SUCCESS
 	};
-	int rc = 0, len;
+	int rc = 0, len, i;
 
-	MSG_OUT("Got data in with command %d\n", req->msg.command);
+	MSG_INFO("Received MBOX command: %u\n", req->msg.command);
 	rc = check_req_valid(context, req);
 	if (rc < 0) {
 		resp.response = -rc;
@@ -751,7 +779,13 @@ static int handle_mbox_req(struct mbox_context *context, union mbox_regs *req)
 
 	context->prev_seq = req->msg.seq;
 
-	MSG_OUT("Writing response to MBOX regs: %d\n", resp.response);
+	MSG_DBG("Writing MBOX response:\n");
+	MSG_DBG("MBOX cmd: %u\n", resp.command);
+	MSG_DBG("MBOX seq: %u\n", resp.seq);
+	for (i = 0; i < MBOX_ARGS_BYTES; i++) {
+		MSG_DBG("MBOX arg[%d]: 0x%.2x\n", i, resp.args[i]);
+	}
+	MSG_INFO("Writing MBOX response: %u\n", resp.response);
 	len = write(context->fds[MBOX_FD].fd, &resp, sizeof(resp));
 	if (len < sizeof(resp)) {
 		MSG_ERR("Didn't write the full response\n");
@@ -770,7 +804,7 @@ static int handle_mbox_req(struct mbox_context *context, union mbox_regs *req)
  */
 static int get_message(struct mbox_context *context, union mbox_regs *msg)
 {
-	int rc;
+	int rc, i;
 
 	rc = read(context->fds[MBOX_FD].fd, msg, sizeof(msg->raw));
 	if (rc < 0) {
@@ -781,6 +815,13 @@ static int get_message(struct mbox_context *context, union mbox_regs *msg)
 		return -1;
 	}
 
+	MSG_DBG("Received MBOX request:\n");
+	MSG_DBG("MBOX cmd: %u\n", msg->msg.command);
+	MSG_DBG("MBOX seq: %u\n", msg->msg.seq);
+	for (i = 0; i < MBOX_ARGS_BYTES; i++) {
+		MSG_DBG("MBOX arg[%d]: 0x%.2x\n", i, msg->msg.args[i]);
+	}
+
 	return 0;
 }
 
@@ -797,7 +838,6 @@ int dispatch_mbox(struct mbox_context *context)
 
 	assert(context);
 
-	MSG_OUT("Dispatched to mbox\n");
 	rc = get_message(context, &req);
 	if (rc) {
 		return rc;
@@ -817,6 +857,7 @@ int __init_mbox_dev(struct mbox_context *context, const char *path)
 			path, strerror(errno));
 		return -errno;
 	}
+	MSG_DBG("Opened mbox dev: %s\n", path);
 
 	context->fds[MBOX_FD].fd = fd;
 
diff --git a/mboxd_windows.c b/mboxd_windows.c
index f02b0d7..451ecd1 100644
--- a/mboxd_windows.c
+++ b/mboxd_windows.c
@@ -82,8 +82,11 @@ static int init_window_mem(struct mbox_context *context)
 	 * did we will error out here
 	 */
 	for (i = 0; i < context->windows.num; i++) {
+		uint32_t size = context->windows.window[i].size;
+		MSG_DBG("Window %d @ %p for size 0x%.8x\n", i,
+			mem_location, size);
 		context->windows.window[i].mem = mem_location;
-		mem_location += context->windows.window[i].size;
+		mem_location += size;
 		if (mem_location > (context->mem + context->mem_size)) {
 			/* Tried to allocate window past the end of memory */
 			MSG_ERR("Total size of windows exceeds reserved mem\n");
@@ -110,13 +113,13 @@ int init_windows(struct mbox_context *context)
 		/* Default to 1MB windows */
 		context->windows.default_size = 1 << 20;
 	}
-	MSG_OUT("Window size: 0x%.8x\n", context->windows.default_size);
+	MSG_INFO("Window size: 0x%.8x\n", context->windows.default_size);
 	if (!context->windows.num) {
 		/* Use the entire reserved memory region by default */
 		context->windows.num = context->mem_size /
 				       context->windows.default_size;
 	}
-	MSG_OUT("Number of Windows: %d\n", context->windows.num);
+	MSG_INFO("Number of windows: %d\n", context->windows.num);
 
 	context->windows.window = calloc(context->windows.num,
 					 sizeof(*context->windows.window));
@@ -404,6 +407,8 @@ int set_window_bytemap(struct mbox_context *context, struct window_context *cur,
 void close_current_window(struct mbox_context *context, bool set_bmc_event,
 			  uint8_t flags)
 {
+	MSG_DBG("Close current window, flags: 0x%.2x\n", flags);
+
 	if (set_bmc_event) {
 		set_bmc_events(context, BMC_EVENT_WINDOW_RESET, SET_BMC_EVENT);
 	}
@@ -443,6 +448,7 @@ void reset_all_windows(struct mbox_context *context, bool set_bmc_event)
 {
 	int i;
 
+	MSG_DBG("Resetting all windows\n");
 	/* We might have an open window which needs closing */
 	if (context->current) {
 		close_current_window(context, set_bmc_event, FLAGS_NONE);
@@ -522,6 +528,8 @@ struct window_context *search_windows(struct mbox_context *context,
 	struct window_context *cur;
 	int i;
 
+	MSG_DBG("Searching for window which contains 0x%.8x %s\n",
+		offset, exact ? "exactly" : "");
 	for (i = 0; i < context->windows.num; i++) {
 		cur = &context->windows.window[i];
 		if (cur->flash_offset == FLASH_OFFSET_UNINIT) {
@@ -567,12 +575,15 @@ int create_map_window(struct mbox_context *context,
 	struct window_context *cur = NULL;
 	int rc;
 
+	MSG_DBG("Creating window which maps 0x%.8x %s\n", offset,
+		exact ? "exactly" : "");
 
 	/* Search for an uninitialised window, use this before evicting */
 	cur = search_windows(context, FLASH_OFFSET_UNINIT, true);
 
 	/* No uninitialised window found, we need to choose one to "evict" */
 	if (!cur) {
+		MSG_DBG("No uninitialised window, evicting one\n");
 		cur = find_oldest_window(context);
 	}
 
@@ -628,6 +639,8 @@ int create_map_window(struct mbox_context *context,
 	if (context->version == API_VERSION_1) {
 		uint32_t i;
 
+		MSG_DBG("Checking for window overlap\n");
+
 		for (i = offset; i < (offset + cur->size); i += (cur->size - 1)) {
 			struct window_context *tmp = NULL;
 			do {