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
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 @@
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 @@
}
}
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 @@
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 @@
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 @@
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 @@
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 @@
{
context->terminate = 1;
- MSG_OUT("DBUS Kill - Exiting...\n");
+ MSG_INFO("DBUS Kill - Exiting...\n");
return 0;
}
@@ -276,7 +276,7 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
{
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 @@
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 @@
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 @@
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 @@
}
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 @@
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 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 @@
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 @@
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 @@
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 @@
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 @@
}
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 @@
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 @@
{
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 @@
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 @@
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 @@
/* 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 @@
/* 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 @@
}
}
+ 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 @@
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 @@
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 @@
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 @@
}
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 @@
.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 @@
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 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 @@
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 @@
assert(context);
- MSG_OUT("Dispatched to mbox\n");
rc = get_message(context, &req);
if (rc) {
return rc;
@@ -817,6 +857,7 @@
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 @@
* 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 @@
/* 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 @@
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 @@
{
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 *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 @@
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 @@
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 {