Bug 7521

Created attachment 9503 [details]
Dmesg output when the error is first seen

Dmesg output with debug enabled for ohci1394 and ieee1394 modules. Looks like
"IntEvent: 00000080" is not treated correctly or something.

You wrote "Most recent kernel where this bug did not occur". --- I suppose you
actually meant "kernel where this bug _did_ occur", didn't you?

Side note: I am maintaining backports too.
http://me.in-berlin.de/~s5r6/linux1394/updates/
You can get slightly newer stuff there but it certainly won't help you.

Yes, sorry, i read "Most recent kernel where this bug did occur"

Could you resend the log with "Packet sent to node..." lines too?

BTW, the (asynchronous) transactions before it breaks are quadlet write requests
(tcode 0) and write responses (tcode 2).

The IntEvent 00000080 right before the breakage means "isochRx" = "Isochronous
Receive DMA interrupt. Indicates that one or more isochronous
receive contexts have generated an interrupt". The other IntEvents refer to
asynchronous transmit and receive DMAs.

The transactions which fail because of alleged tlabel mismatch are quadlet read
requests (tcode 4) and read responses (tcode 6).

Your conjecture that ieee1394 doesn't wait for a response to the request with
tlabel 61 and instead expects the response to request with tlabel 62 is not
necessarily true. These transactions are so-called split transactions and the
tlabels are there to allow several split transactions to overlap. What happened
here is that ieee1394 discarded the tlabel 61 for some reason before it got the
response to the outstanding request with tlabel 61. The "Packet sent to node..."
line after the request 61 was issued may perhaps contain a reason for this.

Hmm, actually the information in "Got reqTxComplete interrupt status=0x00008012"
after the request 61 already says what I wanted to know. The request packet got
through to the destination node and was accepted by it with ack_pending, i.e.
the acknowledgement that it arrived and a response packet will come back later.

Now the question is why ieee1394 threw the tlabel away before the response
arrived. Could you attach the .config of this kernel?

Could you also recompile the kernel with "Kernel hacking"/ "Show timing
information on printks", i.e. CONFIG_PRINTK_TIME=y? That way we get sub-second
timestamps. Transactions time out after 100ms per default, and maybe the
responding node really did respond too late.

But before you do that, you could try the following trick. It is possible to
stretch the transaction timeout at runtime. Write the value 1 as a quadlet to
the local node to address 0xFFFFF0000018. This gives 1100ms timeout; likewise a
2 would give 2100ms timeout. You can do this with gscanbus or 1394commander.

With gscanbus: Click on the icon of the local host and note the "Physical ID".
Then use the menue item "Transaction"/ "Write Quadlet..." and fill in the
physical ID as Destination ID, 0xFFFFF0000018 as Memory Offset, and 1 as Data,
click OK. You can check whether it succeeded by reading from the same
destination and offset with the quadlet read menue item. Also, if you read from
0xFFFFF000001c you should get 0x19000000 as result. This (result >> 19) * 125 is
the subsecond part of the timeout, in microseconds.

With 1394commander: Start it and you get into a command line interface. You can
write to the local node with the command
w . . 0xFFFFF0000018 4 1
which sends a quadlet (4 bytes) of the value 1 to the offset 0xFFFFF0000018 on
the local node (.) at the local bus (.). You can read with
r . . 0xFFFFF0000018 4

Does an increased transaction timeout, as described in comment #6, prevent the
"unsolicited response"s?

Pleae reopen this bug if:
- it is still present with kernel 2.6.20 and
- you can provide the requested information.