external firewire sbp2 login timeout

[Allison Karlitskaya]

When I plug my firewire CD-ROM drive in I get:

[17359007.496000] ieee1394: Node resumed: ID:BUS[0-00:1023] GUID[0001d20000000535]
[17359007.496000] ieee1394: Node changed: 0-01:1023 -> 0-02:1023
[17359007.496000] scsi4 : SBP-2 IEEE-1394
[17359029.300000] ieee1394: sbp2: Error logging into SBP-2 device - login timed-out
[17359029.300000] sbp2: probe of 0001d20000000535-1 failed with error -16

The device then doesn't work at all.

The drive in question is really a normal IDE CDROM drive mounted inside of an
Oxford-911 based firewire enclosure.

I have an Audigy 2 that I am using at my firewire card.

I have similar problems to this at work when I try to use my laptop in target
disk mode with my G5 tower or one of the Xserves.

I've had this problem on and off for ages. It comes and goes with new kernel
revisions. Probably an unstream bug.

Willing to provide any additional information.

[Allison Karlitskaya (desrt)]

no help from any of these:
 - max_speed=0
 - serialize_io=1
 - force_inquiry_hack=1

[Ben Collins (ben-collins)]

What kernel? Can you send me full dmesg output?

[Simo Sorce (s-ssimo)]

