From patchwork Mon Jan 6 19:21:45 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Deb McLemore X-Patchwork-Id: 1218450 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.ozlabs.org (lists.ozlabs.org [203.11.71.2]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 47s5tx3ZlRz9sNH for ; Tue, 7 Jan 2020 06:59:21 +1100 (AEDT) Authentication-Results: ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) by lists.ozlabs.org (Postfix) with ESMTP id 47s5tx2NfKzDqJj for ; Tue, 7 Jan 2020 06:59:21 +1100 (AEDT) X-Original-To: skiboot@lists.ozlabs.org Delivered-To: skiboot@lists.ozlabs.org Authentication-Results: lists.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=linux.ibm.com (client-ip=148.163.156.1; helo=mx0a-001b2d01.pphosted.com; envelope-from=debmc@linux.ibm.com; receiver=) Authentication-Results: lists.ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from mx0a-001b2d01.pphosted.com (mx0a-001b2d01.pphosted.com [148.163.156.1]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by lists.ozlabs.org (Postfix) with ESMTPS id 47s5lC008XzDqGt for ; Tue, 7 Jan 2020 06:52:38 +1100 (AEDT) Received: from pps.filterd (m0098396.ppops.net [127.0.0.1]) by mx0a-001b2d01.pphosted.com (8.16.0.42/8.16.0.42) with SMTP id 006JqKYA025162 for ; Mon, 6 Jan 2020 14:52:36 -0500 Received: from ppma04dal.us.ibm.com (7a.29.35a9.ip4.static.sl-reverse.com [169.53.41.122]) by mx0a-001b2d01.pphosted.com with ESMTP id 2xb92mdgur-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 14:52:36 -0500 Received: from pps.filterd (ppma04dal.us.ibm.com [127.0.0.1]) by ppma04dal.us.ibm.com (8.16.0.27/8.16.0.27) with SMTP id 006JpP4j030746 for ; Mon, 6 Jan 2020 19:52:35 GMT Received: from b03cxnp08025.gho.boulder.ibm.com (b03cxnp08025.gho.boulder.ibm.com [9.17.130.17]) by ppma04dal.us.ibm.com with ESMTP id 2xajb6a1h6-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 19:52:35 +0000 Received: from b03ledav005.gho.boulder.ibm.com (b03ledav005.gho.boulder.ibm.com [9.17.130.236]) by b03cxnp08025.gho.boulder.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id 006JqX6J61931790 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=OK) for ; Mon, 6 Jan 2020 19:52:34 GMT Received: from b03ledav005.gho.boulder.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id DB988BE04F for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from b03ledav005.gho.boulder.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 9448DBE051 for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from oc4402612711.ibm.com (unknown [9.41.175.242]) by b03ledav005.gho.boulder.ibm.com (Postfix) with ESMTP for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: by oc4402612711.ibm.com (Postfix, from userid 1000) id 44E61AE043A; Mon, 6 Jan 2020 13:22:42 -0600 (CST) From: Deb McLemore To: skiboot@lists.ozlabs.org Date: Mon, 6 Jan 2020 13:21:45 -0600 Message-Id: <1578338508-13424-11-git-send-email-debmc@linux.ibm.com> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> References: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> X-TM-AS-GCONF: 00 X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.95, 18.0.572 definitions=2020-01-06_06:2020-01-06, 2020-01-06 signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 mlxscore=0 adultscore=0 lowpriorityscore=0 spamscore=0 phishscore=0 priorityscore=1501 impostorscore=0 bulkscore=0 malwarescore=0 mlxlogscore=999 suspectscore=3 clxscore=1015 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-1910280000 definitions=main-2001060165 Subject: [Skiboot] [PATCH v3 10/13] libflash/ipmi-hiomap: Add some debug logging X-BeenThere: skiboot@lists.ozlabs.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Mailing list for skiboot development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , MIME-Version: 1.0 Errors-To: skiboot-bounces+incoming=patchwork.ozlabs.org@lists.ozlabs.org Sender: "Skiboot" 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 --- 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 ca4b448..482a5cd 100644 --- a/core/flash.c +++ b/core/flash.c @@ -680,8 +680,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, we need to hold lock to continue transaction */ return OPAL_ASYNC_COMPLETION; diff --git a/libflash/ipmi-hiomap.c b/libflash/ipmi-hiomap.c index 2e288b3..c2db98f 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; } @@ -114,16 +119,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 the caller @@ -330,8 +346,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; @@ -388,7 +406,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; @@ -403,8 +423,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); @@ -684,8 +704,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; } @@ -711,8 +733,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; @@ -728,11 +752,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; } @@ -755,8 +781,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; @@ -767,10 +795,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; } @@ -810,12 +840,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) { @@ -824,7 +857,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; } @@ -850,8 +883,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; @@ -867,11 +902,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; } @@ -936,10 +974,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); } @@ -952,7 +997,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) { @@ -1000,7 +1045,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) { @@ -1016,7 +1061,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; @@ -1036,6 +1081,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 @@ -1058,9 +1104,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); @@ -1078,21 +1133,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; } @@ -1102,7 +1158,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__); } /* @@ -1120,7 +1176,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; @@ -1136,15 +1194,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) { @@ -1158,8 +1218,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; @@ -1243,8 +1302,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) { @@ -1258,8 +1319,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; @@ -1364,14 +1424,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) { @@ -1383,8 +1446,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; @@ -1468,12 +1531,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; @@ -1520,26 +1587,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; }