Re: [Scst-devel] iSCSI svn-rev668 issue

[Vladislav B. <vs...@vl...>]

sdrb, on 02/12/2009 01:05 PM wrote:
> Vladislav Bolkhovitin wrote:
>> sdrb, on 02/12/2009 09:49 AM wrote:
>>> Vladislav Bolkhovitin wrote:
>>>> sdrb, on 02/11/2009 03:03 PM wrote:
>>>>> Vladislav Bolkhovitin wrote:
>>>>>> Hello,
>>>>>>
>>>>>> sdrb, on 02/11/2009 11:59 AM wrote:
>>>>>>> Hello,
>>>>>>>
>>>>>>> Recently I've updated my svn trunk tree of iSCSI SCST to svn-rev 
>>>>>>> 668 and with this revision I cannot log into target. iSCSI 
>>>>>>> initiator complains about some errors. Below there are 2 
>>>>>>> invocations with and without debugging:
>>>>>>>
>>>>>>> ------------------
>>>>>>> # iscsiadm -m discovery -t sendtargets -p 192.168.0.2
>>>>>>>
>>>>>>> iscsiadm: discovery login to 192.168.0.2 rejected: initiator error 
>>>>>>> (02/00), non-retryable, giving up
>>>>>>>
>>>>>>>
>>>>>>> # iscsiadm -m discovery -t sendtargets -p 192.168.0.2 -d 8
>>>>>>>
>>>>>>> iscsiadm: Max file limits 1024 1024
>>>>>>>
>>>>>>> iscsiadm: updating defaults from '/etc/iscsi/iscsid.conf'
>>>>>>> iscsiadm: updated 
>>>>>>> 'discovery.sendtargets.iscsi.MaxRecvDataSegmentLength', '32768' => 
>>>>>>> '32768'
>>>>>>> iscsiadm: updated 'node.startup', 'manual' => 'automatic'
>>>>>>> iscsiadm: updated 'node.session.timeo.replacement_timeout', '120' 
>>>>>>> => '120'
>>>>>>> iscsiadm: updated 'node.conn[0].timeo.login_timeout', '30' => '15'
>>>>>>> iscsiadm: updated 'node.conn[0].timeo.logout_timeout', '15' => '15'
>>>>>>> iscsiadm: sending login PDU with current stage 1, next stage 3, 
>>>>>  >> (...)
>>>>>>> iscsiadm: >    DataPDUInOrder=Irrelevant
>>>>>>> iscsiadm: >    DataSequenceInOrder=Irrelevant
>>>>>>> iscsiadm: wrote 48 bytes of PDU header
>>>>>>> iscsiadm: wrote 164 bytes of PDU data
>>>>>>> iscsiadm: read 48 bytes of PDU header
>>>>>>> iscsiadm: read 48 PDU header bytes, opcode 0x23, dlength 0, data 
>>>>>>> 0x83ad430, max 32768
>>>>>>> iscsiadm: login response status 0200
>>>>>>> iscsiadm: discovery login to 192.168.0.2 rejected: initiator error 
>>>>>>> (02/00), non-retryable, giving up
>>>>>>> iscsiadm: disconnecting conn 0x83a8f38, fd 3
>>>>>>> -----------------
>>>>>>>
>>>>>>>
>>>>>>> I reverted for testing purpose changes in svn to revision 667.
>>>>>>> With this revision iSCSI allows to login to target, so it seems 
>>>>>>> like "iscsi-scstd" from svn r667 works good but r668 contains some 
>>>>>>> bug.
>>>>>> Are you sure this is r668? This revision contains only white space 
>>>>>> like cleanups and functionally identical to r667. There must be 
>>>>>> something other involved. Like you forgot to start target daemon 
>>>>>> for r667, or it suddenly died. Please recheck.
>>>>> Ok, I've rechecked it again and it seems like it is not r668. That 
>>>>> what I did is to recompiling user-space "iscsi-scstd" for three 
>>>>> revisions: r666, r667 and r668. The kernel modules I've tested comes 
>>>>> from r668. The only difference in testing between those 3 revisions 
>>>>> was "iscsi-scstd". I don't know why earlier "iscsi-scstd" worked on 
>>>>> r667. Now only r666 of "iscsi-scstd" is working fine and r667 
>>>>> doesn't - so probably the problem lies in r667. Seem like I forget 
>>>>> to do "make clean".
>>>>>
>>>>>
>>>>>> What was in the system and kernel logs on the target?
>>>>> I haven't seen any suspicious messages:
>>>>>
>>>>> [17921]: scst_suspend_activity:553:Waiting for 0 active commands 
>>>>> finally to complete
>>>>> [17921]: scst_susp_wait:487:wait_event() returned 0
>>>>> [17921]: __scst_resume_activity:584:suspend_count 0 left
>>>>> [17921]: scst: scst_register:376:Target iqn.scst:storage (f58da7c0) 
>>>>> for template iscsi registered successfully
>>>>> [17921]: iscsi-scst: release:534:Releasing allocated resources
>>>>> [17921]: target_del_all:266:Deleting all targets
>>>>> [17921]: target_del_all:282:Deleting target f6af0000
>>>>> [17921]: target_destroy:175:Destroying target tid 58
>>>>> [17921]: scst_suspend_activity:508:suspend_count 0
>>>>> [17921]: scst_susp_wait:487:wait_event() returned 0
>>>>> [17921]: scst_suspend_activity:553:Waiting for 0 active commands 
>>>>> finally to complete
>>>>> [17921]: scst_susp_wait:487:wait_event() returned 0
>>>>> [17921]: __scst_resume_activity:584:suspend_count 0 left
>>>>> [17921]: scst: scst_unregister:458:Target f58da7c0 for template 
>>>>> iscsi unregistered successfully
>>>>> [17921]: target_del_all:296:Deleting all targets finished
>>>>> [17997]: iscsi_target_create:88:Creating target tid 59, name 
>>>>> iqn.scst:storage
>>>>> [17997]: scst_suspend_activity:508:suspend_count 0
>>>>> [17997]: scst_susp_wait:487:wait_event() returned 0
>>>>> [17997]: scst_suspend_activity:553:Waiting for 0 active commands 
>>>>> finally to complete
>>>>> [17997]: scst_susp_wait:487:wait_event() returned 0
>>>>> [17997]: __scst_resume_activity:584:suspend_count 0 left
>>>>> [17997]: scst: scst_register:376:Target iqn.scst:storage (edeae3c0) 
>>>>> for template iscsi registered successfully
>>>> What's in the system log, where iscsi-scstd sends its logs?
>>> Here there are logs from iscsi-scstd invoked as follows:
>>>
>>> iscsi-scstd -a 0.0.0.0 -d16:
>> Is it when the connection failed?
> 
> Yes, the "iscsi-scstd" generates those logs on target side while I get 
> error:
> 
> "iscsiadm: discovery login to 192.168.0.2 rejected: initiator error 
> (02/00), non-retryable, giving up"
> 
> on the initiator side.
> 
> I wonder why I get this error on initiator side. Maybe I'm doing 
> something wrong?

This is what we should find out.

So, please:

1. Update to the latest open-iscsi

2. Reboot both initiator and target

3. Reproduce the problem. Capture the connection dump using wireshark, 
tcpdump or any similar tool.

4. Save both kernel and system logs since reboot.

5. Clear both system and kernel logs.

6. Reproduce the normal login. Capture the connection dump.

7. Save both kernel and system logs.

8. Send me what what you got in 3, 4, 6, 7 (privately).

Thanks,
Vlad