| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <5fb2a4d0-4b7c-4cf6-a8ed-752e85acd088@suse.de>
Date: Thu, 2 Nov 2023 09:14:05 +0100
From: Hannes Reinecke <hare@...e.de>
To: Karan Tilak Kumar <kartilak@...co.com>, sebaddel@...co.com
Cc: arulponn@...co.com, djhawar@...co.com, gcboffa@...co.com,
mkai2@...co.com, satishkh@...co.com, jejb@...ux.ibm.com,
martin.petersen@...cle.com, linux-scsi@...r.kernel.org,
linux-kernel@...r.kernel.org
Subject: Re: [PATCH v2 13/13] scsi: fnic: Improve logs and add support for
multiqueue (MQ)
On 10/27/23 20:03, Karan Tilak Kumar wrote:
> Improve existing logs by adding fnic number, hardware queue,
> tag, and mqtag in the prints.
> Add logs with the above elements for effective debugging.
>
> Reviewed-by: Sesidhar Baddela <sebaddel@...co.com>
> Reviewed-by: Arulprabhu Ponnusamy <arulponn@...co.com>
> Tested-by: Karan Tilak Kumar <kartilak@...co.com>
> Signed-off-by: Karan Tilak Kumar <kartilak@...co.com>
> ---
> drivers/scsi/fnic/fnic.h | 2 +-
> drivers/scsi/fnic/fnic_scsi.c | 127 ++++++++++++++++++++--------------
> 2 files changed, 77 insertions(+), 52 deletions(-)
>
> diff --git a/drivers/scsi/fnic/fnic.h b/drivers/scsi/fnic/fnic.h
> index 87dab09a426d..0f1581c1fb4a 100644
> --- a/drivers/scsi/fnic/fnic.h
> +++ b/drivers/scsi/fnic/fnic.h
> @@ -27,7 +27,7 @@
>
> #define DRV_NAME "fnic"
> #define DRV_DESCRIPTION "Cisco FCoE HBA Driver"
> -#define DRV_VERSION "1.6.0.56"
> +#define DRV_VERSION "1.6.0.58"
> #define PFX DRV_NAME ": "
> #define DFX DRV_NAME "%d: "
>
> diff --git a/drivers/scsi/fnic/fnic_scsi.c b/drivers/scsi/fnic/fnic_scsi.c
> index fdc4d73ba63c..e6dccb752f7e 100644
> --- a/drivers/scsi/fnic/fnic_scsi.c
> +++ b/drivers/scsi/fnic/fnic_scsi.c
> @@ -211,12 +211,14 @@ int fnic_fw_reset_handler(struct fnic *fnic)
>
> if (!ret) {
> atomic64_inc(&fnic->fnic_stats.reset_stats.fw_resets);
> - FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
> - "Issued fw reset\n");
> + FNIC_SCSI_DBG(KERN_INFO, fnic->lport->host,
> + "fnic<%d>: %s: %d: Issued fw reset\n",
> + fnic->fnic_num, __func__, __LINE__);
> } else {
> fnic_clear_state_flags(fnic, FNIC_FLAGS_FWRESET);
> - FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
> - "Failed to issue fw reset\n");
> + FNIC_SCSI_DBG(KERN_ERR, fnic->lport->host,
> + "fnic<%d>: %s: %d: Failed to issue fw reset\n",
> + fnic->fnic_num, __func__, __LINE__);
> }
>
> return ret;
> @@ -265,9 +267,9 @@ int fnic_flogi_reg_handler(struct fnic *fnic, u32 fc_id)
> } else {
> fnic_queue_wq_copy_desc_flogi_reg(wq, SCSI_NO_TAG,
> format, fc_id, gw_mac);
> - FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
> - "FLOGI reg issued fcid %x map %d dest %pM\n",
> - fc_id, fnic->ctlr.map_dest, gw_mac);
> + FNIC_SCSI_DBG(KERN_INFO, fnic->lport->host,
> + "fnic<%d>: %s: %d: FLOGI reg issued fcid 0x%x map %d dest 0x%p\n",
> + fnic->fnic_num, __func__, __LINE__, fc_id, fnic->ctlr.map_dest, gw_mac);
> }
>
> atomic64_inc(&fnic->fnic_stats.fw_stats.active_fw_reqs);
> @@ -644,15 +646,16 @@ static int fnic_fcpio_fw_reset_cmpl_handler(struct fnic *fnic,
> if (fnic->state == FNIC_IN_FC_TRANS_ETH_MODE) {
> /* Check status of reset completion */
> if (!hdr_status) {
> - FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
> - "reset cmpl success\n");
> + FNIC_SCSI_DBG(KERN_INFO, fnic->lport->host,
> + "fnic<%d>: %s: %d: reset cmpl success\n",
> + fnic->fnic_num, __func__, __LINE__);
> /* Ready to send flogi out */
> fnic->state = FNIC_IN_ETH_MODE;
> } else {
> - FNIC_SCSI_DBG(KERN_DEBUG,
> - fnic->lport->host,
> - "fnic fw_reset : failed %s\n",
> - fnic_fcpio_status_to_str(hdr_status));
> + FNIC_SCSI_DBG(KERN_ERR, fnic->lport->host,
> + "fnic<%d>: %s: %d: reset failed with header status: %s\n",
> + fnic->fnic_num, __func__, __LINE__,
> + fnic_fcpio_status_to_str(hdr_status));
>
> /*
> * Unable to change to eth mode, cannot send out flogi
> @@ -665,10 +668,9 @@ static int fnic_fcpio_fw_reset_cmpl_handler(struct fnic *fnic,
> ret = -1;
> }
> } else {
> - FNIC_SCSI_DBG(KERN_DEBUG,
> - fnic->lport->host,
> - "Unexpected state %s while processing"
> - " reset cmpl\n", fnic_state_to_str(fnic->state));
> + FNIC_SCSI_DBG(KERN_ERR, fnic->lport->host,
> + "fnic<%d>: %s: %d: Unexpected state while processing reset completion: %s\n",
> + fnic->fnic_num, __func__, __LINE__, fnic_state_to_str(fnic->state));
> atomic64_inc(&reset_stats->fw_reset_failures);
> ret = -1;
> }
> @@ -1177,9 +1179,10 @@ static void fnic_fcpio_itmf_cmpl_handler(struct fnic *fnic, unsigned int cq_inde
> if ((id & FNIC_TAG_ABORT) && (id & FNIC_TAG_DEV_RST)) {
> /* Abort and terminate completion of device reset req */
> /* REVISIT : Add asserts about various flags */
> - FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
> - "dev reset abts cmpl recd. id %x status %s\n",
> - id, fnic_fcpio_status_to_str(hdr_status));
> + FNIC_SCSI_DBG(KERN_INFO, fnic->lport->host,
> + "fnic<%d>: %s: %d: hwq: %d mqtag: 0x%x tag: 0x%x hst: %s Abt/term completion received\n",
> + fnic->fnic_num, __func__, __LINE__, hwq, mqtag, tag,
> + fnic_fcpio_status_to_str(hdr_status));
> fnic_priv(sc)->state = FNIC_IOREQ_ABTS_COMPLETE;
> fnic_priv(sc)->abts_status = hdr_status;
> fnic_priv(sc)->flags |= FNIC_DEV_RST_DONE;
> @@ -1188,6 +1191,10 @@ static void fnic_fcpio_itmf_cmpl_handler(struct fnic *fnic, unsigned int cq_inde
> spin_unlock_irqrestore(&fnic->wq_copy_lock[hwq], flags);
> } else if (id & FNIC_TAG_ABORT) {
> /* Completion of abort cmd */
> + shost_printk(KERN_DEBUG, fnic->lport->host,
> + "fnic<%d>: %s: %d: hwq: %d mqtag: 0x%x tag: 0x%x Abort header status: %s\n",
> + fnic->fnic_num, __func__, __LINE__, hwq, mqtag, tag,
> + fnic_fcpio_status_to_str(hdr_status));
> switch (hdr_status) {
> case FCPIO_SUCCESS:
> break;
> @@ -1247,9 +1254,14 @@ static void fnic_fcpio_itmf_cmpl_handler(struct fnic *fnic, unsigned int cq_inde
> if (io_req->abts_done) {
> complete(io_req->abts_done);
> spin_unlock_irqrestore(&fnic->wq_copy_lock[hwq], flags);
> + shost_printk(KERN_INFO, fnic->lport->host,
> + "fnic<%d>: %s: %d: hwq: %d mqtag: 0x%x tag: 0x%x Waking up abort thread\n",
> + fnic->fnic_num, __func__, __LINE__, hwq, mqtag, tag);
> } else {
> FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
> - "abts cmpl, completing IO\n");
> + "fnic<%d>: %s: %d: hwq: %d mqtag: 0x%x tag: 0x%x hst: %s Completing IO\n",
> + fnic->fnic_num, __func__, __LINE__, hwq, mqtag,
> + tag, fnic_fcpio_status_to_str(hdr_status));
> fnic_priv(sc)->io_req = NULL;
> sc->result = (DID_ERROR << 16);
> fnic->sw_copy_wq[hwq].io_req_table[tag] = NULL;
> @@ -1277,6 +1289,10 @@ static void fnic_fcpio_itmf_cmpl_handler(struct fnic *fnic, unsigned int cq_inde
> }
> } else if (id & FNIC_TAG_DEV_RST) {
> /* Completion of device reset */
> + shost_printk(KERN_INFO, fnic->lport->host,
> + "fnic<%d>: %s: %d: hwq: %d mqtag: 0x%x tag: 0x%x DR hst: %s\n",
> + fnic->fnic_num, __func__, __LINE__, hwq, mqtag,
> + tag, fnic_fcpio_status_to_str(hdr_status));
> fnic_priv(sc)->lr_status = hdr_status;
> if (fnic_priv(sc)->state == FNIC_IOREQ_ABTS_PENDING) {
> spin_unlock_irqrestore(&fnic->wq_copy_lock[hwq], flags);
> @@ -1286,10 +1302,9 @@ static void fnic_fcpio_itmf_cmpl_handler(struct fnic *fnic, unsigned int cq_inde
> jiffies_to_msecs(jiffies - start_time),
> desc, 0, fnic_flags_and_state(sc));
> FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
> - "Terminate pending "
> - "dev reset cmpl recd. id %d status %s\n",
> - (int)(id & FNIC_TAG_MASK),
> - fnic_fcpio_status_to_str(hdr_status));
> + "fnic<%d>: %s: %d: hwq: %d mqtag: 0x%x tag: 0x%x hst: %s Terminate pending\n",
> + fnic->fnic_num, __func__, __LINE__, hwq, mqtag,
> + tag, fnic_fcpio_status_to_str(hdr_status));
> return;
> }
> if (fnic_priv(sc)->flags & FNIC_DEV_RST_TIMED_OUT) {
> @@ -1308,18 +1323,18 @@ static void fnic_fcpio_itmf_cmpl_handler(struct fnic *fnic, unsigned int cq_inde
> }
> fnic_priv(sc)->state = FNIC_IOREQ_CMD_COMPLETE;
> fnic_priv(sc)->flags |= FNIC_DEV_RST_DONE;
> - FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
> - "dev reset cmpl recd. id %d status %s\n",
> - (int)(id & FNIC_TAG_MASK),
> - fnic_fcpio_status_to_str(hdr_status));
> + FNIC_SCSI_DBG(KERN_INFO, fnic->lport->host,
> + "fnic<%d>: %s: %d: hwq: %d mqtag: 0x%x tag: 0x%x hst: %s DR completion received\n",
> + fnic->fnic_num, __func__, __LINE__, hwq, mqtag,
> + tag, fnic_fcpio_status_to_str(hdr_status));
> if (io_req->dr_done)
> complete(io_req->dr_done);
> spin_unlock_irqrestore(&fnic->wq_copy_lock[hwq], flags);
>
> } else {
> shost_printk(KERN_ERR, fnic->lport->host,
> - "Unexpected itmf io state %s tag %x\n",
> - fnic_ioreq_state_to_str(fnic_priv(sc)->state), id);
> + "%s: Unexpected itmf io state: hwq: %d tag 0x%x %s\n",
> + __func__, hwq, id, fnic_ioreq_state_to_str(fnic_priv(sc)->state));
> spin_unlock_irqrestore(&fnic->wq_copy_lock[hwq], flags);
> }
>
> @@ -1470,9 +1485,9 @@ static bool fnic_cleanup_io_iter(struct scsi_cmnd *sc, void *data)
> mempool_free(io_req, fnic->io_req_pool);
>
> sc->result = DID_TRANSPORT_DISRUPTED << 16;
> - FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
> - "fnic_cleanup_io: tag:0x%x : sc:0x%p duration = %lu DID_TRANSPORT_DISRUPTED\n",
> - tag, sc, jiffies - start_time);
> + FNIC_SCSI_DBG(KERN_ERR, fnic->lport->host,
> + "fnic<%d>: %s: %d: mqtag:0x%x tag: 0x%x sc:0x%p duration = %lu DID_TRANSPORT_DISRUPTED\n",
> + fnic->fnic_num, __func__, __LINE__, mqtag, tag, sc, (jiffies - start_time));
>
> if (atomic64_read(&fnic->io_cmpl_skip))
> atomic64_dec(&fnic->io_cmpl_skip);
> @@ -1641,9 +1656,9 @@ static bool fnic_rport_abort_io_iter(struct scsi_cmnd *sc, void *data)
>
> if ((fnic_priv(sc)->flags & FNIC_DEVICE_RESET) &&
> !(fnic_priv(sc)->flags & FNIC_DEV_RST_ISSUED)) {
> - FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
> - "fnic_rport_exch_reset dev rst not pending sc 0x%p\n",
> - sc);
> + FNIC_SCSI_DBG(KERN_ERR, fnic->lport->host,
> + "fnic<%d>: %s: %d: hwq: %d abt_tag: 0x%x flags: 0x%x Device reset is not pending\n",
> + fnic->fnic_num, __func__, __LINE__, hwq, abt_tag, fnic_priv(sc)->flags);
> spin_unlock_irqrestore(&fnic->wq_copy_lock[hwq], flags);
> return true;
> }
> @@ -1699,6 +1714,9 @@ static bool fnic_rport_abort_io_iter(struct scsi_cmnd *sc, void *data)
> * lun reset
> */
> spin_lock_irqsave(&fnic->wq_copy_lock[hwq], flags);
> + FNIC_SCSI_DBG(KERN_ERR, fnic->lport->host,
> + "fnic<%d>: %s: %d: hwq: %d abt_tag: 0x%x flags: 0x%x Queuing abort failed\n",
> + fnic->fnic_num, __func__, __LINE__, hwq, abt_tag, fnic_priv(sc)->flags);
> if (fnic_priv(sc)->state == FNIC_IOREQ_ABTS_PENDING)
> fnic_priv(sc)->state = old_ioreq_state;
> spin_unlock_irqrestore(&fnic->wq_copy_lock[hwq], flags);
> @@ -1869,8 +1887,9 @@ int fnic_abort_cmd(struct scsi_cmnd *sc)
> else
> atomic64_inc(&abts_stats->abort_issued_greater_than_60_sec);
>
> - FNIC_SCSI_DBG(KERN_INFO, fnic->lport->host,
> - "CBD Opcode: %02x Abort issued time: %lu msec\n", sc->cmnd[0], abt_issued_time);
> + FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
> + "fnic<%d>: %s: CDB Opcode: 0x%02x Abort issued time: %lu msec\n",
> + fnic->fnic_num, __func__, sc->cmnd[0], abt_issued_time);
> /*
> * Command is still pending, need to abort it
> * If the firmware completes the command after this point,
> @@ -1959,8 +1978,9 @@ int fnic_abort_cmd(struct scsi_cmnd *sc)
>
> if (!(fnic_priv(sc)->flags & (FNIC_IO_ABORTED | FNIC_IO_DONE))) {
> spin_unlock_irqrestore(&fnic->wq_copy_lock[hwq], flags);
> - FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
> - "Issuing Host reset due to out of order IO\n");
> + FNIC_SCSI_DBG(KERN_ERR, fnic->lport->host,
> + "fnic<%d>: %s: Issuing host reset due to out of order IO\n",
> + fnic->fnic_num, __func__);
>
> ret = FAILED;
> goto fnic_abort_cmd_end;
> @@ -2167,6 +2187,9 @@ static bool fnic_pending_aborts_iter(struct scsi_cmnd *sc, void *data)
> fnic_priv(sc)->state = old_ioreq_state;
> spin_unlock_irqrestore(&fnic->wq_copy_lock[hwq], flags);
> iter_data->ret = FAILED;
> + FNIC_SCSI_DBG(KERN_ERR, fnic->lport->host,
> + "fnic<%d>: %s: %d: hwq: %d abt_tag: 0x%lx Abort could not be queued\n",
> + fnic->fnic_num, __func__, __LINE__, hwq, abt_tag);
> return false;
> } else {
> spin_lock_irqsave(&fnic->wq_copy_lock[hwq], flags);
> @@ -2300,8 +2323,9 @@ int fnic_device_reset(struct scsi_cmnd *sc)
>
> rport = starget_to_rport(scsi_target(sc->device));
> FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
> - "Device reset called FCID 0x%x, LUN 0x%llx sc 0x%p\n",
> - rport->port_id, sc->device->lun, sc);
> + "fnic<%d>: %s: %d: fcid: 0x%x lun: 0x%llx hwq: %d mqtag: 0x%x flags: 0x%x Device reset\n",
> + fnic->fnic_num, __func__, __LINE__, rport->port_id, sc->device->lun, hwq, mqtag,
> + fnic_priv(sc)->flags);
>
> if (lp->state != LPORT_ST_READY || !(lp->link_up))
> goto fnic_device_reset_end;
> @@ -2536,8 +2560,9 @@ int fnic_reset(struct Scsi_Host *shost)
> fnic = lport_priv(lp);
> reset_stats = &fnic->fnic_stats.reset_stats;
>
> - FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
> - "fnic_reset called\n");
> + FNIC_SCSI_DBG(KERN_INFO, fnic->lport->host,
> + "fnic<%d>: %s: %d: Issuing fnic reset\n",
> + fnic->fnic_num, __func__, __LINE__);
>
> atomic64_inc(&reset_stats->fnic_resets);
>
> @@ -2547,10 +2572,9 @@ int fnic_reset(struct Scsi_Host *shost)
> */
> ret = fc_lport_reset(lp);
>
> - FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
> - "Returning from fnic reset %s\n",
> - (ret == 0) ?
> - "SUCCESS" : "FAILED");
> + FNIC_SCSI_DBG(KERN_INFO, fnic->lport->host,
> + "fnic<%d>: %s: %d: Returning from fnic reset with: %s\n",
> + fnic->fnic_num, __func__, __LINE__, (ret == 0) ? "SUCCESS" : "FAILED");
>
> if (ret == 0)
> atomic64_inc(&reset_stats->fnic_reset_completio to a > @@ -2766,8 +2790,9 @@ static bool fnic_abts_pending_iter(struct
scsi_cmnd *sc, void *data)
> * belongs to the LUN that we are resetting
> */
> FNIC_SCSI_DBG(KERN_INFO, fnic->lport->host,
> - "Found IO in %s on lun\n",
> - fnic_ioreq_state_to_str(fnic_priv(sc)->state));
> + "fnic<%d>: %s: %d: hwq: %d tag: 0x%x Found IO in state: %s on lun\n",
> + fnic->fnic_num, __func__, __LINE__, hwq, tag,
> + fnic_ioreq_state_to_str(fnic_priv(sc)->state));
> cmd_state = fnic_priv(sc)->state;
> spin_unlock_irqrestore(&fnic->wq_copy_lock[hwq], flags);
> if (cmd_state == FNIC_IOREQ_ABTS_PENDING)
See my comments to the previous patch. Please update FNIC_SCSI_DBG() to
accept an 'fnic' parameter instead of 'fnic->lport->host', and generate
the 'fnic<%d>' here in the macro.
Cheers,
Hannes
--
Dr. Hannes Reinecke Kernel Storage Architect
hare@...e.de +49 911 74053 688
SUSE Software Solutions GmbH, Maxfeldstr. 5, 90409 Nürnberg
HRB 36809 (AG Nürnberg), Geschäftsführer: Ivo Totev, Andrew
Myers, Andrew McDonald, Martje Boudien Moerman
Powered by blists - more mailing lists