I have an Opteron-based machine that has 1 Unibrain Fireboard 800 and
1 Indigita IDT804 card (4 separate 1394 controllers). Sometimes upon
bus reset, one of the controllers is lost. By lost, I mean that
debugging printouts in /var/log/messages which are usually prefixed
"fw-hostXYZ" are gone. Additionally, I have software that (among
other things) installs a bus reset handler for each port that it uses,
and the handler is never called after the controller vanishes from the
log. However, the problem can occur without my ever loading that
software: it's just a handy way of confirming that the controller is
missing. Note that all ports show up with a raw1394_new_handle() and
raw1394_get_port_info(), etc., and a raw1394_set_port() succeeds.
I originally noticed this under 2.6.16-rt29, but have had the same
results with both plain 2.6.16 and 2.6.18 (though it was much harder
to reproduce with the non-rt kernels). It appears to be timing
related, in that it doesn't appear possible to predict on which bus
reset it might occur. On the -rt kernel, I've had it appear as
quickly as the 2nd bus reset after boot, but with 2.6.18 it's taken
perhaps 40 resets to cause the problem. I cause the resets using a
DAP Firespy, which has a GUI button for causing a bus reset.
I'm appending a bit of the /var/log/messages from the machine. I am
running with the excessive debugging info, and the problem always
occurs sometime after the statement "PhyReqFilter=000..." is printed.
The hosts that continue to work always print "IntEvent: 00020010"
thereafter, but never the broken one.
It is possible to restore functionality to the lost port by rmmod'ing
ohci1394 and then modprobing it.
Please let me know what I can do to help track this down and fix it.
--
Robert Crocombe
[email protected]
This log is from a bus with 18 nodes on it. As noted, there are 5
ports on the machine. At the point when this occurred, I was clicking
the bus reset button on the analyzer like a chimp. "fw-host3" is the
host that is lost: host0 is the single port on the Fireboard, and 1-4
are on the Indigita. Which port is lost varies from occurrence to
occurrence, but it actually had never been anything other than 2 or 4
until it happened to 3 on this attempt. This problem has occurred
with several different machines (even after swapping to different
Indigita cards).
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host0: IntEvent: 00020010
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host4: IntEvent: 00020000
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host4: irq_handler: Bus
reset requested
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host4: Cancel request received
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host1: IntEvent: 00020010
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host1: irq_handler: Bus
reset requested
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host1: Cancel request received
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host4: IntEvent: 00000010
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host1: Got RQPkt interrupt
status=0x00008409
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host4: Got RQPkt interrupt
status=0x00008409
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host2: IntEvent: 00020010
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host0: irq_handler: Bus
reset requested
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host0: Cancel request received
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host2: irq_handler: Bus
reset requested
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host2: Cancel request received
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host0: Got RQPkt interrupt
status=0x00008409
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host3: IntEvent: 00020010
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host3: irq_handler: Bus
reset requested
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host3: Cancel request received
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host2: Got RQPkt interrupt
status=0x00008409
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host2: Single packet rcv'd
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host2: Single packet rcv'd
Nov 22 07:59:54 spanky kernel: ohci1394: fw-host4: Single packet rcv'd
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host3: Got RQPkt interrupt
status=0x00008409
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host3: Single packet rcv'd
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host3: Single packet rcv'd
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host0: Single packet rcv'd
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host1: Single packet rcv'd
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host1: Single packet rcv'd
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: Single packet rcv'd
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host0: IntEvent: 00010000
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host0: SelfID interrupt
received (phyid 8, not root)
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host1: IntEvent: 00010000
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host1: SelfID interrupt
received (phyid 5, not root)
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: IntEvent: 00010000
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID interrupt
received (phyid 6, not root)
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host1: SelfID packet
0x803fc094 received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x803fc094 received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x817fc494 received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x823fc4f8 received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x837fc494 received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x843fc4f8 received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x857fc494 received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x867fc494 received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID for this
node is 0x867fc494
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x873fc4f8 received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x887fc45a received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x893fc458 received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8a3fc4da received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8b3fc496 received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8c3fc4bc received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8d3fc49c received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8e3fc4bc received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8f3fc4fa received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x903fc494 received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID packet
0x913fc4fc received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: SelfID complete
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host4: PhyReqFilter=0000000000000000
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host1: SelfID packet
0x817fc494 received
Nov 22 07:59:55 spanky kernel: ohci1394: fw-host1: SelfID packet
0x823fc4f8 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host1: SelfID packet
0x837fc494 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host1: SelfID packet
0x843fc4f8 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host1: SelfID packet
0x857fc494 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host1: SelfID for this
node is 0x857fc494
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host1: SelfID packet
0x867fc494 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host1: SelfID packet
0x873fc4f8 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host1: SelfID packet
0x887fc45a received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host1: SelfID packet
0x893fc458 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8a3fc4da received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8b3fc496 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8c3fc4bc received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8d3fc49c received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: IntEvent: 00010000
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID interrupt
received (phyid 1, not root)
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8e3fc4bc received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x803fc094 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x817fc494 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID for this
node is 0x817fc494
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x823fc4f8 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x837fc494 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x843fc4f8 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x857fc494 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x867fc494 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x873fc4f8 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x887fc45a received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x893fc458 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8a3fc4da received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8b3fc496 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8c3fc4bc received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8d3fc49c received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8e3fc4bc received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8f3fc4fa received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x903fc494 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID packet
0x913fc4fc received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: SelfID complete
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host2: PhyReqFilter=0000000000000000
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8f3fc4fa received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host1: SelfID packet
0x903fc494 received
Nov 22 07:59:56 spanky kernel: ohci1394: fw-host1: SelfID packet
0x913fc4fc received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host1: SelfID complete
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host1: PhyReqFilter=0000000000000000
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x803fc094 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x817fc494 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x823fc4f8 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x837fc494 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x843fc4f8 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x857fc494 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x867fc494 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x873fc4f8 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x887fc45a received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID for this
node is 0x887fc45a
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x893fc458 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8a3fc4da received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8b3fc496 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8c3fc4bc received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8d3fc49c received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8e3fc4bc received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8f3fc4fa received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x903fc494 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID packet
0x913fc4fc received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: SelfID complete
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host0: PhyReqFilter=0000000000000000
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: IntEvent: 00010000
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: SelfID interrupt
received (phyid 3, not root)
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: SelfID packet
0x803fc094 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: SelfID packet
0x817fc494 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: SelfID packet
0x823fc4f8 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: SelfID packet
0x837fc494 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: SelfID for this
node is 0x837fc494
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: SelfID packet
0x843fc4f8 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: SelfID packet
0x857fc494 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: SelfID packet
0x867fc494 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: SelfID packet
0x873fc4f8 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: SelfID packet
0x887fc45a received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: SelfID packet
0x893fc458 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8a3fc4da received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8b3fc496 received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8c3fc4bc received
Nov 22 07:59:57 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8d3fc49c received
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8e3fc4bc received
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8f3fc4fa received
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host3: SelfID packet
0x903fc494 received
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host3: SelfID packet
0x913fc4fc received
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host3: SelfID complete
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host3: PhyReqFilter=0000000000000000
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host4: IntEvent: 00020010
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host1: IntEvent: 00020010
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host1: irq_handler: Bus
reset requested
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host1: Cancel request received
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host4: irq_handler: Bus
reset requested
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host4: Cancel request received
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host1: Got RQPkt interrupt
status=0x00008409
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host4: Got RQPkt interrupt
status=0x00008409
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host0: IntEvent: 00020010
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host0: irq_handler: Bus
reset requested
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host0: Cancel request received
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host2: IntEvent: 00020010
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host0: Got RQPkt interrupt
status=0x00008409
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host2: irq_handler: Bus
reset requested
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host2: Cancel request received
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host3: IntEvent: 00020010
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host3: irq_handler: Bus
reset requested
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host3: Cancel request received
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host3: Got RQPkt interrupt
status=0x00008409
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host2: Got RQPkt interrupt
status=0x00008409
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host3: Single packet rcv'd
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host2: Single packet rcv'd
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host4: Single packet rcv'd
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host0: Single packet rcv'd
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host1: Single packet rcv'd
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host0: IntEvent: 00010000
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host0: SelfID interrupt
received (phyid 11, not root)
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host0: SelfID packet
0x807fc494 received
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host1: IntEvent: 00010000
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host4: IntEvent: 00010000
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host1: SelfID interrupt
received (phyid 0, not root)
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host4: SelfID interrupt
received (phyid 1, not root)
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host4: SelfID packet
0x807fc494 received
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host1: SelfID packet
0x807fc494 received
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host1: SelfID for this
node is 0x807fc494
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host1: SelfID packet
0x817fc494 received
Nov 22 07:59:58 spanky kernel: ohci1394: fw-host1: SelfID packet
0x823fc4f8 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: SelfID packet
0x833fc096 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: SelfID packet
0x847fc494 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: SelfID packet
0x853fc4f8 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: SelfID packet
0x867fc494 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: SelfID packet
0x873fc4f8 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: SelfID packet
0x883fc494 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: SelfID packet
0x893fc4ec received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8a3fc4ec received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8b7fc458 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8c3fc4f8 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8d3fc4d8 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8e3fc458 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8f3fc4d8 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: SelfID packet
0x903fc494 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: SelfID packet
0x913fc4fc received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: SelfID complete
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host1: PhyReqFilter=0000000000000000
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host4: SelfID packet
0x817fc494 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host4: SelfID for this
node is 0x817fc494
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host4: SelfID packet
0x823fc4f8 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host4: SelfID packet
0x833fc096 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host4: SelfID packet
0x847fc494 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host4: SelfID packet
0x853fc4f8 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host4: SelfID packet
0x867fc494 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host4: SelfID packet
0x873fc4f8 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host4: SelfID packet
0x883fc494 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host4: SelfID packet
0x893fc4ec received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8a3fc4ec received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8b7fc458 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8c3fc4f8 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8d3fc4d8 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host0: SelfID packet
0x817fc494 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host0: SelfID packet
0x823fc4f8 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host0: SelfID packet
0x833fc096 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host0: SelfID packet
0x847fc494 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host0: SelfID packet
0x853fc4f8 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host0: SelfID packet
0x867fc494 received
Nov 22 07:59:59 spanky kernel: ohci1394: fw-host0: SelfID packet
0x873fc4f8 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host0: SelfID packet
0x883fc494 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host0: SelfID packet
0x893fc4ec received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8a3fc4ec received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8b7fc458 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host0: SelfID for this
node is 0x8b7fc458
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8c3fc4f8 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8d3fc4d8 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8e3fc458 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8f3fc4d8 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host0: SelfID packet
0x903fc494 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host0: SelfID packet
0x913fc4fc received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host0: SelfID complete
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host0: PhyReqFilter=0000000000000000
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8e3fc458 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8f3fc4d8 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host4: SelfID packet
0x903fc494 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host4: SelfID packet
0x913fc4fc received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host4: SelfID complete
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host4: PhyReqFilter=0000000000000000
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host3: IntEvent: 00010000
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host3: SelfID interrupt
received (phyid 6, not root)
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host3: SelfID packet
0x807fc494 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host3: SelfID packet
0x817fc494 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host3: SelfID packet
0x823fc4f8 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host3: SelfID packet
0x833fc096 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host3: SelfID packet
0x847fc494 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host3: SelfID packet
0x853fc4f8 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host2: IntEvent: 00010000
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host3: SelfID packet
0x867fc494 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host2: SelfID interrupt
received (phyid 4, not root)
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host2: SelfID packet
0x807fc494 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host2: SelfID packet
0x817fc494 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host2: SelfID packet
0x823fc4f8 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host2: SelfID packet
0x833fc096 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host2: SelfID packet
0x847fc494 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host2: SelfID for this
node is 0x847fc494
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host2: SelfID packet
0x853fc4f8 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host2: SelfID packet
0x867fc494 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host2: SelfID packet
0x873fc4f8 received
Nov 22 08:00:00 spanky kernel: ohci1394: fw-host2: SelfID packet
0x883fc494 received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host2: SelfID packet
0x893fc4ec received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8a3fc4ec received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8b7fc458 received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8c3fc4f8 received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8d3fc4d8 received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8e3fc458 received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8f3fc4d8 received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host2: SelfID packet
0x903fc494 received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host2: SelfID packet
0x913fc4fc received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host2: SelfID complete
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host2: PhyReqFilter=0000000000000000
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: SelfID for this
node is 0x867fc494
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: SelfID packet
0x873fc4f8 received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: SelfID packet
0x883fc494 received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: SelfID packet
0x893fc4ec received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8a3fc4ec received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8b7fc458 received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8c3fc4f8 received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8d3fc4d8 received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8e3fc458 received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8f3fc4d8 received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: SelfID packet
0x903fc494 received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: SelfID packet
0x913fc4fc received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: SelfID complete
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: PhyReqFilter=0000000000000000
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host4: IntEvent: 00020010
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host4: irq_handler: Bus
reset requested
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host4: Cancel request received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host1: IntEvent: 00020010
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host1: irq_handler: Bus
reset requested
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host1: Cancel request received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host4: Got RQPkt interrupt
status=0x00008409
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host1: Got RQPkt interrupt
status=0x00008409
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host2: IntEvent: 00020010
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host0: IntEvent: 00020010
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host0: irq_handler: Bus
reset requested
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host0: Cancel request received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host2: irq_handler: Bus
reset requested
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host0: Got RQPkt interrupt
status=0x00008409
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host2: Cancel request received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: IntEvent: 00020010
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: irq_handler: Bus
reset requested
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: Cancel request received
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host2: Got RQPkt interrupt
status=0x00008409
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host3: Got RQPkt interrupt
status=0x00008409
Nov 22 08:00:01 spanky kernel: ohci1394: fw-host2: Single packet rcv'd
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host3: Single packet rcv'd
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host3: Single packet rcv'd
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host0: Single packet rcv'd
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: Single packet rcv'd
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: Single packet rcv'd
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host2: Single packet rcv'd
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host4: Single packet rcv'd
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host4: Single packet rcv'd
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host0: IntEvent: 00010000
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host0: SelfID interrupt
received (phyid 7, not root)
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: IntEvent: 00010000
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host4: IntEvent: 00010000
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID interrupt
received (phyid 4, not root)
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host4: SelfID interrupt
received (phyid 5, not root)
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host4: SelfID packet
0x803fc094 received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x803fc094 received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x817fc494 received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x823fc4f8 received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x837fc494 received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x847fc494 received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID for this
node is 0x847fc494
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x857fc494 received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x863fc4f8 received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x877fc45a received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x883fc458 received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x893fc4da received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8a3fc496 received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8b3fc4bc received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8c3fc49c received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8d3fc4bc received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8e3fc4fa received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8f3fc494 received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x903fc4bc received
Nov 22 08:00:02 spanky kernel: ohci1394: fw-host1: SelfID packet
0x913fc4fc received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host1: SelfID complete
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host1: PhyReqFilter=0000000000000000
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x817fc494 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x823fc4f8 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x837fc494 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x847fc494 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x857fc494 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID for this
node is 0x857fc494
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x863fc4f8 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x877fc45a received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x883fc458 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x893fc4da received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8a3fc496 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8b3fc4bc received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8c3fc49c received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8d3fc4bc received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x803fc094 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x817fc494 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x823fc4f8 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x837fc494 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x847fc494 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x857fc494 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x863fc4f8 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x877fc45a received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID for this
node is 0x877fc45a
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x883fc458 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x893fc4da received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8a3fc496 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8b3fc4bc received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8c3fc49c received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8d3fc4bc received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8e3fc4fa received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8f3fc494 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x903fc4bc received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID packet
0x913fc4fc received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: SelfID complete
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host0: PhyReqFilter=0000000000000000
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8e3fc4fa received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x8f3fc494 received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x903fc4bc received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID packet
0x913fc4fc received
Nov 22 08:00:03 spanky kernel: ohci1394: fw-host4: SelfID complete
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host4: PhyReqFilter=0000000000000000
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host3: IntEvent: 00010000
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host3: SelfID interrupt
received (phyid 3, not root)
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host3: SelfID packet
0x803fc094 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host3: SelfID packet
0x817fc494 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host3: SelfID packet
0x823fc4f8 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host3: SelfID packet
0x837fc494 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host3: SelfID for this
node is 0x837fc494
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host3: SelfID packet
0x847fc494 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: IntEvent: 00010000
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host3: SelfID packet
0x857fc494 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID interrupt
received (phyid 1, not root)
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x803fc094 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x817fc494 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID for this
node is 0x817fc494
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x823fc4f8 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x837fc494 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x847fc494 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x857fc494 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x863fc4f8 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x877fc45a received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x883fc458 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x893fc4da received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8a3fc496 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8b3fc4bc received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8c3fc49c received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8d3fc4bc received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8e3fc4fa received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8f3fc494 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x903fc4bc received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID packet
0x913fc4fc received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: SelfID complete
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host2: PhyReqFilter=0000000000000000
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host3: SelfID packet
0x863fc4f8 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host3: SelfID packet
0x877fc45a received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host3: SelfID packet
0x883fc458 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host3: SelfID packet
0x893fc4da received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8a3fc496 received
Nov 22 08:00:04 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8b3fc4bc received
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8c3fc49c received
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8d3fc4bc received
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8e3fc4fa received
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host3: SelfID packet
0x8f3fc494 received
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host3: SelfID packet
0x903fc4bc received
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host3: SelfID packet
0x913fc4fc received
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host3: SelfID complete
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host3: PhyReqFilter=0000000000000000
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host4: IntEvent: 00020010
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host1: IntEvent: 00020010
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host1: irq_handler: Bus
reset requested
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host1: Cancel request received
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host4: irq_handler: Bus
reset requested
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host4: Cancel request received
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host1: Got RQPkt interrupt
status=0x00008409
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host4: Got RQPkt interrupt
status=0x00008409
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host0: IntEvent: 00020010
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host0: irq_handler: Bus
reset requested
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host0: Cancel request received
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host2: IntEvent: 00020010
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host2: irq_handler: Bus
reset requested
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host2: Cancel request received
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host2: Got RQPkt interrupt
status=0x00008409
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host0: Got RQPkt interrupt
status=0x00008409
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host0: Single packet rcv'd
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host2: Single packet rcv'd
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host4: Single packet rcv'd
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host1: Single packet rcv'd
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host0: IntEvent: 00010000
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host0: SelfID interrupt
received (phyid 11, not root)
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host0: SelfID packet
0x807fc494 received
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host1: IntEvent: 00010000
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host1: SelfID interrupt
received (phyid 0, not root)
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host4: IntEvent: 00010000
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host4: SelfID interrupt
received (phyid 1, not root)
Nov 22 08:00:05 spanky kernel: ohci1394: fw-host1: SelfID packet
0x807fc494 received
There is nothing from fw-host3 until I rmmod ohci1394 later:
Nov 22 08:12:32 spanky kernel: ohci1394: fw-host4: Soft reset finished
Nov 22 08:12:32 spanky kernel: ohci1394: fw-host1: IntEvent: 00020010
Nov 22 08:12:32 spanky kernel: ohci1394: fw-host1: irq_handler: Bus
reset requested
Nov 22 08:12:32 spanky kernel: ohci1394: fw-host2: IntEvent: 00020010
Nov 22 08:12:32 spanky kernel: ohci1394: fw-host1: Cancel request received
Nov 22 08:12:32 spanky kernel: ohci1394: fw-host2: irq_handler: Bus
reset requested
Nov 22 08:12:32 spanky kernel: ohci1394: fw-host2: Cancel request received
Nov 22 08:12:32 spanky kernel: ohci1394: fw-host1: Got RQPkt interrupt
status=0x00008409
Nov 22 08:12:32 spanky kernel: ohci1394: fw-host4: Freeing dma_rcv_ctx 0
Nov 22 08:12:32 spanky kernel: ohci1394: fw-host2: Got RQPkt interrupt
status=0x00008409
Nov 22 08:12:32 spanky kernel: ohci1394: fw-host1: Single packet rcv'd
Nov 22 08:12:32 spanky kernel: ohci1394: fw-host4: Freeing dma_rcv_ctx 0
Nov 22 08:12:32 spanky kernel: ohci1394: fw-host0: IntEvent: 00020010
Nov 22 08:12:32 spanky kernel: ohci1394: fw-host4: Freeing dma_trm_ctx 0
Nov 22 08:12:32 spanky kernel: ohci1394: fw-host0: irq_handler: Bus
reset requested
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host0: Cancel request received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host0: Got RQPkt interrupt
status=0x00008409
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host0: Single packet rcv'd
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host4: Freeing dma_trm_ctx 1
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host4: Freeing dma_rcv_ctx 0
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: Single packet rcv'd
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: IntEvent: 00010000
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host0: IntEvent: 00010000
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID interrupt
received (phyid 4, not root)
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host0: SelfID interrupt
received (phyid 11, not root)
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x807fc494 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x813fc496 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x823fc4f8 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x833fc094 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x847fc494 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID for this
node is 0x847fc494
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x853fc4f8 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x867fc494 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x873fc4f8 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x883fc494 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x893fc4ec received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8a3fc4ec received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8b7fc458 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8c3fc458 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8d3fc4d8 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8e3fc494 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x8f3fc4bc received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x903fc49c received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID packet
0x913fc4fc received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: SelfID complete
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host0: SelfID packet
0x807fc494 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host2: PhyReqFilter=0000000000000000
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host0: SelfID packet
0x813fc496 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host0: SelfID packet
0x823fc4f8 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host0: SelfID packet
0x833fc094 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host0: SelfID packet
0x847fc494 received
Nov 22 08:12:33 spanky kernel: ohci1394: fw-host0: SelfID packet
0x853fc4f8 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host0: SelfID packet
0x867fc494 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host0: SelfID packet
0x873fc4f8 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host0: SelfID packet
0x883fc494 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host0: SelfID packet
0x893fc4ec received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8a3fc4ec received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8b7fc458 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host0: SelfID for this
node is 0x8b7fc458
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8c3fc458 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8d3fc4d8 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8e3fc494 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host0: SelfID packet
0x8f3fc4bc received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host0: SelfID packet
0x903fc49c received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host0: SelfID packet
0x913fc4fc received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host0: SelfID complete
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: IntEvent: 00010000
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host0: PhyReqFilter=0000000000000000
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID interrupt
received (phyid 0, not root)
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x807fc494 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID for this
node is 0x807fc494
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x813fc496 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x823fc4f8 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x833fc094 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x847fc494 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x853fc4f8 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x867fc494 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x873fc4f8 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x883fc494 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x893fc4ec received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8a3fc4ec received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8b7fc458 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8c3fc458 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8d3fc4d8 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8e3fc494 received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x8f3fc4bc received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x903fc49c received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID packet
0x913fc4fc received
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: SelfID complete
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host1: PhyReqFilter=0000000000000000
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host3: Soft reset finished
Nov 22 08:12:34 spanky kernel: ohci1394: fw-host0: IntEvent: 00020010
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host2: IntEvent: 00020010
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host0: irq_handler: Bus
reset requested
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host2: irq_handler: Bus
reset requested
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host0: Cancel request received
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host2: Cancel request received
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host0: Got RQPkt interrupt
status=0x00008409
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host3: Freeing dma_rcv_ctx 0
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host0: Single packet rcv'd
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host2: Got RQPkt interrupt
status=0x00008409
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host1: IntEvent: 00020010
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host3: Freeing dma_rcv_ctx 0
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host1: irq_handler: Bus
reset requested
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host3: Freeing dma_trm_ctx 0
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host1: Cancel request received
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host3: Freeing dma_trm_ctx 1
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host1: Got RQPkt interrupt
status=0x00008409
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host3: Freeing dma_rcv_ctx 0
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host1: Single packet rcv'd
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host2: Single packet rcv'd
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host2: Soft reset finished
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host1: IntEvent: 00000010
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host0: IntEvent: 00000010
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host1: Got RQPkt interrupt
status=0x00008409
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host0: Got RQPkt interrupt
status=0x00008409
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host1: Single packet rcv'd
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host1: Single packet rcv'd
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host2: Freeing dma_rcv_ctx 0
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host0: Single packet rcv'd
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host2: Freeing dma_rcv_ctx 0
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host2: Freeing dma_trm_ctx 0
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host2: Freeing dma_trm_ctx 1
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host2: Freeing dma_rcv_ctx 0
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host1: Soft reset finished
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host1: Freeing dma_rcv_ctx 0
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host1: Freeing dma_rcv_ctx 0
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host1: Freeing dma_trm_ctx 0
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host1: Freeing dma_trm_ctx 1
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host1: Freeing dma_rcv_ctx 0
Nov 22 08:12:35 spanky kernel: ohci1394: fw-host0: IntEvent: 00010000
Robert Crocombe wrote:
> I have an Opteron-based machine that has 1 Unibrain Fireboard 800 and
> 1 Indigita IDT804 card (4 separate 1394 controllers). Sometimes upon
> bus reset, one of the controllers is lost. By lost, I mean that
> debugging printouts in /var/log/messages which are usually prefixed
> "fw-hostXYZ" are gone.
[...]
IOW, ohci1394's bus reset handler is never called again.
Does this happen only if you reset all buses at once?
Does it only happen on the Indigita card or also on the Unibrain card?
Do the controllers share IRQs?
Does it happen if there is no transmission or reception going on?
It would be nice if you create an entry at bugzilla.kernel.org. If you
do, also add a link to an archive of this discussion, e.g.
http://lkml.org/lkml/2006/11/22/122 .
Maybe it's related to http://bugzilla.kernel.org/show_bug.cgi?id=6070
(use of msleep busy-wait loops in ohci1394's interrupt handler's
context). Whatever it is, the fact that you lose interrupt events only
after a bus reset & selfID complete event strongly indicates that there
is something wrong with the drivers' low-level bus reset handling. OTOH
I don't remember a similar report.
One thing you could try next is to add a debug logging macro which
prints the contents of OHCI1394_IntEventClear, OHCI1394_IntEventSet, and
OHCI1394_IntMaskSet, right after ohci1394's call to
hpsb_selfid_complete. (I'm merely poking in the dark here.)
--
Stefan Richter
-=====-=-==- =-== =-==-
http://arcgraph.de/sr/
On 11/22/06, Stefan Richter <[email protected]> wrote:
> It would be nice if you create an entry at bugzilla.kernel.org.
Okay, bug # is 7569.
> One thing you could try next is to add a debug logging macro which
> prints the contents of OHCI1394_IntEventClear, OHCI1394_IntEventSet, and
> OHCI1394_IntMaskSet, right after ohci1394's call to
> hpsb_selfid_complete. (I'm merely poking in the dark here.)
We're just entering a holiday weekend here (Thursday is Thanksgiving),
but I will try when I return on Monday.
Thanks.
--
Robert Crocombe
[email protected]
On 11/22/06, Stefan Richter <[email protected]> wrote:
> One thing you could try next is to add a debug logging macro which
> prints the contents of OHCI1394_IntEventClear, OHCI1394_IntEventSet, and
> OHCI1394_IntMaskSet, right after ohci1394's call to
> hpsb_selfid_complete. (I'm merely poking in the dark here.)
I think you've got something! I managed to provoke failure from 3 of
the 5 interfaces in a single burst of reset clicking! And yes, all 3
failed interfaces are on the Indigita card, and no, the Fireboard has
never failed.
The last thing I see from the failed interfaces is this:
Nov 27 08:25:51 spanky kernel: ohci1394: fw-host3: PhyReqFilter=0000000000000000
Nov 27 08:25:51 spanky kernel: ohci1394: fw-host3: IntEventClear
00000000 IntEventSet 6ffdc33f IntMaskSet 00000000
which looks very different from the entries by the interfaces that
survive (these are the lines immediately before the one above)
Nov 27 08:25:51 spanky kernel: ohci1394: fw-host4: IntEventClear
00000000 IntEventSet 04508000 IntMaskSet 818300f3
Nov 27 08:25:51 spanky kernel:
Nov 27 08:25:51 spanky kernel: ohci1394: fw-host2: IntEventClear
00000000 IntEventSet 04508000 IntMaskSet 818300f3
Nov 27 08:25:51 spanky kernel:
I'm not sure if this says anything to you except "hey, don't use those
Indigita cards". The problem is, I can't get the number of ports I
need using only Fireboards (I think I need 6, and I have 5 PCI slots
but need to use some of the other slots).
Is there further diagnostic poking about that I can do to narrow down
the problem? Is something for Indigita? The card is pretty basic: 4
of the TI TSB82AA2 (Ice Lynx) links behind a IBM/Tundra PCI-X bridge.
I have an Intel quad ethernet card that uses the exact same part
(well, one rev older, actually). Here's a chunk of my lspci for
completeness sake:
01:04.0 PCI bridge: IBM PCI-X to PCI-X Bridge (rev 03)
01:06.0 FireWire (IEEE 1394): Texas Instruments TSB82AA2 IEEE-1394b
Link Layer Controller (rev 01)
02:04.0 FireWire (IEEE 1394): Texas Instruments TSB82AA2 IEEE-1394b
Link Layer Controller (rev 01)
02:05.0 FireWire (IEEE 1394): Texas Instruments TSB82AA2 IEEE-1394b
Link Layer Controller (rev 01)
02:06.0 FireWire (IEEE 1394): Texas Instruments TSB82AA2 IEEE-1394b
Link Layer Controller (rev 01)
02:07.0 FireWire (IEEE 1394): Texas Instruments TSB82AA2 IEEE-1394b
Link Layer Controller (rev 01)
I will also try cramming a machine full of Fireboards and seeing if I
can't get one of them to fail.
--
Robert Crocombe
[email protected]
On 11/27/2006 4:39 PM, Robert Crocombe wrote:
> On 11/22/06, Stefan Richter <[email protected]> wrote:
>> One thing you could try next is to add a debug logging macro which
>> prints the contents of OHCI1394_IntEventClear, OHCI1394_IntEventSet, and
>> OHCI1394_IntMaskSet, right after ohci1394's call to
>> hpsb_selfid_complete. (I'm merely poking in the dark here.)
>
> I think you've got something! I managed to provoke failure from 3 of
> the 5 interfaces in a single burst of reset clicking! And yes, all 3
> failed interfaces are on the Indigita card, and no, the Fireboard has
> never failed.
>
> The last thing I see from the failed interfaces is this:
>
> Nov 27 08:25:51 spanky kernel: ohci1394: fw-host3: PhyReqFilter=0000000000000000
> Nov 27 08:25:51 spanky kernel: ohci1394: fw-host3: IntEventClear
> 00000000 IntEventSet 6ffdc33f IntMaskSet 00000000
Zero bits in the mask mean that the chip will not generate a processor
interrupt for the type of event represented by the bit. And the
difference between what can be read from IntEventClear and IntEventSet
is that the former is the masked version of the latter.
You probably noticed yourself that ohci1394's interrupt handler
explicitly enables some bits in the interrupt mask shortly before the
call to hpsb_selfid_complete. This means there is either something going
wrong during hpsb_selfid_complete (which wouldn't surprise me, since
there are busy wait loops involved) or the write access to the interrupt
mask wasn't flushed soon enough.
> which looks very different from the entries by the interfaces that
> survive (these are the lines immediately before the one above)
>
> Nov 27 08:25:51 spanky kernel: ohci1394: fw-host4: IntEventClear
> 00000000 IntEventSet 04508000 IntMaskSet 818300f3
> Nov 27 08:25:51 spanky kernel:
> Nov 27 08:25:51 spanky kernel: ohci1394: fw-host2: IntEventClear
> 00000000 IntEventSet 04508000 IntMaskSet 818300f3
> Nov 27 08:25:51 spanky kernel:
This mask looks much better.
> I'm not sure if this says anything to you except "hey, don't use those
> Indigita cards". The problem is, I can't get the number of ports I
> need using only Fireboards (I think I need 6, and I have 5 PCI slots
> but need to use some of the other slots).
[...]
As you wrote, both cards use the same link layer controller, although
they could have different chip revisions. The controllers of the
Indigita card sit behind the bridge, which /perhaps/ contributes to the
problem. But perhaps more importantly, how are the IRQs distributed?
# cat /proc/interrupts
Anyway, I think a driver problem is more likely the cause than a
potential hardware issue.
Please add
reg_read(ohci, OHCI1394_IntMaskSet);
right before hpsb_selfid_complete(host, phyid, isroot);. This will flush
the previous reg_write before hpsb_selfid_complete starts doing
unspeakable things.
And I should finally start to work on a fix for hpsb_selfid_complete,
i.e. move all the time-consuming but less time-critical parts off into a
tasklet or workqueue job...
Question to others:
ohci1394.c::ohci_irq_handler() is taking a per-host spinlock around some
register reads and writes, particularly:
...
spin_lock_irqsave(&ohci->event_lock, flags);
event = reg_read(ohci, OHCI1394_IntEventClear);
reg_write(ohci, OHCI1394_IntEventClear, event &
~OHCI1394_busReset);
spin_unlock_irqrestore(&ohci->event_lock, flags);
...
spin_lock_irqsave(&ohci->event_lock, flags);
reg_write(ohci, OHCI1394_IntMaskClear, OHCI1394_busReset);
run_an_insane_loop_as_an_alleged_fix_for_dorky_hardware;
spin_unlock_irqrestore(&ohci->event_lock, flags);
...
spin_lock_irqsave(&ohci->event_lock, flags);
reg_write(ohci, OHCI1394_IntEventClear, OHCI1394_busReset);
reg_write(ohci, OHCI1394_IntMaskSet, OHCI1394_busReset);
spin_unlock_irqrestore(&ohci->event_lock, flags);
I think these spinlocks are totally useless 1. because
ohci_irq_handler() is only called as the hardware interrupt servicing
routine and 2. because they don't flush the register write operations.
Right? Wrong? [Ohci1394's reg_write() is a writel().]
--
Stefan Richter
-=====-=-==- =-== ==-==
http://arcgraph.de/sr/
On 11/27/06, Stefan Richter <[email protected]> wrote:
But perhaps more importantly, how are the IRQs distributed?
> # cat /proc/interrupts
This is almost right after boot. I generated about 40 bus resets just
to stir things up a little:
CPU0 CPU1 CPU2 CPU3
0: 33660 36393 30037 69980 IO-APIC-edge timer
1: 0 0 1 10 IO-APIC-edge i8042
8: 0 0 0 0 IO-APIC-edge rtc
9: 0 0 0 0 IO-APIC-level acpi
12: 0 0 0 113 IO-APIC-edge i8042
15: 0 270 686 215 IO-APIC-edge ide1
50: 1 0 11567 7 IO-APIC-level aic79xx
58: 0 0 0 0 IO-APIC-level ehci_hcd:usb1
66: 0 0 0 0 IO-APIC-level ohci_hcd:usb2
74: 0 1 7 80 IO-APIC-level
ohci1394, ohci1394
82: 7 23 30 28 IO-APIC-level ohci1394
90: 2 28 17 71 IO-APIC-level eth0
98: 9 27 21 9182 IO-APIC-level eth1
106: 19 17 20 26 IO-APIC-level ohci1394
114: 16 26 34 12 IO-APIC-level ohci1394
233: 0 0 15 0 IO-APIC-level aic79xx
NMI: 410 78 75 77
LOC: 166733 166657 166542 166432
ERR: 0
MIS: 0
Also:
I couldn't cause the problem when using 4 Fireboard 800s through
several hundred bus resets (usually took <= 40 for the Indigita card)
> Please add
> reg_read(ohci, OHCI1394_IntMaskSet);
> right before hpsb_selfid_complete(host, phyid, isroot);. This will flush
> the previous reg_write before hpsb_selfid_complete starts doing
> unspeakable things.
Okay, so the code looks like this now:
DBGMSG("PhyReqFilter=%08x%08x",
reg_read(ohci,OHCI1394_PhyReqFilterHiSet),
reg_read(ohci,OHCI1394_PhyReqFilterLoSet));
reg_read(ohci, OHCI1394_IntMaskSet);
hpsb_selfid_complete(host, phyid, isroot);
DBGMSG( "IntEventClear %08x "
"IntEventSet %08x "
"IntMaskSet %08x",
reg_read(ohci, OHCI1394_IntEventClear),
reg_read(ohci, OHCI1394_IntEventSet),
reg_read(ohci, OHCI1394_IntMaskSet));
this is in 2.6.16-rt29 which has proved to be the easiest to provoke.
I actually couldn't get 2.6.18 to break earlier this morning (few
hundred resets).
Okay, I've lost host1 (on the Indigita), but this time the last print
statement is:
Nov 27 10:38:27 spanky kernel: ohci1394: fw-host1: IntEventClear
00000000 IntEventSet 04588000 IntMaskSet 818300f3
just like all the other hosts. I can confirm that no bus reset
handlers are called, and there are another 4,000 lines of statements
from the other hosts after the last from host1.
--
Robert Crocombe
[email protected]
Robert Crocombe wrote:
> Okay, so the code looks like this now:
>
> DBGMSG("PhyReqFilter=%08x%08x",
> reg_read(ohci,OHCI1394_PhyReqFilterHiSet),
> reg_read(ohci,OHCI1394_PhyReqFilterLoSet));
>
> reg_read(ohci, OHCI1394_IntMaskSet);
>
> hpsb_selfid_complete(host, phyid, isroot);
>
> DBGMSG( "IntEventClear %08x "
> "IntEventSet %08x "
> "IntMaskSet %08x",
> reg_read(ohci, OHCI1394_IntEventClear),
> reg_read(ohci, OHCI1394_IntEventSet),
> reg_read(ohci, OHCI1394_IntMaskSet));
OK.
> this is in 2.6.16-rt29 which has proved to be the easiest to provoke.
> I actually couldn't get 2.6.18 to break earlier this morning (few
> hundred resets).
You could replace 2.6.16-rt29/drivers/ieee1394/ by drivers/ieee1394/
from 2.6.16.28 or later plus one of the patches from
http://me.in-berlin.de/~s5r6/linux1394/updates/2.6.16.x/ and see if it
makes a difference. But judging from the changes that went in, I would
be surprised if there was any improvement.
> Okay, I've lost host1 (on the Indigita), but this time the last print
> statement is:
>
> Nov 27 10:38:27 spanky kernel: ohci1394: fw-host1: IntEventClear
> 00000000 IntEventSet 04588000 IntMaskSet 818300f3
>
> just like all the other hosts. I can confirm that no bus reset
> handlers are called, and there are another 4,000 lines of statements
> from the other hosts after the last from host1.
This is strange. The mask has bus reset and self ID received events
switched on. There is nothing manipulating this mask besides the
interrupt handler and the initialization and shutdown routines. And if
I'm not mistaken, the interrupt handler does not run concurrently to
itself for the same chip.
Ingo et al, is the -rt patched kernel fundamentally different WRT
reentrance of interrupt handlers?
--
Stefan Richter
-=====-=-==- =-== ==-==
http://arcgraph.de/sr/
I wrote:
> Question to others:
>
> ohci1394.c::ohci_irq_handler() is taking a per-host spinlock around some
> register reads and writes, particularly:
> ...
> spin_lock_irqsave(&ohci->event_lock, flags);
> event = reg_read(ohci, OHCI1394_IntEventClear);
> reg_write(ohci, OHCI1394_IntEventClear, event &
> ~OHCI1394_busReset);
> spin_unlock_irqrestore(&ohci->event_lock, flags);
> ...
> spin_lock_irqsave(&ohci->event_lock, flags);
> reg_write(ohci, OHCI1394_IntMaskClear, OHCI1394_busReset);
> run_an_insane_loop_as_an_alleged_fix_for_dorky_hardware;
> spin_unlock_irqrestore(&ohci->event_lock, flags);
> ...
> spin_lock_irqsave(&ohci->event_lock, flags);
> reg_write(ohci, OHCI1394_IntEventClear, OHCI1394_busReset);
> reg_write(ohci, OHCI1394_IntMaskSet, OHCI1394_busReset);
> spin_unlock_irqrestore(&ohci->event_lock, flags);
>
> I think these spinlocks are totally useless 1. because
> ohci_irq_handler() is only called as the hardware interrupt servicing
> routine and 2. because they don't flush the register write operations.
> Right? Wrong? [Ohci1394's reg_write() is a writel().]
Also, what is the status of ordering guarantees --- or lack thereof ---
for writel() under Linux 2.6.16 and 2.6.18? Especially in presence of a
PCI-X to PCI bridge...
--
Stefan Richter
-=====-=-==- =-== ==-==
http://arcgraph.de/sr/
Robert Crocombe wrote:
> this is in 2.6.16-rt29 which has proved to be the easiest to provoke.
> I actually couldn't get 2.6.18 to break earlier this morning (few
> hundred resets).
Okay, I got the problem to occur again with 2.6.18. I will attach my
config in case you wish to scrutinize for any boneheadedness on my
part.
I provoked the problem both with and without the additional read of
IntMaskSet. Amazingly, I lost host1 on the bus reset that occured
after this sequence:
rmmod ohci1394
rmmod ieee1394
make
make modules_install
modprobe ohci1394
which followed my adding the extra register read line. Here's the
entirety of the host1 stuff (I did a s/.*host[^1].*//g in vim). I
snipped some of the self ID chatter.
Nov 27 13:06:35 spanky kernel: ieee1394: nodemgr and IRM functionality disabled
Nov 27 13:06:35 spanky kernel: ohci1394: fw-host1: Remapped memory
spaces reg 0xffffc20000058000
Nov 27 13:06:36 spanky kernel: ohci1394: fw-host1: Soft reset finished
Nov 27 13:06:36 spanky kernel: ohci1394: fw-host1: Iso contexts reg:
000000a8 implemented: 0000000f
Nov 27 13:06:36 spanky kernel: ohci1394: fw-host1: Iso contexts reg:
00000098 implemented: 000000ff
Nov 27 13:06:36 spanky kernel: ohci1394: fw-host1: Receive DMA ctx=0 initialized
Nov 27 13:06:36 spanky kernel: ohci1394: fw-host1: Receive DMA ctx=0 initialized
Nov 27 13:06:36 spanky kernel: ohci1394: fw-host1: Transmit DMA ctx=0
initialized
Nov 27 13:06:36 spanky kernel: ohci1394: fw-host1: Transmit DMA ctx=1
initialized
Nov 27 13:06:36 spanky kernel: ohci1394: fw-host1: physUpperBoundOffset=00000000
Nov 27 13:06:36 spanky kernel: ohci1394: fw-host1: OHCI-1394 1.1
(PCI): IRQ=[98] MMIO=[f9ffe000-f9ffe7ff] Max Packet=[4096] IR/IT
contexts=[4/8]
Nov 27 13:06:37 spanky kernel: ohci1394: fw-host1: IntEvent: 00020010
Nov 27 13:06:37 spanky kernel: ohci1394: fw-host1: irq_handler: Bus
reset requested
Nov 27 13:06:37 spanky kernel: ohci1394: fw-host1: Cancel request received
Nov 27 13:06:37 spanky kernel: ohci1394: fw-host1: Got RQPkt interrupt
status=0x00008409
Nov 27 13:06:37 spanky kernel: ohci1394: fw-host1: Single packet rcv'd
Nov 27 13:06:37 spanky kernel: ohci1394: fw-host1: IntEvent: 00010000
Nov 27 13:06:37 spanky kernel: ohci1394: fw-host1: SelfID interrupt
received (phyid 1, not root)
Nov 27 13:06:37 spanky kernel: ohci1394: fw-host1: SelfID packet
0x807fc494 received
Nov 27 13:06:38 spanky kernel: ohci1394: fw-host1: SelfID packet
0x817fc494 received
Nov 27 13:06:38 spanky kernel: ohci1394: fw-host1: SelfID for this
node is 0x817fc494
Nov 27 13:06:39 spanky kernel: ohci1394: fw-host1: SelfID packet BLAH
...15 more SelfID...
Nov 27 13:06:40 spanky kernel: ohci1394: fw-host1: SelfID complete
Nov 27 13:06:40 spanky kernel: ohci1394: fw-host1: PhyReqFilter=0000000000000000
Nov 27 13:06:40 spanky kernel: ohci1394: fw-host1: IntEventClear
00000000 IntEventSet 04508000 IntMaskSet 838301f3
Nov 27 13:06:40 spanky kernel: ohci1394: fw-host1: IntEvent: 00020010
Nov 27 13:06:40 spanky kernel: ohci1394: fw-host1: irq_handler: Bus
reset requested
Nov 27 13:06:40 spanky kernel: ohci1394: fw-host1: Cancel request received
Nov 27 13:06:40 spanky kernel: ohci1394: fw-host1: Got RQPkt interrupt
status=0x00008409
Nov 27 13:06:40 spanky kernel: ohci1394: fw-host1: Single packet rcv'd
Nov 27 13:06:41 spanky kernel: ohci1394: fw-host1: IntEvent: 00010000
Nov 27 13:06:42 spanky kernel: ohci1394: fw-host1: SelfID interrupt
received (phyid 1, not root)
Nov 27 13:06:42 spanky kernel: ohci1394: fw-host1: SelfID packet
0x807fc494 received
Nov 27 13:06:42 spanky kernel: ohci1394: fw-host1: SelfID packet
0x817fc496 received
Nov 27 13:06:42 spanky kernel: ohci1394: fw-host1: SelfID for this
node is 0x817fc496
Nov 27 13:06:42 spanky kernel: ohci1394: fw-host1: SelfID packet BLAH
...15 more SelfID...
Nov 27 13:06:43 spanky kernel: ohci1394: fw-host1: SelfID complete
Nov 27 13:06:43 spanky kernel: ohci1394: fw-host1: PhyReqFilter=0000000000000000
Nov 27 13:06:44 spanky kernel: ohci1394: fw-host1: IntEventClear
00000000 IntEventSet 6ffdc33f IntMaskSet 00000000
with the bad IntMaskSet again.
I don't know if the host loss when I didn't have the additional read
is meaningful, but there it is simply:
Nov 27 13:04:39 spanky kernel: ohci1394: fw-host2: SelfID packet
0x823fc4f8 rf8c43f8c
.
.
.
Nov 27 13:06:30 spanky kernel: ohci1394: fw-host2: Soft reset finished
with 2 minutes and ~30 bus resets in between.
Oh, poop. I didn't mention that I have:
options ieee1394 disable_nodemgr=1
options ohci1394 phys_dma=0
in my /etc/modprobe.conf. The Linux adapters are functioning as
simulated peripherals to a piece of control hardware that always has a
dest address of 0x0000 0000 0000 on all packets so I needed to get rid
of posted writes and any bickering over bus master.
--
Robert Crocombe
[email protected]
Robert Crocombe wrote:
...
> Nov 27 13:06:37 spanky kernel: ohci1394: fw-host1: IntEvent: 00020010
busReset + RQPkt (packet sent)
...
> Nov 27 13:06:37 spanky kernel: ohci1394: fw-host1: IntEvent: 00010000
selfIDcomplete
...
> Nov 27 13:06:40 spanky kernel: ohci1394: fw-host1: IntEventClear
> 00000000 IntEventSet 04508000 IntMaskSet 838301f3
IntEventSet = phyRegRcvd + cycleLost + cycleSynch + selfIDcomplete2
> Nov 27 13:06:40 spanky kernel: ohci1394: fw-host1: IntEvent: 00020010
...
> Nov 27 13:06:41 spanky kernel: ohci1394: fw-host1: IntEvent: 00010000
...
> Nov 27 13:06:44 spanky kernel: ohci1394: fw-host1: IntEventClear
> 00000000 IntEventSet 6ffdc33f IntMaskSet 00000000
IntEventSet = vendorSpecific + softInterrupt + ack_tardy + phyRegRcvd +
cycleTooLong + unrecoverableError + cycleInconsistent + cycleLost +
cycle64Seconds + cycleSynch + phy + regAccessFail + selfIDComplete +
selfIDComplete2 + [reserved...?] + lockRespErr + postedWriteErr + RSPkt
+ RQPkt + ARRS + ARRQ + respTxComplete + reqTxComplete
(The bit 00004000 is not standardized and shouldn't be there. Whatever.)
That's a lot of stuff that happened right before this last print macro.
Maybe ages were spent in hpsb_selfid_complete. I will try to work on
getting non-critical parts out of hpsb_selfid_complete issue during the
week, but I don't know how fast I can do this and if this will help in
the first place.
...
> I didn't mention that I have:
>
> options ieee1394 disable_nodemgr=1
> options ohci1394 phys_dma=0
>
> in my /etc/modprobe.conf. The Linux adapters are functioning as
> simulated peripherals to a piece of control hardware that always has a
> dest address of 0x0000 0000 0000 on all packets so I needed to get rid
> of posted writes and any bickering over bus master.
Posted writes are still enabled. phys_dma=0 disables only the physical
response unit. You have to change the source if you want to disable
posted writes. See the top of ohci_initialize. Should this be a module
load parameter too?
--
Stefan Richter
-=====-=-==- =-== ==-==
http://arcgraph.de/sr/
On 11/27/06, Stefan Richter <[email protected]> wrote:
> Posted writes are still enabled. phys_dma=0 disables only the physical
> response unit. You have to change the source if you want to disable
> posted writes. See the top of ohci_initialize. Should this be a module
> load parameter too?
Er. I misspoke. What I need is for write requests directed to
address 0 to be directed to the asynchronous unit so that I can treat
them as regular asynchronous write requests. As the OHCI 1.1 spec
says:
"Physical requests that are rejected by the PhysicalRequestFilter
shall be sent to the AR Request DMA context if the AR Request DMA
context is enabled". (5.14.2, page 58)
That does appear to be happening: I have an ARM mapping set to begin
at 0 and extend some ways along, and I do receive write requests. At
first I was simply changing the lines:
reg_write(ohci,OHCI1394_PhyReqFilterHiSet, 0xffffffff);
reg_write(ohci,OHCI1394_PhyReqFilterLoSet, 0xffffffff);
to be 0x0000 0000 instead, but then I paid more attention to the
source and saw the phys_dma parameter, which does the same. .... Well,
*did*, in 2.6.16. I see that 2.6.18 doesn't write 0 if !phys_dma, it
just leaves the values alone, but I guess that's okay since they are
set to 0 on reset. Same difference.
So that's okay. Uhm, mostly. You should really see the horrors I
have created in order to be able to have 5 hosts map the same address
range (the custom protocol we're using doesn't use the destination
address at all, so it's 0 for everybody).
So long ways round, I think the phys_dma parameter is the proper thing for me.
And I will try and do some actual thinking about what is happening. I
was hoping to offload that work to you and simply perform mechanical
changes to the source! Rats!
--
Robert Crocombe
[email protected]
Robert Crocombe wrote:
> On 11/27/06, Stefan Richter <[email protected]> wrote:
>> Posted writes are still enabled. phys_dma=0 disables only the physical
>> response unit.
...
> What I need is for write requests directed to
> address 0 to be directed to the asynchronous unit so that I can treat
> them as regular asynchronous write requests.
...
> So long ways round, I think the phys_dma parameter is the proper thing
> for me.
Yes, correct.
(Leaving posted writes on has two subtle effects which may or may not be
interesting to you. 1. Write transactions will be performed as unified
transactions. 2. The transaction is already complete before the
controller writes to main memory. There are devices out there which
behave unexpectedly with unified transactions on, and some which do so
if they are off.)
> And I will try and do some actual thinking about what is happening. I
> was hoping to offload that work to you and simply perform mechanical
> changes to the source! Rats!
I'm on it, but working slowly, as usual. (I thought I get something
together during your holidays, but I fought with other buggy software
which crippled my main PC...)
--
Stefan Richter
-=====-=-==- =-== ===--
http://arcgraph.de/sr/