[RFC PATCH] lpfc: additional lpfc_printf_log() to PLOGI and other failure cases.

[RFC PATCH] lpfc: additional lpfc_printf_log() to PLOGI and other failure cases.

[Kei Tokunaga]

Hi James (Smart),

This is a RFC for additional logging points to lpfc driver.  lpfc has a logging
system with lpfc_printf_v/log() functions and it gives us valid messages for
problem analysis, debugging, etc.  I'd like to suggest some additional logging
points to it.  Some time ago, we have experienced this issue that took us a
relatively long time to find out the root cause because we didn't get helpful
messages we needed to identify the root cause.  From that experience, I think
adding these would be helpful to prevent the same situation in the future,

Brief descriptions of the issue:  One customer noticed, from the boot log, one
of their servers didn't detect a tape library at boot time.  The root cause was
a hardware failure on the tape library and that caused PLOGI to fail.  However,
lpfc output no messages indicating the PLOGI failure, and thus that did not give
us a quick idea of narrowing down to the focus to a hardware failure.
Fortunately, the customer let us make a debug lpfc driver with some additional
logging points, and finally we found the cause, but it's not always the case.

Since each message of lpfc has a four digit ID, in the proposal patch, I just
put 'xxxx' for now.  This applies to 2.6.33-rc7.

It'd be really great if something like this patch would be included.

Thanks,
Kei

Signed-off-by: Kei Tokunaga <tokunaga.keiich@jp.fujitsu.com>


---

 linux-2.6.33-rc7-log-kei/drivers/scsi/lpfc/lpfc_els.c |   14 +++++++++++++-
 1 file changed, 13 insertions(+), 1 deletion(-)

diff -puN drivers/scsi/lpfc/lpfc_els.c~lpfc_printf_log_additions drivers/scsi/lpfc/lpfc_els.c
--- linux-2.6.33-rc7-log/drivers/scsi/lpfc/lpfc_els.c~lpfc_printf_log_additions	2010-02-12 11:21:49.000000000 +0900
+++ linux-2.6.33-rc7-log-kei/drivers/scsi/lpfc/lpfc_els.c	2010-02-12 15:11:31.000000000 +0900
@@ -797,7 +797,7 @@ lpfc_cmpl_els_flogi(struct lpfc_hba *phb
 		}
 
 		/* FLOGI failure */
