Apogee Duet Firewire not discovered by latest kernel

[TeamB12]

Artix Linux with latest kerne. 6.11 and openbox - no pipewire, only apulse - jack1 installed.
Everything is working great, also the firewire control is working great - thanks again.
Sometimes, which is almost always on the latest 6.11 kernel, the Duet is not discovered by aplay -l.
Sometimes (very rarely) it is not powered on ( no LEd, no clicking of the device)
The problem exists with the latest Linux and Linux-rt kernel.
Older LTS kernel like 6.6 -rt-LTS an d 6.6 LTS are allways discovering the Duet audio interface.
My workaround: boot into linux-rt-lts 6.6 kernel and then reboot into the latest 6.11 kernel and then my apogee duet is discovered by aplay -l
If i am trying to boot into latest kernel directly, the probablity of the Duet being disconvered is maybe 15%.
What was changed in kernel 6.10 so that my audio interface is not recognized anymore?
Tried different firewire host controllers like the apple thunderbolt and an OWC dock with firewire 800 host interface - both the same results.
Are you aware of this regression?
(sorry for the trouble)

[takaswie]

Hi @TeamB12,

Thanks for the report. In Linux kernel v6.11 or later, the initial step to communicate to any nodes in IEEE 1394 bus could be recorded by Linux tracepoints framework. Would I ask you to provide me the tracepoints events?

There are some ways to retrieve the log of tracepoints events. The easiest way is to use debugfs, like:

$ echo 1 > /sys/kernel/debug/tracing/events/firewire/self_id_sequence/enable
(insert your device)
$ echo 0 > /sys/kernel/debug/tracing/events/firewire/self_id_sequence/enable
$ cat /sys/kernel/debug/tracing/trace

Linux FireWire subsystem has some tracepoints events. The following events are useful to debug the issue:

• async_phy_inbound
• async_phy_outbound_complete
• async_phy_outbound_initiate
• async_request_inbound
• async_request_outbound_complete
• async_request_outbound_initiate
• async_response_inbound
• async_response_outbound_complete
• async_response_outbound_initiate
• bus_reset_handle
• bus_reset_initiate
• bus_reset_postpone
• bus_reset_schedule
• self_id_sequence

The above events can be enabled simultaneously. Please provide the dump of trace node when enabling all of the above.

Regards

[TeamB12]

Could not issue the commands as you discribed.
Normal user has not the permission here though I carefully added my user to most of the important groups:
$ groups
tty dbus network power rtkit adbusers realtime users video storage lp input audio wheel

cat: /sys/kernel/debug/tracing/trace: Permission denied

Then I tried to install doublecheck all dependencies - everything seems installed like dgb.
Tried again, same result:

cat /sys/kernel/debug/tracing/trace

tracer: nop

entries-in-buffer/entries-written: 0/0

checked dmesg, maybe you can read the glibblish:

