Re: CmdSN greather than MaxCmdSN protocol error in LIO Iser

[Mike Christie <michaelc@cs.wisc.edu>]

On 11/11/13 10:34 PM, Nicholas A. Bellinger wrote:
> On Mon, 2013-11-11 at 20:39 -0600, Michael Christie wrote:
>>
>>> On Nov 11, 2013, at 8:32 PM, Michael Christie <michaelc@cs.wisc.edu> wrote:
>>>
>
> <SNIP>
>
>>>>>>> Mike, any idea as to how this might be happening on the initiator
>>>>>>> side..?
>>>>
>>>> <SNIP>
>>>>
>>>> Mmmmm, just noticed a bit of very suspicious logic in open-iscsi.
>>>> (CC'ing linux-scsi)
>>>>
>>>> Namely, how drivers/scsi/libiscsi.c:iscsi_data_xmit() attempts to drain
>>>> conn->cmdqueue and hence call iscsi_prep_scsi_cmd_pdu() + increment
>>>> session->cmdsn, without ever checking to see if the CmdSN window may
>>>> have already closed..
>>>>
>>>> The only CmdSN window check that I see in the I/O dispatch codepath is
>>>> in iscsi_queuecommand() -> iscsi_check_cmdsn_window_closed(), but once
>>>> iscsi_conn_queue_work() is invoked and process context in
>>>> iscsi_xmitworker() -> iscsi_data_xmit() starts to execute, there is
>>>> AFAICT no further CmdSN window open checks to ensure the initiator does
>>>> not overflow MaxCmdSN..
>>>>
>>>> This would very much line up with the type of bug that is being
>>>> reported.  Before trying to determine what a possible fix might look
>>>> like, can you try the following libiscsi patch to see if your able to
>>>> hit either of the BUG's below..?
>>>>
>>>> Thanks,
>>>>
>>>> --nab
>>>>
>>>> diff --git a/drivers/scsi/libiscsi.c b/drivers/scsi/libiscsi.c
>>>> index e399561..9106f63 100644
>>>> --- a/drivers/scsi/libiscsi.c
>>>> +++ b/drivers/scsi/libiscsi.c
>>>> @@ -1483,6 +1483,12 @@ check_mgmt:
>>>>                        fail_scsi_task(conn->task, DID_IMM_RETRY);
>>>>                        continue;
>>>>                }
>>>> +
>>>> +               if (iscsi_check_cmdsn_window_closed(conn)) {
>>>> +                       printk("CmdSN window already closed in iscsi_data_xmit #1\n");
>>>> +                       BUG();
>>>> +               }
>>>> +
>>>>                rc = iscsi_prep_scsi_cmd_pdu(conn->task);
>>>>                if (rc) {
>>>>                        if (rc == -ENOMEM || rc == -EACCES) {
>>>> @@ -1518,6 +1524,11 @@ check_mgmt:
>>>>                if (iscsi_check_tmf_restrictions(task, ISCSI_OP_SCSI_DATA_OUT))
>>>>                        break;
>>>>
>>>> +               if (iscsi_check_cmdsn_window_closed(conn)) {
>>>> +                       printk("CmdSN window already closed in iscsi_data_xmit #2\n");
>>>> +                       BUG();
>>>> +               }
>>>> +
>>>>                conn->task = task;
>>>>                list_del_init(&conn->task->running);
>>>>                conn->task->state = ISCSI_TASK_RUNNING;
>>>
>>> If you hit a bug there then it is probably the target or if you are
>> using the new libiscsi back/frwd lock patches it could be related to
>> them.
>
> FYI, this is with v3.11 and RHEL 6.x open-iscsi code..
>
>> We should not need to check above because we never queue more cmds
>> from the scsi layer than the window will allow at the time. If the
>> window is 10, the queued_cmdsn check should make sure we have only
>> accepted 10 commands into the iscsi layer so we should not need to
>> recheck above.
>>>
>>> You should just enable libiscsi debug printk in
>> iscsi_check_cmdsn_window so we can see the sn related values at the
>> time of queuing. You should enable that printk whithout your patch.
>>
>> Actually that will not help because we always have the queued cmdsn
>> lower than the max in that path. I would do your patch but then also
>> print the queued cmdsn, cmdsn and also the maxcmdsn in the check
>> function.
>>
>>
>
> Yes, notice the second test patch is doing the explicit check of
> task->cmdsn vs. sess->max_cmdsn, instead of the one that checks
> ->queued_cmdsn vs. ->max_cmdsn in iscsi_check_cmdsn_window_closed().
>
> Btw, I'm surmising the bug in question does not happen from the
> iscsi_queuecommand() submission path, but rather from the
> iscsi_update_cmdsn() -> __iscsi_update_cmdsn() completion path, where
> iscsi_conn_queue_work() gets called when the CmdSN window was
> previously closed, eg:
>
>          if (max_cmdsn != session->max_cmdsn &&
>              !iscsi_sna_lt(max_cmdsn, session->max_cmdsn)) {
>                  session->max_cmdsn = max_cmdsn;
>                  /*
>                   * if the window closed with IO queued, then kick the
>                   * xmit thread
>                   */
>                  if (!list_empty(&session->leadconn->cmdqueue) ||
>                      !list_empty(&session->leadconn->mgmtqueue))
>                          iscsi_conn_queue_work(session->leadconn);
>          }
> }
>
> Once iscsi_conn_queue_work() is invoked here to start process context
> execution of iscsi_xmitworker() -> iscsi_data_xmit() code, AFAICT there
> is no logic in place within iscsi_data_xmit() to honor the last received
> MaxCmdSN.
>
> Or to put it another way: what is preventing iscsi_data_xmit() from
> completely draining both conn->cmdqueue + conn->requeue, even when the
> CmdSN window has potentially been closed again..?
>

If the window was not big enough we would have not accepted the cmd from 
scsi-ml in iscsi_queuecommand. We would have never put it on the list 
above then.

In the initiator we have:

session->queued_cmdsn - It will always be less than or equal to the 
max_cmdsn, but greater than or equal to session->cmdsn. Think of it like 
preallocating the sn we are going to give the cmd. Depending on ordering 
it might be different (3 instead of 4), but the final value it gets will 
be less than the max_cmdsn.

session->cmdsn - the sn we give the cmd when we actually put it on the 
wire. It is always less than or equal to queued_cmdsn.

So we have cmdsn <= queued_cmdsn <= max_cmdsn.

The iscsi_queuecommand window check makes sure we will only have put a 
cmd on the cmdqueue list if queued_cmdsn was less than or equal to the 
max_cmdsn. And cmdsn is less than or equal to queued_cmdsn, so we can 
run iscsi_data_xmit without checking the window values again, because it 
is not possible for something like max_cmdsn to decrease on us.