Bug 519772

Created attachment 358942 [details]
dmesg output

kernel recognizes firewire harddrive as sde

Created attachment 358943 [details]
anaconda.log

Created attachment 358944 [details]
syslog

Does this happen with a regular device that has a gpt label.  I'm thinking this has to do with the label being gpt and not with the hard drive being ieee1394.

Both anaconda-12.15 (F12-Alpha) and anaconda-12.17 recognize all harddrives when there are two drives with DOS label and two drives with GPT label, all internal SATA2 (ASUS main board.)  So a GPT label is not the problem by itself.

hrm, this might have something to do with it:

...
[2009-08-27 18:27:57,676]    DEBUG: no type or existing type for sde, bailing
...

I don't see a message for creating a parted disk for /dev/sde.  Could this be a parted, pyparted related error?
Can you pls go to tty2 and run the following scritp (run it as `python script`):

<snip>
import parted
dev = parted.getDevice("/dev/sde")
disk = parted.Disk(device=dev)
print disk.partitions
print disk.type
</snip>

Here is the output of "python ./script".  stdout is empty, stderr has a
traceback:
-----
Traceback (most recent call last):
  File "./script", line 2, in <module>
    dev = parted.getDevice("/dev/sde")
  File "<string>", line 2, in getDevice
  File "/usr/lib/python2.6/site-packages/parted/decorators.py", line 30, in
localeC
    ret = fn(*args, **kwds)
  File "/usr/lib/python2.6/site-packages/parted/__init__.py", line 230, in
getDevice
    return Device(path=path)
  File "<string>", line 2, in __init__
  File "/usr/lib/python2.6/site-packages/parted/decorators.py", line 30, in
localeC
    ret = fn(*args, **kwds)
  File "/usr/lib/python2.6/site-packages/parted/device.py", line 52, in
__init__
    self.__device = _ped.device_get(path)
_ped.DeviceException: Could not find device for path /dev/sde
-----

/dev/sde exists and is a block device (major=8, minor=64) with permissions 0660
(rw-rw----).  Immediately prior to the boot of the DVD for install, a running
Fedora 12 rawhide [of last last week] automatically recognized the device, and
all its partitions appeared on Gnome desktop as icons and as windows.

Here is a copy+paste of ./script itself, just to check for typos, etc:
-----
import parted
dev = parted.getDevice("/dev/sde")
disk = parted.Disk(device=dev)
print disk.partitions
print disk.type
-----

Created attachment 359686 [details]
/tmp/storage.log

/tmp/storage.log after running the "python ./script"

Created attachment 359687 [details]
syslog

Notice these lines from syslog:
-----
<5>firewire_sbp2: fw1.0: sbp2_scsi_abort
<3>firewire_sbp2: status write for unknown orb
<3>=============================================================================
<3>BUG kmalloc-192 (Not tainted): Invalid object pointer 0xc19e50a4
<3>-----------------------------------------------------------------------------
<3>
<3>INFO: Slab 0xc28501ac objects=17 used=17 fp=0x(null) flags=0x40000083
<4>Pid: 316, comm: hald Not tainted 2.6.31-0.125.4.2.rc5.git2.fc12.i686 #1
<4>Call Trace:
<4> [<c04ed059>] slab_err+0x63/0x7c
<4> [<c0600d4c>] ? free_object+0x7c/0xa1
<4> [<c04ed0a1>] ? slab_pad_check+0x2f/0xde
<4> [<c04eeb07>] __slab_free+0x140/0x24e
<4> [<f870a2aa>] ? free_orb+0x1f/0x32 [firewire_sbp2]
<4> [<c04ef151>] kfree+0xf8/0x13a
<4> [<f870a2aa>] ? free_orb+0x1f/0x32 [firewire_sbp2]
<4> [<f870a2aa>] ? free_orb+0x1f/0x32 [firewire_sbp2]
<4> [<f870a28b>] ? free_orb+0x0/0x32 [firewire_sbp2]
<4> [<f870a2aa>] free_orb+0x1f/0x32 [firewire_sbp2]
<4> [<c05f63ef>] kref_put+0x47/0x62
<4> [<f870ae22>] sbp2_status_write+0x13d/0x163 [firewire_sbp2]
<4> [<c081d4e3>] ? _spin_unlock_irqrestore+0x4f/0x6d
<4> [<f8363587>] fw_core_handle_request+0x20b/0x249 [firewire_core]
<4> [<f83791f3>] handle_ar_packet+0x106/0x12f [firewire_ohci]
<4> [<f837930f>] ar_context_tasklet+0xf3/0x112 [firewire_ohci]
<4> [<c044a5ef>] ? tasklet_action+0x4b/0xe6
<4> [<c046f25f>] ? trace_hardirqs_on_caller+0x109/0x155
<4> [<c044a627>] tasklet_action+0x83/0xe6
<4> [<c044ae23>] __do_softirq+0xc8/0x192
<4> [<c044af36>] do_softirq+0x49/0x7f
<4> [<c044b08a>] irq_exit+0x48/0x8c
<4> [<c0405705>] do_IRQ+0x92/0xb7
<4> [<c0404095>] common_interrupt+0x35/0x3c
<3>FIX kmalloc-192: Object at 0xc19e50a4 not freed
<5>firewire_sbp2: fw1.0: sbp2_scsi_abort
<6>sd 6:0:0:0: Device offlined - not ready after error recovery
<3>sd 6:0:0:0: rejecting I/O to offline device
<3>sd 6:0:0:0: rejecting I/O to offline device
<5>sd 6:0:0:0: [sde] Write Protect is off
<7>sd 6:0:0:0: [sde] Mode Sense: 00 00 00 00
<3>sd 6:0:0:0: rejecting I/O to offline device
<3>sd 6:0:0:0: [sde] Asking for cache data failed
<3>sd 6:0:0:0: [sde] Assuming drive cache: write through
<5>sd 6:0:0:0: [sde] Attached SCSI disk
-----

Yeah, that would explain why the device node exists and yet parted is unable to do anything with it.  I'm going to reassign this to kernel.  Once the kernel bug is fixed, if you are still experiencing problems in anaconda, feel free to open another bug and we'll take a look at it.  There may be some work to do in pyparted/libparted to fully support firewire disks.

The problem has disappeared using
  kernel-2.6.31-0.199.rc8.git2.fc12i.686
  anaconda-12.20
when booted from a self-composed DVD of rawhide for Thurs.Sept.3.

There are two independent issues here.

Problem 1)
The disk responded to SCSI Inquiry and Read Capacity commands, but the next SCSI command timed out.  IIRC that's a Mode_Sense command to query the cache type of the disk.

Since the disk did not respond to such a command (and to a retry) during the sd driver's probe, the SCSI core takes the device offline.

The disk did actually respond, but too late.  Or did the SCSI timer fire earlier than intended?  Unlikely, but who knows.

From comment 0:
> How reproducible: every time

And from comment 12:
> The problem has disappeared using
>   kernel-2.6.31-0.199.rc8.git2.fc12i.686
>   anaconda-12.20
> when booted from a self-composed DVD of rawhide for Thurs.Sept.3.

Very strange.

Problem 2)
The firewire-sbp2 driver attempted to free memory which it hadn't allocated.  That's a bug in the driver, happening in the code path which is taken if a disk sends status for a SCSI command that already timed out.  I'll post a fix.

> Problem 2)
> I'll post a fix.

http://marc.info/?l=linux1394-devel&m=125201214331538