infinite loop with 36 Byte inquiry (sbp2 regression in 2.6.14-rcX)

infinite loop with 36 Byte inquiry (sbp2 regression in 2.6.14-rcX)

[Stefan Richter]

Hi all,

I just noticed that devices which require sbp2's inquiry hack are not 
usable anymore. I don't know when the regression crept in since I don't 
remember when I used the affected device successfully the last time. One 
thing is for sure: The code change which triggered the regression took 
not place in sbp2 itself.

The device in question is an older 2.5" FireWire disk, DViCO Momobay 
CX-1. What happens under Linux 2.6.14-rc5 is this: Without debug logging 
turned on, it seems as if the process which started the sbp2 probe 
(knodemgrd or modprobe) is hanging in D state. But debug logging enabled 
in sbp2 reveals that it isn't locked up but rather caught in a loop, 
sending inquiry commands:

> Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_module_init
> Oct 23 01:26:59 shuttle kernel: sbp2: $Rev: 1306 $ Ben Collins <bcollins@debian.org>
> Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_probe
> Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_alloc_device
> Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_alloc_device: allocated hostinfo
> Oct 23 01:26:59 shuttle kernel: scsi0 : SCSI emulation for IEEE-1394 SBP-2 Devices
> Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_parse_unit_directory
> Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_management_agent_addr = f0010000
> Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_unit_characteristics = a08
> Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_command_set_spec_id = 609e
> Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_command_set = 104d8
> Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_firmware_revision = 2800
> Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: Node 1-01:1023: Using 36byte inquiry workaround

Note: The following also happens if sbp2's inquiry blacklist is 
commented out, i.e. if sbp2 does _not_ enable its own inquiry mangling.

> Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_start_device
> Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: New SBP-2 device inserted, SCSI ID = 0
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_login_device
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_login_device: password_hi/lo initialized
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_login_device: login_response_hi/lo initialized
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_query_logins: set lun to 0
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_login_device: lun_misc initialized
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_login_device: passwd_resp_lengths initialized
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_login_device: status FIFO initialized
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_login_device: orb byte-swapped
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_login_device: login_response/status FIFO memset
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_login_device: prepared to write to f0010000
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_login_device: written
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_handle_status_write
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: command_block_agent_hi = ffc1ffff
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: command_block_agent_lo = f0010020
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Logged into SBP-2 device
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_set_busy_timeout
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_agent_reset
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_max_speed_and_size
> Oct 23 01:27:00 shuttle kernel: ieee1394: Node 1-01:1023: Max speed [S400] - Max payload [2048]
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2scsi_queuecommand
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_send_command
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: SCSI transfer size = 24
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: SCSI s/g elements = 1
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Use scatter/gather
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Only one s/g element
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_check_sbp2_command
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_handle_status_write
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Found status for command ORB
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Completing SCSI command
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2scsi_complete_command
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_check_sbp2_response
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2scsi_queuecommand
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_send_command
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: SCSI transfer size = 25
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: SCSI s/g elements = 1
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Use scatter/gather
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Only one s/g element
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_check_sbp2_command
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_handle_status_write
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Found status for command ORB
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: CHECK CONDITION
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_status_to_sense_data
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Completing SCSI command
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2scsi_complete_command
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: SBP2_SCSI_STATUS_CHECK_CONDITION
> Oct 23 01:27:00 shuttle kernel: scsi0 : destination target 0, lun 0
> Oct 23 01:27:00 shuttle kernel:         command: Inquiry: 12 00 00 00 24 00
> Oct 23 01:27:00 shuttle kernel: bh: Current: sense key: Unit Attention
> Oct 23 01:27:00 shuttle kernel:     Additional sense: Invalid field in cdb
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2scsi_queuecommand
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_send_command
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: SCSI transfer size = 25
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: SCSI s/g elements = 1
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Use scatter/gather
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Only one s/g element
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_check_sbp2_command
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_handle_status_write
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Found status for command ORB
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: CHECK CONDITION
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_status_to_sense_data
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Completing SCSI command
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2scsi_complete_command
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: SBP2_SCSI_STATUS_CHECK_CONDITION
> Oct 23 01:27:00 shuttle kernel: scsi0 : destination target 0, lun 0
> Oct 23 01:27:00 shuttle kernel:         command: Inquiry: 12 00 00 00 24 00
> Oct 23 01:27:00 shuttle kernel: bh: Current: sense key: Unit Attention
> Oct 23 01:27:00 shuttle kernel:     Additional sense: Invalid field in cdb
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2scsi_queuecommand
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_send_command
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: SCSI transfer size = 25
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: SCSI s/g elements = 1
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Use scatter/gather
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Only one s/g element
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_check_sbp2_command
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_handle_status_write
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Found status for command ORB
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: CHECK CONDITION
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2_status_to_sense_data
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: Completing SCSI command
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: sbp2scsi_complete_command
> Oct 23 01:27:00 shuttle kernel: ieee1394: sbp2: SBP2_SCSI_STATUS_CHECK_CONDITION
> Oct 23 01:27:00 shuttle kernel: scsi0 : destination target 0, lun 0
> Oct 23 01:27:00 shuttle kernel:         command: Inquiry: 12 00 00 00 24 00
> Oct 23 01:27:00 shuttle kernel: bh: Current: sense key: Unit Attention
> Oct 23 01:27:00 shuttle kernel:     Additional sense: Invalid field in cdb