INFO: task kworker/0:2:165 blocked for more than 860 seconds.
[ 982.869699] Not tainted 6.11.6-artix1-1 #1
[ 982.869703] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 982.869705] task:kworker/0:2 state:D stack:0 pid:165 tgid:165 ppid:2 flags:0x00004000
[ 982.869715] Workqueue: firewire fw_device_workfn [firewire_core]
[ 982.869758] Call Trace:
[ 982.869760]
[ 982.869763] __schedule+0x402/0x1440
[ 982.869772] ? ttwu_do_activate+0x64/0x220
[ 982.869779] schedule+0x27/0xf0
[ 982.869784] schedule_timeout+0x12f/0x160
[ 982.869790] wait_for_completion+0x86/0x170
[ 982.869794] fw_run_transaction+0xdf/0x120 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 982.869822] ? __pfx_split_transaction_timeout_callback+0x10/0x10 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 982.869844] ? __pfx_transmit_complete_callback+0x10/0x10 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 982.869864] ? __pfx_transaction_callback+0x10/0x10 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 982.869885] read_rom+0x55/0x90 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 982.869908] read_config_rom+0x8c/0x3f0 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 982.869929] fw_device_init+0x32/0x300 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 982.869949] process_one_work+0x17b/0x330
[ 982.869954] worker_thread+0x2ce/0x3f0
[ 982.869959] ? __pfx_worker_thread+0x10/0x10
[ 982.869963] kthread+0xcf/0x100
[ 982.869969] ? __pfx_kthread+0x10/0x10
[ 982.869974] ret_from_fork+0x31/0x50
[ 982.869979] ? __pfx_kthread+0x10/0x10
[ 982.869984] ret_from_fork_asm+0x1a/0x30
[ 982.869991]
[ 1105.753301] INFO: task kworker/0:2:165 blocked for more than 983 seconds.
[ 1105.753310] Not tainted 6.11.6-artix1-1 #1
[ 1105.753312] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1105.753314] task:kworker/0:2 state:D stack:0 pid:165 tgid:165 ppid:2 flags:0x00004000
[ 1105.753322] Workqueue: firewire fw_device_workfn [firewire_core]
[ 1105.753359] Call Trace:
[ 1105.753361]
[ 1105.753364] __schedule+0x402/0x1440
[ 1105.753373] ? ttwu_do_activate+0x64/0x220
[ 1105.753381] schedule+0x27/0xf0
[ 1105.753386] schedule_timeout+0x12f/0x160
[ 1105.753393] wait_for_completion+0x86/0x170
[ 1105.753397] fw_run_transaction+0xdf/0x120 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1105.753425] ? __pfx_split_transaction_timeout_callback+0x10/0x10 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1105.753448] ? __pfx_transmit_complete_callback+0x10/0x10 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1105.753468] ? __pfx_transaction_callback+0x10/0x10 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1105.753488] read_rom+0x55/0x90 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1105.753511] read_config_rom+0x8c/0x3f0 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1105.753532] fw_device_init+0x32/0x300 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1105.753551] process_one_work+0x17b/0x330
[ 1105.753557] worker_thread+0x2ce/0x3f0
[ 1105.753562] ? __pfx_worker_thread+0x10/0x10
[ 1105.753566] kthread+0xcf/0x100
[ 1105.753572] ? __pfx_kthread+0x10/0x10
[ 1105.753577] ret_from_fork+0x31/0x50
[ 1105.753582] ? __pfx_kthread+0x10/0x10
[ 1105.753586] ret_from_fork_asm+0x1a/0x30
[ 1105.753593]
[ 1228.629732] INFO: task kworker/0:2:165 blocked for more than 1105 seconds.
[ 1228.629742] Not tainted 6.11.6-artix1-1 #1
[ 1228.629745] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1228.629747] task:kworker/0:2 state:D stack:0 pid:165 tgid:165 ppid:2 flags:0x00004000
[ 1228.629757] Workqueue: firewire fw_device_workfn [firewire_core]
[ 1228.629800] Call Trace:
[ 1228.629802]
[ 1228.629805] __schedule+0x402/0x1440
[ 1228.629815] ? ttwu_do_activate+0x64/0x220
[ 1228.629822] schedule+0x27/0xf0
[ 1228.629827] schedule_timeout+0x12f/0x160
[ 1228.629832] wait_for_completion+0x86/0x170
[ 1228.629837] fw_run_transaction+0xdf/0x120 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1228.629864] ? __pfx_split_transaction_timeout_callback+0x10/0x10 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1228.629886] ? __pfx_transmit_complete_callback+0x10/0x10 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1228.629906] ? __pfx_transaction_callback+0x10/0x10 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1228.629926] read_rom+0x55/0x90 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1228.629949] read_config_rom+0x8c/0x3f0 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1228.629969] fw_device_init+0x32/0x300 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1228.629989] process_one_work+0x17b/0x330
[ 1228.629995] worker_thread+0x2ce/0x3f0
[ 1228.629999] ? __pfx_worker_thread+0x10/0x10
[ 1228.630004] kthread+0xcf/0x100
[ 1228.630010] ? __pfx_kthread+0x10/0x10
[ 1228.630015] ret_from_fork+0x31/0x50
[ 1228.630019] ? __pfx_kthread+0x10/0x10
[ 1228.630024] ret_from_fork_asm+0x1a/0x30
[ 1228.630031]
[ 1351.509703] INFO: task kworker/0:2:165 blocked for more than 1228 seconds.
[ 1351.509711] Not tainted 6.11.6-artix1-1 #1
[ 1351.509714] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1351.509715] task:kworker/0:2 state:D stack:0 pid:165 tgid:165 ppid:2 flags:0x00004000
[ 1351.509739] Workqueue: firewire fw_device_workfn [firewire_core]
[ 1351.509773] Call Trace:
[ 1351.509775]
[ 1351.509778] __schedule+0x402/0x1440
[ 1351.509803] ? ttwu_do_activate+0x64/0x220
[ 1351.509810] schedule+0x27/0xf0
[ 1351.509815] schedule_timeout+0x12f/0x160
[ 1351.509821] wait_for_completion+0x86/0x170
[ 1351.509825] fw_run_transaction+0xdf/0x120 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1351.509852] ? __pfx_split_transaction_timeout_callback+0x10/0x10 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1351.509874] ? __pfx_transmit_complete_callback+0x10/0x10 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1351.509894] ? __pfx_transaction_callback+0x10/0x10 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1351.509914] read_rom+0x55/0x90 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1351.509937] read_config_rom+0x8c/0x3f0 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1351.509957] fw_device_init+0x32/0x300 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 1351.509976] process_one_work+0x17b/0x330
[ 1351.509982] worker_thread+0x2ce/0x3f0
[ 1351.509987] ? __pfx_worker_thread+0x10/0x10
[ 1351.509991] kthread+0xcf/0x100
[ 1351.509997] ? __pfx_kthread+0x10/0x10
[ 1351.510002] ret_from_fork+0x31/0x50
[ 1351.510007] ? __pfx_kthread+0x10/0x10
[ 1351.510011] ret_from_fork_asm+0x1a/0x30
[ 1351.510018]

