linux1394-devel Mailing List for IEEE 1394 for Linux (Page 11)
Brought to you by:
aeb,
bencollins
You can subscribe to this list here.
2000 |
Jan
|
Feb
|
Mar
(39) |
Apr
(154) |
May
(172) |
Jun
(237) |
Jul
(127) |
Aug
(135) |
Sep
(193) |
Oct
(175) |
Nov
(173) |
Dec
(148) |
---|---|---|---|---|---|---|---|---|---|---|---|---|
2001 |
Jan
(161) |
Feb
(225) |
Mar
(193) |
Apr
(158) |
May
(179) |
Jun
(292) |
Jul
(146) |
Aug
(134) |
Sep
(185) |
Oct
(190) |
Nov
(149) |
Dec
(161) |
2002 |
Jan
(186) |
Feb
(236) |
Mar
(254) |
Apr
(207) |
May
(189) |
Jun
(182) |
Jul
(202) |
Aug
(155) |
Sep
(149) |
Oct
(449) |
Nov
(191) |
Dec
(108) |
2003 |
Jan
(174) |
Feb
(242) |
Mar
(243) |
Apr
(255) |
May
(202) |
Jun
(290) |
Jul
(237) |
Aug
(178) |
Sep
(101) |
Oct
(153) |
Nov
(144) |
Dec
(95) |
2004 |
Jan
(162) |
Feb
(278) |
Mar
(282) |
Apr
(152) |
May
(127) |
Jun
(138) |
Jul
(94) |
Aug
(63) |
Sep
(64) |
Oct
(150) |
Nov
(102) |
Dec
(197) |
2005 |
Jan
(102) |
Feb
(172) |
Mar
(89) |
Apr
(158) |
May
(139) |
Jun
(160) |
Jul
(288) |
Aug
(89) |
Sep
(201) |
Oct
(92) |
Nov
(190) |
Dec
(139) |
2006 |
Jan
(121) |
Feb
(204) |
Mar
(133) |
Apr
(134) |
May
(91) |
Jun
(226) |
Jul
(122) |
Aug
(101) |
Sep
(144) |
Oct
(141) |
Nov
|
Dec
|
2023 |
Jan
(19) |
Feb
(1) |
Mar
(5) |
Apr
(5) |
May
(33) |
Jun
(17) |
Jul
|
Aug
|
Sep
(3) |
Oct
(1) |
Nov
(5) |
Dec
(40) |
2024 |
Jan
(26) |
Feb
(14) |
Mar
(26) |
Apr
(46) |
May
(17) |
Jun
(47) |
Jul
(23) |
Aug
(72) |
Sep
(33) |
Oct
|
Nov
|
Dec
|
From: Takashi S. <o-t...@sa...> - 2024-03-25 01:21:50
|
Hi Bjorn Helgaas, (C.C.ed to lin...@li...) I have an objection to applying the change. I've been using the issued 1394 OHCI hardware in my development for recent years, while I have never faced the reported trouble. I think there are any misunderstanding or misjudge somwhow in the review process to apply it. Would I ask your precise advice to regenerate the reported issue in my local? This is my 1394 OHCI hardware. ``` $ sudo lspci -vvvnns 06:00.0 06:00.0 FireWire (IEEE 1394) [0c00]: LSI Corporation FW643 [TrueFire] PCIe 1394b Controller [11c1:5901] (rev 06) (prog-if 10 [OHCI]) Subsystem: LSI Corporation FW643 [TrueFire] PCIe 1394b Controller [11c1:5900] Control: I/O- Mem- BusMaster- SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx- Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx- Interrupt: pin A routed to IRQ 255 IOMMU group: 17 Region 0: Memory at fc700000 (64-bit, non-prefetchable) [disabled] [size=4K] Capabilities: [44] Power Management version 3 Flags: PMEClk- DSI- D1+ D2+ AuxCurrent=375mA PME(D0+,D1+,D2+,D3hot+,D3cold+) Status: D3 NoSoftRst- PME-Enable+ DSel=0 DScale=0 PME- Capabilities: [4c] MSI: Enable- Count=1/1 Maskable- 64bit+ Address: 0000000000000000 Data: 0000 Capabilities: [60] Express (v1) Endpoint, MSI 00 DevCap: MaxPayload 256 bytes, PhantFunc 0, Latency L0s <4us, L1 <64us ExtTag- AttnBtn- AttnInd- PwrInd- RBE+ FLReset- SlotPowerLimit 0W DevCtl: CorrErr+ NonFatalErr+ FatalErr+ UnsupReq+ RlxdOrd+ ExtTag- PhantFunc- AuxPwr- NoSnoop- MaxPayload 128 bytes, MaxReadReq 512 bytes DevSta: CorrErr- NonFatalErr- FatalErr- UnsupReq- AuxPwr+ TransPend- LnkCap: Port #0, Speed 2.5GT/s, Width x1, ASPM L0s L1, Exit Latency L0s <512ns, L1 <64us ClockPM+ Surprise- LLActRep- BwNot- ASPMOptComp- LnkCtl: ASPM Disabled; RCB 64 bytes, Disabled- CommClk+ ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt- LnkSta: Speed 2.5GT/s, Width x1 TrErr- Train- SlotClk+ DLActive- BWMgmt- ABWMgmt- Capabilities: [100 v1] Advanced Error Reporting UESta: DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol- UEMsk: DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol- UESvrt: DLP+ SDES+ TLP- FCP+ CmpltTO- CmpltAbrt- UnxCmplt- RxOF+ MalfTLP+ ECRC- UnsupReq- ACSViol- CESta: RxErr- BadTLP- BadDLLP- Rollover- Timeout- AdvNonFatalErr- CEMsk: RxErr- BadTLP- BadDLLP- Rollover- Timeout- AdvNonFatalErr+ AERCap: First Error Pointer: 00, ECRCGenCap+ ECRCGenEn- ECRCChkCap+ ECRCChkEn- MultHdrRecCap- MultHdrRecEn- TLPPfxPres- HdrLogCap- HeaderLog: 00000000 00000000 00000000 00000000 Capabilities: [140 v1] Virtual Channel Caps: LPEVC=0 RefClk=100ns PATEntryBits=1 Arb: Fixed- WRR32- WRR64- WRR128- Ctrl: ArbSelect=Fixed Status: InProgress- VC0: Caps: PATOffset=00 MaxTimeSlots=1 RejSnoopTrans- Arb: Fixed- WRR32- WRR64- WRR128- TWRR128- WRR256- Ctrl: Enable+ ID=0 ArbSelect=Fixed TC/VC=01 Status: NegoPending- InProgress- VC1: Caps: PATOffset=00 MaxTimeSlots=1 RejSnoopTrans- Arb: Fixed- WRR32- WRR64- WRR128- TWRR128- WRR256- Ctrl: Enable- ID=1 ArbSelect=Fixed TC/VC=00 Status: NegoPending- InProgress- Capabilities: [170 v1] Device Serial Number 12-34-56-10-12-30-00-86 Kernel driver in use: vfio-pci Kernel modules: firewire_ohci ``` I use it in the following environment at present: * Host system * AMD Ryzen 5 2400G * TUF GAMING X570-PLUS with BIOS 5003 (AGESA ComboV2PI 1.2.0.B) * SMT enabled * SVM enabled * IOMMU enabled * Secure boot disabled * Ubuntu 24.04 LTS amd64 * linux-image-6.8.0-11-generic (6.8.0-11.11) * default kernel cmdline * QEMU 8.2.1 (1:8.2.1+ds-1ubuntu1) * Libvert 10.0.0 (10.0.0-2ubuntu1) * Guest system * UEFI using OVMF * Seecure boot enabled * Ubuntu 24.04 LTS amd64 (the same as above) * default kernel cmdline > Using LSI / Agere FW643 with vfio-pci will exhaust all > pci_reset_fn_methods, the bus reset at the end causes a broken link > only recoverable by removing power > (power-off / suspend + rescan). > Prevent this bus reset. > With this change, the device can be assigned to VMs with VFIO. > Note that it will not be reset, resulting in leaking state between VMs > and host. > > Signed-off-by: Edmund Raile <edm...@pr...> > > I sincerely thank you for your patience and explaining > the background of pci resets which I lacked. > The commit message and comment now describe it correctly. > The comment on leaking states was added. > > Usefulness: > > The LSI FW643 PCIe->FireWire 800 interface may be EOL but it is > the only one that does not use a PCIe->PCI bridge. > It is reliable and enables FireWire audio interfaces to be used > on modern machines. > > Virtualization allows for flexible access to professional audio > software. > > It has been used in at least the following Apple machines: > MacBookPro10,1 > MacBookPro9,2 > MacBookPro6,2 > MacBookPro5,1 > Macmini6,1 > Macmini3,1 > iMac12,2 > iMac9,1 > iMac8,1 > > Implementation: > > PCI_VENDOR_ID_ATT was reused as they are identical. > > drivers/pci/quirks.c | 13 +++++++++++++ > 1 file changed, 13 insertions(+) > > diff --git a/drivers/pci/quirks.c b/drivers/pci/quirks.c > index d797df6e5f3e..e0e4ad9e6d50 100644 > --- a/drivers/pci/quirks.c > +++ b/drivers/pci/quirks.c > @@ -3765,6 +3765,19 @@ DECLARE_PCI_FIXUP_HEADER(PCI_VENDOR_ID_ATHEROS, 0x003e, quirk_no_bus_reset); > */ > DECLARE_PCI_FIXUP_HEADER(PCI_VENDOR_ID_CAVIUM, 0xa100, quirk_no_bus_reset); > > +/* > + * Using LSI / Agere FW643 with vfio-pci will exhaust all > + * pci_reset_fn_methods, the bus reset at the end causes a broken link > + * only recoverable by removing power > + * (power-off / suspend + rescan). > + * Prevent this bus reset. > + * With this change, the device can be assigned to VMs with VFIO. > + * Note that it will not be reset, resulting in leaking state between VMs > + * and host. > + */ > +DECLARE_PCI_FIXUP_HEADER(PCI_VENDOR_ID_ATT, 0x5900, quirk_no_bus_reset); > +DECLARE_PCI_FIXUP_HEADER(PCI_VENDOR_ID_ATT, 0x5901, quirk_no_bus_reset); > + > /* > * Some TI KeyStone C667X devices do not support bus/hot reset. The PCIESS > * automatically disables LTSSM when Secondary Bus Reset is received and Regards Takashi Sakamoto |
From: Takashi S. <o-t...@sa...> - 2024-03-25 00:58:38
|
Hi, On Wed, Mar 20, 2024 at 02:15:19AM -0700, Adam Goldman wrote: > In the FireWire OHCI interrupt handler, if a bus reset interrupt has > occurred, mask bus reset interrupts until bus_reset_work has serviced and > cleared the interrupt. > > Normally, we always leave bus reset interrupts masked. We infer the bus > reset from the self-ID interrupt that happens shortly thereafter. A > scenario where we unmask bus reset interrupts was introduced in 2008 in > a007bb857e0b26f5d8b73c2ff90782d9c0972620: If > OHCI_PARAM_DEBUG_BUSRESETS (8) is set in the debug parameter bitmask, we > will unmask bus reset interrupts so we can log them. > > irq_handler logs the bus reset interrupt. However, we can't clear the bus > reset event flag in irq_handler, because we won't service the event until > later. irq_handler exits with the event flag still set. If the > corresponding interrupt is still unmasked, the first bus reset will > usually freeze the system due to irq_handler being called again each > time it exits. This freeze can be reproduced by loading firewire_ohci > with "modprobe firewire_ohci debug=-1" (to enable all debugging output). > Apparently there are also some cases where bus_reset_work will get called > soon enough to clear the event, and operation will continue normally. > > This freeze was first reported a few months after a007bb85 was committed, > but until now it was never fixed. The debug level could safely be set > to -1 through sysfs after the module was loaded, but this would be > ineffectual in logging bus reset interrupts since they were only > unmasked during initialization. > > irq_handler will now leave the event flag set but mask bus reset > interrupts, so irq_handler won't be called again and there will be no > freeze. If OHCI_PARAM_DEBUG_BUSRESETS is enabled, bus_reset_work will > unmask the interrupt after servicing the event, so future interrupts > will be caught as desired. > > As a side effect to this change, OHCI_PARAM_DEBUG_BUSRESETS can now be > enabled through sysfs in addition to during initial module loading. > However, when enabled through sysfs, logging of bus reset interrupts will > be effective only starting with the second bus reset, after > bus_reset_work has executed. > > Signed-off-by: Adam Goldman <ad...@po...> > --- > > --- linux-6.8-rc1.orig/drivers/firewire/ohci.c 2024-01-21 14:11:32.000000000 -0800 > +++ linux-6.8-rc1/drivers/firewire/ohci.c 2024-03-12 01:15:10.000000000 -0700 > @@ -2060,6 +2060,8 @@ static void bus_reset_work(struct work_s > > ohci->generation = generation; > reg_write(ohci, OHCI1394_IntEventClear, OHCI1394_busReset); > + if (param_debug & OHCI_PARAM_DEBUG_BUSRESETS) > + reg_write(ohci, OHCI1394_IntMaskSet, OHCI1394_busReset); > > if (ohci->quirks & QUIRK_RESET_PACKET) > ohci->request_generation = generation; > @@ -2125,12 +2127,14 @@ static irqreturn_t irq_handler(int irq, > return IRQ_NONE; > > /* > - * busReset and postedWriteErr must not be cleared yet > + * busReset and postedWriteErr events must not be cleared yet > * (OHCI 1.1 clauses 7.2.3.2 and 13.2.8.1) > */ > reg_write(ohci, OHCI1394_IntEventClear, > event & ~(OHCI1394_busReset | OHCI1394_postedWriteErr)); > log_irqs(ohci, event); > + if (event & OHCI1394_busReset) > + reg_write(ohci, OHCI1394_IntMaskClear, OHCI1394_busReset); > > if (event & OHCI1394_selfIDComplete) > queue_work(selfid_workqueue, &ohci->bus_reset_work); Thanks for the patch. I pushed topic branch[1] for it, since I'm considering about whether to send it to stable and longterm releases. I had realized that the debug=8 for firewire-ohci module provides tons of logs triggering by the irq handler, since the irq for bus reset is not unmasked, so I rely on selfID events when debugging bus-reset. I have few objections to the change. My concern is how much invasive it is. The unmasking is kept until bus_reset_work() is executed in the workqueue. When considering about the delay of workqueue (since it is a kind of schedulable task), many irq events for bus reset is potentially skipped from the logging. Of course, it is the aim of change. Let me take more time to evaluate the change, but I'm willing to send it to upstream until -rc3 or -rc4, at least, if receiving no objections from the others. [1] https://git.kernel.org/pub/scm/linux/kernel/git/ieee1394/linux1394.git/log/?h=v6.9-firewire-mask-bus-reset-event-during-handling Thanks Takashi Sakamoto |
From: Takashi S. <o-t...@sa...> - 2024-03-25 00:41:47
|
Hi Adam, On Wed, Mar 20, 2024 at 02:14:11AM -0700, Adam Goldman wrote: > Add a debug parameter to firewire-core, analogous to the one in > firewire-ohci. When this is set to 1, log when we schedule, delay, or > initiate a bus reset. Since FireWire bus resets can originate from any > node on the bus, specific logging of the resets we initiate provides > additional insight. > > Signed-off-by: Adam Goldman <ad...@po...> Thanks for the patch. I applied it to for-next[1]. Now we have two debug parameters per module for the slightly-similar purpose. In my opinion, it is a pretty cumbersome to enable them when checking bus-reset behaviour. I think it is time to investigate the other way. Linux Kernel Tracepoints[2] is one of options. Roughly describing, the tracepoints mechanism allows users to deliver structured data from kernel space to user space via ring-buffer when enabling it by either sysfs or kernel command-line parameters. Linux kernel also has a command-line parameter to redirect the human-readable formatted data to kernel log[3]. I think it is suitable in the case. It requires many work to replace the existent debug parameter of firewire-ohci, while it is a good start to work just for bus-reset debug. The data structure layout should be pre-defined in each subsystem, thus we need to decide it. In my opinion, it would be like: ``` struct bus_reset_event { enum reason { Initiate, Schedule, Postpone, Detect, }, // We can put any other data if prefering. } ``` Would I ask your opinion about my idea? [1] https://git.kernel.org/pub/scm/linux/kernel/git/ieee1394/linux1394.git/log/?h=for-next [2] https://docs.kernel.org/trace/tracepoints.html [3] 'tp_printk' in kernel/trace/trace.c, 'trace_event' in kernel/trace/trace_event.c Regards Takashi Sakamoto |
From: Takashi S. <o-t...@sa...> - 2024-03-21 13:25:33
|
Hi Adam, Thanks for the patches to improve the subsystem. Inconveniently to you , we are now just at the merge window for v6.9 kernel, thus I would not put any changes except for the changes to Linus. I'd like you to wait until the next week, sorry. However, in the topic of logging PHY register, I have an idea to utilize the Linux kernel tracepoints framework[1]. It is tangled to program with the provided macros, and it is available just with the relevant tools[2], but it would be helpful in the case, I think. [1] https://docs.kernel.org/trace/tracepoints.html [2] https://docs.kernel.org/trace/tracepoint-analysis.html On Wed, Mar 20, 2024 at 02:38:05AM -0700, Adam Goldman wrote: > Hi Takashi, > > On Wed, Feb 28, 2024 at 09:41:44AM +0900, Takashi Sakamoto wrote: > > Additionally, for your investigation, you added the debug print to get the > > timing of bus reset scheduling. I think it useful for this kind of issue. > > Would I ask you to write another patch to add it? In my opinion, the case > > of mixed versions of 1394 PHYs in the same bus has more quirks and the > > debug print is helpful to investigate it further. > > I'm sorry for my delay in preparing a patch. > > I've submitted a patch to linux1394-devel to log when we schedule or > initiate a bus reset. This is enabled with a new parameter to the > firewire-core module. It provides logging similar to the debug print I > used to investigate the reset loop. > > Also, there is already logging for bus reset interrupts in > firewire-ohci. This logs all bus resets and does not indicate whether we > initiated the reset or some other node on the bus initiated it. However, > the logging in firewire-ohci always froze my computer when I enabled it. > I've submitted a separate patch to fix the firewire-ohci logging. > > I believe both forms of logging can be useful. firewire-ohci logs all > bus resets, but it doesn't tell where the resets came from. firewire-core > only logs bus resets we initiate. > > I also considered adding an option to firewire-ohci to log PHY register > access. This would include writes to IBR and ISBR, so it would log when > we initiate resets. However, this logging would be more complicated to > add, so I didn't do it. > > -- Adam Thanks Takashi Sakamoto |
From: Adam G. <ad...@po...> - 2024-03-20 09:38:21
|
Hi Takashi, On Wed, Feb 28, 2024 at 09:41:44AM +0900, Takashi Sakamoto wrote: > Additionally, for your investigation, you added the debug print to get the > timing of bus reset scheduling. I think it useful for this kind of issue. > Would I ask you to write another patch to add it? In my opinion, the case > of mixed versions of 1394 PHYs in the same bus has more quirks and the > debug print is helpful to investigate it further. I'm sorry for my delay in preparing a patch. I've submitted a patch to linux1394-devel to log when we schedule or initiate a bus reset. This is enabled with a new parameter to the firewire-core module. It provides logging similar to the debug print I used to investigate the reset loop. Also, there is already logging for bus reset interrupts in firewire-ohci. This logs all bus resets and does not indicate whether we initiated the reset or some other node on the bus initiated it. However, the logging in firewire-ohci always froze my computer when I enabled it. I've submitted a separate patch to fix the firewire-ohci logging. I believe both forms of logging can be useful. firewire-ohci logs all bus resets, but it doesn't tell where the resets came from. firewire-core only logs bus resets we initiate. I also considered adding an option to firewire-ohci to log PHY register access. This would include writes to IBR and ISBR, so it would log when we initiate resets. However, this logging would be more complicated to add, so I didn't do it. -- Adam |
From: Adam G. <ad...@po...> - 2024-03-20 09:15:34
|
In the FireWire OHCI interrupt handler, if a bus reset interrupt has occurred, mask bus reset interrupts until bus_reset_work has serviced and cleared the interrupt. Normally, we always leave bus reset interrupts masked. We infer the bus reset from the self-ID interrupt that happens shortly thereafter. A scenario where we unmask bus reset interrupts was introduced in 2008 in a007bb857e0b26f5d8b73c2ff90782d9c0972620: If OHCI_PARAM_DEBUG_BUSRESETS (8) is set in the debug parameter bitmask, we will unmask bus reset interrupts so we can log them. irq_handler logs the bus reset interrupt. However, we can't clear the bus reset event flag in irq_handler, because we won't service the event until later. irq_handler exits with the event flag still set. If the corresponding interrupt is still unmasked, the first bus reset will usually freeze the system due to irq_handler being called again each time it exits. This freeze can be reproduced by loading firewire_ohci with "modprobe firewire_ohci debug=-1" (to enable all debugging output). Apparently there are also some cases where bus_reset_work will get called soon enough to clear the event, and operation will continue normally. This freeze was first reported a few months after a007bb85 was committed, but until now it was never fixed. The debug level could safely be set to -1 through sysfs after the module was loaded, but this would be ineffectual in logging bus reset interrupts since they were only unmasked during initialization. irq_handler will now leave the event flag set but mask bus reset interrupts, so irq_handler won't be called again and there will be no freeze. If OHCI_PARAM_DEBUG_BUSRESETS is enabled, bus_reset_work will unmask the interrupt after servicing the event, so future interrupts will be caught as desired. As a side effect to this change, OHCI_PARAM_DEBUG_BUSRESETS can now be enabled through sysfs in addition to during initial module loading. However, when enabled through sysfs, logging of bus reset interrupts will be effective only starting with the second bus reset, after bus_reset_work has executed. Signed-off-by: Adam Goldman <ad...@po...> --- --- linux-6.8-rc1.orig/drivers/firewire/ohci.c 2024-01-21 14:11:32.000000000 -0800 +++ linux-6.8-rc1/drivers/firewire/ohci.c 2024-03-12 01:15:10.000000000 -0700 @@ -2060,6 +2060,8 @@ static void bus_reset_work(struct work_s ohci->generation = generation; reg_write(ohci, OHCI1394_IntEventClear, OHCI1394_busReset); + if (param_debug & OHCI_PARAM_DEBUG_BUSRESETS) + reg_write(ohci, OHCI1394_IntMaskSet, OHCI1394_busReset); if (ohci->quirks & QUIRK_RESET_PACKET) ohci->request_generation = generation; @@ -2125,12 +2127,14 @@ static irqreturn_t irq_handler(int irq, return IRQ_NONE; /* - * busReset and postedWriteErr must not be cleared yet + * busReset and postedWriteErr events must not be cleared yet * (OHCI 1.1 clauses 7.2.3.2 and 13.2.8.1) */ reg_write(ohci, OHCI1394_IntEventClear, event & ~(OHCI1394_busReset | OHCI1394_postedWriteErr)); log_irqs(ohci, event); + if (event & OHCI1394_busReset) + reg_write(ohci, OHCI1394_IntMaskClear, OHCI1394_busReset); if (event & OHCI1394_selfIDComplete) queue_work(selfid_workqueue, &ohci->bus_reset_work); |
From: Adam G. <ad...@po...> - 2024-03-20 09:14:31
|
Add a debug parameter to firewire-core, analogous to the one in firewire-ohci. When this is set to 1, log when we schedule, delay, or initiate a bus reset. Since FireWire bus resets can originate from any node on the bus, specific logging of the resets we initiate provides additional insight. Signed-off-by: Adam Goldman <ad...@po...> --- --- linux-6.8-rc1.orig/drivers/firewire/core.h 2024-01-21 14:11:32.000000000 -0800 +++ linux-6.8-rc1/drivers/firewire/core.h 2024-03-10 03:56:09.000000000 -0700 @@ -238,6 +238,10 @@ /* OHCI-1394's default upper bound for physical DMA: 4 GB */ #define FW_MAX_PHYSICAL_RANGE (1ULL << 32) +#define FW_CORE_PARAM_DEBUG_BUSRESETS 1 + +extern int fw_core_param_debug; + void fw_core_handle_request(struct fw_card *card, struct fw_packet *request); void fw_core_handle_response(struct fw_card *card, struct fw_packet *packet); int fw_get_response_length(struct fw_request *request); --- linux-6.8-rc1.orig/drivers/firewire/core-transaction.c 2024-01-21 14:11:32.000000000 -0800 +++ linux-6.8-rc1/drivers/firewire/core-transaction.c 2024-03-12 02:08:29.000000000 -0700 @@ -1385,5 +1385,12 @@ idr_destroy(&fw_device_idr); } +int fw_core_param_debug; +module_param_named(debug, fw_core_param_debug, int, 0644); +MODULE_PARM_DESC(debug, "Verbose logging (default = 0" + ", bus resets = " __stringify(FW_CORE_PARAM_DEBUG_BUSRESETS) + ")"); + + module_init(fw_core_init); module_exit(fw_core_cleanup); --- linux-6.8-rc1.orig/drivers/firewire/core-card.c 2024-01-21 14:11:32.000000000 -0800 +++ linux-6.8-rc1/drivers/firewire/core-card.c 2024-03-10 03:34:00.000000000 -0700 @@ -221,11 +221,19 @@ int reg = short_reset ? 5 : 1; int bit = short_reset ? PHY_BUS_SHORT_RESET : PHY_BUS_RESET; + if (unlikely(fw_core_param_debug & FW_CORE_PARAM_DEBUG_BUSRESETS)) + fw_notice(card, "initiating %s bus reset\n", + short_reset ? "short" : "long"); + return card->driver->update_phy_reg(card, reg, 0, bit); } void fw_schedule_bus_reset(struct fw_card *card, bool delayed, bool short_reset) { + if (unlikely(fw_core_param_debug & FW_CORE_PARAM_DEBUG_BUSRESETS)) + fw_notice(card, "scheduling %s bus reset\n", + short_reset ? "short" : "long"); + /* We don't try hard to sort out requests of long vs. short resets. */ card->br_short = short_reset; @@ -244,6 +252,8 @@ /* Delay for 2s after last reset per IEEE 1394 clause 8.2.1. */ if (card->reset_jiffies != 0 && time_before64(get_jiffies_64(), card->reset_jiffies + 2 * HZ)) { + if (unlikely(fw_core_param_debug & FW_CORE_PARAM_DEBUG_BUSRESETS)) + fw_notice(card, "delaying bus reset\n"); if (!queue_delayed_work(fw_workqueue, &card->br_work, 2 * HZ)) fw_card_put(card); return; |
From: Takashi S. <o-t...@sa...> - 2024-03-18 09:23:31
|
Hi, On Mon, Mar 18, 2024 at 06:24:52AM +0000, Zhijian Li (Fujitsu) wrote: > ... > Sorry for the mistake. I haven't considered callers from other than sysfs. > I'm fine to reverting both *two*. > > If we are interesting in the sysfs_emit conversion one, i cooked(see the attachment) > a patch to revert "firewire: Kill unnecessary buf check in device_attribute.show" only. > > (Feel free to ignore it if you have had a local fix.) > ... > From 96ad3e15b86e2504f3c17fd6a10be48e5ff81cb1 Mon Sep 17 00:00:00 2001 > From: Li Zhijian <liz...@fu...> > Date: Mon, 18 Mar 2024 14:05:32 +0800 > Subject: [PATCH] Revert "firewire: Kill unnecessary buf check in > device_attribute.show" > > This reverts commit 4a2b06ca33763b363038d333274e212db6ff0de1. > > The previous fix didn't consider callers from other than sysfs. Revert > it to fix the NULL dereference > > kernel: ? sysfs_emit+0xb5/0xc0 > kernel: show_immediate+0x13f/0x1d0 [firewire_core] > kernel: init_fw_attribute_group+0x81/0x150 [firewire_core] > kernel: create_units+0x119/0x160 [firewire_core] > kernel: fw_device_init+0x1a9/0x330 [firewire_core] > kernel: fw_device_workfn+0x12/0x20 [firewire_core] > kernel: process_one_work+0x16f/0x350 > kernel: worker_thread+0x306/0x440 > kernel: ? __pfx_worker_thread+0x10/0x10 > kernel: kthread+0xf2/0x120 > kernel: ? __pfx_kthread+0x10/0x10 > kernel: ret_from_fork+0x47/0x70 > kernel: ? __pfx_kthread+0x10/0x10 > kernel: ret_from_fork_asm+0x1b/0x30 > kernel: </TASK> > kernel: ---[ end trace 0000000000000000 ]--- > kernel: ------------[ cut here ]------------ > > Fixes: 4a2b06ca3376 ("firewire: Kill unnecessary buf check in device_attribute.show") > Reported-by: Takashi Sakamoto <o-t...@sa...> > Signed-off-by: Li Zhijian <liz...@fu...> > --- > drivers/firewire/core-device.c | 16 ++++++++++++---- > 1 file changed, 12 insertions(+), 4 deletions(-) Thanks for your immediate action. I applied it to for-linus branch, and will send it in this week with my additional patch for notes. Let's back to test, hehe. Thanks Takashi Sakamoto |
From: Takashi S. <o-t...@sa...> - 2024-03-18 09:18:18
|
In the case of firewire core function, the caller of show functions for device attributes is not only sysfs user, but also device initialization. This commit adds memo about it against the typical assumption that the functions are just dedicated to sysfs user. Signed-off-by: Takashi Sakamoto <o-t...@sa...> --- drivers/firewire/core-device.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/drivers/firewire/core-device.c b/drivers/firewire/core-device.c index f208a02d0ebf..a8172a6c2caa 100644 --- a/drivers/firewire/core-device.c +++ b/drivers/firewire/core-device.c @@ -322,6 +322,7 @@ static ssize_t show_immediate(struct device *dev, if (value < 0) return -ENOENT; + // Note that this function is called by init_fw_attribute_group() with NULL pointer. return buf ? sysfs_emit(buf, "0x%06x\n", value) : 0; } @@ -357,6 +358,7 @@ static ssize_t show_text_leaf(struct device *dev, } } + // Note that this function is called by init_fw_attribute_group() with NULL pointer. if (buf) { bufsize = PAGE_SIZE - 1; } else { -- 2.43.0 |
From: Takashi S. <o-t...@sa...> - 2024-03-18 04:46:30
|
Hi, On Mon, Jan 22, 2024 at 05:56:04PM +0900, Takashi Sakamoto wrote: > Hi, > > On Mon, Jan 22, 2024 at 01:39:41PM +0800, Li Zhijian wrote: > > Per Documentation/filesystems/sysfs.rst: > > > sysfs allocates a buffer of size (PAGE_SIZE) and passes it to the > > > method. > > > > So we can kill the unnecessary buf check safely. > > > > Signed-off-by: Li Zhijian <liz...@fu...> > > --- > > drivers/firewire/core-device.c | 14 +++----------- > > 1 file changed, 3 insertions(+), 11 deletions(-) > > Applied both patches to linux-next branch, since they are not so-urgent > fixes. I realized that it causes an issue at the path to initialize device structure for node in IEEE 1394 bus. (drivers/firewire/core-device.c) fw_device_init() / fw_device_refresh() ->create_units() ->init_fw_attribute_group() ->attr->show(dev, attr, NULL) kernel: ------------[ cut here ]------------ kernel: invalid sysfs_emit: buf:0000000000000000 kernel: WARNING: CPU: 5 PID: 647501 at fs/sysfs/file.c:747 sysfs_emit+0xb5/0xc0 kernel: Modules linked in: snd_fireworks(OE) snd_firewire_lib(OE) firewire_ohci(OE) firewire_core(OE) cfg80211 veth nft_masq crc_itu_t vfio_pci vfio_pci_core vfio_iommu_type1 vfio iommufd rpcsec_gss_krb5 nfsv4 nfs netfs snd_seq_dummy sn> kernel: crypto_simd asus_wmi snd_timer ledtrig_audio cryptd cec sparse_keymap nls_iso8859_1 rapl platform_profile wmi_bmof k10temp i2c_piix4 snd rc_core i2c_algo_bit ccp soundcore zfs(PO) spl(O) input_leds joydev cdc_mbim cdc_wdm mac_h> kernel: CPU: 5 PID: 647501 Comm: kworker/5:0 Tainted: P W OE 6.8.0-11-generic #11-Ubuntu kernel: Hardware name: System manufacturer System Product Name/TUF GAMING X570-PLUS, BIOS 5003 10/07/2023 kernel: Workqueue: firewire fw_device_workfn [firewire_core] kernel: RIP: 0010:sysfs_emit+0xb5/0xc0 kernel: Code: 25 28 00 00 00 75 29 c9 31 d2 31 c9 31 f6 31 ff 45 31 c0 45 31 c9 e9 5a 89 c7 00 48 89 fe 48 c7 c7 64 06 3f bd e8 1b 80 b4 ff <0f> 0b 31 c0 eb c7 e8 a0 ea c5 00 90 90 90 90 90 90 90 90 90 90 90 kernel: RSP: 0018:ffffacd857103cd0 EFLAGS: 00010246 kernel: RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000 kernel: RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000 kernel: RBP: ffffacd857103d20 R08: 0000000000000000 R09: 0000000000000000 kernel: R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000010000 kernel: R13: ffffffffc28e2ff8 R14: 0000000000000000 R15: 0000000000000001 kernel: FS: 0000000000000000(0000) GS:ffff918190080000(0000) knlGS:0000000000000000 kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 kernel: CR2: 00007835dca0b048 CR3: 00000003cb898000 CR4: 00000000003506f0 kernel: Call Trace: kernel: <TASK> kernel: ? show_regs+0x6d/0x80 kernel: ? __warn+0x89/0x160 kernel: ? sysfs_emit+0xb5/0xc0 kernel: ? report_bug+0x17e/0x1b0 kernel: ? handle_bug+0x51/0xa0 kernel: ? exc_invalid_op+0x18/0x80 kernel: ? asm_exc_invalid_op+0x1b/0x20 kernel: ? sysfs_emit+0xb5/0xc0 kernel: show_immediate+0x13f/0x1d0 [firewire_core] kernel: init_fw_attribute_group+0x81/0x150 [firewire_core] kernel: create_units+0x119/0x160 [firewire_core] kernel: fw_device_init+0x1a9/0x330 [firewire_core] kernel: fw_device_workfn+0x12/0x20 [firewire_core] kernel: process_one_work+0x16f/0x350 kernel: worker_thread+0x306/0x440 kernel: ? __pfx_worker_thread+0x10/0x10 kernel: kthread+0xf2/0x120 kernel: ? __pfx_kthread+0x10/0x10 kernel: ret_from_fork+0x47/0x70 kernel: ? __pfx_kthread+0x10/0x10 kernel: ret_from_fork_asm+0x1b/0x30 kernel: </TASK> kernel: ---[ end trace 0000000000000000 ]--- kernel: ------------[ cut here ]------------ Furthermore, 'show_text_leaf()' returns negative value when the NULL pointer is passed. It results in the lack of vendor/model names from sysfs. I absolutely overlooked them. I would like to fix them within this merge window, or revert them as a last resort... Regards Takashi Sakamoto |
From: Takashi S. <o-t...@sa...> - 2024-03-06 13:41:13
|
Hi, On Thu, Feb 29, 2024 at 02:47:59PM +0000, Edmund Raile wrote: > > Commit 5a95f1ded28691e6 ("firewire: ohci: use devres for requested IRQ") > also removed the call to free_irq() in pci_remove(), leading to a > leftover irq of devm_request_irq() at pci_disable_msi() in pci_remove() > when unbinding the driver from the device > > remove_proc_entry: removing non-empty directory 'irq/136', leaking at > least 'firewire_ohci' > Call Trace: > ? remove_proc_entry+0x19c/0x1c0 > ? __warn+0x81/0x130 > ? remove_proc_entry+0x19c/0x1c0 > ? report_bug+0x171/0x1a0 > ? console_unlock+0x78/0x120 > ? handle_bug+0x3c/0x80 > ? exc_invalid_op+0x17/0x70 > ? asm_exc_invalid_op+0x1a/0x20 > ? remove_proc_entry+0x19c/0x1c0 > unregister_irq_proc+0xf4/0x120 > free_desc+0x3d/0xe0 > ? kfree+0x29f/0x2f0 > irq_free_descs+0x47/0x70 > msi_domain_free_locked.part.0+0x19d/0x1d0 > msi_domain_free_irqs_all_locked+0x81/0xc0 > pci_free_msi_irqs+0x12/0x40 > pci_disable_msi+0x4c/0x60 > pci_remove+0x9d/0xc0 [firewire_ohci > 01b483699bebf9cb07a3d69df0aa2bee71db1b26] > pci_device_remove+0x37/0xa0 > device_release_driver_internal+0x19f/0x200 > unbind_store+0xa1/0xb0 > > remove irq with devm_free_irq() before pci_disable_msi() > also remove it in fail_msi: of pci_probe() as this would lead to > an identical leak > > Fixes: 5a95f1ded28691e6 ("firewire: ohci: use devres for requested IRQ") > > Signed-off-by: Edmund Raile <edm...@pr...> Applied to for-linus branch. I'll send it for v6.8-final. I think the pairs of 'pci_alloc_irq_vectors()' and 'request_irq()', 'free_irq()' and 'pci_free_irq_vectors()' would be fine here, but the replacement of legacy API is not welcome in the last week of kernel development, so I postpone the work to the future. Thanks Takashi Sakamoto |
From: Takashi S. <o-t...@sa...> - 2024-03-06 01:10:50
|
Hi, On Tue, Mar 05, 2024 at 11:24:15AM -0600, Gustavo A. R. Silva wrote: > -Wflex-array-member-not-at-end is coming in GCC-14, and we are getting > ready to enable it globally. So, we are deprecating flexible-array > members in the middle of another struct. > > There are currently a couple of local structures (`u` and `template`) > that are using a flexible `struct fw_iso_packet` as header for a couple > of on-stack arrays. > > We make use of the `struct_group_tagged()` helper to separate the > flexible array from the rest of the members in the flexible structure, > and, with this, we can now declare objects of the type of the tagged > struct, without embedding the flexible array in the middle of another > struct. > > We also use `container_of()` whenever we need to retrieve a pointer to > the flexible structure, through which the flexible-array member can be > accessed. > > With these changes, we fix a couple of -Wflex-array-member-not-at-end > warnings. > > Gustavo A. R. Silva (2): > firewire: Avoid -Wflex-array-member-not-at-end warning > ALSA: firewire-lib: Avoid -Wflex-array-member-not-at-end warning > > drivers/firewire/core-cdev.c | 9 +++++---- > include/linux/firewire.h | 16 +++++++++------- > sound/firewire/amdtp-stream.c | 8 +++++--- > 3 files changed, 19 insertions(+), 14 deletions(-) Thanks for the improvements, however we are mostly at the end of development period for v6.8 kernel. Let me postpone applying the patches until closing the next merge window (for v6.9), since we need the term to evaluate the change. I mean that it goes to v6.10 kernel. If you would like me to applying the patch v6.9 kernel, please inform it to us. Thanks Takashi Sakamoto |
From: Takashi S. <o-t...@sa...> - 2024-03-03 03:13:45
|
Hi, (C.C.ed to the list of PCI SUBSYSTEM.) On Sat, Mar 02, 2024 at 04:52:06PM +0000, Edmund Raile wrote: > > In my opinion, the devres mechanism releases the allocated memory when > > releasing the data of associated device structure. > > device_release_driver_internal() > > ->__device_release_driver() > > ->device_unbind_cleanup() > > (drivers/base/devres.c) > > ->devres_release_all(dev); > > ->release_nodes() > > (kernel/irq/devres.c) > > ->free_irq() > > Looking at __device_release_driver() in drivers/base/dd.c, > device_remove() gets called, leading to dev->bus->remove(dev), > which likely calls our good old friend from the call trace: > pci_device_remove(). > > > > Call Trace: > > > ? remove_proc_entry+0x19c/0x1c0 > > > ? __warn+0x81/0x130 > > > ? remove_proc_entry+0x19c/0x1c0 > > > ? report_bug+0x171/0x1a0 > > > ? console_unlock+0x78/0x120 > > > ? handle_bug+0x3c/0x80 > > > ? exc_invalid_op+0x17/0x70 > > > ? asm_exc_invalid_op+0x1a/0x20 > > > ? remove_proc_entry+0x19c/0x1c0 > > > unregister_irq_proc+0xf4/0x120 > > > free_desc+0x3d/0xe0 > > > ? kfree+0x29f/0x2f0 > > > irq_free_descs+0x47/0x70 > > > msi_domain_free_locked.part.0+0x19d/0x1d0 > > > msi_domain_free_irqs_all_locked+0x81/0xc0 > > > pci_free_msi_irqs+0x12/0x40 > > > pci_disable_msi+0x4c/0x60 > > > pci_remove+0x9d/0xc0 [firewire_ohci > > > 01b483699bebf9cb07a3d69df0aa2bee71db1b26] > > > pci_device_remove+0x37/0xa0 > > > device_release_driver_internal+0x19f/0x200 > > > unbind_store+0xa1/0xb0 > > Then in ohci.c's pci_remove(), we kill the MSIs, which leads to > the removal of the IRQ, etc. > Back in __device_release_driver(), after device_remove(), > device_unbind_cleanup() is called, leading to free_irq(), but too late. > > I think the order of these calls may be our issue but I doubt it > has been done like this without good reason. > That code is 8 years old, someone would have noticed if it had an error. Now I got the point. Before optimizing to device managing resource, the 1394 OHCI driver called `free_irq()` then `pci_disable_msi()` in the .remove() callback. So the issue did not occur. At present, the order is reversed, as you find. To be honestly, I have little knowledge about current implementation of PCIe MSI operation and the current best-practice in Linux PCI subsystem. I've just replaced the old implementation of the driver with the relevant APIs, so I need to consult someone about the issue. > I could be entirely wrong but the function description in > /kernel/irq/devres.c tells me that function is meant to be used: > > > Except for the extra @dev argument, this function takes the > > same arguments and performs the same function as free_irq(). > > This function instead of free_irq() should be used to manually > > free IRQs allocated with devm_request_irq(). > > And while devm_request_irq() has no function description of its own, its > sister devm_request_threaded_irq() mentions this: > > > IRQs requested with this function will be > > automatically freed on driver detach. > > > > If an IRQ allocated with this function needs to be freed > > separately, devm_free_irq() must be used. > > Should we pull in the maintainers of dd.c for their opinion? > > Thank you very much for all the very hard work you do Sakamoto-Sensei! Indeed. If the current implementation of PCIe MSI requires the call of `free_irq()` (or something) before calling `pci_disable_msi()`, it should be documented. But we can also see the `pci_disable_msi()` is legacy API in PCIe MSI implementation[1]. I guess that the extra care of order to call these two functions would be useless nowadays by some enhancement. [1] https://docs.kernel.org/PCI/msi-howto.html#legacy-apis Thanks Takashi Sakamoto |
From: Takashi S. <o-t...@sa...> - 2024-03-01 04:40:42
|
Hi, Thanks for your taking the issue, and sending the patch. But I have a concern about the change, since the allocated IRQ should be released as the part of managed device resource[1]: (include/linux/interrupt.h) devm_request_irq() (kernel/irq/devres.c) ->devm_request_threaded_irq() ->devres_alloc(devm_irq_release) (kernel/irq/devres.c) devrm_irq_release() ->free_irq() In my opinion, the devres mechanism releases the allocated memory when releasing the data of associated device structure. In our case, it is the data of pci_dev structure (precisely, the data of device structure embedded in it). In the call trace of your commit comment, the release should be done in: (drivers/base/dd.c) device_release_driver_internal() ->__device_release_driver() ->device_unbind_cleanup() (drivers/base/devres.c) ->devres_release_all(dev); ->release_nodes() (kernel/irq/devres.c) ->free_irq() However, you encounter the leak actually. I think we have another cause for the leak, but never figured it out. Anyway, I'll further investigate the issue. [1] https://docs.kernel.org/driver-api/driver-model/devres.html On Thu, Feb 29, 2024 at 02:47:59PM +0000, Edmund Raile wrote: > > Commit 5a95f1ded28691e6 ("firewire: ohci: use devres for requested IRQ") > also removed the call to free_irq() in pci_remove(), leading to a > leftover irq of devm_request_irq() at pci_disable_msi() in pci_remove() > when unbinding the driver from the device > > remove_proc_entry: removing non-empty directory 'irq/136', leaking at > least 'firewire_ohci' > Call Trace: > ? remove_proc_entry+0x19c/0x1c0 > ? __warn+0x81/0x130 > ? remove_proc_entry+0x19c/0x1c0 > ? report_bug+0x171/0x1a0 > ? console_unlock+0x78/0x120 > ? handle_bug+0x3c/0x80 > ? exc_invalid_op+0x17/0x70 > ? asm_exc_invalid_op+0x1a/0x20 > ? remove_proc_entry+0x19c/0x1c0 > unregister_irq_proc+0xf4/0x120 > free_desc+0x3d/0xe0 > ? kfree+0x29f/0x2f0 > irq_free_descs+0x47/0x70 > msi_domain_free_locked.part.0+0x19d/0x1d0 > msi_domain_free_irqs_all_locked+0x81/0xc0 > pci_free_msi_irqs+0x12/0x40 > pci_disable_msi+0x4c/0x60 > pci_remove+0x9d/0xc0 [firewire_ohci > 01b483699bebf9cb07a3d69df0aa2bee71db1b26] > pci_device_remove+0x37/0xa0 > device_release_driver_internal+0x19f/0x200 > unbind_store+0xa1/0xb0 > > remove irq with devm_free_irq() before pci_disable_msi() > also remove it in fail_msi: of pci_probe() as this would lead to > an identical leak > > Fixes: 5a95f1ded28691e6 ("firewire: ohci: use devres for requested IRQ") > > Signed-off-by: Edmund Raile <edm...@pr...> > > --- > > Using FW643 with vfio-pci required unbinding from firewire_ohci, > doing so currently produces a memory leak due to a leftover irq > which this patch removes. > > The irq can be observed while the driver is loaded and bound: > find /proc/irq -type d -name "firewire_ohci" > > Is it a good idea to submit a patch to devm_request_irq() in > include/linux/interrupt.h to add the function comment > /* > * counterpart: devm_free_irq() > */ > so LSPs show that hint? > > v2 change: corrected patch title > > drivers/firewire/ohci.c | 2 ++ > 1 file changed, 2 insertions(+) > > diff --git a/drivers/firewire/ohci.c b/drivers/firewire/ohci.c > index 9db9290c3269..7bc71f4be64a 100644 > --- a/drivers/firewire/ohci.c > +++ b/drivers/firewire/ohci.c > @@ -3773,6 +3773,7 @@ static int pci_probe(struct pci_dev *dev, > return 0; > > fail_msi: > + devm_free_irq(&dev->dev, dev->irq, ohci); > pci_disable_msi(dev); > > return err; > @@ -3800,6 +3801,7 @@ static void pci_remove(struct pci_dev *dev) > > software_reset(ohci); > > + devm_free_irq(&dev->dev, dev->irq, ohci); > pci_disable_msi(dev); > > dev_notice(&dev->dev, "removing fw-ohci device\n"); > -- > 2.43.0 Thanks Takashi Sakamoto |
From: Takashi S. <o-t...@sa...> - 2024-02-29 13:41:40
|
Hi, On Wed, Feb 28, 2024 at 03:01:41AM -0800, Adam Goldman wrote: > From: Adam Goldman <ad...@po...> > > When resetting the bus after a gap count error, use a long rather than > short bus reset. > > IEEE 1394-1995 uses only long bus resets. IEEE 1394a adds the option of > short bus resets. When video or audio transmission is in progress and a > device is hot-plugged elsewhere on the bus, the resulting bus reset can > cause video frame drops or audio dropouts. Short bus resets reduce or > eliminate this problem. Accordingly, short bus resets are almost always > preferred. > > However, on a mixed 1394/1394a bus, a short bus reset can trigger an > immediate additional bus reset. This double bus reset can be interpreted > differently by different nodes on the bus, resulting in an inconsistent gap > count after the bus reset. An inconsistent gap count will cause another bus > reset, leading to a neverending bus reset loop. This only happens for some > bus topologies, not for all mixed 1394/1394a buses. > > By instead sending a long bus reset after a gap count inconsistency, we > avoid the doubled bus reset, restoring the bus to normal operation. > > Signed-off-by: Adam Goldman <ad...@po...> > Link: https://sourceforge.net/p/linux1394/mailman/message/58741624/ > --- Applied to for-linus branch. I'll send it for v6.8-rc7 in this weekend. I guess that the maintainers for the stable and longterm kernel would pick it up, like your previous patch. Thanks Takashi Sakamoto |
From: Adam G. <ad...@po...> - 2024-02-28 11:01:57
|
From: Adam Goldman <ad...@po...> When resetting the bus after a gap count error, use a long rather than short bus reset. IEEE 1394-1995 uses only long bus resets. IEEE 1394a adds the option of short bus resets. When video or audio transmission is in progress and a device is hot-plugged elsewhere on the bus, the resulting bus reset can cause video frame drops or audio dropouts. Short bus resets reduce or eliminate this problem. Accordingly, short bus resets are almost always preferred. However, on a mixed 1394/1394a bus, a short bus reset can trigger an immediate additional bus reset. This double bus reset can be interpreted differently by different nodes on the bus, resulting in an inconsistent gap count after the bus reset. An inconsistent gap count will cause another bus reset, leading to a neverending bus reset loop. This only happens for some bus topologies, not for all mixed 1394/1394a buses. By instead sending a long bus reset after a gap count inconsistency, we avoid the doubled bus reset, restoring the bus to normal operation. Signed-off-by: Adam Goldman <ad...@po...> Link: https://sourceforge.net/p/linux1394/mailman/message/58741624/ --- --- linux-6.8-rc1.orig/drivers/firewire/core-card.c 2024-01-21 14:11:32.000000000 -0800 +++ linux-6.8-rc1/drivers/firewire/core-card.c 2024-02-28 02:23:48.000000000 -0800 @@ -484,7 +484,19 @@ fw_notice(card, "phy config: new root=%x, gap_count=%d\n", new_root_id, gap_count); fw_send_phy_config(card, new_root_id, generation, gap_count); - reset_bus(card, true); + /* + * Where possible, use a short bus reset to minimize + * disruption to isochronous transfers. But in the event + * of a gap count inconsistency, use a long bus reset. + * + * As noted in 1394a 8.4.6.2, nodes on a mixed 1394/1394a bus + * may set different gap counts after a bus reset. On a mixed + * 1394/1394a bus, a short bus reset can get doubled. Some + * nodes may treat the double reset as one bus reset and others + * may treat it as two, causing a gap count inconsistency + * again. Using a long bus reset prevents this. + */ + reset_bus(card, card->gap_count != 0); /* Will allocate broadcast channel after the reset. */ goto out; } |
From: Takashi S. <o-t...@sa...> - 2024-02-28 00:42:00
|
Hi Adam, Thanks for your effort and the patch. I would like to send it to upstream, while found some nitpicks. On Mon, Feb 26, 2024 at 12:12:42AM -0800, Adam Goldman wrote: > From: Adam Goldman <ad...@po...> > > When resetting the bus after a gap count error, use a long rather than > short bus reset. > > IEEE 1394-1995 uses only long bus resets. IEEE 1394a adds the option of > short bus resets. When video or audio transmision is in progress and a > device is hot-plugged elsewhere on the bus, the resulting bus reset can > cause video frame drops or audio dropouts. Short bus resets reduce or > eliminate this problem. Accordingly, short bus resets are almost always > preferred. > > However, on a mixed 1394/1394a bus, a short bus reset can trigger an > immediate additional bus reset. This double bus reset can be interpreted > differently by different nodes on the bus, resulting in an inconsistent gap > count after the bus reset. An inconsistent gap count will cause another bus > reset, leading to a neverending bus reset loop. This only happens for some > bus topologies, not for all mixed 1394/1394a buses. > > By instead sending a long bus reset after a gap count inconsistency, we > avoid the doubled bus reset, restoring the bus to normal operation. > > Signed-off-by: Adam Goldman <ad...@po...> > Link: https://sourceforge.net/p/linux1394/mailman/message/58741624/ > --- > > --- linux-6.8-rc1.orig/drivers/firewire/core-card.c 2024-01-21 14:11:32.000000000 -0800 > +++ linux-6.8-rc1/drivers/firewire/core-card.c 2024-02-12 01:16:15.000000000 -0800 > @@ -484,7 +484,17 @@ > fw_notice(card, "phy config: new root=%x, gap_count=%d\n", > new_root_id, gap_count); > fw_send_phy_config(card, new_root_id, generation, gap_count); > - reset_bus(card, true); > + /* > + * Where possible, use a short bus reset to minimize > + * disruption to isochronous transfers. But in the event > + * of a gap count inconsistency, use a long bus reset. On > + * a mixed 1394/1394a bus, a short bus reset can get > + * doubled. Some nodes may treat this as one bus reset and > + * others may treat it as two, causing a gap count > + * inconsistency again. Using a long bus reset prevents > + * this. > + */ > + reset_bus(card, card->gap_count != 0); > /* Will allocate broadcast channel after the reset. */ > goto out; > } In your report, you referred to the section of 1394 specification about a mixed 1394/1394a bus responding differently to a reset (8.4.6.2). I think it preferable to add the section number in the code comment. Additionally, for your investigation, you added the debug print to get the timing of bus reset scheduling. I think it useful for this kind of issue. Would I ask you to write another patch to add it? In my opinion, the case of mixed versions of 1394 PHYs in the same bus has more quirks and the debug print is helpful to investigate it further. And I'm sorry to be helpless to your work. I have some IEEE 1394 hardware for consumer audio equipments, but the most of them is relatively new and support 1394a already... Thanks Takashi Sakamoto |
From: Adam G. <ad...@po...> - 2024-02-26 08:13:02
|
From: Adam Goldman <ad...@po...> When resetting the bus after a gap count error, use a long rather than short bus reset. IEEE 1394-1995 uses only long bus resets. IEEE 1394a adds the option of short bus resets. When video or audio transmision is in progress and a device is hot-plugged elsewhere on the bus, the resulting bus reset can cause video frame drops or audio dropouts. Short bus resets reduce or eliminate this problem. Accordingly, short bus resets are almost always preferred. However, on a mixed 1394/1394a bus, a short bus reset can trigger an immediate additional bus reset. This double bus reset can be interpreted differently by different nodes on the bus, resulting in an inconsistent gap count after the bus reset. An inconsistent gap count will cause another bus reset, leading to a neverending bus reset loop. This only happens for some bus topologies, not for all mixed 1394/1394a buses. By instead sending a long bus reset after a gap count inconsistency, we avoid the doubled bus reset, restoring the bus to normal operation. Signed-off-by: Adam Goldman <ad...@po...> Link: https://sourceforge.net/p/linux1394/mailman/message/58741624/ --- --- linux-6.8-rc1.orig/drivers/firewire/core-card.c 2024-01-21 14:11:32.000000000 -0800 +++ linux-6.8-rc1/drivers/firewire/core-card.c 2024-02-12 01:16:15.000000000 -0800 @@ -484,7 +484,17 @@ fw_notice(card, "phy config: new root=%x, gap_count=%d\n", new_root_id, gap_count); fw_send_phy_config(card, new_root_id, generation, gap_count); - reset_bus(card, true); + /* + * Where possible, use a short bus reset to minimize + * disruption to isochronous transfers. But in the event + * of a gap count inconsistency, use a long bus reset. On + * a mixed 1394/1394a bus, a short bus reset can get + * doubled. Some nodes may treat this as one bus reset and + * others may treat it as two, causing a gap count + * inconsistency again. Using a long bus reset prevents + * this. + */ + reset_bus(card, card->gap_count != 0); /* Will allocate broadcast channel after the reset. */ goto out; } |
From: Adam G. <ad...@po...> - 2024-02-26 07:57:58
|
Hi, Be forewarned: this is a long message about short resets. I found that in some cases, a reset loop can occur when adding a device to a FireWire bus. This happened with the following setup: a SY-PEX30016 PCI Express OHCI card with the TI XIO2213B chip was installed in the computer. This was connected to a Data Transit bus analyzer. An Exsys EX-6682 6-port FireWire 400 hub was plugged into the other port of the bus analyzer. According to lsfirewirephy, this hub has a TI TSB41LV06A chip. A Sony DSR-25 was plugged into the hub. Note that the reset loop only happens with certain topologies; it won't happen if the DSR-25 is plugged directly into the OHCI card. There was a recent change to bus reset generation, 7ed4380009e96d9e9c605e12822e987b35b05648. However, that change did not cause the problem. Also, that change did not solve the problem. The bus reset loop will happen with 7ed4380 and without 7ed4380. I believe that two things must happen to trigger this reset loop: A node on the bus must turn the short bus reset into a "double" bus reset, and another node on the bus must interpret this double reset as two resets. A comment in the open-source Mac OS X FireWire driver (IOFireWireController.cpp) mentions a situation that can cause an apparent double bus reset: > // This works around a problem with certain devices when they > // see an ISBR followed by an IBR due to ISBR promotion. Various OHCI and PHY datasheets from Texas Instruments also mention this "promotion" in the documentation for ISBR. For example, from the XIO2213B datasheet: > Note: Legacy IEEE Std 1394-1995-compliant PHYs are not capable of > performing short bus resets. Therefore, initiation of a short bus > reset in a network that contains such a legacy device results in a > long bus reset being performed. However, this explanation must be an oversimplification. It's true that 1394-1995 PHYs can't *initiate* short bus resets, but they can *recognize* them. Also, the OCHI's 1394b PHY can't be intentionally "promoting" the reset, because it has no way of knowing whether there are any 1394-1995 devices on the bus. And even if it did know, it would have no reason to generate a double reset; it should just generate a single long reset (and set the "i" bit in the self-ID packet, which it's not doing - see the logs, later). Instead, I believe that some other node on the bus is misbehaving, and responding to the short bus reset by immediately sending a long bus reset. This is a bus analyzer trace of a short bus reset, without the DSR-25 present: > 014 BUS RESET 78.96 US > 015 SELFID PKT0 80078465 01 ID=00 L=0 GAP=07 SP=400 C=0 I=0 3.010 US The rightmost column is the time delta from the previous event to the current one. The trace doesn't directly indicate whether a bus reset is short or long, but it can be inferred from the timestamps. As described in 1394a-2000, a short bus reset is ~1.3us and a long bus reset is ~167us. The self-ID packet occurs 3.01us after the bus reset, so it must have been a short bus reset. This is a bus analyzer trace of a double bus reset: > 050 BUS RESET 7.508 MS > 051 BUS RESET 2.950 US > 052 SELFID PKT0 80480880 01 ID=00 L=1 GAP=08 SP=100 C=1 I=0 168.6 US The second reset occurs 2.95us after the first one, so the first reset was short. The self-ID packet occurs 168.6us after the second bus reset, so the second reset was long. By itself, the double bus reset doesn't always cause problems. However, in some cases, some of the devices on the bus will interpret this as a single reset and others will interpret it as two resets. The one-reset devices will keep the gap count intact, while the two-reset devices will reset it, resulting in a gap count error. But if we send another short bus reset to correct the gap count error, the same thing will happen again, leading to a reset loop. This is a trimmed kernel log of the reset loop: > [17589.010477] IRQ 00000010 AR_req > [17589.012279] AR evt_bus_reset, generation 3 > [17589.013987] IRQ 00010000 selfID > [17589.015621] AR evt_bus_reset, generation 3 > [17589.017275] 5 selfIDs, generation 4, local node ID ffc3 > [17589.018893] selfID 0: 807f0880, phy 0 [p..] S100 gc=63 +0W Lc > [17589.020514] selfID 0: 813f8477, phy 1 [-c-] S400 gc=63 -3W i > [17589.022151] selfID n: 81816000, phy 1 [--p.....] > [17589.023740] selfID 0: 827f80b4, phy 2 [pc-] S400 gc=63 +0W L > [17589.025327] selfID 0: 837fcc74, phy 3 [-c-] beta gc=63 -3W Lc The DSR-25 (node 0) was powered on. The hub (node 1) initiated a bus reset because a new node appeared on one of its ports. We are node 3, and the analyzer is node 2. We are the root node. > [17589.542922] AT spd 0 tl 3a, ffc3 -> ffc0, ack_pending , QR req, fffff0000400 > [17589.546098] AR spd 0 tl 3a, ffc0 -> ffc3, ack_complete, QR resp = 04042592 > [17589.549254] AT spd 0 tl 3b, ffc3 -> ffc1, evt_missing_ack, QR req, fffff0000400 > [17589.550799] AT spd 0 tl 3c, ffc3 -> ffc2, evt_missing_ack, QR req, fffff0000400 > [17589.552385] rediscovered device fw0 We start reading the config ROMs. The missing ACKs from the hub and analyzer are normal because those devices don't have config ROMs. > [17589.553916] phy config: new root=ffc3, gap_count=8 > [17589.557011] AR spd 0 tl 14, ffc0 -> ffc3, ack_complete, QR resp = 31333934 > [17589.558507] AT spd 0 tl 14, ffc3 -> ffc0, pending/cancelled, QR req, fffff0000404 We send a PHY configuration packet for gap count optimization. Meanwhile we continue reading the DSR-25's config ROM. > [17589.561477] reset_bus(short_reset=1) > [17589.563013] IRQ 00000010 AR_req > [17589.564534] AR evt_bus_reset, generation 5 > [17589.566021] IRQ 00010000 selfID > [17589.567436] AR evt_bus_reset, generation 5 > [17589.568860] AT spd 0 tl 15, ffc3 -> ffc0, evt_no_status, QR req, fffff0000408 We initiate a short bus reset to complete the gap count optimization. In this log, I added output to reset_bus() so you can see where we initiated the bus reset. evt_bus_reset then gets called TWICE. Meanwhile there is a dangling config ROM read attempt. > [17589.570280] 5 selfIDs, generation 6, local node ID ffc3 > [17589.571663] selfID 0: 80480880, phy 0 [p..] S100 gc=8 +0W Lc > [17589.573087] selfID 0: 81088475, phy 1 [-c-] S400 gc=8 -3W > [17589.574497] selfID n: 81816000, phy 1 [--p.....] > [17589.575869] selfID 0: 827f80b4, phy 2 [pc-] S400 gc=63 +0W L > [17589.577228] selfID 0: 8348cc74, phy 3 [-c-] beta gc=8 -3W Lc After the bus reset, most of the devices have set their gap count to 8, but the analyzer has set it to 63. We had initiated a bus reset, but in the self ID packets, we aren't taking credit for the bus reset and neither is anyone else. > [17589.578599] giving up on node ffc0: reading config rom failed: bus reset > [17590.086737] AR spd 0 tl 17, ffc0 -> ffc3, ack_complete, QR resp = 04042592 > [17590.088094] AT spd 0 tl 17, ffc3 -> ffc0, pending/cancelled, QR req, fffff0000400 > [17590.090849] AT spd 0 tl 18, ffc3 -> ffc1, evt_missing_ack, QR req, fffff0000400 > [17590.093712] AT spd 0 tl 19, ffc3 -> ffc2, evt_missing_ack, QR req, fffff0000400 > [17590.095168] rediscovered device fw0 We start reading config ROMs again. > [17590.096576] phy config: new root=ffc3, gap_count=8 > [17590.099530] AR spd 0 tl 31, ffc0 -> ffc3, ack_complete, QR resp = 31333934 > [17590.101014] AT spd 0 tl 31, ffc3 -> ffc0, pending/cancelled, QR req, fffff0000404 > [17590.103970] reset_bus(short_reset=1) We send another short bus reset to correct the gap count error. > [17590.105471] IRQ 00000010 AR_req > [17590.106934] AR evt_bus_reset, generation 7 > [17590.108439] IRQ 00010000 selfID > [17590.109901] AR evt_bus_reset, generation 7 > [17590.111381] AT spd 0 tl 32, ffc3 -> ffc0, evt_no_status, QR req, fffff0000408 > [17590.112862] 5 selfIDs, generation 8, local node ID ffc3 > [17590.114349] selfID 0: 80480880, phy 0 [p..] S100 gc=8 +0W Lc > [17590.115864] selfID 0: 81088475, phy 1 [-c-] S400 gc=8 -3W > [17590.117373] selfID n: 81816000, phy 1 [--p.....] > [17590.118844] selfID 0: 827f80b4, phy 2 [pc-] S400 gc=63 +0W L > [17590.120297] selfID 0: 8348cc74, phy 3 [-c-] beta gc=8 -3W Lc The reset gets doubled again and the gap counts are inconsistent again. This repeats forever until the DSR-25 is turned off. IEEE 1394a section 8.4.6.2 mentions the possibility of nodes on a mixed 1394/1394a bus responding differently to a reset, and gives the solution of using a long bus reset to recover: > NOTE—Differences in the reset state machines between PHYs compliant with > IEEE Std 1394-1995 (but unmodified by IEEE Std 1394a-2000) and those > compliant with IEEE Std 1394a-2000 may result in different gap counts > (subsequent to a bus reset preceded by a PHY configuration packet) when > a mixture of devices is present. The probability of this inconsistency > may be reduced by asserting BUS_RESET for 166.6 us instead of the > arbitrated (short) bus reset specified by this standard, but this remedy > should not be applied unless inconsistent gap counts have been observed > subsequent to arbitrated (short) bus resets. This heuristic does not > guarantee uniform values for gap_count at all nodes; nevertheless, > because of the probabilistic nature of the problem, success is likely > after a modest number of attempts. Indeed, the Mac OS X driver uses 1394a's suggested approach: > // If the gap counts were mismatched and we're optimizing the > // gap count, use in IBR instead of an ISBR Regarding the difference in 1394-1995 and 1394a devices, the comment in the Mac driver goes on to say this: > // When this occurs the device is supposed to throw out the IBR. > // Devices that don't do this latch the gap count with the ISBR > // and then reset it with the subsequent IBR. > > // This gets us into a loop where we keep trying to optimize the > // gap count only to find it reset on the next bus generation The implication is that some of the PHYs are debouncing the incoming resets and some aren't. However, the node that was clearing the gap count seems to debounce resets in some cases. In the following kernel log and analyzer trace excerpts, the analyzer and DSR-25 are still present but the hub has been removed from the chain: > [ 6927.395841] phy config: new root=ffc2, gap_count=7 > [ 6927.397589] IRQ 00000001 AT_req > [ 6927.399340] AT ack_complete, PHY 02c70000 fd38ffff > [ 6927.401206] IRQ 00000010 AR_req > [ 6927.402928] AR evt_bus_reset, generation 8 > [ 6927.404586] IRQ 00010000 selfID > [ 6927.406196] AR evt_bus_reset, generation 8 > [ 6927.407846] 3 selfIDs, generation 9, local node ID ffc2 > [ 6927.409452] selfID 0: 80070880, phy 0 [p..] S100 gc=7 +0W c > [ 6927.411075] selfID 0: 814780b4, phy 1 [pc-] S400 gc=7 +0W L > [ 6927.412677] selfID 0: 8247ccd4, phy 2 [c--] beta gc=7 -3W Lc > 007 PHY_CONFIG 02C70000 01 ROOT ID=02 R=1 T=1 GAP=07 13.76 MS > 008 ASYNC FD38FFFF 02 0.330 US > 009 SUBACTN GAP 1.690 US > 010 ARB GAP 1.380 US > 011 BUS RESET 3.611 MS > 012 SELFID PKT0 80070880 01 ID=00 L=0 GAP=07 SP=100 C=1 I=0 171.0 US With this topology change, the double reset still seems to be happening. There are two evt_bus_resets in syslog, the timing of the self-ID packet shows that there must have been a long bus reset, and none of the self-ID packets are claiming responsibility for the reset. But this time, the gap count is consistent, and the analyzer trace only shows one reset. The self-ID packet is 171.0us after the bus reset; in the "bad" topology, the self-ID packet is ~171.6us after the first bus reset. So it looks like the analyzer's PHY is considering the two resets to be a single reset in this case, but not in the other case. (The 600ns difference also suggests that the DSR-25 is the origin of the second reset in the double reset pair. The hub would introduce this delay between the OHCI's short reset as seen by the analyzer and the DSR-25's long reset as seen by the analyzer.) So, I think the best explanation for the gap count inconsistency is some more subtle difference in bus reset detection between 1394-1995 and 1394a devices, and not that the node is just failing to throw away a bus reset that it's supposed to. I've prepared a patch that uses a long bus reset when responding to a gap count inconsistency. This eliminates the reset loop. I will submit the patch soon. Here is what happens with the "bad" topology and the patched kernel: > [17074.390846] IRQ 00000010 AR_req > [17074.392893] AR evt_bus_reset, generation 3 > [17074.394846] IRQ 00010000 selfID > [17074.396775] AR evt_bus_reset, generation 3 > [17074.398655] 5 selfIDs, generation 4, local node ID ffc3 > [17074.400589] selfID 0: 807f0880, phy 0 [p..] S100 gc=63 +0W Lc > [17074.402442] selfID 0: 813f8467, phy 1 [-p-] S400 gc=63 -3W i > [17074.404261] selfID n: 81835000, phy 1 [c--.....] > [17074.406075] selfID 0: 827f80b4, phy 2 [pc-] S400 gc=63 +0W L > [17074.407857] selfID 0: 837fccd4, phy 3 [c--] beta gc=63 -3W Lc > 000 BUS RESET 0.000 USX > 001 BUS RESET 2.600 US > 002 SELFID PKT0 807F0880 01 ID=00 L=1 GAP=3F SP=100 C=1 I=0 168.6 US The DSR-25 was powered on and the hub initiated a bus reset. > [17074.918368] AT spd 0 tl 3a, ffc3 -> ffc0, ack_pending , QR req, fffff0000400 > [17074.921964] AR spd 0 tl 3a, ffc0 -> ffc3, ack_complete, QR resp = 04042592 > [17074.925563] AR spd 0 tl 3c, ffc0 -> ffc3, ack_complete, QR resp = 31333934 > [17074.927306] AT spd 0 tl 3c, ffc3 -> ffc0, pending/cancelled, QR req, fffff0000404 > [17074.929046] AT spd 0 tl 3b, ffc3 -> ffc1, evt_missing_ack, QR req, fffff0000400 > [17074.932573] AT spd 0 tl 3d, ffc3 -> ffc2, evt_missing_ack, QR req, fffff0000400 > [17074.934335] rediscovered device fw0 We start reading the config ROMs. > [17074.936033] phy config: new root=ffc3, gap_count=8 > [17074.937810] IRQ 00000021 AR_resp AT_req > [17074.939486] AR spd 0 tl 15, ffc0 -> ffc3, ack_complete, QR resp = e0644000 > [17074.941196] AT spd 0 tl 15, ffc3 -> ffc0, pending/cancelled, QR req, fffff0000408 > [17074.942879] AT ack_complete, PHY 03c80000 fc37ffff > [17074.944597] IRQ 00000011 AR_req AT_req > [17074.946252] AR evt_bus_reset, generation 5 > [17074.947924] IRQ 00010010 selfID AR_req > [17074.949544] AR evt_bus_reset, generation 5 > [17074.951130] AT spd 0 tl 16, ffc3 -> ffc0, ack_pending , QR req, fffff000040c > [17074.952770] 5 selfIDs, generation 6, local node ID ffc3 > [17074.954341] selfID 0: 80480880, phy 0 [p..] S100 gc=8 +0W Lc > [17074.955918] selfID 0: 81088465, phy 1 [-p-] S400 gc=8 -3W > [17074.957480] selfID n: 81835000, phy 1 [c--.....] > [17074.959008] selfID 0: 827f80b4, phy 2 [pc-] S400 gc=63 +0W L > [17074.960537] selfID 0: 8348ccd4, phy 3 [c--] beta gc=8 -3W Lc > 072 ASYNC F000040C 03 DEST OFFSET=FFFF:F000:040C 0.330 US > 073 ASYNC A2508E4C 04 HEADER CRC 0.320 US > 074 ACK 2D ACK_PENDING 1.370 US > 075 BUS RESET 5.730 US > 076 BUS RESET 2.950 US > 077 SELFID PKT0 80480880 01 ID=00 L=1 GAP=08 SP=100 C=1 I=0 168.6 US We send a PHY configuration packet and short bus reset for gap count optimization. This turns into a double bus reset, and there is a gap count inconsistency. > [17075.494059] AT spd 0 tl 18, ffc3 -> ffc0, ack_pending , QR req, fffff0000400 > [17075.497078] AR spd 0 tl 18, ffc0 -> ffc3, ack_complete, QR resp = 04042592 > [17075.500071] AT spd 0 tl 19, ffc3 -> ffc1, evt_missing_ack, QR req, fffff0000400 > [17075.503125] AT spd 0 tl 1a, ffc3 -> ffc2, evt_missing_ack, QR req, fffff0000400 > [17075.504702] rediscovered device fw0 We start reading config ROMs again. > [17075.506199] phy config: new root=ffc3, gap_count=8 > [17075.507759] IRQ 00000021 AR_resp AT_req > [17075.509326] AR spd 0 tl 32, ffc0 -> ffc3, ack_complete, QR resp = 31333934 > [17075.510842] AT spd 0 tl 32, ffc3 -> ffc0, pending/cancelled, QR req, fffff0000404 > [17075.512351] AT ack_complete, PHY 03c80000 fc37ffff > [17075.513960] IRQ 00000010 AR_req > [17075.515477] AR evt_bus_reset, generation 7 > [17075.517035] IRQ 00010000 selfID > [17075.518559] AT spd 0 tl 33, ffc3 -> ffc0, evt_no_status, QR req, fffff0000408 > [17075.520106] 5 selfIDs, generation 7, local node ID ffc3 > [17075.521660] selfID 0: 80480880, phy 0 [p..] S100 gc=8 +0W Lc > [17075.523228] selfID 0: 81088465, phy 1 [-p-] S400 gc=8 -3W > [17075.524793] selfID n: 81835000, phy 1 [c--.....] > [17075.526321] selfID 0: 824880b4, phy 2 [pc-] S400 gc=8 +0W L > [17075.527821] selfID 0: 8348ccd6, phy 3 [c--] beta gc=8 -3W Lci > 133 ASYNC 31333934 04 QUADLET=31333934 0.330 US > 134 ASYNC 86B1088D 05 HEADER CRC 0.320 US > 135 ACK 1E ACK_COMPLETE 1.330 US > 136 SUBACTN GAP 1.830 US > 137 ARB GAP 1.580 US > 138 BUS RESET 6.164 MS > 139 SELFID PKT0 80480880 01 ID=00 L=1 GAP=08 SP=100 C=1 I=0 169.4 US We send a long bus reset to correct the gap count error. This is successful. The bus reset does not get doubled, and the gap counts are consistent. > [17078.534125] AR spd 0 tl 3f, ffc0 -> ffc3, ack_complete, QR resp = 04042592 > [17078.535629] AT spd 0 tl 3f, ffc3 -> ffc0, pending/cancelled, QR req, fffff0000400 ... > [17078.771716] AT spd 0 tl 21, ffc3 -> ffc0, ack_pending , QR req, fffff0000450 > [17078.775367] AR spd 0 tl 21, ffc0 -> ffc3, ack_complete, QR resp = 536f6e79 > [17078.777511] created device fw1: GUID 08004601025e582a, S100 There are no more bus resets. We read the config ROM and we're ready to rock and roll. So, I believe that when there is a gap count inconsistency, sending a long bus reset is the right thing to do. -- Adam |
From: Adam G. <ad...@po...> - 2024-02-19 01:42:25
|
Hi Tasos, On Tue, Feb 13, 2024 at 12:18:01PM +0200, Tasos Sahanidis wrote: > Thank you for still looking into this. Apologies the late response once > more. Things got a bit out of hand... Unfortunately, I haven't had much time for FireWire recently, so my response is also late. Thank you for the additional logs. > I thought maybe it works if the system boots with the camera plugged in, > so I powered off the system, power cycled the camera, and booted > directly to 6.7. Except 6.7 crashed on boot without any logs. I did not > at the time have another machine with a serial port, so I was unable to > gather any logs, and I didn't have time to test out netconsole. A few > more reboots with the camera plugged in, and the system eventually > booted, but I got the following mess: > > [ 88.040334] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset > [message repeated every 5~10us] > [ 88.062147] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset > [ 88.062155] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset > [ 88.062162] firewire_ohci 0000:01:03.0: IRQ 00020010 AR_req busReset > [ 88.062169] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset Are you setting debug=-1 when loading the module? I believe OHCI_PARAM_DEBUG_BUSRESETS has been broken for years. It will freeze the system or spam tons of busReset log entries if enabled during module load, even without a camera connected. debug=7 should be safe. By the way, I will be submitting a patch relating to bus resets soon, but don't get excited. It won't help with the problem you're experiencing. -- Adam |
From: Tasos S. <ta...@ta...> - 2024-02-13 10:18:23
|
On 2024-02-13 11:11, Adam Goldman wrote: > Hi Tasos, > > I can confirm that the same problem occurs on a JVC GR-D30U connected to > an XIO2213B OHCI chip. So it's not specific to the TSB43AB22A, and it > affects several JVC models. I haven't investigated fully. > > -- Adam Thank you for still looking into this. Apologies the late response once more. Things got a bit out of hand... On 2024-01-23 08:57, Adam Goldman wrote: > The camera's oPCR0 register (the response to the read of '904) has the > online and broadcast bits clear, indicating that the output plug will > not be sending any video. I wonder why? (Compare to the value c03f3c7a > in the 2.6.35-rc3 case, which has the online and broadcast bits set.) I noticed dvgrab complaining about "libiec61883 warning: Transmission node has no plugs online!" but I thought it said the same thing when it worked, thus I ignored it. That is actually not the case. It warns about something else. > What do the 6.7 logs look like when the camera is first turned on, > starting with the first evt_bus_reset? And here is why things got out of hand. I booted 2.6 to capture the logs, ran dvgrab to make sure it worked, rebooted to 6.7 while leaving the camera plugged in and re-ran dvgrab on 6.7 and it worked. I thought maybe it works if the system boots with the camera plugged in, so I powered off the system, power cycled the camera, and booted directly to 6.7. Except 6.7 crashed on boot without any logs. I did not at the time have another machine with a serial port, so I was unable to gather any logs, and I didn't have time to test out netconsole. A few more reboots with the camera plugged in, and the system eventually booted, but I got the following mess: [ 88.040334] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [message repeated every 5~10us] [ 88.062147] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062155] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062162] firewire_ohci 0000:01:03.0: IRQ 00020010 AR_req busReset [ 88.062169] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062173] firewire_ohci 0000:01:03.0: AR evt_bus_reset, generation 9 [ 88.062176] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062183] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062191] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062198] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062205] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062212] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062219] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062227] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062234] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062241] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062248] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062255] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062262] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062269] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062277] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062284] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062291] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062298] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062306] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062313] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062320] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062327] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062334] firewire_ohci 0000:01:03.0: IRQ 00030000 selfID busReset [ 88.062344] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062351] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062360] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 88.062365] firewire_ohci 0000:01:03.0: 1 selfIDs, generation 9, local node ID ffc0 [ 88.062369] firewire_ohci 0000:01:03.0: selfID 0: 807f8c52, phy 0 [--.] S400 gc=63 -3W Lci [ 88.570753] firewire_core 0000:01:03.0: rediscovered device fw0 [ 92.597987] firewire_ohci 0000:01:03.0: IRQ 00020010 AR_req busReset [ 92.598010] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598019] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598027] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598034] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598038] firewire_ohci 0000:01:03.0: AR evt_bus_reset, generation 10 [ 92.598041] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598049] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598059] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598067] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598074] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598081] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598088] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598096] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598103] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598110] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598117] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598123] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598131] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598138] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598146] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598153] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598160] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598168] firewire_ohci 0000:01:03.0: IRQ 00030000 selfID busReset [ 92.598177] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598185] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598192] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598199] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598206] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.598213] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [more repeats] [ 92.602565] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602572] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602581] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602585] firewire_ohci 0000:01:03.0: 2 selfIDs, generation 10, local node ID ffc1 [ 92.602588] firewire_ohci 0000:01:03.0: selfID 0: 807f0880, phy 0 [p..] S100 gc=63 +0W Lc [ 92.602593] firewire_ohci 0000:01:03.0: selfID 0: 817f8cd2, phy 1 [c-.] S400 gc=63 -3W Lci [ 92.602621] firewire_core 0000:01:03.0: phy config: new root=ffc1, gap_count=5 [ 92.602632] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 92.602637] firewire_ohci 0000:01:03.0: AT ack_complete, PHY 01c50000 fe3affff [ 92.602650] firewire_ohci 0000:01:03.0: IRQ 00020010 AR_req busReset [ 92.602655] firewire_ohci 0000:01:03.0: AR evt_bus_reset, generation 11 [ 92.602657] firewire_ohci 0000:01:03.0: IRQ 00020010 AR_req busReset [ 92.602662] firewire_ohci 0000:01:03.0: AR evt_bus_reset, generation 11 [ 92.602664] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602671] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602678] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602685] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602692] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602699] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602706] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602713] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602720] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602727] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602734] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602742] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602749] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602756] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602763] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602771] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602777] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602785] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602792] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602799] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602806] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602814] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602821] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602828] firewire_ohci 0000:01:03.0: IRQ 00030000 selfID busReset [ 92.602839] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602847] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602854] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.602858] firewire_ohci 0000:01:03.0: 2 selfIDs, generation 12, local node ID ffc1 [ 92.602861] firewire_ohci 0000:01:03.0: selfID 0: 80450880, phy 0 [p..] S100 gc=5 +0W Lc [ 92.602864] firewire_ohci 0000:01:03.0: selfID 0: 81458cd2, phy 1 [c-.] S400 gc=5 -3W Lci [ 92.996576] firewire_ohci 0000:01:03.0: IRQ 00020010 AR_req busReset [ 92.996591] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996600] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996606] firewire_ohci 0000:01:03.0: AR evt_bus_reset, generation 13 [ 92.996609] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996617] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996625] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996632] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996639] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996647] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996654] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996661] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996668] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996675] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996682] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996689] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996696] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996704] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996711] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996718] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996725] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996733] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996740] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996747] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996754] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996761] firewire_ohci 0000:01:03.0: IRQ 00030000 selfID busReset [ 92.996771] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996779] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996787] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 92.996791] firewire_ohci 0000:01:03.0: 2 selfIDs, generation 13, local node ID ffc1 [ 92.996794] firewire_ohci 0000:01:03.0: selfID 0: 807f0882, phy 0 [p..] S100 gc=63 +0W Lci [ 92.996798] firewire_ohci 0000:01:03.0: selfID 0: 817f8cd0, phy 1 [c-.] S400 gc=63 -3W Lc [ 93.114543] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.114551] firewire_ohci 0000:01:03.0: AT spd 0 tl 18, ffc1 -> ffc0, ack_pending , QR req, fffff0000400 [ 93.114591] firewire_core 0000:01:03.0: rediscovered device fw0 [ 93.114598] firewire_core 0000:01:03.0: giving up on node ffc0: reading config rom failed: bus reset [ 93.114601] firewire_core 0000:01:03.0: phy config: new root=ffc1, gap_count=5 [ 93.114613] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.114618] firewire_ohci 0000:01:03.0: AT ack_complete, PHY 01c50000 fe3affff [ 93.114629] firewire_ohci 0000:01:03.0: IRQ 00020010 AR_req busReset [ 93.114634] firewire_ohci 0000:01:03.0: AR evt_bus_reset, generation 14 [ 93.114637] firewire_ohci 0000:01:03.0: IRQ 00020010 AR_req busReset [ 93.114641] firewire_ohci 0000:01:03.0: AR evt_bus_reset, generation 14 [ 93.114644] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114651] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114658] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114664] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114671] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114677] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114684] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114690] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114697] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114703] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114711] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114717] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114723] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114730] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114736] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114743] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114749] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114756] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114763] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114769] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114776] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114783] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114789] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114797] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114803] firewire_ohci 0000:01:03.0: IRQ 00030000 selfID busReset [ 93.114812] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114821] firewire_ohci 0000:01:03.0: IRQ 00020000 busReset [ 93.114824] firewire_ohci 0000:01:03.0: 2 selfIDs, generation 15, local node ID ffc1 [ 93.114827] firewire_ohci 0000:01:03.0: selfID 0: 80450880, phy 0 [p..] S100 gc=5 +0W Lc [ 93.114830] firewire_ohci 0000:01:03.0: selfID 0: 81458cd2, phy 1 [c-.] S400 gc=5 -3W Lci [ 93.626524] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.626532] firewire_ohci 0000:01:03.0: AT spd 0 tl 31, ffc1 -> ffc0, ack_pending , QR req, fffff0000400 [ 93.626566] firewire_core 0000:01:03.0: rediscovered device fw0 [ 93.627196] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.627202] firewire_ohci 0000:01:03.0: AR spd 0 tl 31, ffc0 -> ffc1, ack_complete, QR resp = 0426907c [ 93.627218] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.627223] firewire_ohci 0000:01:03.0: AT spd 0 tl 0a, ffc1 -> ffc0, ack_pending , QR req, fffff0000404 [ 93.628200] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.628204] firewire_ohci 0000:01:03.0: AR spd 0 tl 0a, ffc0 -> ffc1, ack_complete, QR resp = 31333934 [ 93.628220] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.628224] firewire_ohci 0000:01:03.0: AT spd 0 tl 0b, ffc1 -> ffc0, ack_pending , QR req, fffff0000408 [ 93.629190] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.629195] firewire_ohci 0000:01:03.0: AR spd 0 tl 0b, ffc0 -> ffc1, ack_complete, QR resp = e0644000 [ 93.629211] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.629216] firewire_ohci 0000:01:03.0: AT spd 0 tl 0c, ffc1 -> ffc0, ack_pending , QR req, fffff000040c [ 93.630213] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.630217] firewire_ohci 0000:01:03.0: AR spd 0 tl 0c, ffc0 -> ffc1, ack_complete, QR resp = 00808801 [ 93.630233] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.630238] firewire_ohci 0000:01:03.0: AT spd 0 tl 0d, ffc1 -> ffc0, ack_pending , QR req, fffff0000410 [ 93.631190] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.631196] firewire_ohci 0000:01:03.0: AR spd 0 tl 0d, ffc0 -> ffc1, ack_complete, QR resp = 035809f1 [ 93.634527] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.634533] firewire_ohci 0000:01:03.0: AT spd 0 tl 0e, ffc1 -> ffc0, ack_pending , QR req, fffff0000414 [ 93.635194] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.635201] firewire_ohci 0000:01:03.0: AR spd 0 tl 0e, ffc0 -> ffc1, ack_complete, QR resp = 0008c442 [ 93.635221] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.635227] firewire_ohci 0000:01:03.0: AT spd 0 tl 0f, ffc1 -> ffc0, ack_pending , QR req, fffff0000418 [ 93.636207] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.636214] firewire_ohci 0000:01:03.0: AR spd 0 tl 0f, ffc0 -> ffc1, ack_complete, QR resp = 03008088 [ 93.636234] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.636239] firewire_ohci 0000:01:03.0: AT spd 0 tl 10, ffc1 -> ffc0, ack_pending , QR req, fffff000041c [ 93.637190] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.637196] firewire_ohci 0000:01:03.0: AR spd 0 tl 10, ffc0 -> ffc1, ack_complete, QR resp = 8100000f [ 93.637218] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.637223] firewire_ohci 0000:01:03.0: AT spd 0 tl 11, ffc1 -> ffc0, ack_pending , QR req, fffff0000420 [ 93.638205] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.638211] firewire_ohci 0000:01:03.0: AR spd 0 tl 11, ffc0 -> ffc1, ack_complete, QR resp = 0c0083c0 [ 93.638231] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.638236] firewire_ohci 0000:01:03.0: AT spd 0 tl 12, ffc1 -> ffc0, ack_pending , QR req, fffff0000424 [ 93.639190] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.639196] firewire_ohci 0000:01:03.0: AR spd 0 tl 12, ffc0 -> ffc1, ack_complete, QR resp = d1000005 [ 93.639217] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.639222] firewire_ohci 0000:01:03.0: AT spd 0 tl 13, ffc1 -> ffc0, ack_pending , QR req, fffff0000428 [ 93.640463] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.640469] firewire_ohci 0000:01:03.0: AR spd 0 tl 13, ffc0 -> ffc1, ack_complete, QR resp = 8d000013 [ 93.640489] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.640494] firewire_ohci 0000:01:03.0: AT spd 0 tl 14, ffc1 -> ffc0, ack_pending , QR req, fffff000042c [ 93.641358] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.641364] firewire_ohci 0000:01:03.0: AR spd 0 tl 14, ffc0 -> ffc1, ack_complete, QR resp = c3000008 [ 93.641385] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.641390] firewire_ohci 0000:01:03.0: AT spd 0 tl 15, ffc1 -> ffc0, ack_pending , QR req, fffff0000430 [ 93.642261] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.642268] firewire_ohci 0000:01:03.0: AR spd 0 tl 15, ffc0 -> ffc1, ack_complete, QR resp = 1701006b [ 93.642288] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.642293] firewire_ohci 0000:01:03.0: AT spd 0 tl 16, ffc1 -> ffc0, ack_pending , QR req, fffff0000434 [ 93.643279] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.643285] firewire_ohci 0000:01:03.0: AR spd 0 tl 16, ffc0 -> ffc1, ack_complete, QR resp = 81000013 [ 93.643306] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.643311] firewire_ohci 0000:01:03.0: AT spd 0 tl 17, ffc1 -> ffc0, ack_pending , QR req, fffff0000480 [ 93.644196] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.644202] firewire_ohci 0000:01:03.0: AR spd 0 tl 17, ffc0 -> ffc1, ack_complete, QR resp = 0006c2ad [ 93.644224] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.644228] firewire_ohci 0000:01:03.0: AT spd 0 tl 19, ffc1 -> ffc0, ack_pending , QR req, fffff0000484 [ 93.645196] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.645202] firewire_ohci 0000:01:03.0: AR spd 0 tl 19, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.645222] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.645227] firewire_ohci 0000:01:03.0: AT spd 0 tl 1a, ffc1 -> ffc0, ack_pending , QR req, fffff0000488 [ 93.646201] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.646207] firewire_ohci 0000:01:03.0: AR spd 0 tl 1a, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.646227] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.646232] firewire_ohci 0000:01:03.0: AT spd 0 tl 1b, ffc1 -> ffc0, ack_pending , QR req, fffff000048c [ 93.647195] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.647202] firewire_ohci 0000:01:03.0: AR spd 0 tl 1b, ffc0 -> ffc1, ack_complete, QR resp = 47522d44 [ 93.647222] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.647227] firewire_ohci 0000:01:03.0: AT spd 0 tl 1c, ffc1 -> ffc0, ack_pending , QR req, fffff0000490 [ 93.648199] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.648206] firewire_ohci 0000:01:03.0: AR spd 0 tl 1c, ffc0 -> ffc1, ack_complete, QR resp = 32300000 [ 93.648226] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.648231] firewire_ohci 0000:01:03.0: AT spd 0 tl 1d, ffc1 -> ffc0, ack_pending , QR req, fffff0000494 [ 93.649190] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.649196] firewire_ohci 0000:01:03.0: AR spd 0 tl 1d, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.649216] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.649221] firewire_ohci 0000:01:03.0: AT spd 0 tl 1e, ffc1 -> ffc0, ack_pending , QR req, fffff0000498 [ 93.650216] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.650222] firewire_ohci 0000:01:03.0: AR spd 0 tl 1e, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.650242] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.650247] firewire_ohci 0000:01:03.0: AT spd 0 tl 1f, ffc1 -> ffc0, ack_pending , QR req, fffff000044c [ 93.651189] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.651196] firewire_ohci 0000:01:03.0: AR spd 0 tl 1f, ffc0 -> ffc1, ack_complete, QR resp = 0002ad09 [ 93.651216] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.651221] firewire_ohci 0000:01:03.0: AT spd 0 tl 20, ffc1 -> ffc0, ack_pending , QR req, fffff0000450 [ 93.652268] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.652275] firewire_ohci 0000:01:03.0: AR spd 0 tl 20, ffc0 -> ffc1, ack_complete, QR resp = 1701006b [ 93.652296] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.652301] firewire_ohci 0000:01:03.0: AT spd 0 tl 21, ffc1 -> ffc0, ack_pending , QR req, fffff0000454 [ 93.653258] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.653264] firewire_ohci 0000:01:03.0: AR spd 0 tl 21, ffc0 -> ffc1, ack_complete, QR resp = 8100000b [ 93.653284] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.653289] firewire_ohci 0000:01:03.0: AT spd 0 tl 22, ffc1 -> ffc0, ack_pending , QR req, fffff0000480 [ 93.654189] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.654196] firewire_ohci 0000:01:03.0: AR spd 0 tl 22, ffc0 -> ffc1, ack_complete, QR resp = 0006c2ad [ 93.654217] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.654222] firewire_ohci 0000:01:03.0: AT spd 0 tl 23, ffc1 -> ffc0, ack_pending , QR req, fffff0000484 [ 93.655210] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.655216] firewire_ohci 0000:01:03.0: AR spd 0 tl 23, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.655236] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.655241] firewire_ohci 0000:01:03.0: AT spd 0 tl 24, ffc1 -> ffc0, ack_pending , QR req, fffff0000488 [ 93.656192] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.656198] firewire_ohci 0000:01:03.0: AR spd 0 tl 24, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.656219] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.656224] firewire_ohci 0000:01:03.0: AT spd 0 tl 25, ffc1 -> ffc0, ack_pending , QR req, fffff000048c [ 93.657199] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.657205] firewire_ohci 0000:01:03.0: AR spd 0 tl 25, ffc0 -> ffc1, ack_complete, QR resp = 47522d44 [ 93.657225] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.657230] firewire_ohci 0000:01:03.0: AT spd 0 tl 26, ffc1 -> ffc0, ack_pending , QR req, fffff0000490 [ 93.658184] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.658190] firewire_ohci 0000:01:03.0: AR spd 0 tl 26, ffc0 -> ffc1, ack_complete, QR resp = 32300000 [ 93.658210] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.658215] firewire_ohci 0000:01:03.0: AT spd 0 tl 27, ffc1 -> ffc0, ack_pending , QR req, fffff0000494 [ 93.659191] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.659197] firewire_ohci 0000:01:03.0: AR spd 0 tl 27, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.659217] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.659222] firewire_ohci 0000:01:03.0: AT spd 0 tl 28, ffc1 -> ffc0, ack_pending , QR req, fffff0000498 [ 93.660359] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.660365] firewire_ohci 0000:01:03.0: AR spd 0 tl 28, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.660386] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.660391] firewire_ohci 0000:01:03.0: AT spd 0 tl 29, ffc1 -> ffc0, ack_pending , QR req, fffff0000474 [ 93.661245] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.661251] firewire_ohci 0000:01:03.0: AR spd 0 tl 29, ffc0 -> ffc1, ack_complete, QR resp = 0002f1df [ 93.661271] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.661276] firewire_ohci 0000:01:03.0: AT spd 0 tl 2a, ffc1 -> ffc0, ack_pending , QR req, fffff0000478 [ 93.662314] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.662320] firewire_ohci 0000:01:03.0: AR spd 0 tl 2a, ffc0 -> ffc1, ack_complete, QR resp = 00808801 [ 93.662342] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.662347] firewire_ohci 0000:01:03.0: AT spd 0 tl 2b, ffc1 -> ffc0, ack_pending , QR req, fffff000047c [ 93.663245] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.663252] firewire_ohci 0000:01:03.0: AR spd 0 tl 2b, ffc0 -> ffc1, ack_complete, QR resp = 035809f1 [ 93.663272] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.663277] firewire_ohci 0000:01:03.0: AT spd 0 tl 2c, ffc1 -> ffc0, ack_pending , QR req, fffff0000438 [ 93.664189] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.664195] firewire_ohci 0000:01:03.0: AR spd 0 tl 2c, ffc0 -> ffc1, ack_complete, QR resp = 00043327 [ 93.664215] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.664220] firewire_ohci 0000:01:03.0: AT spd 0 tl 2d, ffc1 -> ffc0, ack_pending , QR req, fffff000043c [ 93.665190] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.665196] firewire_ohci 0000:01:03.0: AR spd 0 tl 2d, ffc0 -> ffc1, ack_complete, QR resp = 1200a02d [ 93.665215] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.665220] firewire_ohci 0000:01:03.0: AT spd 0 tl 2e, ffc1 -> ffc0, ack_pending , QR req, fffff0000440 [ 93.666195] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.666201] firewire_ohci 0000:01:03.0: AR spd 0 tl 2e, ffc0 -> ffc1, ack_complete, QR resp = 13010001 [ 93.666222] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.666227] firewire_ohci 0000:01:03.0: AT spd 0 tl 2f, ffc1 -> ffc0, ack_pending , QR req, fffff0000444 [ 93.667191] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.667198] firewire_ohci 0000:01:03.0: AR spd 0 tl 2f, ffc0 -> ffc1, ack_complete, QR resp = 1701006b [ 93.667218] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.667223] firewire_ohci 0000:01:03.0: AT spd 0 tl 30, ffc1 -> ffc0, ack_pending , QR req, fffff0000448 [ 93.668195] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.668201] firewire_ohci 0000:01:03.0: AR spd 0 tl 30, ffc0 -> ffc1, ack_complete, QR resp = 8100000e [ 93.668222] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.668227] firewire_ohci 0000:01:03.0: AT spd 0 tl 31, ffc1 -> ffc0, ack_pending , QR req, fffff0000480 [ 93.669189] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.669195] firewire_ohci 0000:01:03.0: AR spd 0 tl 31, ffc0 -> ffc1, ack_complete, QR resp = 0006c2ad [ 93.669216] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.669221] firewire_ohci 0000:01:03.0: AT spd 0 tl 32, ffc1 -> ffc0, ack_pending , QR req, fffff0000484 [ 93.670207] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.670213] firewire_ohci 0000:01:03.0: AR spd 0 tl 32, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.670234] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.670240] firewire_ohci 0000:01:03.0: AT spd 0 tl 33, ffc1 -> ffc0, ack_pending , QR req, fffff0000488 [ 93.671189] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.671196] firewire_ohci 0000:01:03.0: AR spd 0 tl 33, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.671215] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.671220] firewire_ohci 0000:01:03.0: AT spd 0 tl 34, ffc1 -> ffc0, ack_pending , QR req, fffff000048c [ 93.672189] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.672195] firewire_ohci 0000:01:03.0: AR spd 0 tl 34, ffc0 -> ffc1, ack_complete, QR resp = 47522d44 [ 93.672216] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.672221] firewire_ohci 0000:01:03.0: AT spd 0 tl 35, ffc1 -> ffc0, ack_pending , QR req, fffff0000490 [ 93.673258] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.673264] firewire_ohci 0000:01:03.0: AR spd 0 tl 35, ffc0 -> ffc1, ack_complete, QR resp = 32300000 [ 93.673285] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.673290] firewire_ohci 0000:01:03.0: AT spd 0 tl 36, ffc1 -> ffc0, ack_pending , QR req, fffff0000494 [ 93.674208] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.674214] firewire_ohci 0000:01:03.0: AR spd 0 tl 36, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.674234] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.674239] firewire_ohci 0000:01:03.0: AT spd 0 tl 37, ffc1 -> ffc0, ack_pending , QR req, fffff0000498 [ 93.675199] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.675206] firewire_ohci 0000:01:03.0: AR spd 0 tl 37, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.675226] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.675231] firewire_ohci 0000:01:03.0: AT spd 0 tl 38, ffc1 -> ffc0, ack_pending , QR req, fffff0000458 [ 93.676182] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.676188] firewire_ohci 0000:01:03.0: AR spd 0 tl 38, ffc0 -> ffc1, ack_complete, QR resp = 0006c930 [ 93.676208] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.676213] firewire_ohci 0000:01:03.0: AT spd 0 tl 39, ffc1 -> ffc0, ack_pending , QR req, fffff000045c [ 93.677191] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.677198] firewire_ohci 0000:01:03.0: AR spd 0 tl 39, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.677219] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.677224] firewire_ohci 0000:01:03.0: AT spd 0 tl 3a, ffc1 -> ffc0, ack_pending , QR req, fffff0000460 [ 93.678206] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.678212] firewire_ohci 0000:01:03.0: AR spd 0 tl 3a, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.678232] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.678237] firewire_ohci 0000:01:03.0: AT spd 0 tl 3b, ffc1 -> ffc0, ack_pending , QR req, fffff0000464 [ 93.679189] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.679196] firewire_ohci 0000:01:03.0: AR spd 0 tl 3b, ffc0 -> ffc1, ack_complete, QR resp = 4a564300 [ 93.679217] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.679222] firewire_ohci 0000:01:03.0: AT spd 0 tl 3c, ffc1 -> ffc0, ack_pending , QR req, fffff0000468 [ 93.680495] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.680501] firewire_ohci 0000:01:03.0: AR spd 0 tl 3c, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.680521] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.680526] firewire_ohci 0000:01:03.0: AT spd 0 tl 3d, ffc1 -> ffc0, ack_pending , QR req, fffff000046c [ 93.681271] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.681277] firewire_ohci 0000:01:03.0: AR spd 0 tl 3d, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.681298] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 93.681303] firewire_ohci 0000:01:03.0: AT spd 0 tl 3e, ffc1 -> ffc0, ack_pending , QR req, fffff0000470 [ 93.682268] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 93.682274] firewire_ohci 0000:01:03.0: AR spd 0 tl 3e, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 93.682413] firewire_core 0000:01:03.0: created device fw1: GUID 00808801035809f1, S100 [ 95.130472] firewire_core 0000:01:03.0: giving up on node ffc0: reading config rom failed: timeout [ 106.570273] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 106.570285] firewire_ohci 0000:01:03.0: AT spd 0 tl 3f, ffc1 -> ffc0, ack_pending , QR req, fffff0000900 [ 106.571063] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 106.571068] firewire_ohci 0000:01:03.0: AR spd 0 tl 3f, ffc0 -> ffc1, ack_complete, QR resp = 3fffff01 [ 106.571099] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 106.571103] firewire_ohci 0000:01:03.0: AT spd 0 tl 00, ffc1 -> ffc0, ack_pending , QR req, fffff0000904 [ 106.572046] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 106.572050] firewire_ohci 0000:01:03.0: AR spd 0 tl 00, ffc0 -> ffc1, ack_complete, QR resp = 003f007a [ 106.572323] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 106.572328] firewire_ohci 0000:01:03.0: AT spd 0 tl 01, ffc1 -> ffc0, ack_pending , QR req, fffff0000900 [ 106.573127] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 106.573133] firewire_ohci 0000:01:03.0: AR spd 0 tl 01, ffc0 -> ffc1, ack_complete, QR resp = 3fffff01 [ 106.574782] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 106.574788] firewire_ohci 0000:01:03.0: AT spd 0 tl 02, ffc1 -> ffc0, ack_pending , QR req, fffff0000904 [ 106.575058] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 106.575064] firewire_ohci 0000:01:03.0: AR spd 0 tl 02, ffc0 -> ffc1, ack_complete, QR resp = 003f007a [ 109.996589] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 109.996600] firewire_ohci 0000:01:03.0: AT spd 0 tl 04, ffc1 -> ffc0, ack_pending , QR req, fffff0000900 [ 109.997292] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 109.997298] firewire_ohci 0000:01:03.0: AR spd 0 tl 04, ffc0 -> ffc1, ack_complete, QR resp = 3fffff01 [ 109.999979] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 109.999986] firewire_ohci 0000:01:03.0: AT spd 0 tl 05, ffc1 -> ffc0, ack_pending , QR req, fffff0000904 [ 110.001363] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 110.001367] firewire_ohci 0000:01:03.0: AR spd 0 tl 05, ffc0 -> ffc1, ack_complete, QR resp = 003f007a If my log files are correct, this is what I got when plugging in the camera after the system had successfully booted with 6.7: [ 230.503956] firewire_ohci 0000:01:03.0: IRQ 00000010 AR_req [ 230.503981] firewire_ohci 0000:01:03.0: AR evt_bus_reset, generation 2 [ 230.504136] firewire_ohci 0000:01:03.0: IRQ 00010000 selfID [ 230.504181] firewire_ohci 0000:01:03.0: 2 selfIDs, generation 2, local node ID ffc1 [ 230.504185] firewire_ohci 0000:01:03.0: selfID 0: 807f0880, phy 0 [p..] S100 gc=63 +0W Lc [ 230.504189] firewire_ohci 0000:01:03.0: selfID 0: 817f8cd2, phy 1 [c-.] S400 gc=63 -3W Lci [ 230.504217] firewire_core 0000:01:03.0: phy config: new root=ffc1, gap_count=5 [ 230.504228] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 230.504233] firewire_ohci 0000:01:03.0: AT ack_complete, PHY 01c50000 fe3affff [ 230.504246] firewire_ohci 0000:01:03.0: IRQ 00000010 AR_req [ 230.504251] firewire_ohci 0000:01:03.0: AR evt_bus_reset, generation 3 [ 230.504253] firewire_ohci 0000:01:03.0: AR evt_bus_reset, generation 3 [ 230.504420] firewire_ohci 0000:01:03.0: IRQ 00010000 selfID [ 230.504432] firewire_ohci 0000:01:03.0: 2 selfIDs, generation 4, local node ID ffc1 [ 230.504435] firewire_ohci 0000:01:03.0: selfID 0: 80450880, phy 0 [p..] S100 gc=5 +0W Lc [ 230.504438] firewire_ohci 0000:01:03.0: selfID 0: 81458cd2, phy 1 [c-.] S400 gc=5 -3W Lci [ 230.903826] firewire_ohci 0000:01:03.0: IRQ 00000010 AR_req [ 230.903839] firewire_ohci 0000:01:03.0: AR evt_bus_reset, generation 5 [ 230.904006] firewire_ohci 0000:01:03.0: IRQ 00010000 selfID [ 230.904024] firewire_ohci 0000:01:03.0: 2 selfIDs, generation 5, local node ID ffc1 [ 230.904028] firewire_ohci 0000:01:03.0: selfID 0: 807f0882, phy 0 [p..] S100 gc=63 +0W Lci [ 230.904031] firewire_ohci 0000:01:03.0: selfID 0: 817f8cd0, phy 1 [c-.] S400 gc=63 -3W Lc [ 231.007999] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.008006] firewire_ohci 0000:01:03.0: AT spd 0 tl 24, ffc1 -> ffc0, ack_pending , QR req, fffff0000400 [ 231.008041] firewire_core 0000:01:03.0: rediscovered device fw0 [ 231.008048] firewire_core 0000:01:03.0: giving up on node ffc0: reading config rom failed: bus reset [ 231.008051] firewire_core 0000:01:03.0: phy config: new root=ffc1, gap_count=5 [ 231.008061] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.008066] firewire_ohci 0000:01:03.0: AT ack_complete, PHY 01c50000 fe3affff [ 231.008078] firewire_ohci 0000:01:03.0: IRQ 00000010 AR_req [ 231.008083] firewire_ohci 0000:01:03.0: AR evt_bus_reset, generation 6 [ 231.008084] firewire_ohci 0000:01:03.0: AR evt_bus_reset, generation 6 [ 231.008252] firewire_ohci 0000:01:03.0: IRQ 00010000 selfID [ 231.008263] firewire_ohci 0000:01:03.0: 2 selfIDs, generation 7, local node ID ffc1 [ 231.008266] firewire_ohci 0000:01:03.0: selfID 0: 80450880, phy 0 [p..] S100 gc=5 +0W Lc [ 231.008269] firewire_ohci 0000:01:03.0: selfID 0: 81458cd2, phy 1 [c-.] S400 gc=5 -3W Lci [ 231.519999] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.520005] firewire_ohci 0000:01:03.0: AT spd 0 tl 3d, ffc1 -> ffc0, ack_pending , QR req, fffff0000400 [ 231.520040] firewire_core 0000:01:03.0: rediscovered device fw0 [ 231.520544] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.520549] firewire_ohci 0000:01:03.0: AR spd 0 tl 3d, ffc0 -> ffc1, ack_complete, QR resp = 0426907c [ 231.520566] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.520571] firewire_ohci 0000:01:03.0: AT spd 0 tl 16, ffc1 -> ffc0, ack_pending , QR req, fffff0000404 [ 231.521559] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.521563] firewire_ohci 0000:01:03.0: AR spd 0 tl 16, ffc0 -> ffc1, ack_complete, QR resp = 31333934 [ 231.521579] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.521584] firewire_ohci 0000:01:03.0: AT spd 0 tl 17, ffc1 -> ffc0, ack_pending , QR req, fffff0000408 [ 231.522618] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.522622] firewire_ohci 0000:01:03.0: AR spd 0 tl 17, ffc0 -> ffc1, ack_complete, QR resp = e0644000 [ 231.522638] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.522642] firewire_ohci 0000:01:03.0: AT spd 0 tl 18, ffc1 -> ffc0, ack_pending , QR req, fffff000040c [ 231.523564] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.523569] firewire_ohci 0000:01:03.0: AR spd 0 tl 18, ffc0 -> ffc1, ack_complete, QR resp = 00808801 [ 231.523585] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.523589] firewire_ohci 0000:01:03.0: AT spd 0 tl 19, ffc1 -> ffc0, ack_pending , QR req, fffff0000410 [ 231.524566] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.524573] firewire_ohci 0000:01:03.0: AR spd 0 tl 19, ffc0 -> ffc1, ack_complete, QR resp = 035809f1 [ 231.528002] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.528008] firewire_ohci 0000:01:03.0: AT spd 0 tl 1a, ffc1 -> ffc0, ack_pending , QR req, fffff0000414 [ 231.528709] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.528715] firewire_ohci 0000:01:03.0: AR spd 0 tl 1a, ffc0 -> ffc1, ack_complete, QR resp = 0008c442 [ 231.528735] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.528740] firewire_ohci 0000:01:03.0: AT spd 0 tl 1b, ffc1 -> ffc0, ack_pending , QR req, fffff0000418 [ 231.529563] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.529569] firewire_ohci 0000:01:03.0: AR spd 0 tl 1b, ffc0 -> ffc1, ack_complete, QR resp = 03008088 [ 231.529590] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.529594] firewire_ohci 0000:01:03.0: AT spd 0 tl 1c, ffc1 -> ffc0, ack_pending , QR req, fffff000041c [ 231.530553] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.530559] firewire_ohci 0000:01:03.0: AR spd 0 tl 1c, ffc0 -> ffc1, ack_complete, QR resp = 8100000f [ 231.530578] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.530583] firewire_ohci 0000:01:03.0: AT spd 0 tl 1d, ffc1 -> ffc0, ack_pending , QR req, fffff0000420 [ 231.531571] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.531577] firewire_ohci 0000:01:03.0: AR spd 0 tl 1d, ffc0 -> ffc1, ack_complete, QR resp = 0c0083c0 [ 231.531599] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.531604] firewire_ohci 0000:01:03.0: AT spd 0 tl 1e, ffc1 -> ffc0, ack_pending , QR req, fffff0000424 [ 231.532554] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.532560] firewire_ohci 0000:01:03.0: AR spd 0 tl 1e, ffc0 -> ffc1, ack_complete, QR resp = d1000005 [ 231.532580] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.532584] firewire_ohci 0000:01:03.0: AT spd 0 tl 1f, ffc1 -> ffc0, ack_pending , QR req, fffff0000428 [ 231.533545] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.533551] firewire_ohci 0000:01:03.0: AR spd 0 tl 1f, ffc0 -> ffc1, ack_complete, QR resp = 8d000013 [ 231.533572] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.533576] firewire_ohci 0000:01:03.0: AT spd 0 tl 20, ffc1 -> ffc0, ack_pending , QR req, fffff000042c [ 231.534551] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.534557] firewire_ohci 0000:01:03.0: AR spd 0 tl 20, ffc0 -> ffc1, ack_complete, QR resp = c3000008 [ 231.534576] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.534581] firewire_ohci 0000:01:03.0: AT spd 0 tl 21, ffc1 -> ffc0, ack_pending , QR req, fffff0000430 [ 231.535783] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.535789] firewire_ohci 0000:01:03.0: AR spd 0 tl 21, ffc0 -> ffc1, ack_complete, QR resp = 1701006b [ 231.535809] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.535814] firewire_ohci 0000:01:03.0: AT spd 0 tl 22, ffc1 -> ffc0, ack_pending , QR req, fffff0000434 [ 231.536551] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.536558] firewire_ohci 0000:01:03.0: AR spd 0 tl 22, ffc0 -> ffc1, ack_complete, QR resp = 81000013 [ 231.536577] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.536582] firewire_ohci 0000:01:03.0: AT spd 0 tl 23, ffc1 -> ffc0, ack_pending , QR req, fffff0000480 [ 231.537558] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.537564] firewire_ohci 0000:01:03.0: AR spd 0 tl 23, ffc0 -> ffc1, ack_complete, QR resp = 0006c2ad [ 231.537584] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.537589] firewire_ohci 0000:01:03.0: AT spd 0 tl 25, ffc1 -> ffc0, ack_pending , QR req, fffff0000484 [ 231.538566] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.538572] firewire_ohci 0000:01:03.0: AR spd 0 tl 25, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.538592] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.538597] firewire_ohci 0000:01:03.0: AT spd 0 tl 26, ffc1 -> ffc0, ack_pending , QR req, fffff0000488 [ 231.539578] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.539584] firewire_ohci 0000:01:03.0: AR spd 0 tl 26, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.539603] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.539608] firewire_ohci 0000:01:03.0: AT spd 0 tl 27, ffc1 -> ffc0, ack_pending , QR req, fffff000048c [ 231.540603] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.540609] firewire_ohci 0000:01:03.0: AR spd 0 tl 27, ffc0 -> ffc1, ack_complete, QR resp = 47522d44 [ 231.540630] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.540635] firewire_ohci 0000:01:03.0: AT spd 0 tl 28, ffc1 -> ffc0, ack_pending , QR req, fffff0000490 [ 231.541550] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.541555] firewire_ohci 0000:01:03.0: AR spd 0 tl 28, ffc0 -> ffc1, ack_complete, QR resp = 32300000 [ 231.541575] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.541580] firewire_ohci 0000:01:03.0: AT spd 0 tl 29, ffc1 -> ffc0, ack_pending , QR req, fffff0000494 [ 231.542638] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.542644] firewire_ohci 0000:01:03.0: AR spd 0 tl 29, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.542663] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.542668] firewire_ohci 0000:01:03.0: AT spd 0 tl 2a, ffc1 -> ffc0, ack_pending , QR req, fffff0000498 [ 231.543556] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.543562] firewire_ohci 0000:01:03.0: AR spd 0 tl 2a, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.543581] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.543586] firewire_ohci 0000:01:03.0: AT spd 0 tl 2b, ffc1 -> ffc0, ack_pending , QR req, fffff000044c [ 231.544560] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.544566] firewire_ohci 0000:01:03.0: AR spd 0 tl 2b, ffc0 -> ffc1, ack_complete, QR resp = 0002ad09 [ 231.544586] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.544591] firewire_ohci 0000:01:03.0: AT spd 0 tl 2c, ffc1 -> ffc0, ack_pending , QR req, fffff0000450 [ 231.545552] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.545559] firewire_ohci 0000:01:03.0: AR spd 0 tl 2c, ffc0 -> ffc1, ack_complete, QR resp = 1701006b [ 231.545581] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.545587] firewire_ohci 0000:01:03.0: AT spd 0 tl 2d, ffc1 -> ffc0, ack_pending , QR req, fffff0000454 [ 231.546569] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.546575] firewire_ohci 0000:01:03.0: AR spd 0 tl 2d, ffc0 -> ffc1, ack_complete, QR resp = 8100000b [ 231.546596] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.546601] firewire_ohci 0000:01:03.0: AT spd 0 tl 2e, ffc1 -> ffc0, ack_pending , QR req, fffff0000480 [ 231.547699] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.547705] firewire_ohci 0000:01:03.0: AR spd 0 tl 2e, ffc0 -> ffc1, ack_complete, QR resp = 0006c2ad [ 231.547725] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.547730] firewire_ohci 0000:01:03.0: AT spd 0 tl 2f, ffc1 -> ffc0, ack_pending , QR req, fffff0000484 [ 231.548597] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.548603] firewire_ohci 0000:01:03.0: AR spd 0 tl 2f, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.548624] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.548629] firewire_ohci 0000:01:03.0: AT spd 0 tl 30, ffc1 -> ffc0, ack_pending , QR req, fffff0000488 [ 231.549654] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.549660] firewire_ohci 0000:01:03.0: AR spd 0 tl 30, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.549679] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.549684] firewire_ohci 0000:01:03.0: AT spd 0 tl 31, ffc1 -> ffc0, ack_pending , QR req, fffff000048c [ 231.550564] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.550570] firewire_ohci 0000:01:03.0: AR spd 0 tl 31, ffc0 -> ffc1, ack_complete, QR resp = 47522d44 [ 231.550590] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.550595] firewire_ohci 0000:01:03.0: AT spd 0 tl 32, ffc1 -> ffc0, ack_pending , QR req, fffff0000490 [ 231.551552] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.551558] firewire_ohci 0000:01:03.0: AR spd 0 tl 32, ffc0 -> ffc1, ack_complete, QR resp = 32300000 [ 231.551578] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.551583] firewire_ohci 0000:01:03.0: AT spd 0 tl 33, ffc1 -> ffc0, ack_pending , QR req, fffff0000494 [ 231.552565] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.552571] firewire_ohci 0000:01:03.0: AR spd 0 tl 33, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.552591] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.552596] firewire_ohci 0000:01:03.0: AT spd 0 tl 34, ffc1 -> ffc0, ack_pending , QR req, fffff0000498 [ 231.553556] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.553562] firewire_ohci 0000:01:03.0: AR spd 0 tl 34, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.553581] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.553586] firewire_ohci 0000:01:03.0: AT spd 0 tl 35, ffc1 -> ffc0, ack_pending , QR req, fffff0000474 [ 231.554558] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.554564] firewire_ohci 0000:01:03.0: AR spd 0 tl 35, ffc0 -> ffc1, ack_complete, QR resp = 0002f1df [ 231.554584] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.554589] firewire_ohci 0000:01:03.0: AT spd 0 tl 36, ffc1 -> ffc0, ack_pending , QR req, fffff0000478 [ 231.555789] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.555795] firewire_ohci 0000:01:03.0: AR spd 0 tl 36, ffc0 -> ffc1, ack_complete, QR resp = 00808801 [ 231.555816] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.555821] firewire_ohci 0000:01:03.0: AT spd 0 tl 37, ffc1 -> ffc0, ack_pending , QR req, fffff000047c [ 231.556557] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.556563] firewire_ohci 0000:01:03.0: AR spd 0 tl 37, ffc0 -> ffc1, ack_complete, QR resp = 035809f1 [ 231.556584] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.556589] firewire_ohci 0000:01:03.0: AT spd 0 tl 38, ffc1 -> ffc0, ack_pending , QR req, fffff0000438 [ 231.557564] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.557570] firewire_ohci 0000:01:03.0: AR spd 0 tl 38, ffc0 -> ffc1, ack_complete, QR resp = 00043327 [ 231.557590] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.557595] firewire_ohci 0000:01:03.0: AT spd 0 tl 39, ffc1 -> ffc0, ack_pending , QR req, fffff000043c [ 231.558572] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.558578] firewire_ohci 0000:01:03.0: AR spd 0 tl 39, ffc0 -> ffc1, ack_complete, QR resp = 1200a02d [ 231.558598] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.558602] firewire_ohci 0000:01:03.0: AT spd 0 tl 3a, ffc1 -> ffc0, ack_pending , QR req, fffff0000440 [ 231.559554] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.559560] firewire_ohci 0000:01:03.0: AR spd 0 tl 3a, ffc0 -> ffc1, ack_complete, QR resp = 13010001 [ 231.559580] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.559585] firewire_ohci 0000:01:03.0: AT spd 0 tl 3b, ffc1 -> ffc0, ack_pending , QR req, fffff0000444 [ 231.560549] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.560555] firewire_ohci 0000:01:03.0: AR spd 0 tl 3b, ffc0 -> ffc1, ack_complete, QR resp = 1701006b [ 231.560575] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.560580] firewire_ohci 0000:01:03.0: AT spd 0 tl 3c, ffc1 -> ffc0, ack_pending , QR req, fffff0000448 [ 231.561564] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.561570] firewire_ohci 0000:01:03.0: AR spd 0 tl 3c, ffc0 -> ffc1, ack_complete, QR resp = 8100000e [ 231.561590] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.561595] firewire_ohci 0000:01:03.0: AT spd 0 tl 3d, ffc1 -> ffc0, ack_pending , QR req, fffff0000480 [ 231.562623] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.562629] firewire_ohci 0000:01:03.0: AR spd 0 tl 3d, ffc0 -> ffc1, ack_complete, QR resp = 0006c2ad [ 231.562649] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.562653] firewire_ohci 0000:01:03.0: AT spd 0 tl 3e, ffc1 -> ffc0, ack_pending , QR req, fffff0000484 [ 231.563570] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.563576] firewire_ohci 0000:01:03.0: AR spd 0 tl 3e, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.563597] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.563601] firewire_ohci 0000:01:03.0: AT spd 0 tl 3f, ffc1 -> ffc0, ack_pending , QR req, fffff0000488 [ 231.564570] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.564576] firewire_ohci 0000:01:03.0: AR spd 0 tl 3f, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.564596] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.564601] firewire_ohci 0000:01:03.0: AT spd 0 tl 00, ffc1 -> ffc0, ack_pending , QR req, fffff000048c [ 231.565563] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.565569] firewire_ohci 0000:01:03.0: AR spd 0 tl 00, ffc0 -> ffc1, ack_complete, QR resp = 47522d44 [ 231.565588] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.565593] firewire_ohci 0000:01:03.0: AT spd 0 tl 01, ffc1 -> ffc0, ack_pending , QR req, fffff0000490 [ 231.566549] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.566555] firewire_ohci 0000:01:03.0: AR spd 0 tl 01, ffc0 -> ffc1, ack_complete, QR resp = 32300000 [ 231.566578] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.566583] firewire_ohci 0000:01:03.0: AT spd 0 tl 02, ffc1 -> ffc0, ack_pending , QR req, fffff0000494 [ 231.567615] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.567621] firewire_ohci 0000:01:03.0: AR spd 0 tl 02, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.567643] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.567648] firewire_ohci 0000:01:03.0: AT spd 0 tl 03, ffc1 -> ffc0, ack_pending , QR req, fffff0000498 [ 231.568686] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.568692] firewire_ohci 0000:01:03.0: AR spd 0 tl 03, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.568712] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.568717] firewire_ohci 0000:01:03.0: AT spd 0 tl 04, ffc1 -> ffc0, ack_pending , QR req, fffff0000458 [ 231.569631] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.569637] firewire_ohci 0000:01:03.0: AR spd 0 tl 04, ffc0 -> ffc1, ack_complete, QR resp = 0006c930 [ 231.569656] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.569661] firewire_ohci 0000:01:03.0: AT spd 0 tl 05, ffc1 -> ffc0, ack_pending , QR req, fffff000045c [ 231.570588] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.570594] firewire_ohci 0000:01:03.0: AR spd 0 tl 05, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.570615] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.570619] firewire_ohci 0000:01:03.0: AT spd 0 tl 06, ffc1 -> ffc0, ack_pending , QR req, fffff0000460 [ 231.571548] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.571554] firewire_ohci 0000:01:03.0: AR spd 0 tl 06, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.571575] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.571580] firewire_ohci 0000:01:03.0: AT spd 0 tl 07, ffc1 -> ffc0, ack_pending , QR req, fffff0000464 [ 231.572561] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.572568] firewire_ohci 0000:01:03.0: AR spd 0 tl 07, ffc0 -> ffc1, ack_complete, QR resp = 4a564300 [ 231.572588] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.572593] firewire_ohci 0000:01:03.0: AT spd 0 tl 08, ffc1 -> ffc0, ack_pending , QR req, fffff0000468 [ 231.573553] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.573559] firewire_ohci 0000:01:03.0: AR spd 0 tl 08, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.573579] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.573584] firewire_ohci 0000:01:03.0: AT spd 0 tl 09, ffc1 -> ffc0, ack_pending , QR req, fffff000046c [ 231.574558] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.574564] firewire_ohci 0000:01:03.0: AR spd 0 tl 09, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.574585] firewire_ohci 0000:01:03.0: IRQ 00000001 AT_req [ 231.574590] firewire_ohci 0000:01:03.0: AT spd 0 tl 0a, ffc1 -> ffc0, ack_pending , QR req, fffff0000470 [ 231.575785] firewire_ohci 0000:01:03.0: IRQ 00000020 AR_resp [ 231.575791] firewire_ohci 0000:01:03.0: AR spd 0 tl 0a, ffc0 -> ffc1, ack_complete, QR resp = 00000000 [ 231.575932] firewire_core 0000:01:03.0: created device fw1: GUID 00808801035809f1, S100 [ 233.023970] firewire_core 0000:01:03.0: giving up on node ffc0: reading config rom failed: timeout And as a point of reference, this is from 2.6: [ 128.943366] firewire_ohci: AR evt_bus_reset, generation 9 [ 128.943541] firewire_ohci: IRQ 00010000 selfID [ 128.943551] firewire_ohci: 2 selfIDs, generation 9, local node ID ffc1 [ 128.943554] firewire_ohci: selfID 0: 807f0880, phy 0 [p..] S100 gc=63 +0W Lc [ 128.943556] firewire_ohci: selfID 0: 817f8cd2, phy 1 [c-.] S400 gc=63 -3W Lci [ 128.943575] firewire_core: phy config: card 0, new root=ffc1, gap_count=5 [ 128.943588] firewire_ohci: IRQ 00000001 AT_req [ 128.943592] firewire_ohci: AT ack_complete, phy config packet, 01c50000 [ 128.960017] firewire_ohci: IRQ 00000010 AR_req [ 128.960021] firewire_ohci: AR evt_bus_reset, generation 10 [ 128.960022] firewire_ohci: AR evt_bus_reset, generation 10 [ 128.960190] firewire_ohci: IRQ 00010000 selfID [ 128.960200] firewire_ohci: 2 selfIDs, generation 11, local node ID ffc1 [ 128.960202] firewire_ohci: selfID 0: 80450880, phy 0 [p..] S100 gc=5 +0W Lc [ 128.960204] firewire_ohci: selfID 0: 81458cd2, phy 1 [c-.] S400 gc=5 -3W Lci [ 128.960206] firewire_core: skipped bus generations, destroying all nodes [ 129.342084] firewire_ohci: IRQ 00000010 AR_req [ 129.342088] firewire_ohci: AR evt_bus_reset, generation 12 [ 129.342265] firewire_ohci: IRQ 00010000 selfID [ 129.342274] firewire_ohci: 2 selfIDs, generation 12, local node ID ffc1 [ 129.342277] firewire_ohci: selfID 0: 807f0882, phy 0 [p..] S100 gc=63 +0W Lci [ 129.342279] firewire_ohci: selfID 0: 817f8cd0, phy 1 [c-.] S400 gc=63 -3W Lc [ 129.442515] firewire_core: giving up on config rom for node id ffc0 [ 129.462297] firewire_core: rediscovered device fw0 [ 129.462319] firewire_ohci: IRQ 00000001 AT_req [ 129.462325] firewire_ohci: AT spd 0 tl 26, ffc1 -> ffc0, ack_pending , QR req, fffff0000400 [ 129.462731] firewire_ohci: IRQ 00000020 AR_resp [ 129.462736] firewire_ohci: AR spd 0 tl 26, ffc0 -> ffc1, ack_complete, QR resp = 0426907c [ 129.462757] firewire_ohci: IRQ 00000001 AT_req [ 129.462762] firewire_ohci: AT spd 0 tl 27, ffc1 -> ffc0, ack_pending , QR req, fffff0000404 [ 129.463723] firewire_ohci: IRQ 00000020 AR_resp [ 129.463727] firewire_ohci: AR spd 0 tl 27, ffc0 -> ffc1, ack_complete, QR resp = 31333934 [ 129.463749] firewire_ohci: IRQ 00000001 AT_req [ 129.463753] firewire_ohci: AT spd 0 tl 28, ffc1 -> ffc0, ack_pending , QR req, fffff0000408 [ 129.464739] firewire_ohci: IRQ 00000020 AR_resp [ 129.464744] firewire_ohci: AR spd 0 tl 28, ffc0 -> ffc1, ack_complete, QR resp = e0644000 [ 129.464766] firewire_ohci: IRQ 00000001 AT_req [ 129.464771] firewire_ohci: AT spd 0 tl 29, ffc1 -> ffc0, ack_pending , QR req, fffff000040c [ 129.465781] firewire_ohci: IRQ 00000020 AR_resp [ 129.465785] firewire_ohci: AR spd 0 tl 29, ffc0 -> ffc1, ack_complete, QR resp = 00808801 [ 129.465807] firewire_ohci: IRQ 00000001 AT_req [ 129.465812] firewire_ohci: AT spd 0 tl 2a, ffc1 -> ffc0, ack_pending , QR req, fffff0000410 [ 129.466738] firewire_ohci: IRQ 00000020 AR_resp [ 129.466742] firewire_ohci: AR spd 0 tl 2a, ffc0 -> ffc1, ack_complete, QR resp = 035809f1 [ 129.466764] firewire_ohci: IRQ 00000001 AT_req [ 129.466769] firewire_ohci: AT spd 0 tl 2b, ffc1 -> ffc0, ack_pending , QR req, fffff0000414 [ 129.467843] firewire_ohci: IRQ 00000020 AR_resp [ 129.467847] firewire_ohci: AR spd 0 tl 2b, ffc0 -> ffc1, ack_complete, QR resp = 0008c442 [ 129.467869] firewire_ohci: IRQ 00000001 AT_req [ 129.467873] firewire_ohci: AT spd 0 tl 2c, ffc1 -> ffc0, ack_pending , QR req, fffff0000418 [ 129.468749] firewire_ohci: IRQ 00000020 AR_resp [ 129.468753] firewire_ohci: AR spd 0 tl 2c, ffc0 -> ffc1, ack_complete, QR resp = 03008088 [ 129.468775] firewire_ohci: IRQ 00000001 AT_req [ 129.468779] firewire_ohci: AT spd 0 tl 2d, ffc1 -> ffc0, ack_pending , QR req, fffff000041c [ 129.469742] firewire_ohci: IRQ 00000020 AR_resp [ 129.469746] firewire_ohci: AR spd 0 tl 2d, ffc0 -> ffc1, ack_complete, QR resp = 8100000f [ 129.469768] firewire_ohci: IRQ 00000001 AT_req [ 129.469772] firewire_ohci: AT spd 0 tl 2e, ffc1 -> ffc0, ack_pending , QR req, fffff0000420 [ 129.470745] firewire_ohci: IRQ 00000020 AR_resp [ 129.470750] firewire_ohci: AR spd 0 tl 2e, ffc0 -> ffc1, ack_complete, QR resp = 0c0083c0 [ 129.470791] firewire_ohci: IRQ 00000001 AT_req [ 129.470795] firewire_ohci: AT spd 0 tl 2f, ffc1 -> ffc0, ack_pending , QR req, fffff0000424 [ 129.471758] firewire_ohci: IRQ 00000020 AR_resp [ 129.471762] firewire_ohci: AR spd 0 tl 2f, ffc0 -> ffc1, ack_complete, QR resp = d1000005 [ 129.471784] firewire_ohci: IRQ 00000001 AT_req [ 129.471788] firewire_ohci: AT spd 0 tl 30, ffc1 -> ffc0, ack_pending , QR req, fffff0000428 [ 129.472716] firewire_ohci: IRQ 00000020 AR_resp [ 129.472721] firewire_ohci: AR spd 0 tl 30, ffc0 -> ffc1, ack_complete, QR resp = 8... [truncated message content] |
From: Adam G. <ad...@po...> - 2024-02-13 09:11:59
|
Hi Tasos, I can confirm that the same problem occurs on a JVC GR-D30U connected to an XIO2213B OHCI chip. So it's not specific to the TSB43AB22A, and it affects several JVC models. I haven't investigated fully. -- Adam |
From: Takashi S. <o-t...@sa...> - 2024-02-06 23:38:55
|
Hi, Thanks for the patch. I applied it to for-linus branch and will send it for v6.8-rc4 in this week. Thanks for your long patience in the review process. On Sun, Feb 04, 2024 at 09:21:14PM -0800, Adam Goldman wrote: > If we are bus manager and the bus has inconsistent gap counts, send a > bus reset immediately instead of trying to read the root node's config > ROM first. Otherwise, we could spend a lot of time trying to read the > config ROM but never succeeding. > > This eliminates a 50+ second delay before the FireWire bus is usable after > a newly connected device is powered on in certain circumstances. > > The delay occurs if a gap count inconsistency occurs, we are not the root > node, and we become bus manager. One scenario that causes this is with a TI > XIO2213B OHCI, the first time a Sony DSR-25 is powered on after being > connected to the FireWire cable. In this configuration, the Linux box will > not receive the initial PHY configuration packet sent by the DSR-25 as IRM, > resulting in the DSR-25 having a gap count of 44 while the Linux box has a > gap count of 63. > > FireWire devices have a gap count parameter, which is set to 63 on power-up > and can be changed with a PHY configuration packet. This determines the > duration of the subaction and arbitration gaps. For reliable communication, > all nodes on a FireWire bus must have the same gap count. > > A node may have zero or more of the following roles: root node, bus manager > (BM), isochronous resource manager (IRM), and cycle master. Unless a root > node was forced with a PHY configuration packet, any node might become root > node after a bus reset. Only the root node can become cycle master. If the > root node is not cycle master capable, the BM or IRM should force a change > of root node. > > After a bus reset, each node sends a self-ID packet, which contains its > current gap count. A single bus reset does not change the gap count, but > two bus resets in a row will set the gap count to 63. Because a consistent > gap count is required for reliable communication, IEEE 1394a-2000 requires > that the bus manager generate a bus reset if it detects that the gap count > is inconsistent. > > When the gap count is inconsistent, build_tree() will notice this after the > self identification process. It will set card->gap_count to the invalid > value 0. If we become bus master, this will force bm_work() to send a bus > reset when it performs gap count optimization. > > After a bus reset, there is no bus manager. We will almost always try to > become bus manager. Once we become bus manager, we will first determine > whether the root node is cycle master capable. Then, we will determine if > the gap count should be changed. If either the root node or the gap count > should be changed, we will generate a bus reset. > > To determine if the root node is cycle master capable, we read its > configuration ROM. bm_work() will wait until we have finished trying to > read the configuration ROM. > > However, an inconsistent gap count can make this take a long time. > read_config_rom() will read the first few quadlets from the config ROM. Due > to the gap count inconsistency, eventually one of the reads will time out. > When read_config_rom() fails, fw_device_init() calls it again until > MAX_RETRIES is reached. This takes 50+ seconds. > > Once we give up trying to read the configuration ROM, bm_work() will wake > up, assume that the root node is not cycle master capable, and do a bus > reset. Hopefully, this will resolve the gap count inconsistency. > > This change makes bm_work() check for an inconsistent gap count before > waiting for the root node's configuration ROM. If the gap count is > inconsistent, bm_work() will immediately do a bus reset. This eliminates > the 50+ second delay and rapidly brings the bus to a working state. > > I considered that if the gap count is inconsistent, a PHY configuration > packet might not be successful, so it could be desirable to skip the PHY > configuration packet before the bus reset in this case. However, IEEE > 1394a-2000 and IEEE 1394-2008 say that the bus manager may transmit a PHY > configuration packet before a bus reset when correcting a gap count error. > Since the standard endorses this, I decided it's safe to retain the PHY > configuration packet transmission. > > Normally, after a topology change, we will reset the bus a maximum of 5 > times to change the root node and perform gap count optimization. However, > if there is a gap count inconsistency, we must always generate a bus reset. > Otherwise the gap count inconsistency will persist and communication will > be unreliable. For that reason, if there is a gap count inconstency, we > generate a bus reset even if we already reached the 5 reset limit. > > Signed-off-by: Adam Goldman <ad...@po...> > Link: https://sourceforge.net/p/linux1394/mailman/message/58727806/ > --- Takashi Sakamoto |
From: Takashi S. <o-t...@sa...> - 2024-02-05 06:13:49
|
Hi, On Mon, Feb 05, 2024 at 03:04:48PM +0900, Takashi Sakamoto wrote: > A commit 47dc55181dcb ("firewire: core: search descriptor leaf just after > vendor directory entry in root directory") for v6.8-rc3 and a commit > 67a5a58c0443 ("firewire: Kill unnecessary buf check in > device_attribute.show") for v6.9 bring build failure in for-next tree due > to the change of the name of local variable. > > This commit fixes it. > > Reported-by: Stephen Rothwell <sf...@ca...> > Closes: https://lore.kernel.org/lkml/202...@ca.../ > Reported-by: kernel test robot <lk...@in...> > Closes: https://lore.kernel.org/oe-kbuild-all/202...@in.../ > Signed-off-by: Takashi Sakamoto <o-t...@sa...> > --- > drivers/firewire/core-device.c | 2 +- > 1 file changed, 1 insertion(+), 1 deletion(-) > > diff --git a/drivers/firewire/core-device.c b/drivers/firewire/core-device.c > index a802c6d4f4fd..c0976f6268d3 100644 > --- a/drivers/firewire/core-device.c > +++ b/drivers/firewire/core-device.c > @@ -366,7 +366,7 @@ static ssize_t show_text_leaf(struct device *dev, > // in the root directory follows to the directory entry for vendor ID > // instead of the immediate value for vendor ID. > result = fw_csr_string(directories[i], CSR_DIRECTORY | attr->key, buf, > - bufsize); > + PAGE_SIZE - 1); > if (result >= 0) > ret = result; > } > -- > 2.40.1 I applied this immediately to fix linux-next integration. Regards Takashi Sakamoto |
From: Takashi S. <o-t...@sa...> - 2024-02-05 06:05:00
|
A commit 47dc55181dcb ("firewire: core: search descriptor leaf just after vendor directory entry in root directory") for v6.8-rc3 and a commit 67a5a58c0443 ("firewire: Kill unnecessary buf check in device_attribute.show") for v6.9 bring build failure in for-next tree due to the change of the name of local variable. This commit fixes it. Reported-by: Stephen Rothwell <sf...@ca...> Closes: https://lore.kernel.org/lkml/202...@ca.../ Reported-by: kernel test robot <lk...@in...> Closes: https://lore.kernel.org/oe-kbuild-all/202...@in.../ Signed-off-by: Takashi Sakamoto <o-t...@sa...> --- drivers/firewire/core-device.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/drivers/firewire/core-device.c b/drivers/firewire/core-device.c index a802c6d4f4fd..c0976f6268d3 100644 --- a/drivers/firewire/core-device.c +++ b/drivers/firewire/core-device.c @@ -366,7 +366,7 @@ static ssize_t show_text_leaf(struct device *dev, // in the root directory follows to the directory entry for vendor ID // instead of the immediate value for vendor ID. result = fw_csr_string(directories[i], CSR_DIRECTORY | attr->key, buf, - bufsize); + PAGE_SIZE - 1); if (result >= 0) ret = result; } -- 2.40.1 |