The inquiry is repeated endlessly, until the drive is physically plugged 
out. The process which entered into this (knodemgrd or modprobe) becomes 
responsive again after that:

> Oct 23 01:27:07 shuttle kernel: ieee1394: Node changed: 1-02:1023 -> 1-01:1023
> Oct 23 01:27:07 shuttle kernel: ieee1394: Node suspended: ID:BUS[1-01:1023]  GUID[0001041010004beb]
> Oct 23 01:27:12 shuttle kernel: ieee1394: sbp2: aborting sbp2 command
> Oct 23 01:27:12 shuttle kernel: scsi0 : destination target 0, lun 0
> Oct 23 01:27:12 shuttle kernel:         command: Inquiry: 12 00 00 00 24 00
> Oct 23 01:27:12 shuttle kernel: ieee1394: sbp2: sbp2scsi_queuecommand
> Oct 23 01:27:12 shuttle kernel: ieee1394: sbp2: reset requested
> Oct 23 01:27:12 shuttle kernel: ieee1394: sbp2: sbp2scsi_queuecommand
> Oct 23 01:27:12 shuttle kernel: ieee1394: sbp2: reset requested
> Oct 23 01:27:22 shuttle kernel: ieee1394: sbp2: sbp2scsi_queuecommand
> Oct 23 01:27:22 shuttle kernel: ieee1394: sbp2: reset requested
> Oct 23 01:27:32 shuttle kernel: ieee1394: sbp2: sbp2scsi_queuecommand
> Oct 23 01:27:32 shuttle kernel: scsi: Device offlined - not ready after error recovery: host 0 channel 0 id 0 lun 0
> Oct 23 01:27:32 shuttle kernel: scsi scan: 37 byte inquiry failed.  Consider BLIST_INQUIRY_36 for this device
> Oct 23 01:27:32 shuttle kernel: scsi0 (0:0): rejecting I/O to offline device
> Oct 23 01:27:32 shuttle kernel: ieee1394: sbp2: scsi_add_device failed

The inquiry obviously comes from scsi_add_device() -> 
scsi_probe_and_add_lun() -> scsi_probe_lun().

Here is all what sbp2's inquiry hack does:

