Bug 228017

... and the disc a) won't eject b) appears to be a coaster.

Still happens with:

* Mon Feb 12 2007 Kristian Høgsberg <krh>
- Update firewire patch with latest usptream changes.

Also, it now is unable to burn CDs:

fw_sbp2: no command orb status, rcode=17
fw_sbp2: no command orb status, rcode=17
fw_sbp2: status write for unknown orb
fw_sbp2: no command orb status, rcode=17

Also also, powering off the drive yields:

fw_core: phy config: card 0, new root=ffc1, gap_count=5
fw_sbp2: management write failed, rcode 0x11
fw_sbp2: reconnect attempt 1 for fw1.0 failed, rescheduling
fw_sbp2: management write failed, rcode 0x13
fw_sbp2: removed sbp2 unit fw1.0
list_add corruption. prev->next should be next (ffff81007e6841c0), but was
6b6b6b6b6b6b6b6b. (prev=ffff810076089480).
------------[ cut here ]------------
kernel BUG at lib/list_debug.c:33!
invalid opcode: 0000 [1] SMP 
last sysfs file: /class/drm/card0/dev
CPU 1 
Modules linked in: nfs lockd nfs_acl i915 drm netconsole autofs4 hidp rfcomm
l2cap bluetooth sunrpc nf_conntrack_netbios_ns nf_conntrack_ipv4 xt_state
nf_conntrack nfnetlink ipt_REJECT iptable_filter ip_tables xt_tcpudp ip6t_REJECT
ip6table_filter ip6_tables x_tables cpufreq_ondemand dm_multipath video sbs
i2c_ec dock button battery asus_acpi backlight ac ipv6 lp fw_sbp2 snd_hda_intel
snd_hda_codec snd_seq_dummy snd_seq_oss snd_seq_midi_event snd_seq
snd_seq_device snd_pcm_oss snd_mixer_oss parport_pc fw_ohci fw_core parport
snd_pcm i2c_i801 serio_raw pcspkr ata_generic i2c_core snd_timer iTCO_wdt snd
sr_mod iTCO_vendor_support cdrom shpchp e1000 soundcore snd_page_alloc sg
dm_snapshot dm_zero dm_mirror dm_mod pata_marvell ahci libata sd_mod scsi_mod
ext3 jbd mbcache ehci_hcd ohci_hcd uhci_hcd
Pid: 9, comm: events/1 Not tainted 2.6.20-1.2925.fc7 #1
RIP: 0010:[<ffffffff80342f27>]  [<ffffffff80342f27>] __list_add+0x47/0x5b
RSP: 0018:ffff81007e629c40  EFLAGS: 00010086
RAX: 0000000000000079 RBX: ffff810076886868 RCX: ffffffff806e07d9
RDX: ffff81007e3c6080 RSI: 0000000000000000 RDI: ffffffff80568ac0
RBP: ffff81007e629c40 R08: ffffffff80568af0 R09: 0000000000000086
R10: ffffffff80289d0b R11: 0000000000000000 R12: ffff81007e684000
R13: ffff81007e684000 R14: 0000000100009c18 R15: 0000000000000000
FS:  0000000000000000(0000) GS:ffff81007e6f20a0(0000) knlGS:0000000000000000
CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
CR2: 00002aaaab1b9030 CR3: 0000000058e50000 CR4: 00000000000006e0
Process events/1 (pid: 9, threadinfo ffff81007e628000, task ffff81007e3c6080)
Stack:  ffff81007e629c50 ffffffff80293f77 ffff81007e629ca0 ffffffff8021c8a1
 0000000000000282 0000000000000046 0000000000000286 ffff810076886848
 ffff810003f714d0 ffff810076886000 ffff810076886478 0000000000000282