(In reply to comment #2)
> What kernel? Can you send me full dmesg output?

I have the same error here with an external IDE Hard drive cabinet (it works ok
when used with the USB2 connector).
I have this error both with the 2.6.12-10 breezy kernel and also with the
2.6.15-8 dapper kernel
I have this error on a Dell Inspiron 8200
On a Dell Latitude D800 with latest Fedora Core 4 kernel, the same disk is
recognized as a ganeric scsi device ...
I had it working with older dsitributions and 2.4 kernels.

Error when plugging it in (from syslog):
[17179681.408000] ohci1394: fw-host0: SelfID received, but NodeID invalid
(probably new bus reset occurred): 0000FFC0
[17179682.360000] ieee1394: Error parsing configrom for node 0-00:1023
[17179682.360000] ieee1394: Node changed: 0-00:1023 -> 0-01:1023
[17179690.476000] ieee1394: Node added: ID:BUS[0-00:1023] GUID[0001b70e100003db]
[17179690.572000] ieee1394: sbp2: Driver forced to serialize I/O (serialize_io=1)
[17179690.572000] ieee1394: sbp2: Try serialize_io=0 for better performance
[17179690.572000] scsi1 : SBP-2 IEEE-1394
[17179712.380000] ieee1394: sbp2: Error logging into SBP-2 device - login timed-out
[17179712.380000] sbp2: probe of 0001b70e100003db-0 failed with error -16

lspci -v of the ieee1394 controller:
0000:02:01.2 FireWire (IEEE 1394): Texas Instruments PCI4451 IEEE-1394
Controller (prog-if 10 [OHCI])
        Subsystem: Dell: Unknown device 00d4
        Flags: bus master, medium devsel, latency 32, IRQ 11
        Memory at f8fff000 (32-bit, non-prefetchable) [size=2K]
        Memory at f8ff8000 (32-bit, non-prefetchable) [size=16K]
        Capabilities: [44] Power Management version 2

[Simo Sorce (s-ssimo)]

Created an attachment (id=5399)
/va/log/dmesg file

[Allison Karlitskaya (desrt)]

Created an attachment (id=5401)
dmesg log file

Running dapper here, 2.6.15-8-686

step 1: reboot
step 2: login
step 3: turn on drive
step 4: make copy of dmesg log

it looks like the top of the log is missing due to too many kernel messages
generated during startup and not a large enough log size.

[Allison Karlitskaya (desrt)]

Created an attachment (id=5402)
extra info

i don't know if this will be helpful.

it contains fragments of lspci and lshal output.

[Ben Collins (ben-collins)]

Please upgrade to Dapper's 2.6.15-9 kernel and let me know if it fixes your
problem (it may be a day or two before the kernel is available from the archives).

[Allison Karlitskaya (desrt)]

desrt@moonpix:~$ echo; uname -a; dmesg | tail # no love :(

Linux moonpix 2.6.15-9-686 #1 SMP PREEMPT Mon Dec 19 18:14:56 UTC 2005 i686
GNU/Linux
[4303679.255000] hub 1-2.3:1.0: USB hub found
[4303679.257000] hub 1-2.3:1.0: 4 ports detected
[4303828.797000] ieee1394: Node added: ID:BUS[0-00:1023]
GUID[0001d20000000535][4303828.797000] ieee1394: Node changed: 0-01:1023 ->
0-02:1023
[4303828.875000] sbp2: $Rev: 1306 $ Ben Collins <email address hidden>
[4303828.875000] ieee1394: sbp2: Driver forced to serialize I/O
(serialize_io=1)[4303828.875000] ieee1394: sbp2: Try serialize_io=0 for better
performance
[4303828.876000] scsi2 : SCSI emulation for IEEE-1394 SBP-2 Devices
[4303850.077000] ieee1394: sbp2: Error logging into SBP-2 device - login timed-out
[4303850.077000] sbp2: probe of 0001d20000000535-1 failed with error -16

[Ben Collins (ben-collins)]

Have you ever been able to get this device to work under linux?

[Allison Karlitskaya (desrt)]

Yes. It worked some time ago (2.6.8? 2.6.6?) in the exact configuration that I
am now using it.

It also worked for some random kernel version between then and now but I forget
which one that is too. :(

Interesting note: if I take the cd-rom drive out of the enclosure and put in a
harddrive it works fine.

[Allison Karlitskaya (desrt)]

Some notes:

kernel upgrade did not help
powerbook in target disk mode attached to the PC works
harddrive in the same enclosure attached to the PC works
cd-rom drive does not work when attached to the PC does not work
cd-rom drive when attached to my laptop works (in both macosx and ubuntu)
removing the cd-rom drive and putting in a different one works even on the PC

i'm going to assume that there is some weird border behaviour in the chipset of
the enclosure that is aggrivated by the particular CD-ROM drive and only causes
problems to manifest on the PC.

in every way this problem is solved for me and i'm reasonably convinced that
this isn't a software problem.

i'll leave the bug open since simo 'me too'd it but as far as i'm concerned it's
done.

[Launchpad Janitor (janitor)]

Beginning with the Hardy Heron 8.04 development cycle, all open Ubuntu kernel bugs need to be reported against the "linux" kernel package. We are automatically migrating this linux-source-2.6.15 kernel bug to the new "linux" package. We appreciate your patience and understanding as we make this transition. Also, if you would be interested in testing the upcoming Intrepid Ibex 8.10 release, it is available at http://www.ubuntu.com/testing . Please let us know your results. Thanks!

[Leann Ogasawara (leannogasawara)]

The Ubuntu Kernel Team is planning to move to the 2.6.27 kernel for the upcoming Intrepid Ibex 8.10 release. As a result, the kernel team would appreciate it if you could please test this newer 2.6.27 Ubuntu kernel. There are one of two ways you should be able to test:

1) If you are comfortable installing packages on your own, the linux-image-2.6.27-* package is currently available for you to install and test.

--or--

2) The upcoming Alpha5 for Intrepid Ibex 8.10 will contain this newer 2.6.27 Ubuntu kernel. Alpha5 is set to be released Thursday Sept 4. Please watch http://www.ubuntu.com/testing for Alpha5 to be announced. You should then be able to test via a LiveCD.

Please let us know immediately if this newer 2.6.27 kernel resolves the bug reported here or if the issue remains. More importantly, please open a new bug report for each new bug/regression introduced by the 2.6.27 kernel and tag the bug report with 'linux-2.6.27'. Also, please specifically note if the issue does or does not appear in the 2.6.26 kernel. Thanks again, we really appreicate your help and feedback.

[kernel-janitor (kernel-janitor)]

This bug report was marked as Confirmed a while ago but has not had any updated comments for quite some time. Please let us know if this issue remains in the current Ubuntu release, http://www.ubuntu.com/getubuntu/download . If the issue remains, click on the current status under the Status column and change the status back to "New". Thanks.

[This is an automated message. Apologies if it has reached you inappropriately; please just reply to this message indicating so.]

[Adam (adambot)]

Just let me know what information you need and i will upload/post it. Thanks!

[david (davidelizondo2006)]

