Hi again Mike,
I'd like to update you on this topic.
The short story is that it probably isn't an infinite loop in
"scsi_sequential_lun_scan". I can't "prove" that it is or isn't in the scsi or
iscsi layer, so please decide based on your own judgment if you'd like to take
part in the investigation. Obviously I'd be glad to hear from you. :)
Evidence:
1)
I added printk's to scsi_sequential_lun_scan:
{{{
static void scsi_sequential_lun_scan(struct scsi_target *starget,
int bflags, int scsi_level, int rescan)
{
...
printk(KERN_INFO "caley debug: scsi scan: Sequential scan of"
"%s, max_dev_lun=%d, bflags=%d\n",
dev_name(&starget->dev), max_dev_lun, bflags);
...
for (lun = 1; lun < max_dev_lun; ++lun)
{
probe_result = scsi_probe_and_add_lun(starget, lun, NULL, NULL,
rescan, NULL);
printk(KERN_INFO "caley debug: scsi_probe_and_add_lun (lun=%d,
rescan=%d) = %d", lun, rescan, probe_result);
if ((probe_result != SCSI_SCAN_LUN_PRESENT) &&
!sparse_lun)
return;
}
}}}
And the output after a run is 2 of these prints:
caley debug: scsi scan: Sequential scan oftarget0:0:0, max_dev_lun=1,
bflags=0
Showing that the "for" loop that was expected to be infinite - doesn't run at
all (!!)
2)
Here is part of a core dump, giving us the stack trace of the (probably) stuck
iscsiadm process, while it is stuck:
{
#6 [ffff880094b6f8d0] memcpy at ffffffff8127d0b0
/emc/krnl/kernels/linux-3.0.56/arch/x86/lib/memcpy_64.S: 159
#7 [ffff880094b6f8d0] vsnprintf at ffffffff8127b997
/emc/krnl/kernels/linux-3.0.56/lib/vsprintf.c: 1202
#8 [ffff880094b6f940] kvasprintf at ffffffff8127ebae
/emc/krnl/kernels/linux-3.0.56/lib/kasprintf.c: 31
#9 [ffff880094b6f990] kobject_set_name_vargs at ffffffff81273fcd
/emc/krnl/kernels/linux-3.0.56/lib/kobject.c: 225
#10 [ffff880094b6f9b0] dev_set_name at ffffffff812dca69
/emc/krnl/kernels/linux-3.0.56/drivers/base/core.c: 814
#11 [ffff880094b6fa90] scsi_sysfs_device_initialize at ffffffff81310c18
/emc/krnl/kernels/linux-3.0.56/drivers/scsi/scsi_sysfs.c: 1082
#12 [ffff880094b6fad0] scsi_alloc_sdev at ffffffff8130dc62
/emc/krnl/kernels/linux-3.0.56/drivers/scsi/scsi_scan.c: 306
#13 [ffff880094b6fb10] scsi_probe_and_add_lun at ffffffff8130e82d
/emc/krnl/kernels/linux-3.0.56/drivers/scsi/scsi_scan.c: 1044
#14 [ffff880094b6fc40] __scsi_scan_target at ffffffff8130f168
/emc/krnl/kernels/linux-3.0.56/drivers/scsi/scsi_scan.c: 1224
#15 [ffff880094b6fd30] scsi_scan_target at ffffffff8130fa28
/emc/krnl/kernels/linux-3.0.56/drivers/scsi/scsi_scan.c: 1650
#16 [ffff880094b6fd70] iscsi_user_scan_session at ffffffffa00111b6
[scsi_transport_iscsi]
}
My point in this stack is that "scsi_sequential_lun_scan" is not called at all.
"scsi_probe_and_add_lun" is called directly from "__scsi_scan_target".
Later I also added some print in " scsi_probe_and_add_lun" and it is definitely
not called ~infinit'ish times. I can also say that every time it started to
run, it finished running.
Do you agree that this rules out the scsi layer bug? Where would you continue
to investigate? Do you have another guess regarding where the bug is hiding?
Any thoughts are most welcome.
Yonatan
-----Original Message-----
From: Mike Christie [mailto:[email protected]]
Sent: Tuesday, April 29, 2014 7:47 PM
To: [email protected]
Cc: Cale, Yonatan; [email protected]
Subject: Re: Target reboot -> iscsiadm rescan Stuck
On 04/29/2014 09:02 AM, Cale, Yonatan wrote:
> Hi,
> I understand this problem is probably unrelated to your product, so
> you're not supposed to start debugging it, that makes sense (and also makes
> me sad :P ) So first of all thank you (and fusion-io) for sitting with me on
> this so far, it's not something trivial for me to expect.
> I'd like to understand your iscsi-related analysis so far, so that I can
> continue the investigation by myself, if that's ok.
> So:
> You assume that an unanswered "report LUNs" that was sent from the scsi layer
> -> caused the scsi layer to inquiry each of the ~infinite possible LUNs
> separately.
Yes. In the logs we see:
Apr 24 10:31:04 rp kernel: session1: iscsi_prep_scsi_cmd_pdu iscsi prep [read
cid 0 sc ffff880138c37800 cdb 0xa0 itt 0x40 len 131080 bidi_len 0 cmdsn 2844
win 255]
The cdb indicates this is a REPORT_LUNs command.
Apr 24 10:31:11 rp kernel: session1: iscsi_eh_cmd_timed_out scsi cmd
ffff880138c37800 timedout
We then see the scsi command timeout has expired. The scsi layer is calling
into the drivers timeout handler function.
Apr 24 10:31:14 rp kernel: connection1:0: detected conn error (1011)
For some reason we lost the tcp connection.
Apr 24 10:33:15 rp kernel: session1: session recovery timed out after
120 secs
We could not log back into the target, and the replacement/recovery timeout
fired, so we are now going to fail all IO. This means the REPORT_LUNs we were
trying to execute is going to be failed and all new IO will be failed.
Apr 24 10:33:15 rp kernel: session1: iscsi_queuecommand iscsi: cmd 0xa0 is not
queued (983040)
Here is where the scsi layer gets stuck and just starts sending endless
inquirys. Because the recovery/replacement timeout expired we fail everything
with DID_TRANSPORT_FAILFAST.
In the logs, we sometimes see slightly different patterns where when the
command times out, we might get a little farther in the scsi eh process and the
device might get offlined by the scsi layer, then we hit the endless inquirys.
> -Can you tell me what "iscsiadm" calls - that is getting stuck? For example,
> are you calling "report LUNs" that the scsi layer is refusing to answer?
>
When you run the iscsiadm rescan command, iscsiadm just does
echo - - - > /sys/class/scsi_host/hostX/scan
This ends up calling
linux-kernel-source/drivers/scsi/scsi_scan.c:scan_target(). And here in
__scsi_scan_target we see that scsi-ml will try a scsi_report_lun_scan(). If
that fails then it drops down to scsi_sequential_lun_scan(). That function is
just a loop that does scsi_probe_and_add_lun where probing is just sending a
inquiry for every possible LUN from 1 to max_lun which for iscsi_tcp is the max
unsigned int.
-In the "messages_end" log I sent you, it has ~infinite "session1:
iscsi_queuecommand iscsi: cmd 0x12 is not queued" prints. What is this?
Is this related to the scsi layer querying all LUNs as you suggested?
(If not then why do you think the problem is in the scsi layer?)
>
See above. Does it make sense? If not let me know.
> In other words, I'm asking what's going on right over the scsi layer (with
> iscsiadm) and just below the scsi layer (iscsi layer), both are components
> that you probably know well - so that I can be on-target with my continued
> investigation.
>
> So thanks again, and wish me luck
> :)
Good luck. I am pretty sure it is the scan issue I described, so you should be
ok. It will be a good first step into open source and sending patches upstream.
If you look in scsi_report_lun_scan(), check out:
if (result) {
/*
* The device probably does not support a REPORT LUN command
*/
ret = 1;
goto out_err;
}
I think instead of always assuming that for any old result value, we might want
to check for specific values. Just add a printk to print the result value. It
is probably DID_TRANSPORT_FAILFAST or DID_TRANSPORT_DISRUPTED or DID_NO_CONNECT.
You probably also want to see if in the cases it works if the REPORT_LUNs is
successful, or if the iscsi layer is figuring out the session is bad before you
do the rescan command.
> Yonatan
>
> -----Original Message-----
> From: Mike Christie [mailto:[email protected]]
> Sent: Monday, April 28, 2014 4:11 AM
> To: Cale, Yonatan
> Cc: [email protected]; [email protected]
> Subject: Re: Target reboot -> iscsiadm rescan Stuck
>
> On 4/27/14, 10:38 AM, Cale, Yonatan wrote:
>> Hi,
>> Our sim module is above the scsi layer (not between the iscsi&scsi layers),
>> so I think this already rules out this guess.
>>
>> What we do is something like this:
>> -Send scsi command
>> -If we didn't get a response after X seconds, --Abort the command
>> (perhaps many times, if the abort fails)
>>
>> So.. We add some prints somewhere new?
>>
>
> I should have written *you* have to add some printks in the scsi/block
> layer :) As iscsi maintainer I am happy to help all vendors on iscsi
> related issue as you have seen in this thread, but I work for
> Fusion-io on their FC/SRP/iSCSI target, ION, so I do not have time to
> debug all kernel layers for a multi-billion dollar company like EMC :)
>
> If I hit this problem with our product, I would look over the scsi scan code
> since we see those commands time out. I would look at the scsi scan code and
> see how it handled time out failures for report luns and inquirys.
>
> Probably what the problem is, is that scsi layer tried to send a report luns,
> that timedout due to your target not responding for whatever reason, the scsi
> layer handled that by thinking that it failed because target does not support
> report luns and not due it just timing out, and scsi layer dropped down to a
> sequential scan as a result. So all those inquirys in the logs are not
> retries but instead the scsi layer trying to see if a lu is behind lun0,
> lun1, lun2....... lun(N = MAX_UNSIGNED_INT).
>
> If that is not the problem, I would add debug code to the
> scsi_request_fn/scsi_dispatch_cmd and
> scsi_done/scsi_softirq_done/scsi_decide_disposition/scsi_finish_comman
> d/scsi_io_completion to see why those inquirys are retried when they
> should be failed.
>
>
>> I'd like to say again, that this bug happens with one version of VNX but not
>> with another version. Do you think that might give us a hint?
>>
>
> Yes. I would guess your other VNX versions reply to the scsi scan related IO,
> so we do not fall into this problem where the scsi scan IO timedout, and IO
> is now endlessly retried or we drop down a sequential scan. Again, if I
> worked for EMC, I would have compared the logs for different versions to see
> what behavior changed.
>
> Hope this helps. If you have even the slightest hunch it is a iscsi code
> problem come back and bug me, because I really do not care what vendor you
> are from when fixing iscsi bugs.
>
>
>
>
>> -----Original Message-----
>> From: Mike Christie [mailto:[email protected]]
>> Sent: Thursday, April 24, 2014 10:04 PM
>> To: Cale, Yonatan
>> Cc: [email protected]; [email protected]
>> Subject: Re: Target reboot -> iscsiadm rescan Stuck
>>
>> On 04/22/2014 04:10 AM, Cale, Yonatan wrote:
>>> -----Original Message-----
>>> From: Mike Christie [mailto:[email protected]]
>>> Sent: Tuesday, April 22, 2014 12:38 AM
>>> To: Cale, Yonatan
>>> Cc: [email protected]; [email protected]
>>> Subject: Re: Target reboot -> iscsiadm rescan Stuck
>>>
>>>> Do you have some module that is hooking into the scsi layer or iscsi
>>>> modules? Just wondering what the "sim_try_to_abort_cmd" call is. Where are
>>>> you hooking in?
>>> "sim" is our module that handles iscsi data-path. We hook for
>>> notifications in order to know if we should cancel a command
>>
>>
>> Hey, does your sim module that handles the data path just monitor or
>> do you handle error codes that the iscsi modules returns. The problem
>> is that the iscsi layer is trying to fail a scsi scan related
>> command, but whatever layer is above it (I thought it was just the
>> scsi layer like normal in my other response) just keeps retrying it.
>> Does your module do anything to IO failed with
>>
>> #define DID_TRANSPORT_FAILFAST 0x0f /* Transport class fastfailed
>> the io */
>>
>> from the queuecommand path? Is it the one forcing the retry? That would
>> explain why we do not see anything from the scsi scan layer debug printks.
>>
>> If not, then it is the scsi or block layer and we will have to add some
>> printks in there.
>>
>>
>
>
--
You received this message because you are subscribed to the Google Groups
"open-iscsi" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To post to this group, send email to [email protected].
Visit this group at http://groups.google.com/group/open-iscsi.
For more options, visit https://groups.google.com/d/optout.