-		lpfc_printf_vlog(vport, KERN_INFO, LOG_ELS,
+		lpfc_printf_vlog(vport, KERN_ERR, LOG_ELS,
 				 "0100 FLOGI failure Data: x%x x%x "
 				 "x%x\n",
 				 irsp->ulpStatus, irsp->un.ulpWord[4],
@@ -1397,6 +1397,9 @@ lpfc_cmpl_els_plogi(struct lpfc_hba *phb
 			goto out;
 		}
 		/* PLOGI failed */
+		lpfc_printf_vlog(vport, KERN_ERR, LOG_ELS,
+			 "xxxx PLOGI failure Data: x%x x%x x%x\n",
+			 ndlp->nlp_DID, irsp->ulpStatus, irsp->un.ulpWord[4]);
 		/* Do not call DSM for lpfc_els_abort'ed ELS cmds */
 		if (lpfc_error_lost_link(irsp))
 			rc = NLP_STE_FREED_NODE;
@@ -1565,6 +1568,9 @@ lpfc_cmpl_els_prli(struct lpfc_hba *phba
 			goto out;
 		}
 		/* PRLI failed */
+		lpfc_printf_vlog(vport, KERN_ERR, LOG_ELS,
+			 "xxxx PRLI failure Data: x%x x%x x%x\n",
+			 ndlp->nlp_DID, irsp->ulpStatus, irsp->un.ulpWord[4]);
 		/* Do not call DSM for lpfc_els_abort'ed ELS cmds */
 		if (lpfc_error_lost_link(irsp))
 			goto out;
@@ -1848,6 +1854,9 @@ lpfc_cmpl_els_adisc(struct lpfc_hba *phb
 			goto out;
 		}
 		/* ADISC failed */
+		lpfc_printf_vlog(vport, KERN_ERR, LOG_ELS,
+			 "xxxx ADISC failure Data: x%x x%x x%x\n",
+			 ndlp->nlp_DID, irsp->ulpStatus, irsp->un.ulpWord[4]);
 		/* Do not call DSM for lpfc_els_abort'ed ELS cmds */
 		if (!lpfc_error_lost_link(irsp))
 			lpfc_disc_state_machine(vport, ndlp, cmdiocb,
@@ -1997,6 +2006,9 @@ lpfc_cmpl_els_logo(struct lpfc_hba *phba
 			/* ELS command is being retried */
 			goto out;
 		/* LOGO failed */
+		lpfc_printf_vlog(vport, KERN_ERR, LOG_ELS,
+			 "xxxx LOGO failure Data: x%x x%x x%x\n",
+			 ndlp->nlp_DID, irsp->ulpStatus, irsp->un.ulpWord[4]);
 		/* Do not call DSM for lpfc_els_abort'ed ELS cmds */
 		if (lpfc_error_lost_link(irsp))
 			goto out;
diff -puN drivers/scsi/lpfc/lpfc_scsi.c~lpfc_printf_log_additions drivers/scsi/lpfc/lpfc_scsi.c
diff -puN drivers/scsi/lpfc/lpfc_sli.c~lpfc_printf_log_additions drivers/scsi/lpfc/lpfc_sli.c

_

Re: [RFC PATCH] lpfc: additional lpfc_printf_log() to PLOGI and other failure cases.

[James Smart]

Kei,

Sounds very reasonable.  Let me pull this into our team. We have a process of 
assigning unique log message numbers, which gets tied to documentation, and 
field support guides.  We'll include an updated version of this patch in a 
future patch set.  Please note though, we're in the final throes of distro 
submissions, so it may be a little delayed.

-- james s


Kei Tokunaga wrote:
> Hi James (Smart),
> 
> This is a RFC for additional logging points to lpfc driver.  lpfc has a logging
> system with lpfc_printf_v/log() functions and it gives us valid messages for
> problem analysis, debugging, etc.  I'd like to suggest some additional logging
> points to it.  Some time ago, we have experienced this issue that took us a
> relatively long time to find out the root cause because we didn't get helpful
> messages we needed to identify the root cause.  From that experience, I think
> adding these would be helpful to prevent the same situation in the future,
> 
> Brief descriptions of the issue:  One customer noticed, from the boot log, one
> of their servers didn't detect a tape library at boot time.  The root cause was
> a hardware failure on the tape library and that caused PLOGI to fail.  However,
> lpfc output no messages indicating the PLOGI failure, and thus that did not give
> us a quick idea of narrowing down to the focus to a hardware failure.
> Fortunately, the customer let us make a debug lpfc driver with some additional
> logging points, and finally we found the cause, but it's not always the case.
> 
> Since each message of lpfc has a four digit ID, in the proposal patch, I just
> put 'xxxx' for now.  This applies to 2.6.33-rc7.
> 
> It'd be really great if something like this patch would be included.
> 
> Thanks,
> Kei
> 
> Signed-off-by: Kei Tokunaga <tokunaga.keiich@jp.fujitsu.com>
> 
> 
> ---
> 
>  linux-2.6.33-rc7-log-kei/drivers/scsi/lpfc/lpfc_els.c |   14 +++++++++++++-
>  1 file changed, 13 insertions(+), 1 deletion(-)
> 
> diff -puN drivers/scsi/lpfc/lpfc_els.c~lpfc_printf_log_additions drivers/scsi/lpfc/lpfc_els.c
> --- linux-2.6.33-rc7-log/drivers/scsi/lpfc/lpfc_els.c~lpfc_printf_log_additions	2010-02-12 11:21:49.000000000 +0900
> +++ linux-2.6.33-rc7-log-kei/drivers/scsi/lpfc/lpfc_els.c	2010-02-12 15:11:31.000000000 +0900
> @@ -797,7 +797,7 @@ lpfc_cmpl_els_flogi(struct lpfc_hba *phb
>  		}
>  
>  		/* FLOGI failure */
> -		lpfc_printf_vlog(vport, KERN_INFO, LOG_ELS,
> +		lpfc_printf_vlog(vport, KERN_ERR, LOG_ELS,
>  				 "0100 FLOGI failure Data: x%x x%x "
>  				 "x%x\n",
>  				 irsp->ulpStatus, irsp->un.ulpWord[4],
> @@ -1397,6 +1397,9 @@ lpfc_cmpl_els_plogi(struct lpfc_hba *phb
>  			goto out;
>  		}
>  		/* PLOGI failed */
> +		lpfc_printf_vlog(vport, KERN_ERR, LOG_ELS,
> +			 "xxxx PLOGI failure Data: x%x x%x x%x\n",
> +			 ndlp->nlp_DID, irsp->ulpStatus, irsp->un.ulpWord[4]);
>  		/* Do not call DSM for lpfc_els_abort'ed ELS cmds */
>  		if (lpfc_error_lost_link(irsp))
>  			rc = NLP_STE_FREED_NODE;
> @@ -1565,6 +1568,9 @@ lpfc_cmpl_els_prli(struct lpfc_hba *phba
>  			goto out;
>  		}
>  		/* PRLI failed */
> +		lpfc_printf_vlog(vport, KERN_ERR, LOG_ELS,
> +			 "xxxx PRLI failure Data: x%x x%x x%x\n",
> +			 ndlp->nlp_DID, irsp->ulpStatus, irsp->un.ulpWord[4]);
>  		/* Do not call DSM for lpfc_els_abort'ed ELS cmds */
>  		if (lpfc_error_lost_link(irsp))
>  			goto out;
> @@ -1848,6 +1854,9 @@ lpfc_cmpl_els_adisc(struct lpfc_hba *phb
>  			goto out;
>  		}
>  		/* ADISC failed */
> +		lpfc_printf_vlog(vport, KERN_ERR, LOG_ELS,
> +			 "xxxx ADISC failure Data: x%x x%x x%x\n",
> +			 ndlp->nlp_DID, irsp->ulpStatus, irsp->un.ulpWord[4]);
>  		/* Do not call DSM for lpfc_els_abort'ed ELS cmds */
>  		if (!lpfc_error_lost_link(irsp))
>  			lpfc_disc_state_machine(vport, ndlp, cmdiocb,
> @@ -1997,6 +2006,9 @@ lpfc_cmpl_els_logo(struct lpfc_hba *phba
>  			/* ELS command is being retried */
>  			goto out;
>  		/* LOGO failed */
> +		lpfc_printf_vlog(vport, KERN_ERR, LOG_ELS,
> +			 "xxxx LOGO failure Data: x%x x%x x%x\n",
> +			 ndlp->nlp_DID, irsp->ulpStatus, irsp->un.ulpWord[4]);
>  		/* Do not call DSM for lpfc_els_abort'ed ELS cmds */
>  		if (lpfc_error_lost_link(irsp))
>  			goto out;
> diff -puN drivers/scsi/lpfc/lpfc_scsi.c~lpfc_printf_log_additions drivers/scsi/lpfc/lpfc_scsi.c
> diff -puN drivers/scsi/lpfc/lpfc_sli.c~lpfc_printf_log_additions drivers/scsi/lpfc/lpfc_sli.c
> 
> _
> 
> 
> 
> 

Re: [RFC PATCH] lpfc: additional lpfc_printf_log() to PLOGI and other failure cases.

[Kei Tokunaga]

James Smart wrote:
> Kei,
>
> Sounds very reasonable.  Let me pull this into our team. We have a process of 
> assigning unique log message numbers, which gets tied to documentation, and 
> field support guides.  We'll include an updated version of this patch in a 
> future patch set.  Please note though, we're in the final throes of distro 
> submissions, so it may be a little delayed.
That's no problem.  Glad to hear the patch will be pulled in.

While waiting for the inclusion, please let me bring up a few
more potential points here to discuss.  This patch shows the
points which I think should help us as well.  Would you also
comment on the patch, please?

Kei

---

 linux-2.6.33-rc7-log-kei/drivers/scsi/lpfc/lpfc_scsi.c |   14 ++++++++++++--
 linux-2.6.33-rc7-log-kei/drivers/scsi/lpfc/lpfc_sli.c  |   11 ++++++++++-
 2 files changed, 22 insertions(+), 3 deletions(-)

diff -puN drivers/scsi/lpfc/lpfc_els.c~lpfc_log_add_misc drivers/scsi/lpfc/lpfc_els.c
diff -puN drivers/scsi/lpfc/lpfc_scsi.c~lpfc_log_add_misc drivers/scsi/lpfc/lpfc_scsi.c
--- linux-2.6.33-rc7-log/drivers/scsi/lpfc/lpfc_scsi.c~lpfc_log_add_misc	2010-02-15 10:44:02.000000000 +0900
+++ linux-2.6.33-rc7-log-kei/drivers/scsi/lpfc/lpfc_scsi.c	2010-02-15 16:47:03.000000000 +0900
@@ -2079,8 +2079,7 @@ lpfc_handle_fcp_err(struct lpfc_vport *v
 
 	if (resp_info & RSP_LEN_VALID) {
 		rsplen = be32_to_cpu(fcprsp->rspRspLen);
-		if ((rsplen != 0 && rsplen != 4 && rsplen != 8) ||
-		    (fcprsp->rspInfo3 != RSP_NO_FAILURE)) {
+		if (rsplen != 0 && rsplen != 4 && rsplen != 8) {
 			lpfc_printf_vlog(vport, KERN_ERR, LOG_FCP,
 				 "2719 Invalid response length: "
 				 "tgt x%x lun x%x cmnd x%x rsplen x%x\n",
@@ -2090,6 +2089,17 @@ lpfc_handle_fcp_err(struct lpfc_vport *v
 			host_status = DID_ERROR;
 			goto out;
 		}
+		if (fcprsp->rspInfo3 != RSP_NO_FAILURE) {
+			lpfc_printf_vlog(vport, KERN_ERR, LOG_FCP,
+				 "xxxx Protocol failure detected during "
+				 "processing of FCP I/O op: "
+				 "tgt x%x lun x%x cmnd x%x rspInfo3 x%x\n",
+				 cmnd->device->id,
+				 cmnd->device->lun, cmnd->cmnd[0],
+				 fcprsp->rspInfo3);
+			host_status = DID_ERROR;
+			goto out;
+		}
 	}
 
 	if ((resp_info & SNS_LEN_VALID) && fcprsp->rspSnsLen) {
diff -puN drivers/scsi/lpfc/lpfc_sli.c~lpfc_log_add_misc drivers/scsi/lpfc/lpfc_sli.c
--- linux-2.6.33-rc7-log/drivers/scsi/lpfc/lpfc_sli.c~lpfc_log_add_misc	2010-02-15 10:44:02.000000000 +0900
+++ linux-2.6.33-rc7-log-kei/drivers/scsi/lpfc/lpfc_sli.c	2010-02-15 10:44:02.000000000 +0900
@@ -3039,6 +3039,12 @@ lpfc_sli_brdready_s3(struct lpfc_hba *ph
 
 	/* Check to see if any errors occurred during init */
 	if ((status & HS_FFERM) || (i >= 20)) {
+		lpfc_printf_log(phba, KERN_ERR, LOG_INIT,
+				"xxxx Adapter failed to restart, "
+				"status reg x%x, FW Data: A8 x%x AC x%x\n",
+				status,
+				readl(phba->MBslimaddr + 0xa8),
+				readl(phba->MBslimaddr + 0xac));
 		phba->link_state = LPFC_HBA_ERROR;
 		retval = 1;
 	}
@@ -3226,6 +3232,9 @@ lpfc_sli_brdkill(struct lpfc_hba *phba)
 	if (retval != MBX_SUCCESS) {
 		if (retval != MBX_BUSY)
 			mempool_free(pmb, phba->mbox_mem_pool);
+		lpfc_printf_log(phba, KERN_ERR, LOG_SLI,
+				"xxxx KILL_BOARD command failed "
+				"retval %d\n", retval);
 		spin_lock_irq(&phba->hbalock);
 		phba->link_flag &= ~LS_IGNORE_ERATT;
 		spin_unlock_irq(&phba->hbalock);
@@ -3983,7 +3992,7 @@ lpfc_sli_hba_setup(struct lpfc_hba *phba
 
 lpfc_sli_hba_setup_error:
 	phba->link_state = LPFC_HBA_ERROR;
-	lpfc_printf_log(phba, KERN_INFO, LOG_INIT,
+	lpfc_printf_log(phba, KERN_ERR, LOG_INIT,
 			"0445 Firmware initialization failed\n");
 	return rc;
 }

_