Oct 3 14:29:54 david-desktop kernel: [ 0.000000] MTRR default type: uncachable
Oct 3 14:29:54 david-desktop kernel: [ 0.000000] MTRR variable ranges disabled:
Oct 3 14:29:54 david-desktop kernel: [ 0.000000] e820 update range: 0000000000002000 - 0000000000006000 (usable) ==> (reserved)
Oct 3 14:29:54 david-desktop kernel: [ 0.000000] initial memory mapped : 0 - 00c00000
Oct 3 14:29:54 david-desktop kernel: [ 0.000000] 0000000000 - 0000400000 page 4k
Oct 3 14:29:54 david-desktop kernel: [ 0.000000] 0000400000 - 0017c00000 page 2M
Oct 3 14:29:54 david-desktop kernel: [ 0.000000] 0017c00000 - 0017ff0000 page 4k
Oct 3 14:29:54 david-desktop kernel: [ 0.000000] kernel direct mapping tables up to 17ff0000 @ 7000-c000
Oct 3 14:29:54 david-desktop kernel: [ 0.000000] On node 0 totalpages: 98187
Oct 3 14:29:54 david-desktop kernel: [ 0.000000] free_area_init_node: node 0, pgdat c077b840, node_mem_map c1000000
Oct 3 14:29:54 david-desktop kernel: [ 0.000000] DMA zone: 32 pages used for memmap
Oct 3 14:29:54 david-desktop kernel: [ 0.000000] DMA zone: 0 pages reserved
Oct 3 14:29:54 david-desktop kernel: [ 0.000000] DMA zone: 3963 pages, LIFO batch:0
Oct 3 14:29:54 david-desktop kernel: [ 0.000000] Normal zone: 736 pages used for memmap
Oct 3 14:29:54 david-desktop kernel: [ 0.000000] Normal zone: 93456 pages, LIFO batch:31
Oct 3 14:29:54 david-desktop kernel: [ 0.000000] nr_irqs_gsi: 16
Oct 3 14:29:54 david-desktop kernel: [ 0.758396] CPU0 attaching NULL sched-domain.
Oct 3 14:29:54 david-desktop kernel: [ 0.837446] ACPI: EC: Look up EC in DSDT
Oct 3 14:29:54 david-desktop kernel: [ 0.864002] pci 0000:00:01.1: reg 20 io port: [0xd000-0xd00f]
Oct 3 14:29:54 david-desktop kernel: [ 0.865842] pci 0000:00:02.0: reg 10 32bit mmio: [0xe0000000-0xe0ffffff]
Oct 3 14:29:54 david-desktop kernel: [ 0.868801] pci 0000:00:03.0: reg 10 io port: [0xd020-0xd03f]
Oct 3 14:29:54 david-desktop kernel: [ 0.869027] pci 0000:00:03.0: reg 14 32bit mmio: [0xf0000000-0xf0000fff]
Oct 3 14:29:54 david-desktop kernel: [ 0.869231] pci 0000:00:03.0: reg 18 32bit mmio: [0xf0080000-0xf00fffff]
Oct 3 14:29:54 david-desktop kernel: [ 0.869772] pci 0000:00:04.0: reg 10 io port: [0xd040-0xd05f]
Oct 3 14:29:54 david-desktop kernel: [ 0.869982] pci 0000:00:04.0: reg 14 32bit mmio: [0xf0400000-0xf07fffff]
Oct 3 14:29:54 david-desktop kernel: [ 0.870142] pci 0000:00:04.0: reg 18 32bit mmio: [0xf0800000-0xf0803fff]
Oct 3 14:29:54 david-desktop kernel: [ 0.870689] pci 0000:00:05.0: reg 10 io port: [0xd100-0xd1ff]
Oct 3 14:29:54 david-desktop kernel: [ 0.870819] pci 0000:00:05.0: reg 14 io port: [0xd200-0xd23f]
Oct 3 14:29:54 david-desktop kernel: [ 0.871397] pci 0000:00:06.0: reg 10 32bit mmio: [0xf0804000-0xf0804fff]
Oct 3 14:29:54 david-desktop kernel: [ 0.873422] pci 0000:00:0b.0: reg 10 32bit mmio: [0xf0805000-0xf0805fff]
Oct 3 14:29:54 david-desktop kernel: [ 0.873834] pci_bus 0000:00: on NUMA node 0
Oct 3 14:29:54 david-desktop kernel: [ 0.873882] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
Oct 3 14:29:54 david-desktop kernel: [ 0.881273...

[david (davidelizondo2006)]

2009-10-01 19:32:12,162 DEBUG: updating <jockey.detection.LocalKernelModulesDriverDB instance at 0x8e81fec>
2009-10-01 19:32:12,420 DEBUG: reading modalias file /lib/modules/2.6.31-11-generic/modules.alias
2009-10-01 19:32:12,851 DEBUG: reading modalias file /usr/share/jockey/modaliases/bcmwl
2009-10-01 19:32:12,858 DEBUG: reading modalias file /usr/share/jockey/modaliases/disable-upstream-nvidia
2009-10-01 19:32:12,960 DEBUG: reading modalias file /usr/share/jockey/modaliases/fglrx-modules.alias.override
2009-10-01 19:32:12,968 DEBUG: reading modalias file /usr/share/jockey/modaliases/nvidia-173
2009-10-01 19:32:12,973 DEBUG: reading modalias file /usr/share/jockey/modaliases/nvidia-185
2009-10-01 19:32:12,997 DEBUG: reading modalias file /usr/share/jockey/modaliases/nvidia-96
2009-10-01 19:32:13,020 WARNING: Could not open DriverDB cache /var/cache/jockey/driverdb-OpenPrintingDriverDB.cache: [Errno 2] No such file or directory: '/var/cache/jockey/driverdb-OpenPrintingDriverDB.cache'
2009-10-01 19:32:13,034 DEBUG: loading custom handler /usr/share/jockey/handlers/sl_modem.py
2009-10-01 19:32:17,238 DEBUG: Instantiated Handler subclass __builtin__.SlModem from name SlModem
2009-10-01 19:32:17,560 DEBUG: Software modem not available
2009-10-01 19:32:17,562 DEBUG: loading custom handler /usr/share/jockey/handlers/broadcom_wl.py
2009-10-01 19:32:17,620 WARNING: modinfo for module wl failed: ERROR: modinfo: could not find module wl

2009-10-01 19:32:17,658 DEBUG: Instantiated Handler subclass __builtin__.BroadcomWLHandler from name BroadcomWLHandler
2009-10-01 19:32:17,660 DEBUG: Broadcom STA wireless driver availability undetermined, adding to pool
2009-10-01 19:32:17,660 DEBUG: loading custom handler /usr/share/jockey/handlers/b43.py
2009-10-01 19:32:17,788 DEBUG: Instantiated Handler subclass __builtin__.B43LegacyHandler from name B43LegacyHandler
2009-10-01 19:32:17,790 DEBUG: Broadcom B43legacy wireless driver availability undetermined, adding to pool
2009-10-01 19:32:17,823 DEBUG: Instantiated Handler subclass __builtin__.B43Handler from name B43Handler
2009-10-01 19:32:17,825 DEBUG: Broadcom B43 wireless driver availability undetermined, adding to pool
2009-10-01 19:32:17,825 DEBUG: loading custom handler /usr/share/jockey/handlers/fglrx.py
2009-10-01 19:32:17,857 WARNING: modinfo for module fglrx failed: ERROR: modinfo: could not find module fglrx

2009-10-01 19:32:17,860 DEBUG: Instantiated Handler subclass __builtin__.FglrxDriver from name FglrxDriver
2009-10-01 19:32:17,892 DEBUG: ATI/AMD proprietary FGLRX graphics driver availability undetermined, adding to pool
2009-10-01 19:32:17,893 DEBUG: loading custom handler /usr/share/jockey/handlers/dvb_usb_firmware.py
2009-10-01 19:32:18,003 DEBUG: Instantiated Handler subclass __builtin__.DvbUsbFirmwareHandler from name DvbUsbFirmwareHandler
2009-10-01 19:32:18,005 DEBUG: Firmware for DVB cards not available
2009-10-01 19:32:18,006 DEBUG: loading custom handler /usr/share/jockey/handlers/madwifi.py
2009-10-01 19:32:18,123 WARNING: modinfo for module ath_pci failed: ERROR: modinfo: could not find module ath_pci

2009-10-01 19:32:18,126 DEBUG: Instantiated Handler subclass __builtin__.Madwifi...

[Stefan Richter (stefan-r-ubz)]

I don't see anything related to 1394 in david's comments. Wrong bug number?

-----------------

Those who still have sbp2 login failures should please try the following:
  - Make sure to have a somewhat recent kernel package which has firewire-ohci.ko installed in parallel with ohci1394.ko.
  - Switch from the drivers ohci1394 + ieee1394 + sbp2 to the drivers firewire-ohci + firewire-core + firewire-sbp2 by editing a module blacklist file:
http://ieee1394.wiki.kernel.org/index.php/Juju_Migration#How_to_suppress_auto-loading

This suggestion is because firewire-core + firewire-sbp2 bring enhancements WRT SBP-2 login (and further enhancements, e.g. to 1394a/S400 throughput). Alas I cannot be more specific which kernel package version is minimally required for this and which particular modprobe configuration file to edit since I don't have Ubuntu installed myself.

[Jeremy Foshee (jeremyfoshee)]

Ryan,
     Can you confirm this issue exists with the most recent Karmic Koala 9.10 Alpha release? ISO CD images are available at http://cdimage.ubuntu.com/releases/karmic/ . If the issue remains with Karmic it would be great to then also test the latest upstream mainline kernel available. This will allow additional upstream developers to examine this issue. Refer to https://wiki.ubuntu.com/KernelMainlineBuilds . Thanks in advance.

Adam,
    I don't quite understand why you changed this bug back to new and indicated that you would upload further debugging? Are you working with Ryan in some capacity on this? Also, not sure why you would change the assignee?

David,
    I agree with Stefan, I don't understand what your entries have to do with this bug. Also, why would you change the assignee?

I have changed the assignee to the kernel team. If this is still an issue in the latest Karmic, then please say so; otherwise we will be closing this bug in favor of a new one once the confusion ends.

-JFo

[Adam (adambot)]

I changed the status because of directions in post #14 Also, i was unsure on what to upload that would be useful.

Dmesg is attached:

[Adam (adambot)]

lshw output attached

[Adam (adambot)]

lspci attached

[Jeremy Foshee (jeremyfoshee)]

Adam,
    Thank you for the clarification. :) Have you confirmed this issue exists with the most recent Karmic Koala 9.10 Alpha release?
