Firewire IPOD does not work since upgrade to 8.10

[454abp]

I upgraded to Ubuntu 8.10 a couple of days ago. Since then my Firewire IPOD does not get mounted on my computer any more.

Everything was fine before the upgrade.

dmesg has the following output:
[ 1361.636113] ieee1394: The root node is not cycle master capable; selecting a new root node and resetting...
[ 1361.914781] ieee1394: Node added: ID:BUS[0-00:1023] GUID[000a27000275787b]
[ 1361.916200] ieee1394: Node changed: 0-00:1023 -> 0-01:1023
[ 1361.921465] scsi4 : SBP-2 IEEE-1394
[ 1363.123864] ieee1394: sbp2: Logged into SBP-2 device
[ 1363.125451] ieee1394: sbp2: Node 0-00:1023: Max speed [S400] - Max payload [2048]
[ 1363.129066] scsi 4:0:0:0: Direct-Access-RBC Apple iPod 1.53 PQ: 0 ANSI: 2
[ 1365.059349] sd 4:0:0:0: [sdc] Spinning up disk....ready
[ 1367.215657] sd 4:0:0:0: [sdc] 29297520 512-byte hardware sectors (15000 MB)
[ 1367.218740] sd 4:0:0:0: [sdc] Test WP failed, assume Write Enabled
[ 1367.221696] sd 4:0:0:0: [sdc] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[ 1367.227208] sd 4:0:0:0: [sdc] 29297520 512-byte hardware sectors (15000 MB)
[ 1367.232125] sd 4:0:0:0: [sdc] Test WP failed, assume Write Enabled
[ 1367.234969] sd 4:0:0:0: [sdc] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[ 1367.239776] sdc: sdc1 sdc2
[ 1367.259583] sd 4:0:0:0: [sdc] Attached SCSI removable disk
[ 1367.265834] sd 4:0:0:0: Attached scsi generic sg3 type 14
[ 1367.404657] end_request: I/O error, dev sdc, sector 104
[ 1367.404674] __ratelimit: 3 callbacks suppressed
[ 1367.404679] Buffer I/O error on device sdc, logical block 13
[ 1367.404688] Buffer I/O error on device sdc, logical block 14
[ 1367.404692] Buffer I/O error on device sdc, logical block 15
[ 1367.404696] Buffer I/O error on device sdc, logical block 16
[ 1367.404699] Buffer I/O error on device sdc, logical block 17
[ 1367.404702] Buffer I/O error on device sdc, logical block 18
[ 1367.404706] Buffer I/O error on device sdc, logical block 19
[ 1367.404709] Buffer I/O error on device sdc, logical block 20
[ 1367.404712] Buffer I/O error on device sdc, logical block 21
[ 1367.404716] Buffer I/O error on device sdc, logical block 22
[ 1367.405472] end_request: I/O error, dev sdc, sector 104
[ 1367.407063] end_request: I/O error, dev sdc, sector 104
[ 1367.407871] end_request: I/O error, dev sdc, sector 104
[ 1367.410911] end_request: I/O error, dev sdc, sector 104
[ 1367.590651] end_request: I/O error, dev sdc, sector 0
[ 1367.591419] end_request: I/O error, dev sdc, sector 0
[ 1367.592261] end_request: I/O error, dev sdc, sector 0
[ 1367.600801] end_request: I/O error, dev sdc, sector 63
[ 1367.601574] end_request: I/O error, dev sdc, sector 63
[ 1367.602211] end_request: I/O error, dev sdc, sector 65
[ 1367.634722] end_request: I/O error, dev sdc, sector 80325
[ 1367.635465] end_request: I/O error, dev sdc, sector 80325
[ 1367.636095] end_request: I/O error, dev sdc, sector 80327
[ 1367.751871] end_request: I/O error, dev sdc, sector 63
[ 1367.752623] end_request: I/O error, dev sdc, sector 63
[ 1367.753247] end_request: I/O error, dev sdc, sector 65
[ 1367.756249] end_request: I/O error, dev sdc, sector 0
[ 1367.756998] end_request: I/O error, dev sdc, sector 8
[ 1367.757625] end_request: I/O error, dev sdc, sector 0
[ 1367.759601] end_request: I/O error, dev sdc, sector 0
[ 1367.847657] end_request: I/O error, dev sdc, sector 80325
[ 1367.848408] end_request: I/O error, dev sdc, sector 80325
[ 1367.849026] end_request: I/O error, dev sdc, sector 80327
[ 1367.852160] end_request: I/O error, dev sdc, sector 0
[ 1367.852911] end_request: I/O error, dev sdc, sector 8
[ 1367.853535] end_request: I/O error, dev sdc, sector 0
[ 1367.854333] end_request: I/O error, dev sdc, sector 0
[ 1370.065431] end_request: I/O error, dev sdc, sector 0
[ 1370.066245] end_request: I/O error, dev sdc, sector 0
[ 1370.067080] end_request: I/O error, dev sdc, sector 0