Call Trace:
 [<ffffffff80293f77>] internal_add_timer+0xbb/0xbd
 [<ffffffff8021c8a1>] __mod_timer+0x9d/0xbb
 [<ffffffff8029a97c>] queue_delayed_work+0x7f/0x88
 [<ffffffff8029a99e>] schedule_delayed_work+0x19/0x1b
 [<ffffffff881bc639>] :fw_core:fw_card_bm_work+0x1c1/0x2c6
 [<ffffffff80263cb0>] _spin_unlock_irq+0x2b/0x31
 [<ffffffff881bc478>] :fw_core:fw_card_bm_work+0x0/0x2c6
 [<ffffffff8024c6fd>] run_workqueue+0xa2/0x187
 [<ffffffff8024909f>] worker_thread+0x0/0x150
 [<ffffffff802491b8>] worker_thread+0x119/0x150
 [<ffffffff8028ae43>] default_wake_function+0x0/0xf
 [<ffffffff8024909f>] worker_thread+0x0/0x150
 [<ffffffff802330cc>] kthread+0xd7/0x10a
 [<ffffffff8025cf38>] child_rip+0xa/0x12
 [<ffffffff80263cb0>] _spin_unlock_irq+0x2b/0x31
 [<ffffffff8025c6bc>] restore_args+0x0/0x30
 [<ffffffff80289d0b>] task_rq_lock+0x42/0x74
 [<ffffffff80232ff5>] kthread+0x0/0x10a
 [<ffffffff8025cf2e>] child_rip+0x0/0x12


Code: 0f 0b eb fe 48 89 7e 08 48 89 37 48 89 57 08 48 89 3a c9 c3 
RIP  [<ffffffff80342f27>] __list_add+0x47/0x5b
 RSP <ffff81007e629c40>

It the crash always reproducible on unplug?  Do you have other devices connected
or is it only the box and the drive?  I have an idea what this could be, I'll
take a look.

The inconsistent lock state is a known problem, I just need to come up with
better way of iterating over device sub-units.

The crash isn't always reproducible. I assume it's related to the drive going
off into la-la land when attempting to write a CD.

I'm seeing some of the same initial spew (but not quite as bad) when I hook up a
burner (before even powering it on).

Interestingly, the first time I hooked up the burner and powered it on, CDs
wouldn't mount anywhere and I couldn't find the device to burn on. The following
is the only feedback I get on the console when I power the drive off and on:

fw_core: phy config: card 0, new root=ffc2, gap_count=7

After completely removing the device from the firewire bus, hooking it back up
and powering it on, I now get this:

fw_core: phy config: card 0, new root=ffc2, gap_count=7
fw_core: phy config: card 0, new root=ffc2, gap_count=7
fw_core: phy config: card 0, new root=ffc2, gap_count=7
fw_core: created new fw device fw1 (5 config rom retries)
fw_core: giving up on config rom for node id ffc0
fw_sbp2: logged in to sbp2 unit fw1.0
fw_sbp2:  - management_agent_address: 0xfffff0030000
fw_sbp2:  - command_block_agent_address: 0xffc1fffff0100000
fw_sbp2:  - status write address: 0x000100000000
fw_sbp2: agent reset write rcode=0
scsi3 : SBP-2 IEEE-1394
scsi 3:0:0:0: CD-ROM            TEAC     CD-W540E         1.0B PQ: 0 ANSI: 0
sr2: scsi3-mmc drive: 48x/48x writer cd/rw xa/form2 cdda tray
sr 3:0:0:0: Attached scsi CD-ROM sr2
sr 3:0:0:0: Attached scsi generic sg4 type 5


That looks much better. However, I still don't seem to be able to access the
drive at all.


Nb: just to eliminate any concerns over the device being bad, it does work when
hooked up to an FC6 machine w/the old firewire stack, as well as under Mac OS X.

Hooking up a firewire hard drive to the same system yields the following on the
console:

fw_sbp2: management write failed, rcode 0x12
fw_sbp2: reconnect attempt 1 for fw1.0 failed, rescheduling
fw_sbp2: reconnected to unit fw1.0
fw_sbp2: agent reset write rcode=0
fw_sbp2: reconnected to unit fw1.0
fw_sbp2: agent reset write rcode=0

Drive never shows its face though.

At least the box doesn't freak out when I power things off and disconnect
them... Bouncing box w/o the firewire burner in the picture to see if behavior
is any different. Both of these devices are in ADS Pyro cases w/Oxford 911
chipsets, fwiw.