[TeamB12]

Sorry for the caps, dont know what happened.
Update:
with latest kernel, after reboot and discovered firewire audio interface:

tracer: nop

entries-in-buffer/entries-written: 1/1 #P:8

_-----=> irqs-off/BH-disabled

/ _----=> need-resched

| / _---=> hardirq/softirq

|| / _--=> preempt-depth

||| / _-=> migrate-disable

|||| / delay

TASK-PID CPU# ||||| TIMESTAMP FUNCTION

| | | ||||| | |

 kworker/0:0-8       [000] d..1.   228.834175: self_id_sequence: card_index=0 generation=3 phy_id=0x00 link_active=true gap_count=63 scode=3 contender=true power_class=4 initiated_reset=true port_status={0x1,0x1,0x1} self_id_sequence={0x807fcc56}

Tried again on lts kernel, and firewire was not found (???)

echo 1 > /sys/kernel/debug/tracing/events/firewire/self_id_sequence/enable
bash: /sys/kernel/debug/tracing/events/firewire/self_id_sequence/enable: No such file or directory

[takaswie]

Hi,

Note that the block following/followed by three backticks (`) is rendered as pre-formatted area. It is useful to share the logs.

As long as I know, the following issue is specific to realtime kernels, and no one has ever worked to solve it. Please discourage using this type of kernels to investigate the cause of regression which you reported.

INFO: task kworker/0:2:165 blocked for more than 860 seconds.
[ 982.869699] Not tainted 6.11.6-artix1-1 https://github.com/takaswie/linux-firewire-dkms/issues/1
[ 982.869703] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 982.869705] task:kworker/0:2 state:D stack:0 pid:165 tgid:165 ppid:2 flags:0x00004000
[ 982.869715] Workqueue: firewire fw_device_workfn [firewire_core]
[ 982.869758] Call Trace:
[ 982.869760]
[ 982.869763] __schedule+0x402/0x1440
[ 982.869772] ? ttwu_do_activate+0x64/0x220
[ 982.869779] schedule+0x27/0xf0
[ 982.869784] schedule_timeout+0x12f/0x160
[ 982.869790] wait_for_completion+0x86/0x170
[ 982.869794] fw_run_transaction+0xdf/0x120 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 982.869822] ? __pfx_split_transaction_timeout_callback+0x10/0x10 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 982.869844] ? __pfx_transmit_complete_callback+0x10/0x10 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 982.869864] ? __pfx_transaction_callback+0x10/0x10 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 982.869885] read_rom+0x55/0x90 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 982.869908] read_config_rom+0x8c/0x3f0 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 982.869929] fw_device_init+0x32/0x300 [firewire_core 1400000003000000474e5500f906568dcd0bf511]
[ 982.869949] process_one_work+0x17b/0x330
[ 982.869954] worker_thread+0x2ce/0x3f0
[ 982.869959] ? __pfx_worker_thread+0x10/0x10
[ 982.869963] kthread+0xcf/0x100
[ 982.869969] ? __pfx_kthread+0x10/0x10
[ 982.869974] ret_from_fork+0x31/0x50
[ 982.869979] ? __pfx_kthread+0x10/0x10
[ 982.869984] ret_from_fork_asm+0x1a/0x30

Anyway,

kworker/0:0-8       [000] d..1.   228.834175: self_id_sequence: card_index=0 generation=3 phy_id=0x00 link_active=true gap_count=63 scode=3 contender=true power_class=4 initiated_reset=true port_status={0x1,0x1,0x1} self_id_sequence={0x807fcc56}

You look to retrieve some logs from the self_id_sequence tracepoints event. Please enable the other events simultaneously which I've addressed, then try to retrieve logs.

[TeamB12]

I will try to log all firewire events and if I got something, I will post it here.
I have deinstalled linux-rt kernel and I want to use the vanilla kernel from 6.12 on.
There was this problem on linux 6.10 and 6.11 and i tried the lts kernels: both, linux-lts and linux-rt are able to discover the Apogge Duet Firefire on latest RT kernel and also the vanilla kernels are showing these issues.
Seems all latest kernels are havingproblems here - not only rt kernels.
trying to get the logs now. thanks