[454abp (sideshowbob-454abp)]

Now i tried it with a USB cable and the IPOD works fine. Is there a problem with the firewire implementation in 8.10?

/454abp

[Kevin Dwyer (kevin-pheared)]

I get similar messages in dmesg. My ipod worked just fine over firewire before the upgrade to 8.10. I don't have any way of hooking up USB (it's a 2nd generation) so I'm stuck. I just noticed that if I wait long enough, eventually sdb2 shows up and I can mount the partition, but writing and syncing files takes forever and just causes more errors to show up in dmesg. I'm not sure if the writes are even really successful.

uname -a: Linux dubbel 2.6.27-7-generic #1 SMP Tue Nov 4 19:33:06 UTC 2008 x86_64 GNU/Linux

[Stefan Richter (stefan-r-ubz)]

Please try the following command as root user:
# echo 8 > /sys/module/sbp2/parameters/workarounds
Then plug in the iPod. If it works, post the contents of dmesg, beginning with the "Node added" message from when the iPod was plugged in.

[Stefan Richter (stefan-r-ubz)]

If workaround 8 does not help, try the same with
# echo 1 > /sys/module/sbp2/parameters/workarounds

[Stefan Richter (stefan-r-ubz)]

I just remembered another old issue with FireWire iPods which was never addressed in the drivers. (Can't process more than one page table element.) It seems that performance enhancements in the block layer of newer kernels changed that problem from a theoretical one into an actual one.

Alas it looks like there is no sysfs switch or module parameter which could enable a necessary workaround. I will look into this and report back later. In the meantime, please try the two suggestions nevertheless and post your results here. Thanks.

[454abp (sideshowbob-454abp)]

When I try it with workaround 8 it works. With workaround 1 the output is a little bit weared. I did however not reboot the system... just unmounted the ipod and unplugged it.

dmesg gives the following output with workaround 8:
[ 2885.950819] ieee1394: Node added: ID:BUS[0-00:1023] GUID[000a27000275787b]
[ 2885.952264] ieee1394: Node changed: 0-00:1023 -> 0-01:1023
[ 2885.956693] scsi4 : SBP-2 IEEE-1394
[ 2885.957798] ieee1394: sbp2: Workarounds for node 0-00:1023: 0x8 (firmware_revision 0x0a2700, vendor_id 0x000a27, model_id 0x000000)
[ 2887.420819] ieee1394: sbp2: Logged into SBP-2 device
[ 2887.421893] ieee1394: sbp2: Node 0-00:1023: Max speed [S400] - Max payload [2048]
[ 2887.424945] scsi 4:0:0:0: Direct-Access-RBC Apple iPod 1.53 PQ: 0 ANSI: 2
[ 2889.357625] sd 4:0:0:0: [sdc] Spinning up disk....ready
[ 2890.363890] sd 4:0:0:0: [sdc] 29297519 512-byte hardware sectors (15000 MB)
[ 2890.366909] sd 4:0:0:0: [sdc] Test WP failed, assume Write Enabled
[ 2890.377987] sd 4:0:0:0: [sdc] Write cache: disabled, read cache: enabled, doesn't support DPOor FUA
[ 2890.388656] sd 4:0:0:0: [sdc] 29297519 512-byte hardware sectors (15000 MB)
[ 2890.392016] sd 4:0:0:0: [sdc] Test WP failed, assume Write Enabled
[ 2890.394776] sd 4:0:0:0: [sdc] Write cache: disabled, read cache: enabled, doesn't support DPOor FUA
[ 2890.396372] sdc: sdc1 sdc2
[ 2890.415166] sd 4:0:0:0: [sdc] Attached SCSI removable disk
[ 2890.416311] sd 4:0:0:0: Attached scsi generic sg3 type 14

workaround 1 gives the following output in dmesg:
[ 3062.700133] ieee1394: Node changed: 0-01:1023 -> 0-00:1023
[ 3062.701250] ieee1394: Node suspended: ID:BUS[0-00:1023] GUID[000a27000275787b]
[ 3062.710159] sd 4:0:0:0: [sdc] READ CAPACITY failed
[ 3062.710171] sd 4:0:0:0: [sdc] Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK,SUGGEST_OK
[ 3062.710177] sd 4:0:0:0: [sdc] Sense not available.
[ 3062.710903] sd 4:0:0:0: [sdc] Write Protect is off
[ 3062.710910] sd 4:0:0:0: [sdc] Mode Sense: 00 00 00 00
[ 3062.711299] sd 4:0:0:0: [sdc] Asking for cache data failed
[ 3062.711307] sd 4:0:0:0: [sdc] Assuming drive cache: write through
[ 3062.711866] sd 4:0:0:0: [sdc] READ CAPACITY failed
[ 3062.711872] sd 4:0:0:0: [sdc] Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK,SUGGEST_OK
[ 3062.711876] sd 4:0:0:0: [sdc] Sense not available.
[ 3062.712044] sd 4:0:0:0: [sdc] Write Protect is off
[ 3062.712047] sd 4:0:0:0: [sdc] Mode Sense: 00 00 00 00
[ 3062.712799] sd 4:0:0:0: [sdc] Asking for cache data failed
[ 3062.712807] sd 4:0:0:0: [sdc] Assuming drive cache: write through
[ 3062.713699] sd 4:0:0:0: [sdc] Stopping disk
[ 3062.714477] sd 4:0:0:0: [sdc] START_STOP FAILED
[ 3062.714482] sd 4:0:0:0: [sdc] Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK,SUGGEST_OK
[ 3080.896573] ieee1394: Node resumed: ID:BUS[0-00:1023] GUID[000a27000275787b]
[ 3080.897971] ieee1394: Node changed: 0-00:1023 -> 0-01:1023
[ 3080.900127] scsi5 : SBP-2 IEEE-1394
[ 3080.906084] ieee1394: sbp2: Workarounds for node 0-00:1023: 0x1 (firmware_revision 0x0a2700, vendor_id 0x000a27, model_id 0x000000)
[ 3082.097984] ieee1394: sbp2: Logged into SBP-2 de...

[Stefan Richter (stefan-r-ubz)]

454abp: Sounds good.
  - Is reading (and writing...) of small and large files stable with workarounds=8?
  - Which iPod model is this? (http://en.wikipedia.org/wiki/IPod#Models)

[454abp (sideshowbob-454abp)]

Hi Stefan,

I was transferring a whole album and a 50 megabyte file to the device and it works fine.

What is the workaround 8 doing anyway?

I have a third generation Ipod.

Thanks for your help.

/454abp

[Stefan Richter (stefan-r-ubz)]

Thanks for the information. We can add the firmware_revision and model_id to a quirks list in the sbp2 driver so that the workaround will activated automatically by upcoming releases of the kernel.

Until this made its way into the kernel, you can enable this workaround permantly by adding the following line either to /etc/modprobe.d/options or to a new file in /etc/modprobe.d/ with a filename of your choice:
options sbp2 workarounds=8

The workaround simply subtracts one from the disk size reported by the device. In your initial report, it is 29297520 sectors, while with the workaround the kernel takes it as 29297519 sectors. This size is determined from the SCSI command READ CAPACITY (10), to which devices are supposed to return the LBA (logical block address) of the last sector. Since the LBA of the 1st sector is 0, the LBA of the last sector is the number of sectors minus 1. Some firmware programmers get this wrong and return not the last LBA but the numbers of sectors. This is a problem of many USB devices and apparently also of USB iPods and some of the dual USB + FireWire iPods. When then the kernel accesses blocks near the supposed end of the disk, there will be I/O errors, or the firmware will even hang. Firmware programmers don't notice their bug because they only test with Windows which typically does not access disks right at the end. Linux does so for example to check for some types of partition tables which Windows does not support.

However, the 29297520 sectors, as an even number, are actually more plausible to me as the real disk size than 29297519 sectors, as an odd number. Perhaps the real issue here is that this iPod firmware has a problem with block accesses /near/ the end. There have been several different flavors of firmware bugs observed with USB devices which concern accesses near the end of the disk, such as expecting only small request sizes. So it could actually be that 29297520 sectors is the real size, but reducing it by one causes the Linux kernel to treat the las few sectors with more care. There have been some changes in the related kernel code in the latest kernels.

Lastly, the reason that it all worked fine for you before you updated Ubuntu may have been changes in the kernel's configuration and features, causing 8.10's kernel to issue requests to disks which the former kernel didn't.

[Kevin Dwyer (kevin-pheared)]

Thanks for following up Stefan!

Workaround 8 does not work for me. I still get the "Buffer I/O error on device" messages.

Workaround 1 appears to work for me. Here is the dmesg for that:

[803933.872139] ieee1394: Node changed: 0-00:1023 -> 0-01:1023
[803941.528625] ieee1394: Node changed: 0-01:1023 -> 0-00:1023
[803942.444747] ieee1394: Node changed: 0-00:1023 -> 0-01:1023
[803944.740136] ieee1394: Node changed: 0-01:1023 -> 0-00:1023
[803945.652083] ieee1394: The root node is not cycle master capable; selecting a
 new root node and resetting...
[803946.604533] ieee1394: Error parsing configrom for node 0-00:1023
[803947.284533] ieee1394: Error parsing configrom for node 0-01:1023
[803947.556603] ieee1394: Node resumed: ID:BUS[0-00:1023] GUID[000a2700020a4ba0]
[803947.556703] ieee1394: Node changed: 0-00:1023 -> 0-01:1023
[803947.557096] scsi12 : SBP-2 IEEE-1394
[803947.561430] ieee1394: sbp2: Workarounds for node 0-00:1023: 0x1 (firmware_revision 0x0a2700, vendor_id 0x000a27, model_id 0x000000)
[803948.564974] ieee1394: sbp2: Logged into SBP-2 device
[803948.565065] ieee1394: sbp2: Node 0-00:1023: Max speed [S400] - Max payload [2048]
[803948.566491] scsi 12:0:0:0: Direct-Access-RBC Apple iPod 1.33 PQ: 0 ANSI: 2
[803948.568071] sd 12:0:0:0: [sdb] 19531260 512-byte hardware sectors (10000 MB)
[803948.572226] sd 12:0:0:0: [sdb] Test WP failed, assume Write Enabled
[803948.573835] sd 12:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[803948.576899] sd 12:0:0:0: [sdb] 19531260 512-byte hardware sectors (10000 MB)
[803948.578531] sd 12:0:0:0: [sdb] Test WP failed, assume Write Enabled
[803948.579755] sd 12:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[803948.579766] sdb: sdb1 sdb2
[803949.182661] sd 12:0:0:0: [sdb] Attached SCSI removable disk
[803949.182896] sd 12:0:0:0: Attached scsi generic sg2 type 14

[Stefan Richter (stefan-r-ubz)]

Kevin,
is it also OK to specify both workarounds combined, i.e.
# echo 9 > /sys/module/sbp2/parameters/workarounds

The trouble is that 2nd generation iPods and 3rd generation iPods have the same firmware_revision, vendor_id, model_id. So we can only add one driver-internal quirks list entry for both generations. It doesn't really hurt if we specify workaround 1 even if we don't need it --- it limits the transfer size that can be done in a single SCSI request; i.e. it will just cause a little bit more protocol overhead. The workaround 8 however could make the very last sector inaccessible if we specified it without actual need.

So, if you have the time for a really thorough test, the following would be good to investigate:
  - Enable workaround 1.
  - Fill the iPod up. The last files written should be small to really use everything, i.e. the very last few files should be smaller than 512 bytes.
  - Unmount and unplug the iPod.
  - Enable workaround 1 and 8 (i.e. 9).
  - Try to read the last files written; watch out for any error messages in dmesg.

Unfortunately for you, only iPod gen. 3 owners will profit from that test, because it will (hopefully) enable me to hardwire workaround 8 (and 1 of course) in the driver.

Regarding workaround 1: I think I will actually implement a variation of this workaround which defines the allowed requests even further, based on the comment at http://lxr.linux.no/linux+v2.6.28/drivers/firewire/fw-sbp2.c#L1390 . I suspect the transfer size limit which workaround 1 sets merely makes it quite likely that no page tables are required as per that comment; the real fix would be to actually guarantee that there won't be a page table for 2nd gen. iPods.

[Stefan Richter (stefan-r-ubz)]

Kevin,
what hardware platform do you have? Intel or AMD or...? Do you know on which chipset (nortbridge, southbridge) your maiboard is based on?

[Stefan Richter (stefan-r-ubz)]

454abp and Kevin,
please also post the result of "ls /sys/bus/ieee1394/devices/*/model_id" from when the iPod is connected.

[Stefan Richter (stefan-r-ubz)]

test patch posted at http://lkml.org/lkml/2009/1/24/83

[454abp (sideshowbob-454abp)]

Hi Stefan,

I have to tell that the workarounds (1,8 and 9) does not solve all my problems. It's possible to mount the IPOD and copy and erase a large file. When i tried to access different files on the IPOD the file manager freezes. Sometimes even the whole KDE desktop freezes and I have to reset the system. So it is definitely not a perfect solution yet.

[Stefan Richter (stefan-r-ubz)]

revised patch posted at http://lkml.org/lkml/2009/1/28/456

My questions from comments 11 and 13 have already been answered by http://lkml.org/lkml/2009/1/28/428

[Stefan Richter (stefan-r-ubz)]

The patch from comment 16 has been merged in upstream released kernels 2.6.29-rc4, 2.6.28.5, and 2.6.27.16.

[Kevin Dwyer (kevin-pheared)]

Thanks Stefan!

[Stefan Richter (stefan-r-ubz)]

454abp ,
if you use workaround 9 (i.e. 1 and 8 as in the patch) and the file manager freezes during iPod access, what do you get from "dmesg"? (If the UI becomes very unresponsive, try [Ctrl][Alt][F1] to get a text console.)

[Leann Ogasawara (leannogasawara)]

Seems Stefan's patches are already in Karmic. Marking this Fix Released for now.

ogasawara@emiko:~/ubuntu-karmic$ git log 1448d7c6a2ff96d3b52ecae49e2d0f046a097fe0
commit 1448d7c6a2ff96d3b52ecae49e2d0f046a097fe0
Author: Stefan Richter <email address hidden>
Date: Thu Jan 29 00:13:20 2009 +0100

    ieee1394: sbp2: add workarounds for 2nd and 3rd generation iPods

    as per https://bugs.launchpad.net/bugs/294391. These got one sample of
    each iPod generation going. However there still occurred I/O stalls
    with the 3rd generation iPod which remain undiagnosed at the time of
    this writing.

    Acked-by: Jarod Wilson <email address hidden>
    Signed-off-by: Stefan Richter <email address hidden>