[Skiboot] [PATCH v3 10/13] libflash/ipmi-hiomap: Add some debug logging
Deb McLemore
debmc at linux.ibm.com
Thu Nov 7 04:22:29 AEDT 2019
Add some additional debug logging for problem determination.
PR_TRACE used since PR_DEBUG seems to always trigger,
unable to figure out why.
Signed-off-by: Deb McLemore <debmc at linux.ibm.com>
---
core/flash.c | 4 +-
libflash/ipmi-hiomap.c | 177 ++++++++++++++++++++++++++++++++++---------------
2 files changed, 125 insertions(+), 56 deletions(-)
diff --git a/core/flash.c b/core/flash.c
index 579af7b..43d5818 100644
--- a/core/flash.c
+++ b/core/flash.c
@@ -677,8 +677,8 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset,
goto out;
}
flash->bl->flags |= IN_PROGRESS;
- prlog(PR_TRACE, "opal_flash_op RE-QUEUE transaction_id=%i flash->async.retry_counter=%i\n",
- flash->async.transaction_id, flash->async.retry_counter);
+ prlog(PR_TRACE, "opal_flash_op RE-QUEUE transaction_id=%i flash->async.retry_counter=%i in_progress_schedule_delay=%i\n",
+ flash->async.transaction_id, flash->async.retry_counter, FLASH_SCHEDULE_DELAY);
schedule_timer(&flash->async.poller, msecs_to_tb(FLASH_SCHEDULE_DELAY));
/* Don't release the flash */
return OPAL_ASYNC_COMPLETION;
diff --git a/libflash/ipmi-hiomap.c b/libflash/ipmi-hiomap.c
index 08af005..df67173 100644
--- a/libflash/ipmi-hiomap.c
+++ b/libflash/ipmi-hiomap.c
@@ -58,10 +58,15 @@ static inline uint16_t bytes_to_blocks_align_up(struct ipmi_hiomap *ctx,
/* Call under ctx->lock */
static int hiomap_protocol_ready(struct ipmi_hiomap *ctx)
{
- if (!(ctx->bmc_state & HIOMAP_E_DAEMON_READY))
+ prlog(PR_TRACE, "%s ctx->bmc_state=%i\n", __func__, ctx->bmc_state);
+ if (!(ctx->bmc_state & HIOMAP_E_DAEMON_READY)) {
+ prlog(PR_NOTICE, "%s FLASH_ERR_DEVICE_GONE\n", __func__);
return FLASH_ERR_DEVICE_GONE;
- if (ctx->bmc_state & HIOMAP_E_FLASH_LOST)
+ }
+ if (ctx->bmc_state & HIOMAP_E_FLASH_LOST) {
+ prlog(PR_NOTICE, "%s HIOMAP_E_FLASH_LOST\n", __func__);
return FLASH_ERR_AGAIN;
+ }
return 0;
}
@@ -111,16 +116,27 @@ static int hiomap_queue_msg(struct ipmi_hiomap *ctx, struct ipmi_msg *msg)
static int hiomap_window_valid(struct ipmi_hiomap *ctx, uint64_t pos,
uint64_t len)
{
- if (ctx->bmc_state & HIOMAP_E_FLASH_LOST)
+ if (ctx->bmc_state & HIOMAP_E_FLASH_LOST) {
+ prlog(PR_NOTICE, "%s HIOMAP_E_FLASH_LOST\n", __func__);
return FLASH_ERR_AGAIN;
- if (ctx->bmc_state & HIOMAP_E_PROTOCOL_RESET)
+ }
+ if (ctx->bmc_state & HIOMAP_E_PROTOCOL_RESET) {
+ prlog(PR_NOTICE, "%s HIOMAP_E_PROTOCOL_RESET\n", __func__);
return FLASH_ERR_AGAIN;
- if (ctx->bmc_state & HIOMAP_E_WINDOW_RESET)
+ }
+ if (ctx->bmc_state & HIOMAP_E_WINDOW_RESET) {
+ prlog(PR_NOTICE, "%s HIOMAP_E_WINDOW_RESET\n", __func__);
return FLASH_ERR_AGAIN;
- if (ctx->window_state == closed_window)
+ }
+ if (ctx->window_state == closed_window) {
+ prlog(PR_TRACE, "%s window_state=closed_window\n", __func__);
return FLASH_ERR_PARM_ERROR;
- if (pos < ctx->current.cur_pos)
+ }
+ if (pos < ctx->current.cur_pos) {
+ prlog(PR_TRACE, "%s we need to move the window pos=%llu < ctx->current.cur_pos=0x%x\n",
+ __func__, pos, ctx->current.cur_pos);
return FLASH_ERR_PARM_ERROR;
+ }
if ((pos + len) > (ctx->current.cur_pos + ctx->current.size)) {
/* we will compensate the proper values in caller */
if ((pos + ctx->current.size) <= (ctx->current.cur_pos + ctx->current.size)) {
@@ -313,8 +329,10 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg)
}
if (msg->data[1] != ctx->inflight_seq) {
- prerror("Unmatched sequence number: wanted %u got %u\n",
- ctx->inflight_seq, msg->data[1]);
+ prlog(PR_TRACE, "%s Unmatched ipmi sequence number: wanted %u got %u\n",
+ __func__,
+ ctx->inflight_seq,
+ msg->data[1]);
res->cc = IPMI_ERR_UNSPECIFIED;
ipmi_free_msg(msg);
return;
@@ -371,7 +389,9 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg)
case HIOMAP_C_ERASE:
case HIOMAP_C_RESET:
if (msg->resp_size != 2) {
- prerror("%u: Unexpected response size: %u\n", msg->data[0],
+ prerror("%s %u: Unexpected response size: %u\n",
+ __func__,
+ msg->data[0],
msg->resp_size);
res->cc = IPMI_ERR_UNSPECIFIED;
ctx->cc = OPAL_HARDWARE;
@@ -386,8 +406,8 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg)
}
break;
default:
- prlog(PR_WARNING, "Unimplemented command handler: %u\n",
- msg->data[0]);
+ prlog(PR_WARNING, "%s Unimplemented command handler: %u\n",
+ __func__, msg->data[0]);
break;
};
ipmi_free_msg(msg);
@@ -655,8 +675,10 @@ static int hiomap_window_move(struct ipmi_hiomap *ctx, uint8_t command,
rc = hiomap_queue_msg(ctx, msg);
- if (rc)
+ if (rc) {
+ prlog(PR_NOTICE, "%s move queue msg failed: rc=%d\n", __func__, rc);
return rc;
+ }
return 0;
}
@@ -682,8 +704,10 @@ static int hiomap_mark_dirty(struct ipmi_hiomap *ctx, uint64_t offset,
ctx->cc = -1;
unlock(&ctx->lock);
- if (state != write_window)
+ if (state != write_window) {
+ prlog(PR_NOTICE, "%s failed: state=%i\n", __func__, state);
return FLASH_ERR_PARM_ERROR;
+ }
req[0] = HIOMAP_C_MARK_DIRTY;
req[1] = dirty_seq;
@@ -699,11 +723,13 @@ static int hiomap_mark_dirty(struct ipmi_hiomap *ctx, uint64_t offset,
rc = hiomap_queue_msg(ctx, msg);
- if (rc)
+ if (rc) {
+ prlog(PR_NOTICE, "%s dirty queue msg failed: rc=%d\n", __func__, rc);
return rc;
+ }
- prlog(PR_DEBUG, "Marked flash dirty at 0x%" PRIx64 " for %" PRIu64 "\n",
- offset, size);
+ prlog(PR_TRACE, "%s Start to mark flash dirty at pos %llu size %llu bytes ipmi seq=%i\n",
+ __func__, offset, size, dirty_seq);
return 0;
}
@@ -726,8 +752,10 @@ static int hiomap_flush(struct ipmi_hiomap *ctx)
ctx->cc = -1;
unlock(&ctx->lock);
- if (state != write_window)
+ if (state != write_window) {
+ prlog(PR_NOTICE, "%s failed: state=%i\n", __func__, state);
return FLASH_ERR_PARM_ERROR;
+ }
req[0] = HIOMAP_C_FLUSH;
req[1] = flush_seq;
@@ -738,10 +766,12 @@ static int hiomap_flush(struct ipmi_hiomap *ctx)
rc = hiomap_queue_msg(ctx, msg);
- if (rc)
+ if (rc) {
+ prlog(PR_NOTICE, "%s flush queue msg failed: rc=%d\n", __func__, rc);
return rc;
+ }
- prlog(PR_DEBUG, "Flushed writes\n");
+ prlog(PR_TRACE, "%s Start to flush writes ipmi seq=%i\n", __func__, flush_seq);
return 0;
}
@@ -777,12 +807,15 @@ static int hiomap_ack(struct ipmi_hiomap *ctx, uint8_t ack)
bmc_platform->sw->ipmi_oem_hiomap_cmd,
ipmi_hiomap_cmd_cb, &ack_res, req, sizeof(req), 2);
+ prlog(PR_TRACE, "%s SENDING req[1]=%i\n", __func__, req[1]);
rc = hiomap_queue_msg(ctx, msg);
lock(&ctx->lock);
ctx->bl.flags = orig_flags;
unlock(&ctx->lock);
- if (rc)
+ if (rc) {
+ prlog(PR_NOTICE, "%s queue msg failed: rc=%d\n", __func__, rc);
return rc;
+ }
rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_ACK_DEFAULT);
if (rc) {
@@ -791,7 +824,7 @@ static int hiomap_ack(struct ipmi_hiomap *ctx, uint8_t ack)
return rc;
}
- prlog(PR_DEBUG, "Acked events: 0x%x\n", ack);
+ prlog(PR_NOTICE, "%s Acked events: 0x%x\n", __func__, ack);
return 0;
}
@@ -817,8 +850,10 @@ static int hiomap_erase(struct ipmi_hiomap *ctx, uint64_t offset,
ctx->cc = -1;
unlock(&ctx->lock);
- if (state != write_window)
+ if (state != write_window) {
+ prlog(PR_NOTICE, "%s failed: state=%i\n", __func__, state);
return FLASH_ERR_PARM_ERROR;
+ }
req[0] = HIOMAP_C_ERASE;
req[1] = erase_seq;
@@ -834,11 +869,14 @@ static int hiomap_erase(struct ipmi_hiomap *ctx, uint64_t offset,
rc = hiomap_queue_msg(ctx, msg);
- if (rc)
+ if (rc) {
+ prlog(PR_NOTICE, "%s erase queue msg failed: rc=%d\n", __func__, rc);
return rc;
+ }
- prlog(PR_DEBUG, "Erased flash at 0x%" PRIx64 " for %" PRIu64 "\n",
- offset, size);
+ prlog(PR_TRACE, "%s Erasing flash at pos %llu for size %llu\n",
+ __func__,
+ offset, size);
return 0;
}
@@ -899,10 +937,17 @@ static void hiomap_event(uint8_t events, void *context)
{
struct ipmi_hiomap *ctx = context;
- prlog(PR_DEBUG, "Received events: 0x%x\n", events);
+ prlog(PR_NOTICE, "%s Received events: 0x%x ctx->bmc_state=%i\n",
+ __func__,
+ events,
+ ctx->bmc_state);
lock(&ctx->lock);
ctx->bmc_state = events | (ctx->bmc_state & HIOMAP_E_ACK_MASK);
+ prlog(PR_NOTICE, "%s Updated bmc_state Received events: 0x%x ctx->bmc_state=%i\n",
+ __func__,
+ events,
+ ctx->bmc_state);
unlock(&ctx->lock);
}
@@ -915,7 +960,7 @@ static int lpc_window_read(struct ipmi_hiomap *ctx, uint32_t pos,
if ((ctx->current.lpc_addr + ctx->current.size) < (off + len))
return FLASH_ERR_PARM_ERROR;
- prlog(PR_TRACE, "Reading at 0x%08x for 0x%08x offset: 0x%08x\n",
+ prlog(PR_TRACE, "LPC Reading at 0x%08x for 0x%08x offset: 0x%08x\n",
pos, len, off);
while(len) {
@@ -963,7 +1008,7 @@ static int lpc_window_write(struct ipmi_hiomap *ctx, uint32_t pos,
if ((ctx->current.lpc_addr + ctx->current.size) < (off + len))
return FLASH_ERR_PARM_ERROR;
- prlog(PR_TRACE, "Writing at 0x%08x for 0x%08x offset: 0x%08x\n",
+ prlog(PR_TRACE, "LPC Writing at 0x%08x for 0x%08x offset: 0x%08x\n",
pos, len, off);
while(len) {
@@ -979,7 +1024,7 @@ static int lpc_window_write(struct ipmi_hiomap *ctx, uint32_t pos,
chunk = 1;
}
if (rc) {
- prlog(PR_ERR, "lpc_write failure %d to FW 0x%08x\n", rc, off);
+ prlog(PR_ERR, "%s failure %d to FW 0x%08x\n", __func__, rc, off);
return rc;
}
len -= chunk;
@@ -999,6 +1044,7 @@ static int ipmi_hiomap_handle_events(struct ipmi_hiomap *ctx)
lock(&ctx->lock);
status = ctx->bmc_state;
+ prlog(PR_TRACE, "%s status=%i\n", __func__, status);
/*
* Immediately clear the ackable events to make sure we don't race to
@@ -1021,9 +1067,18 @@ static int ipmi_hiomap_handle_events(struct ipmi_hiomap *ctx)
* Therefore it is enough to mark the window as closed to consider it
* recovered.
*/
+ if (status & HIOMAP_E_PROTOCOL_RESET) {
+ prlog(PR_TRACE, "%s status=HIOMAP_E_PROTOCOL_RESET\n", __func__);
+ }
- if (status & (HIOMAP_E_PROTOCOL_RESET | HIOMAP_E_WINDOW_RESET))
+ if (status & HIOMAP_E_WINDOW_RESET) {
+ prlog(PR_TRACE, "%s status=HIOMAP_E_WINDOW_RESET\n", __func__);
+ }
+
+ if (status & (HIOMAP_E_PROTOCOL_RESET | HIOMAP_E_WINDOW_RESET)) {
ctx->window_state = closed_window;
+ prlog(PR_TRACE, "%s closed_window\n", __func__);
+ }
unlock(&ctx->lock);
@@ -1041,21 +1096,22 @@ static int ipmi_hiomap_handle_events(struct ipmi_hiomap *ctx)
* the BMC's cache must be valid if opening the window is successful.
*/
if (status & HIOMAP_E_ACK_MASK) {
+ prlog(PR_TRACE, "%s status=%i HIOMAP_E_ACK_MASK so TRY to ACK\n", __func__, status);
/* ACK is unversioned, can send it if the daemon is ready */
rc = hiomap_ack(ctx, status & HIOMAP_E_ACK_MASK);
if (rc) {
- prlog(PR_DEBUG, "Failed to ack events: 0x%x\n",
- status & HIOMAP_E_ACK_MASK);
+ prlog(PR_NOTICE, "%s Failed to ack events rc=%i: status & HIOMAP_E_ACK_MASK=0x%x status=%i\n",
+ __func__, rc, (status & HIOMAP_E_ACK_MASK), status);
goto restore;
}
}
if (status & HIOMAP_E_PROTOCOL_RESET) {
- prlog(PR_INFO, "Protocol was reset\n");
+ prlog(PR_INFO, "%s Protocol was reset\n", __func__);
rc = hiomap_get_info(ctx);
if (rc) {
- prerror("Failure to renegotiate after protocol reset\n");
+ prerror("%s Failure to renegotiate after protocol reset\n", __func__);
goto restore;
}
@@ -1065,7 +1121,7 @@ static int ipmi_hiomap_handle_events(struct ipmi_hiomap *ctx)
goto restore;
}
- prlog(PR_INFO, "Restored state after protocol reset\n");
+ prlog(PR_INFO, "%s Restored state after protocol reset\n", __func__);
}
/*
@@ -1083,7 +1139,9 @@ restore:
* than necessary, but never less than necessary.
*/
lock(&ctx->lock);
+ prlog(PR_TRACE, "%s PRE restore status=%i PRE ctx->bmc_state=%i rc=%i\n", __func__, status, ctx->bmc_state, rc);
ctx->bmc_state |= (status & HIOMAP_E_ACK_MASK);
+ prlog(PR_TRACE, "%s POST restored status=%i POST ctx->bmc_state=%i rc=%i\n", __func__, status, ctx->bmc_state, rc);
unlock(&ctx->lock);
return rc;
@@ -1099,15 +1157,17 @@ static int ipmi_hiomap_read(struct blocklevel_device *bl, uint64_t pos,
/* LPC is only 32bit */
if (pos > UINT_MAX || len > UINT_MAX)
- return FLASH_ERR_PARM_ERROR;
+ return OPAL_PARAMETER;
ctx = container_of(bl, struct ipmi_hiomap, bl);
lock(&ctx->transaction_lock);
rc = ipmi_hiomap_handle_events(ctx);
- if (rc)
+ if (rc) {
+ prlog(PR_NOTICE, "%s ipmi_hiomap_handle_events failed: rc=%d\n", __func__, rc);
goto out;
+ }
lock(&ctx->lock);
if (ctx->bl.flags & IN_PROGRESS) {
@@ -1121,8 +1181,7 @@ static int ipmi_hiomap_read(struct blocklevel_device *bl, uint64_t pos,
}
unlock(&ctx->lock);
- prlog(PR_TRACE, "Flash read at %#" PRIx64 " for %#" PRIx64 "\n", pos,
- len);
+ prlog(PR_TRACE, "Flash READ at pos %llu for %llu bytes\n", pos, len);
while (len > 0) {
lock(&ctx->lock);
state = ctx->window_state;
@@ -1206,8 +1265,10 @@ static int ipmi_hiomap_write(struct blocklevel_device *bl, uint64_t pos,
lock(&ctx->transaction_lock);
rc = ipmi_hiomap_handle_events(ctx);
- if (rc)
+ if (rc) {
+ prlog(PR_NOTICE, "%s ipmi_hiomap_handle_events failed: rc=%d\n", __func__, rc);
goto out;
+ }
lock(&ctx->lock);
if (ctx->bl.flags & IN_PROGRESS) {
@@ -1221,8 +1282,7 @@ static int ipmi_hiomap_write(struct blocklevel_device *bl, uint64_t pos,
}
unlock(&ctx->lock);
- prlog(PR_TRACE, "Flash write at %#" PRIx64 " for %#" PRIx64 "\n", pos,
- len);
+ prlog(PR_TRACE, "Flash WRITE at pos %llu for %llu bytes\n", pos, len);
while (len > 0) {
lock(&ctx->lock);
state = ctx->window_state;
@@ -1318,14 +1378,17 @@ static int ipmi_hiomap_erase(struct blocklevel_device *bl, uint64_t pos,
/* LPC is only 32bit */
if (pos > UINT_MAX || len > UINT_MAX)
- return FLASH_ERR_PARM_ERROR;
+ return OPAL_PARAMETER;
ctx = container_of(bl, struct ipmi_hiomap, bl);
lock(&ctx->transaction_lock);
rc = ipmi_hiomap_handle_events(ctx);
- if (rc)
+ if (rc) {
+ prlog(PR_NOTICE, "%s ipmi_hiomap_handle_events failed: rc=%d\n", __func__, rc);
goto out;
+ }
+
lock(&ctx->lock);
if (ctx->bl.flags & IN_PROGRESS) {
@@ -1337,8 +1400,8 @@ static int ipmi_hiomap_erase(struct blocklevel_device *bl, uint64_t pos,
}
unlock(&ctx->lock);
- prlog(PR_TRACE, "Flash erase at 0x%08x for 0x%08x\n", (u32) pos,
- (u32) len);
+ prlog(PR_TRACE, "Flash ERASE at pos %llu for %llu bytes\n", pos, len);
+
while (len > 0) {
lock(&ctx->lock);
state = ctx->window_state;
@@ -1422,12 +1485,16 @@ static int ipmi_hiomap_get_flash_info(struct blocklevel_device *bl,
lock(&ctx->transaction_lock);
rc = ipmi_hiomap_handle_events(ctx);
- if (rc)
+ if (rc) {
+ prlog(PR_NOTICE, "%s ipmi_hiomap_handle_events failed: rc=%d\n", __func__, rc);
return rc;
+ }
rc = hiomap_get_flash_info(ctx);
- if (rc)
+ if (rc) {
+ prlog(PR_NOTICE, "%s hiomap_get_flash failed: rc=%d\n", __func__, rc);
return rc;
+ }
ctx->bl.erase_mask = ctx->erase_granule - 1;
@@ -1474,26 +1541,28 @@ int ipmi_hiomap_init(struct blocklevel_device **bl)
/* Ack all pending ack-able events to avoid spurious failures */
rc = hiomap_ack(ctx, HIOMAP_E_ACK_MASK);
if (rc) {
- prlog(PR_DEBUG, "Failed to ack events: 0x%x\n",
- HIOMAP_E_ACK_MASK);
+ prlog(PR_NOTICE, "%s Failed to ack events: 0x%x\n",
+ __func__, HIOMAP_E_ACK_MASK);
goto err;
}
rc = ipmi_sel_register(CMD_OP_HIOMAP_EVENT, hiomap_event, ctx);
- if (rc < 0)
+ if (rc < 0) {
+ prerror("%s Failed ipmi_sel_register: %d\n", __func__, rc);
goto err;
+ }
/* Negotiate protocol behaviour */
rc = hiomap_get_info(ctx);
if (rc) {
- prerror("Failed to get hiomap parameters: %d\n", rc);
+ prerror("%s Failed to get hiomap parameters: %d\n", __func__, rc);
goto err;
}
/* Grab the flash parameters */
rc = hiomap_get_flash_info(ctx);
if (rc) {
- prerror("Failed to get flash parameters: %d\n", rc);
+ prerror("%s Failed to get flash parameters: %d\n", __func__, rc);
goto err;
}
--
2.7.4
More information about the Skiboot
mailing list