Okay, w/o the burner involved, same spew at first connection. Upon powering the
drive on, I see two 'fw_core: phy config: card 0, new root=ffc1, gap_count=5'
messages and then nada. Powering off and on does nothing. Powering off,
unplugging, replugging and powering back up results in some extra output:

fw_core: phy config: card 0, new root=ffc1, gap_count=5
fw_core: giving up on config rom for node id ffc0
fw_core: phy config: card 0, new root=ffc1, gap_count=5

But still can't get at the drive.

Should this be in a different bugzilla, perhaps?

At notting's suggestion, I rolled back to 2922 (all prior stuff was w/2925).
Much less spew just connecting devices:

fw_core: giving up on config rom for node id 1
fw_core: giving up on config rom for node id 0

Powering on both devices (hard drive, then burner) results in no additional
output though. Disconnecting and reconnecting, then powering up again results in
the same two lines of output as above.

There's three different things going on in this bug:

  - the 'lock inconsistent' warning which is dues to calling
device_for_each_child() in IRQ context.

  - the oops, which looks like the reconnect tasklet got scheduled and then the
device got freed, screwing up the keventd job queue

  - failure to connect to oxford fw911 based drives.

And we should probably have seperate bugzillas.  Btw. this log output

  fw_core: phy config: card 0, new root=ffc2, gap_count=7

it harmless and just means that the stack is reconfiguring the bus.

Jarod are you here in Westford?  I'd like to take a look at those drives.

Yep, I'm in Westford.

The lock order warning is fixed, the crash on power down should be fixed, I'll
increase the timeouts and number of retries so the devices are detected from
powerup.  I'm using Jarods harddisk and cdrom without problems now, just booted
off of a fedora rescue cd burned on the burner.

Ooh, cool! In that case, I'd like to swipe 'em back from ya and start playing
with 'em again, see if anything blows up on different arches or firewire
controllers... :)

Unfortunately, neither the CD-RW or HD seem to want to play nice on the box I'd
had them hooked to where I previously captured output (now running kernel
2.6.20-1.2999.fc6.i686). All I see while powering up, powering down, unplugging,
plugging, powering back up, etc. is:

fw_core: phy config: card 0, new root=ffc1, gap_count=5
fw_core: phy config: card 0, new root=ffc2, gap_count=7
fw_core: phy config: card 0, new root=ffc2, gap_count=7
fw_core: giving up on config rom for node id ffc1
fw_core: giving up on config rom for node id ffc0
fw_core: phy config: card 0, new root=ffc2, gap_count=7
fw_core: phy config: card 0, new root=ffc2, gap_count=7
fw_core: phy config: card 0, new root=ffc2, gap_count=7

Firewire stack hates my controller, perhaps? Its the firewire port on a
SoundBlaster Audigy.

I'll move the drives to another system and see what I can see there...

Okay, same kernel and arch, different box and firewire controller, things look
much better:

07:01.0 FireWire (IEEE 1394): Texas Instruments TSB43AB23 IEEE-1394a-2000
Controller (PHY/Link) (prog-if 10 [OHCI])
        Subsystem: Intel Corporation Unknown device e302
        Flags: bus master, medium devsel, latency 32, IRQ 21
        Memory at 50204000 (32-bit, non-prefetchable) [size=2K]
        Memory at 50200000 (32-bit, non-prefetchable) [size=16K]
        Capabilities: [44] Power Management version 2

With that controller, I've got access to both the cd-rw drive and hard drive.

Very interesting - can you lend me the audigy controller for a few days?

So... The audigy works fine in Kristian's box, and the card that worked in one
box does NOT work in the same box where the audigy originally resided.

In semi-related news, I tried out the same devices with my PowerBook. Ouch.
First time I've ever seen xmon on a PowerBook... :) (will open another bz for
that one).

Upon unplugging and replugging the devices, I got the CD-RW drive to show up
when it was powered up. Once I powered up the hard drive though, I got a kernel
panic. Smells very similar to what happened with the PowerBook. That's all filed
as bug 235463 now.

Bill, all better with current builds?

fw bridge isn't available ATM. Feel free to close.

Whoops, found it. No strange noise anymore.

Could someone put this bug entry to rest please?  :-)