If so, you can attach relevant logging from the system itself using:

apport-collect -p linux 27287

This will provide this bug ticket with all relevant logging.

Thanks again,

-JFo

[Stefan Richter (stefan-r-ubz)]

Adam,

the failure mode which you are reporting is different.
  a) The other reporters got a login timeout i.e. no login response. You get a login failure i.e. an error response.
  b) The problem reported by the others seemed to be generic, while I suspect your problem to be specific to the disk enclosure which you are using.

####

According to the vendor OUI of the device, it is from Data Robotics, i.e. a Drobo or a DroboPro. Which one is it? How much disk capacity is in it (how many disks of what size, and how much of it is usable according to Data Robotics' size calculator)?

Your log in comment 20 shows that one logical unit of 2.19 TB/ 1.99 TiB size was detected and should be fully functional (in the session you logged: /dev/sdb as the block device, with a single partition on it: /dev/sdb1).

Furthermore, the log shows that two further logical units on this device were detected, but the sbp2 driver got an error status when it attempted to log in into these two logical units. Should your Drobo or DroboPro expose three logical units?

What do you get when you connect it via USB?
Are you able to test it with Windows or OS X?
Is a current firmware installed on the Drobo or DroboPro?

####

As far as I have read, Drobo and DroboPro will divide their total available disk space --- minus space required for redundancy etc. --- into logical units whose size can be configured with Data Robotics' dashboard application for Windows and OS X, or with the community-maintained drobo-utils for Linux. The default size of the logical units is 2 TiB (or TB?).

(As a side note: If you want to use logical units bigger than 2.0 TiB over FireWire, you need a recent FireWire kernel driver update, released in the kernel.org versions 2.6.31, 2.6.30.5, and 2.6.27.30: http://ieee1394.wiki.kernel.org/index.php/Release_Notes . Without this driver update, FireWire disks larger than 2.0 TiB will be shown as merely 2.0 TiB sized. This is _not_ related to the login failures to your 2nd and 3rd logical unit though.)

[Stefan Richter (stefan-r-ubz)]

PS:
Here is an article about the inner workings of Drobo and what this implies for its support by Linux (not FireWire-specific):
http://groups.google.com/group/drobo-talk/web/linux-support?hl=en
Due to Drobo and DroboPro firmware limitations, it is currently impractical to use a logical unit size larger than the default 2.0 TiB under Linux:
http://groups.google.com/group/drobo-talk/browse_thread/thread/34f08da1708d2f7b
I.e. if you have more than 2 TB net disk space built into the Drobo or DroboPro, it needs to be exposed to Linux as a 2nd and perhaps 3rd logical unit indeed.

[rusivi2 (rusivi2-deactivatedaccount)]

Thank you for reporting this bug.

Does this issue occur in Lucid?

[dino99 (9d9)]

This version has expired