static int sbp2_send_command(struct scsi_id_instance_data *scsi_id,
			     struct scsi_cmnd *SCpnt,
			     void (*done)(struct scsi_cmnd *))
{
	unchar *cmd = (unchar *) SCpnt->cmnd;
	unsigned int request_bufflen = SCpnt->request_bufflen;
[...]
	if (*cmd == INQUIRY) {
		if (force_inquiry_hack || scsi_id->workarounds &
         	    SBP2_BREAKAGE_INQUIRY_HACK)
			request_bufflen = cmd[4] = 0x24;
		else
			request_bufflen = cmd[4];
	}
	sbp2_create_command_orb(scsi_id, command, cmd, SCpnt->use_sg,
				request_bufflen, SCpnt->request_buffer,
				SCpnt->sc_data_direction);
[...]

As mentioned, the infinite inquiry command loop also happens if the 
inquiry hack is disabled, i.e. if the "else" branche of the above code 
is taken. Furthermore, the loop happens with or without RBC command set 
conversions being done in sbp2. (I discovered that while testing the old 
pending patch which cleanses sbp2 of those conversions.)

I stared intently at scsi_probe_lun() but did not discover yet how the 
infinite loop might happen. It's a bad hour to do such things.
-- 
Stefan Richter
-=====-=-=-= =-=- =-===
http://arcgraph.de/sr/

Re: infinite loop with 36 Byte inquiry (sbp2 regression in 2.6.14-rcX)

[Stefan Richter]

PS: The subject is a badly worded. The loop occurs with any type of 
inquiry, with a SBP-2 bridge's firmware which expects 36 Byte inquiry.
-- 
Stefan Richter
-=====-=-=-= =-=- =-===
http://arcgraph.de/sr/


-------------------------------------------------------
This SF.Net email is sponsored by the JBoss Inc.
Get Certified Today * Register for a JBoss Training Course
Free Certification Exam for All Training Attendees Through End of 2005
Visit http://www.jboss.com/services/certification for more information

Re: infinite loop with 36 Byte inquiry (sbp2 regression in 2.6.14-rcX)

[James Bottomley]

On Sun, 2005-10-23 at 02:33 +0200, Stefan Richter wrote:
> I just noticed that devices which require sbp2's inquiry hack are not 
> usable anymore. I don't know when the regression crept in since I don't 
> remember when I used the affected device successfully the last time. One 
> thing is for sure: The code change which triggered the regression took 
> not place in sbp2 itself.
> 
> The device in question is an older 2.5" FireWire disk, DViCO Momobay 
> CX-1. What happens under Linux 2.6.14-rc5 is this: Without debug logging 
> turned on, it seems as if the process which started the sbp2 probe 
> (knodemgrd or modprobe) is hanging in D state. But debug logging enabled 
> in sbp2 reveals that it isn't locked up but rather caught in a loop, 
> sending inquiry commands:
> 
> > Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_module_init
> > Oct 23 01:26:59 shuttle kernel: sbp2: $Rev: 1306 $ Ben Collins <bcollins@debian.org>
> > Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_probe
> > Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_alloc_device
> > Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_alloc_device: allocated hostinfo
> > Oct 23 01:26:59 shuttle kernel: scsi0 : SCSI emulation for IEEE-1394 SBP-2 Devices
> > Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_parse_unit_directory
> > Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_management_agent_addr = f0010000
> > Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_unit_characteristics = a08
> > Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_command_set_spec_id = 609e
> > Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_command_set = 104d8
> > Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_firmware_revision = 2800
> > Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: Node 1-01:1023: Using 36byte inquiry workaround

I don't see any looping in the traces, could you characterise what's
going on for those of us who haven't fully explored the sbp2 driver?

However, at a brief examination it looks like you do quite a lot of
response snooping.  This always was broken for commands from userspace,
but it's completely broken now we only use scatter/gather commands from
block.

Secondly, I don't think your inquiry hack is effective any more, because
you try to alter request_bufflen, which doesn't carry the length of a
s/g command.

We have a device flag: BLIST_INQUIRY_36 which restricts the named
devices only to having 36 byte inquiries sent.  Could your internal
table be migrated up to the mid-layer list to avoid the issue
altogether?

James


James

Re: infinite loop with 36 Byte inquiry (sbp2 regression in 2.6.14-rcX)

[Stefan Richter]

James Bottomley wrote:
> On Sun, 2005-10-23 at 02:33 +0200, Stefan Richter wrote:
> 
>>I just noticed that devices which require sbp2's inquiry hack are not 
>>usable anymore. I don't know when the regression crept in since I don't 
>>remember when I used the affected device successfully the last time. One 
>>thing is for sure: The code change which triggered the regression took 
>>not place in sbp2 itself.
>>
>>The device in question is an older 2.5" FireWire disk, DViCO Momobay 
>>CX-1. What happens under Linux 2.6.14-rc5 is this: Without debug logging 
>>turned on, it seems as if the process which started the sbp2 probe 
>>(knodemgrd or modprobe) is hanging in D state. But debug logging enabled 
>>in sbp2 reveals that it isn't locked up but rather caught in a loop, 
>>sending inquiry commands:
>>
>>
>>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_module_init
>>>Oct 23 01:26:59 shuttle kernel: sbp2: $Rev: 1306 $ Ben Collins <bcollins@debian.org>
>>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_probe
>>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_alloc_device
>>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_alloc_device: allocated hostinfo
>>>Oct 23 01:26:59 shuttle kernel: scsi0 : SCSI emulation for IEEE-1394 SBP-2 Devices
>>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_parse_unit_directory
>>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_management_agent_addr = f0010000
>>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_unit_characteristics = a08
>>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_command_set_spec_id = 609e
>>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_command_set = 104d8
>>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_firmware_revision = 2800
>>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: Node 1-01:1023: Using 36byte inquiry workaround
> 
> 
> I don't see any looping in the traces, could you characterise what's
> going on for those of us who haven't fully explored the sbp2 driver?

I cut the log. The portion

	kernel: ieee1394: sbp2: sbp2scsi_queuecommand
	[...]
	kernel: ieee1394: sbp2: SBP2_SCSI_STATUS_CHECK_CONDITION
	kernel: scsi0 : destination target 0, lun 0
	kernel:         command: Inquiry: 12 00 00 00 24 00
	kernel: bh: Current: sense key: Unit Attention

is repeated over and over. I would have digged deeper but ran out of time.
I will look further into it during the week.

> However, at a brief examination it looks like you do quite a lot of
> response snooping.  This always was broken for commands from userspace,
> but it's completely broken now we only use scatter/gather commands from
> block.
> 
> Secondly, I don't think your inquiry hack is effective any more, because
> you try to alter request_bufflen, which doesn't carry the length of a
> s/g command.
> 
> We have a device flag: BLIST_INQUIRY_36 which restricts the named
> devices only to having 36 byte inquiries sent.  Could your internal
> table be migrated up to the mid-layer list to avoid the issue
> altogether?

Yes, that would certainly be better.

But what about the note in scsi_devinfo.c?

  * Do not add to this list, use the command line or proc interface to add
  * to the scsi_dev_info_list. This table will eventually go away.

Thanks,
-- 
Stefan Richter
-=====-=-=-= =-=- ==---
http://arcgraph.de/sr/

Re: infinite loop with 36 Byte inquiry (sbp2 regression in 2.6.14-rcX)

[Stefan Richter]

James Bottomley wrote:
> However, at a brief examination it looks like you do quite a lot of
> response snooping.  This always was broken for commands from userspace,
> but it's completely broken now we only use scatter/gather commands from
> block.

BTW, a lot of the snooping and mangling in sbp2 was removed a while ago
by the RBC cache patch. The sbp2 portion of the patch was backed out
from mainline (but kept in the linux1394.org trunk) due to initial
stability issues. It will be merged soon.
-- 
Stefan Richter
-=====-=-=-= =-=- ==---
http://arcgraph.de/sr/

Re: infinite loop with 36 Byte inquiry (sbp2 regression in 2.6.14-rcX)

[James Bottomley]

On Mon, 2005-10-24 at 08:58 +0200, Stefan Richter wrote:
> James Bottomley wrote:
> > On Sun, 2005-10-23 at 02:33 +0200, Stefan Richter wrote:
> > 
> >>I just noticed that devices which require sbp2's inquiry hack are not 
> >>usable anymore. I don't know when the regression crept in since I don't 
> >>remember when I used the affected device successfully the last time. One 
> >>thing is for sure: The code change which triggered the regression took 
> >>not place in sbp2 itself.
> >>
> >>The device in question is an older 2.5" FireWire disk, DViCO Momobay 
> >>CX-1. What happens under Linux 2.6.14-rc5 is this: Without debug logging 
> >>turned on, it seems as if the process which started the sbp2 probe 
> >>(knodemgrd or modprobe) is hanging in D state. But debug logging enabled 
> >>in sbp2 reveals that it isn't locked up but rather caught in a loop, 
> >>sending inquiry commands:
> >>
> >>
> >>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_module_init
> >>>Oct 23 01:26:59 shuttle kernel: sbp2: $Rev: 1306 $ Ben Collins <bcollins@debian.org>
> >>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_probe
> >>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_alloc_device
> >>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_alloc_device: allocated hostinfo
> >>>Oct 23 01:26:59 shuttle kernel: scsi0 : SCSI emulation for IEEE-1394 SBP-2 Devices
> >>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_parse_unit_directory
> >>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_management_agent_addr = f0010000
> >>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_unit_characteristics = a08
> >>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_command_set_spec_id = 609e
> >>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_command_set = 104d8
> >>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: sbp2_firmware_revision = 2800
> >>>Oct 23 01:26:59 shuttle kernel: ieee1394: sbp2: Node 1-01:1023: Using 36byte inquiry workaround
> > 
> > 
> > I don't see any looping in the traces, could you characterise what's
> > going on for those of us who haven't fully explored the sbp2 driver?
> 
> I cut the log. The portion
> 
> 	kernel: ieee1394: sbp2: sbp2scsi_queuecommand
> 	[...]
> 	kernel: ieee1394: sbp2: SBP2_SCSI_STATUS_CHECK_CONDITION
> 	kernel: scsi0 : destination target 0, lun 0
> 	kernel:         command: Inquiry: 12 00 00 00 24 00
> 	kernel: bh: Current: sense key: Unit Attention
> 
> is repeated over and over. I would have digged deeper but ran out of time.
> I will look further into it during the week.

Like I said, I think that's because you send an orb to the device with a
command indicated length of 36 but a buffer length of 37

I don't see any loops in the lun probing routines.  For UNIT_ATTENTION
to inquiry, we should retry three times and then give up.  If you enable
debugging at the SCSI layer, that might give a better indication of
what's going on.

There's an #if 0 around an incorrect piece of code that would return
DID_BUS_BUSY in this condition, you don't have that enabled, do you?

DID_BUS_BUSY is a dangerous reply because it causes an immediate retry
without decrementing the retry count.  If you return it for a condition
that never clears, it used to cause a hang.  Now it should actually exit
the loop after the command times out (6 seconds, I think).

> > However, at a brief examination it looks like you do quite a lot of
> > response snooping.  This always was broken for commands from userspace,
> > but it's completely broken now we only use scatter/gather commands from
> > block.
> > 
> > Secondly, I don't think your inquiry hack is effective any more, because
> > you try to alter request_bufflen, which doesn't carry the length of a
> > s/g command.
> > 
> > We have a device flag: BLIST_INQUIRY_36 which restricts the named
> > devices only to having 36 byte inquiries sent.  Could your internal
> > table be migrated up to the mid-layer list to avoid the issue
> > altogether?
> 
> Yes, that would certainly be better.
> 
> But what about the note in scsi_devinfo.c?
> 
>   * Do not add to this list, use the command line or proc interface to add
>   * to the scsi_dev_info_list. This table will eventually go away.

That was put in when we vainly hoped we could move the exception tables
up to user level.  No distribution ever managed to do that, so we're
stuck with the in-kernel ones for the time being.

James

Re: infinite loop with 36 Byte inquiry (sbp2 regression in 2.6.14-rcX)

[Stefan Richter]

James Bottomley wrote:
> Like I said, I think that's because you send an orb to the device with a
> command indicated length of 36 but a buffer length of 37

It happens regardless of what I force sbp2_send_command() to do:
	request_bufflen = cmd[4] = 0x24;
or
	request_bufflen = cmd[4];
or none of that.

> I don't see any loops in the lun probing routines.  For UNIT_ATTENTION
> to inquiry, we should retry three times and then give up.  If you enable
> debugging at the SCSI layer, that might give a better indication of
> what's going on.

Yes, I will do so.

> There's an #if 0 around an incorrect piece of code that would return
> DID_BUS_BUSY in this condition, you don't have that enabled, do you?
> 
> DID_BUS_BUSY is a dangerous reply because it causes an immediate retry
> without decrementing the retry count.  If you return it for a condition
> that never clears, it used to cause a hang.  Now it should actually exit
> the loop after the command times out (6 seconds, I think).

The #if 0 block is still deactivated here.

Thanks a lot for the advice. I will post what I find out.
-- 
Stefan Richter
-=====-=-=-= =-=- ==---
http://arcgraph.de/sr/