Bug 624394

Created attachment 438914 [details]
Kernel config

Created attachment 438915 [details]
Mike Snitzer's ALUA handler debug patch

I was able to download the source files and built lpfc from the kernel source tree. The driver is failing because it's abort_handler is being called from the mid-layer and the host_scribble area of the command has been nulled out.

 2191 lpfc_abort_handler(struct scsi_cmnd *cmnd)
   2192 {
   2193         struct Scsi_Host  *shost = cmnd->device->host;
   2194         struct lpfc_vport *vport = (struct lpfc_vport *) shost->hostdata        ;
   2195         struct lpfc_hba   *phba = vport->phba;
   2196         struct lpfc_iocbq *iocb;
   2197         struct lpfc_iocbq *abtsiocb;
   2198         struct lpfc_scsi_buf *lpfc_cmd;
   2199         IOCB_t *cmd, *icmd;
   2200         int ret = SUCCESS;
   2201         DECLARE_WAIT_QUEUE_HEAD_ONSTACK(waitq);
   2202
   2203
   2204         lpfc_block_error_handler(cmnd);
   2205         lpfc_cmd = (struct lpfc_scsi_buf *)cmnd->host_scribble;
   2206         BUG_ON(!lpfc_cmd);
   2207

Without host_scribble we cannot identify the IO to be aborted so we BUG out.
 
The driver only sets host_scribble when it successfully completes lpfc_queuecommand. If lpfc_queuecommand cannot issue the command it will return the command to the mid-layer with BUSY status. It does not set the host_scribble area in this case. 

We may need redhats help, could this be a race between the driver calling the done routine and the IO being aborted by the mid-layer? 

Does the ALUA code that is being debugged ever null out the host_scribble in the scsi_cmnd ?

Can we get a trace with the scsi debug level truned up?

(In reply to comment #3)

> We may need redhats help, could this be a race between the driver calling the
> done routine and the IO being aborted by the mid-layer? 

I'd be amazed if that were the case but I must defer to others to provide a more comprehensive answer.

From the trace, it is not clear to me which path was taken to call .eh_abort_handler

Was it scsi_eh_abort_cmds() or scsi_send_eh_cmnd()?

But scsi_error.c:scsi_try_to_abort_cmd states:
"scsi_done was called just after the command timed out and
we had a chance to process it."
Having documented that assertion it goes on to call .eh_abort_handler

> Does the ALUA code that is being debugged ever null out the host_scribble in
> the scsi_cmnd ?

No.  The patch from comment#2 traces state transitions in scsi_dh_alua and adds retry capability if TPGS_STATE_TRANSITIONING is seen in 2 code paths.  None of which would alter host_scribble -- which AFAIK is managed entirely by the LLD.

> Can we get a trace with the scsi debug level turned up?

That is a question for NetApp.  I've been doing this same NetApp controller failure testing with the 2.6.18-194.11.1.el5.alua_dbg kernel using lpfc and haven't had any issues.  Only NetApp can trigger these problems.

But chances are additional scsi debug would really alter the timing (given the flood of error handling and overall IO load performed during these NetApp controller failure tests)... is there some precise level you'd like used?

2 things:

1) Is it possible to attach the /var/log/messages file associated with this BUG_ON?

2) (In reply to comment #3)
> I was able to download the source files and built lpfc from the kernel source
> tree. The driver is failing because it's abort_handler is being called from the
> mid-layer and the host_scribble area of the command has been nulled out.
> 
>  2191 lpfc_abort_handler(struct scsi_cmnd *cmnd)
>    2192 {
>    2193         struct Scsi_Host  *shost = cmnd->device->host;
>    2194         struct lpfc_vport *vport = (struct lpfc_vport *)
> shost->hostdata        ;
>    2195         struct lpfc_hba   *phba = vport->phba;
>    2196         struct lpfc_iocbq *iocb;
>    2197         struct lpfc_iocbq *abtsiocb;
>    2198         struct lpfc_scsi_buf *lpfc_cmd;
>    2199         IOCB_t *cmd, *icmd;
>    2200         int ret = SUCCESS;
>    2201         DECLARE_WAIT_QUEUE_HEAD_ONSTACK(waitq);
>    2202
>    2203
>    2204         lpfc_block_error_handler(cmnd);
>    2205         lpfc_cmd = (struct lpfc_scsi_buf *)cmnd->host_scribble;
>    2206         BUG_ON(!lpfc_cmd);
>    2207
> 
> Without host_scribble we cannot identify the IO to be aborted so we BUG out.
> 
> The driver only sets host_scribble when it successfully completes
> lpfc_queuecommand. If lpfc_queuecommand cannot issue the command it will return

There are a few paths in the lpfc_queuecommand that can result in the function returning without setting the cmnd->host_scribble, see snippet of lpfc_queuecommand below.  Is there any chance that the command that ends up in the abort handler was returned from lpfc_queuecommand without the host_scribble field being set?  If so, should the abort handler be able to handle this condition?

	err = fc_remote_port_chkready(rport);
	if (err) {
		cmnd->result = err;
		sdev = cmnd->device;
		if ((phba->link_state == LPFC_HBA_ERROR) &&
			(cmnd->result == ScsiResult(DID_NO_CONNECT, 0)) &&
			(sdev->queue_depth != 1)) {

			/* If we reach this point, the HBA is not responding
			 * and has been taken offline. If alot of SCSI IO
			 * was active, this could cause a massive amount of
			 * SCSI layer initiated logging. On some systems,
			 * this massive amount of logging has been known to
			 * cause CPU soft lockups. In an attempt to throttle
			 * the amount of logging, set the sdev queue depth to 1.
			 */
			if (sdev->ordered_tags)
				scsi_adjust_queue_depth(sdev,
					MSG_ORDERED_TAG, 1);
			else
				scsi_adjust_queue_depth(sdev,
					MSG_SIMPLE_TAG, 1);
		}
		goto out_fail_command;
	}
	ndlp = rdata->pnode;

	/*
	 * Catch race where our node has transitioned, but the
	 * transport is still transitioning.
	 */
	if (!ndlp || !NLP_CHK_NODE_ACT(ndlp)) {
		cmnd->result = ScsiResult(DID_TRANSPORT_DISRUPTED, 0);
		goto out_fail_command;
	}
	if (vport->cfg_max_scsicmpl_time &&
		(atomic_read(&ndlp->cmd_pending) >= ndlp->cmd_qdepth))
		goto out_host_busy;

	lpfc_cmd = lpfc_get_scsi_buf(phba);
	if (lpfc_cmd == NULL) {
		lpfc_rampdown_queue_depth(phba);

		lpfc_printf_vlog(vport, KERN_INFO, LOG_FCP,
				 "0707 driver's buffer pool is empty, "
				 "IO busied\n");
		goto out_host_busy;
	}

	/*
	 * Store the midlayer's command structure for the completion phase
	 * and complete the command initialization.
	 */
	lpfc_cmd->pCmd  = cmnd;
	lpfc_cmd->rdata = rdata;
	lpfc_cmd->timeout = 0;
	lpfc_cmd->start_time = jiffies;
	cmnd->host_scribble = (unsigned char *)lpfc_cmd;

(In reply to comment #5)
> 1) Is it possible to attach the /var/log/messages file associated with this
> BUG_ON?
> 

I can try that. But this is highly intermittent - I've just hit this once so far in my tests.

(In reply to comment #6)
> (In reply to comment #5)
> > 1) Is it possible to attach the /var/log/messages file associated with this
> > BUG_ON?
> > 
> 
> I can try that. But this is highly intermittent - I've just hit this once so
> far in my tests.

Is it possible to configure kdump (and test the kdump configuration under load
esp. if boot from SAN) while running the scenario that induced this problem?

A dump file would provide much information valuable to diagnosing this problem.

Hit a similar bug on RHEL6 described at bug 633231

Created attachment 452159 [details]
Patch for 624393

(In reply to comment #10)
> Created attachment 452159 [details]
> Patch for 624393

Was this patch tested after the problem was reproduced reliably or were some other means used to confirm its legitimacy?

(In reply to comment #10)
> Created attachment 452159 [details]
> Patch for 624393

Not hit the panic so far in our tests with the above patch.

Is this patch being queued for the next 5.5.z release?

(In reply to comment #15)
> Is this patch being queued for the next 5.5.z release?

Yes, but still in progress.

(In reply to comment #11)
> (In reply to comment #10)
> > Created attachment 452159 [details] [details]
> > Patch for 624393
> 
> Was this patch tested after the problem was reproduced reliably or were some
> other means used to confirm its legitimacy?

(In reply to comment #12)
> (In reply to comment #10)
> > Created attachment 452159 [details] [details]
> > Patch for 624393
> 
> Not hit the panic so far in our tests with the above patch.

Clearing needinfo due to patch being part of rhel5.6 update, and testing results by Martin George.

Thanks, Rob

Miroslav, this is a 5.5.z targeted bugzilla that contains a discrete patch from a wholesale driver update in bug 639028.

Closing this bugzilla as a dupe of 639028, and then will request z-stream from there with the specific patch.

*** This bug has been marked as a duplicate of bug 639028 ***