Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Sparky SBC | Kernel error trace when switching audio source on USB DAC #2610

Closed
seniorgod opened this issue Mar 2, 2019 · 39 comments
Closed

Sparky SBC | Kernel error trace when switching audio source on USB DAC #2610

seniorgod opened this issue Mar 2, 2019 · 39 comments
Labels
Sparky SBC Visual 🌹 Issues affecting only the beauty of menus and output, but not the functionality
Milestone
v6.31

Comments

@seniorgod
Copy link

seniorgod commented Mar 2, 2019 •
edited by MichaIng
Loading

Creating a bug report/issue

Required Information

  • DietPi version | `6.21.1
  • Distro version | stretch

i still test my allo sparky with USBridge after upgrading to 6.21.1
I have several audio software installed

shairport-sync from dietpi installation
spotifyd from GitHub (because i never get shairport-sync to work properly)
mpd with upmpdcli as upnp frontend for mpd

i control my music with my mobile phone, running spotify, apple music, mpdeluxe.
spotiyfyd and shairport-sny use plughw:1,0 as audio device. When i hear a song from apple music and start playing music from spotify, the system smoothly change the music from one source and go to the second music source (e.g. from apple music to spotify). It seems, that "plughw" stop the first stream and start the new stream.
But i get, from time to time, the following error.
Is it an error resulting from spotifyd/shairport-sync or is it problem of the driver?

Mär 02 23:55:12 DietPi spotifyd[1802]: 23:55:12 [INFO] Track "Berlin" loaded
Mär 02 23:55:12 DietPi spotifyd[1802]: 23:55:12 [ERROR] Alsa error PCM open -16
Mär 02 23:55:12 DietPi spotifyd[1802]: 23:55:12 [ERROR] Could not start audio: Alsa error: PCM open failed
Mär 02 23:55:12 DietPi spotifyd[1802]: 23:55:12 [ERROR] Alsa error PCM open -16
Mär 02 23:55:12 DietPi spotifyd[1802]: 23:55:12 [ERROR] Could not start audio: Alsa error: PCM open failed
Mär 02 23:55:13 DietPi kernel: timeout: still 1 active urbs on EP #1
Mär 02 23:55:14 DietPi kernel: timeout: still 1 active urbs on EP #1
Mär 02 23:55:14 DietPi kernel: ------------[ cut here ]------------
Mär 02 23:55:14 DietPi kernel: WARNING: at /imxhdd/opt/1301TAG/sparky_volumio/kernel/drivers/usb/core/urb.c:328 usb_submit_urb+0x3d4/0x404()
Mär 02 23:55:14 DietPi kernel: URB e1115000 submitted while active
Mär 02 23:55:14 DietPi kernel: Modules linked in: snd_usb_audio snd_hwdep snd_usbmidi_lib nls_cp437 ethernet spidev atc260x_cap_gauge atc260x_irkeypad autofs4
Mär 02 23:55:14 DietPi kernel: CPU: 1 PID: 2200 Comm: shairport-sync Tainted: G        W    3.10.38 #22
Mär 02 23:55:14 DietPi kernel: [<c0015b34>] (unwind_backtrace+0x0/0x138) from [<c001304c>] (show_stack+0x24/0x2c)
Mär 02 23:55:14 DietPi kernel: [<c001304c>] (show_stack+0x24/0x2c) from [<c002beb8>] (warn_slowpath_common+0x4c/0x6c)
Mär 02 23:55:14 DietPi kernel: [<c002beb8>] (warn_slowpath_common+0x4c/0x6c) from [<c002bf6c>] (warn_slowpath_fmt+0x30/0x40)
Mär 02 23:55:14 DietPi kernel: [<c002bf6c>] (warn_slowpath_fmt+0x30/0x40) from [<c03fe604>] (usb_submit_urb+0x3d4/0x404)
Mär 02 23:55:14 DietPi kernel: [<c03fe604>] (usb_submit_urb+0x3d4/0x404) from [<bf051518>] (snd_usb_endpoint_start+0x15c/0x348 [snd_usb_audio])
Mär 02 23:55:14 DietPi kernel: [<bf051518>] (snd_usb_endpoint_start+0x15c/0x348 [snd_usb_audio]) from [<bf0578f8>] (start_endpoints+0xc4/0x140 [snd_usb_audio])
Mär 02 23:55:14 DietPi kernel: [<bf0578f8>] (start_endpoints+0xc4/0x140 [snd_usb_audio]) from [<bf059394>] (snd_usb_pcm_prepare+0x138/0x3a8 [snd_usb_audio])
Mär 02 23:55:14 DietPi kernel: [<bf059394>] (snd_usb_pcm_prepare+0x138/0x3a8 [snd_usb_audio]) from [<c055384c>] (snd_pcm_do_prepare+0x14/0x2c)
Mär 02 23:55:14 DietPi kernel: [<c055384c>] (snd_pcm_do_prepare+0x14/0x2c) from [<c055322c>] (snd_pcm_action_single+0x38/0x78)
Mär 02 23:55:14 DietPi kernel: [<c055322c>] (snd_pcm_action_single+0x38/0x78) from [<c055354c>] (snd_pcm_action_nonatomic+0x54/0x60)
Mär 02 23:55:14 DietPi kernel: [<c055354c>] (snd_pcm_action_nonatomic+0x54/0x60) from [<c055482c>] (snd_pcm_common_ioctl1+0x828/0xd4c)
Mär 02 23:55:14 DietPi kernel: [<c055482c>] (snd_pcm_common_ioctl1+0x828/0xd4c) from [<c0555420>] (snd_pcm_playback_ioctl1+0x138/0x440)
Mär 02 23:55:14 DietPi kernel: [<c0555420>] (snd_pcm_playback_ioctl1+0x138/0x440) from [<c0121e38>] (do_vfs_ioctl+0x80/0x598)
Mär 02 23:55:14 DietPi kernel: [<c0121e38>] (do_vfs_ioctl+0x80/0x598) from [<c01223bc>] (SyS_ioctl+0x6c/0x7c)
Mär 02 23:55:14 DietPi kernel: [<c01223bc>] (SyS_ioctl+0x6c/0x7c) from [<c000f340>] (ret_fast_syscall+0x0/0x30)
Mär 02 23:55:14 DietPi kernel: ---[ end trace d41fcab1096be704 ]---
Mär 02 23:55:14 DietPi kernel: cannot submit urb 6, error -16: unknown error
Mär 02 23:55:14 DietPi kernel: cannot submit urb 6, error -16: unknown error
Mär 02 23:55:14 DietPi shairport-sync[1580]: ALSA lib pcm.c:8309:(snd_pcm_recover) cannot recovery from underrun, prepare failed: Broken pipe
Mär 02 23:55:14 DietPi shairport-sync[1580]: ALSA lib pcm.c:8309:(snd_pcm_recover) cannot recovery from underrun, prepare failed: Broken pipe
Mär 02 23:55:14 DietPi kernel: cannot submit urb 6, error -16: unknown error
Mär 02 23:55:14 DietPi kernel: cannot submit urb 6, error -16: unknown error
Mär 02 23:55:14 DietPi kernel: cannot submit urb 6, error -16: unknown error
Mär 02 23:55:14 DietPi kernel: aotg_ring_enqueue_isoc_td:927, dbg!
Mär 02 23:55:14 DietPi kernel: cannot submit urb 5, error -1: unknown error
Mär 02 23:55:14 DietPi kernel: cannot submit urb 6, error -16: unknown error
Mär 02 23:55:14 DietPi kernel: aotg_hub_urb_dequeue, retval:-43, urb not submitted or unlinked , type = 0 
Mär 02 23:55:14 DietPi kernel: aotg_hub_urb_dequeue, retval:-43, urb not submitted or unlinked , type = 0 
Mär 02 23:55:14 DietPi kernel: aotg_hub_urb_dequeue, retval:-43, urb not submitted or unlinked , type = 0 
Mär 02 23:55:14 DietPi kernel: aotg_hub_urb_dequeue, retval:-43, urb not submitted or unlinked , type = 0 
Mär 02 23:55:14 DietPi kernel: aotg_hub_urb_dequeue, retval:-43, urb not submitted or unlinked , type = 0 
Mär 02 23:55:14 DietPi shairport-sync[1580]: ALSA lib pcm.c:8309:(snd_pcm_recover) cannot recovery from underrun, prepare failed: Broken pipe
Mär 02 23:55:15 DietPi shairport-sync[1580]: ALSA lib pcm.c:8309:(snd_pcm_recover) cannot recovery from underrun, prepare failed: Broken pipe
Mär 02 23:55:15 DietPi shairport-sync[1580]: ALSA lib pcm.c:8309:(snd_pcm_recover) cannot recovery from underrun, prepare failed: Broken pipe
Mär 02 23:55:15 DietPi shairport-sync[1580]: Very large sync error: 140086 frames, with delay: 228286, td_in_frames: 19129, rt: 4750335090, nt: 4750125933, current_delay: 0, seqno: 20351, given timestamp: 455158637.
Mär 02 23:55:15 DietPi kernel: timeout: still 5 active urbs on EP #1
Mär 02 23:55:15 DietPi kernel: cannot submit urb 0, error -16: unknown error
Mär 02 23:55:15 DietPi kernel: cannot submit urb 0, error -16: unknown error
Mär 02 23:55:15 DietPi kernel: cannot submit urb 0, error -16: unknown error
Mär 02 23:55:15 DietPi kernel: cannot submit urb 0, error -16: unknown error
@MichaIng MichaIng changed the title error on usb audio Sparky SBC | Error on USB audio Mar 2, 2019
@MichaIng
Copy link
Owner

MichaIng commented Mar 2, 2019 •
edited
Loading

@seniorgod
Thanks for your report.

Will investigate, need to have a look into the sound card selection code.

As you use MPD, please first apply this fix that causes permission issues that might or might not be related to your issue: #2522 (comment)

Okay so you selected usb-dac from dietpi-config, right?

The config is done quite straight forward with that. I don't believe something can fail here. Will check the software installs...

Software installs as well do no special sound configs.

Could you paste output of:

cat /etc/asound.conf
aplay -l

@MichaIng
Copy link
Owner

MichaIng commented Mar 3, 2019 •
edited
Loading

Okay, did some search for the actual error messages and indeed it seems to be a kernel bug that is fixed with kernel 3.8: torvalds/linux@ae5943d

Strange is that on our current Sparky SBC image kernel is 3.10.
Can you paste: uname -a

@seniorgod
Copy link
Author

seniorgod commented Mar 3, 2019 •
edited by MichaIng
Loading

To do new set up with the sparky the Friday, i started with an image i downloaded last December. I think it was Dietpi 6.14. I called dietpi-config to update all to the new version.

The language of the system is german. sorry. :-)
So you se some german strings....:

root@DietPi:# uname -a
Linux DietPi 3.10.38 #22 SMP PREEMPT Fri Dec 22 10:45:41 IST 2017 armv7l GNU/Linux
root@DietPi:# cat /etc/asound.conf
pcm.!default {
    type hw
    card 1
    device 0
}
ctl.!default {
    type hw
    card 1
}
root@DietPi:# aplay -l
**** Liste der Hardware-Geräte (PLAYBACK) ****
Karte 0: atm7059link [atm7059_link], Gerät 0: ATC2603C PCM atc2603c-dai-0 []
  Sub-Geräte: 1/1
  Sub-Gerät #0: subdevice #0
Karte 0: atm7059link [atm7059_link], Gerät 1: HDMI PCM atm7059-hdmi-dai-1 []
  Sub-Geräte: 1/1
  Sub-Gerät #0: subdevice #0
Karte 0: atm7059link [atm7059_link], Gerät 2: SPDIF PCM atm7059-spdif-dai-2 []
  Sub-Geräte: 1/1
  Sub-Gerät #0: subdevice #0
Karte 1: P20 [Project RS USB Audio 2.0], Gerät 0: USB Audio [USB Audio]
  Sub-Geräte: 0/1
  Sub-Gerät #0: subdevice #0
root@DietPi:~#

mpd is working fine

@seniorgod
Copy link
Author

one question regarding #2522
I would prefer to change simply mpd.conf and mpd.service by hand
Is that ok?
What's the advantage by doing it like described with sed and G_CONFIG?

@MichaIng
Copy link
Owner

MichaIng commented Mar 3, 2019 •
edited
Loading

@seniorgod

What's the advantage by doing it like described with sed and G_CONFIG?

No advantage as long as you add them correctly to the right line.

  • sed -Ei '/^(user|group)[[:blank:]]/d' /etc/mpd.conf will simply remove the user and group setting line from mpd.conf.
  • The G_CONFIG_INJECT commands add the user instead to the MPD systemd unit (service file) and make resulting limited permissions only being applied to the final daemon execution. User=mpd and PermissionsStartOnly=true need to be in the [Service] section, possibly existent Group= setting is not required and can/should be removed.

The reason why this caused issues was:

  • In mpd.conf we set user mpd and group dietpi to run MPD with the desired limited/safe permissions and allow it via group to ready from dietpi owned media directories.
  • The mpd user is also inside the audio group which allows him to access the audio device interfaces.
  • But the group setting in mpd.conf does not "add" this group to the users permissions but overrides all user groups instead. So with group dietpi the audio group permission were lost, leading to audoio interface access errors.
  • To solve this, we now do not touch user and group via mpd.conf but instead do with within the systemd unit that imits the MPD daemon. User and group settings there do not override any system-wise applied permission, do it is possible then to have MPD access as group audio AND dietpi.

If MPD already works fine for you, you possible already changed something about that (e.g. setting user root) or recovered your previous mpd.conf after update? Or the audio group permissions are not required for all audio devices, which is most likely true since the earlier MPD settings passed our local testing as well. However the above method is safer then running MPD with root permissions in case.

Okay so you use a quite generic USB DAC and at least to ALSA it is exactly configured as desired.

About the fix within the Linux kernel, this was actually only a certain USB WiFi dongle: https://www.viatech.com/en/support/eol/vnt6656-usb-module-dongle-eol/

Identified the code line that produces the error, which is about USB low level messaging: https://github.com/sparkysbc/Linux/blob/master/drivers/usb/core/urb.c#L328

I am trying to find out what this is all about. I guess the source is indeed: [ERROR] Alsa error PCM open -16

Do the timestamps of this error match track switch? Looks like since first log is [INFO] Track "Berlin" loaded. Perhaps this switch is simply done not gracefully.

When i hear a song from apple music and start playing music from spotify, the system smoothly change the music from one source and go to the second music source

  • Perhaps there is some overlap issue. Not sure if it is e.g. possible to increase the delay when switching the music source, so the one fully finishes before the second starts up?

But as every thing runs well, I guess for now these errors can be ignored. However where do they show up actually, journalctl? Perhaps it is possible to reduce some log level to not have them spamming 😉.

@seniorgod
Copy link
Author

thank you, most things are clear.
My question was more dedicated to the usage of the tools G_CONFIG_INCJECT.
When i use that tool to do the changes, will may changes survive the rollout of an new mpd.conf oder mpd.service? If not, why using that tool instead of doing the changes in the files mentioned above manually?

@MichaIng
Copy link
Owner

MichaIng commented Mar 3, 2019 •
edited
Loading

@seniorgod
G_CONFIG_INCJECT is just a function we created to easily add/change settings to config files in a failsafe way: https://github.com/MichaIng/DietPi/blob/dev/dietpi/func/dietpi-globals#L2277-L2399

  • This assures there are no multiple entries of the same setting.
  • If the setting is already present but commented, it will use the comment line.
  • Via options it is possible to preserve the existing values, add the setting after a specific line and create a backup of the config file before touching.
  • And it includes all required escaping of special characters and prints any result and in case errors to terminal.

Mostly we use this internally within DietPi scripts, but it is available from the command line by default on DietPi systems.
There is no advantage for you to use this function, only that it is easier (copy&paste) than opening the editor, find the required lines and type the changes manually.

And nope, reinstall will currently still place the default mpd.conf, G_CONFIG_INJECT has no effect on this. However a backup is always created, so one can easily move it in place after MPD reinstall.
And I aim to change that behaviour soon, so that on reinstall mpd.conf is not overwritten but instead required changes are applied during update via G_CONFIG_INJECT 😉.

@seniorgod
Copy link
Author

understand. fine. :-)

What we do with the kernel problem?
Does it make sense to do a new compile of sharepoint-sync?

@MichaIng
Copy link
Owner

MichaIng commented Mar 3, 2019

@seniorgod
Not sure about the kernel issue currently, if it is indeed related to the audio source transition and thus software related or a kernel bug indeed.

Ah can you verify these errors (timestamps) show up when switching the audio source and/or track and not randomly in the middle of playing any source?

The first error messages come from spotifyd, so I assume, if software related, then it is more likely a spotifyd issue then sharepoint-sync.
Also our shairport-sync packages are already the most current upstream version. But indeed there are several build options, where I am not 100% sure if anything might be related: https://github.com/mikebrady/shairport-sync#building-and-installing

@seniorgod
Copy link
Author

seniorgod commented Mar 3, 2019 via email

@MichaIng
Copy link
Owner

MichaIng commented Mar 3, 2019

@seniorgod
I think we should add https://github.com/Spotifyd/spotifyd as new install option by times and drop https://github.com/Fornoth/spotify-connect-web when it does not work anymore. Spotifyd is much more actively developed, so seems to be indeed the way to go.

Would be great if you could open a new feature request about this and possible as well add it to our FeatHub page: https://feathub.com/MichaIng/DietPi/

@MichaIng
Copy link
Owner

MichaIng commented Mar 4, 2019

@seniorgod
Ah just found another open issue. Please try this: #2427 (comment)

In /DietPi/uEnv.txt
change
aotg.urb_fix = 1
to
aotg.urb_fix = 0

Reboot and check if it makes a difference.

@MichaIng MichaIng added this to the v6.22 milestone Mar 4, 2019
@MichaIng MichaIng mentioned this issue Mar 4, 2019
Closed
@seniorgod
Copy link
Author

seniorgod commented Mar 5, 2019 •
edited
Loading

@MichaIng

nice try:-)

#2427 was created by me.
aotg.urb_fix = 0 is already set.

To remember: the behavior if atop_urb_fix != 0 is that sparky hang, after shutting of the DAC while music is playing.

what i wonder:
even when spotifyd and shairport have a "problem" working together.
This should not lead to an kernel trace. Isn't it?

I give a new compilation of shairport-sync a try. But i have to wait for next week, will go skiing at weekend.....

@MichaIng
Copy link
Owner

MichaIng commented Mar 5, 2019

@seniorgod
Ah lol recognized that this is your topic as well just now 🤣.

User programs generally can trigger kernel error when using kernel features a wrong way, accessing resources they have no permissions for or in case of general I/O issues due to corruption and stuff. But yeah to be true I am not sure how exactly the audio device is accessed here. Of course ALSA is always middleware and also always shows up in your error log, but possible it is accessed/used wrong by the players... But as well possible that it is indeed a kernel issue Sparky-side: /imxhdd/opt/1301TAG/sparky_volumio/kernel/drivers/usb/core/urb.c

Actually would be great to test the exact same setup on another SBC. Hmm actually I have an USB DAC here as well, perhaps I find some time to test it on notebook. Hmm have no spotify or something, have to digging a bid into this to have two sources to switch between. The setup will be totally different, but at least we can sort out a general issue with Debian + ALSA + switch audio source.

But I mark this as low priority now, since functionality is fine and it is a visual issue only.

@MichaIng MichaIng added Priority Low 🔅 Visual 🌹 Issues affecting only the beauty of menus and output, but not the functionality labels Mar 5, 2019
@MichaIng MichaIng changed the title Sparky SBC | Error on USB audio Sparky SBC | Kernel error trace when switching audio source on USB DAC Mar 5, 2019
@MichaIng MichaIng modified the milestones: v6.22, v6.23 Mar 8, 2019
@seniorgod
Copy link
Author

seniorgod commented Mar 16, 2019 •
edited by MichaIng
Loading

Hi MichaIng,

i have a new error trace. But today only spotifyd was running. No other music client was playing music (but all run as daemons):

Mär 16 11:13:31 DietPi kernel: aotg_hub_endpoint_disable
Mär 16 11:13:31 DietPi kernel: aotg_hcd aotg_hcd.1: <EP DISABLE> ep1 index 1 from ep [out]
Mär 16 11:13:31 DietPi kernel: aotg_hub_endpoint_disable
Mär 16 11:13:31 DietPi kernel: aotg_hcd aotg_hcd.1: <EP DISABLE> ep1 index 3 from ep [in]
Mär 16 11:13:31 DietPi spotifyd[27338]: 11:13:31 [INFO] Loading track "Halfway Up The Hindu Kush" with Spotify URI "spotify:track:2ibjom0ewZZYf9heGgXIhc"
Mär 16 11:13:32 DietPi spotifyd[27338]: 11:13:32 [INFO] Track "Halfway Up The Hindu Kush" loaded
Mär 16 11:13:32 DietPi kernel: snd_pcm_mmap,default
Mär 16 11:13:32 DietPi kernel: iso_packets:0, bInterval:1, urb_interval:1, reg_con:0x4
Mär 16 11:13:32 DietPi kernel: iso_packets:0, bInterval:4, urb_interval:8, reg_con:0x4
Mär 16 11:16:38 DietPi kernel: noticd:aotg_ring_dequeue_td, IN1IRQ:0x0; OUT1IRQ:0x2
Mär 16 11:16:38 DietPi kernel: aotg_hub_endpoint_disable
Mär 16 11:16:38 DietPi kernel: aotg_hcd aotg_hcd.1: <EP DISABLE> ep1 index 1 from ep [out]
Mär 16 11:16:38 DietPi kernel: aotg_hub_endpoint_disable
Mär 16 11:16:38 DietPi kernel: aotg_hcd aotg_hcd.1: <EP DISABLE> ep1 index 3 from ep [in]
Mär 16 11:16:38 DietPi spotifyd[27338]: 11:16:38 [INFO] Loading track "Pumped Up Kicks" with Spotify URI "spotify:track:7w87IxuO7BDcJ3YUqCyMTT"
Mär 16 11:16:39 DietPi spotifyd[27338]: 11:16:39 [INFO] Track "Pumped Up Kicks" loaded
Mär 16 11:16:39 DietPi kernel: snd_pcm_mmap,default
Mär 16 11:16:39 DietPi kernel: iso_packets:0, bInterval:1, urb_interval:1, reg_con:0x4
Mär 16 11:16:39 DietPi kernel: iso_packets:0, bInterval:4, urb_interval:8, reg_con:0x4
Mär 16 11:16:44 DietPi kernel: TX ERROR status: 0x00760000
Mär 16 11:17:01 DietPi CRON[27354]: pam_unix(cron:session): session opened for user root by (uid=0)
Mär 16 11:17:01 DietPi CRON[27355]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mär 16 11:17:03 DietPi CRON[27354]: pam_unix(cron:session): session closed for user root
Mär 16 11:20:38 DietPi kernel: aotg_hub_endpoint_disable
Mär 16 11:20:38 DietPi kernel: aotg_hcd aotg_hcd.1: <EP DISABLE> ep1 index 1 from ep [out]
Mär 16 11:20:38 DietPi kernel: aotg_hub_endpoint_disable
Mär 16 11:20:38 DietPi kernel: aotg_hcd aotg_hcd.1: <EP DISABLE> ep1 index 3 from ep [in]
Mär 16 11:20:38 DietPi spotifyd[27338]: 11:20:38 [INFO] Loading track "Crystal Frontier - Original Version" with Spotify URI "spotify:track:4osMHG9HvVIEqTciAPtZKK"
Mär 16 11:20:38 DietPi spotifyd[27338]: 11:20:38 [INFO] Track "Crystal Frontier" loaded
Mär 16 11:20:38 DietPi kernel: snd_pcm_mmap,default
Mär 16 11:20:38 DietPi kernel: iso_packets:0, bInterval:1, urb_interval:1, reg_con:0x4
Mär 16 11:20:38 DietPi kernel: iso_packets:0, bInterval:4, urb_interval:8, reg_con:0x4
Mär 16 11:20:39 DietPi kernel: ------------[ cut here ]------------
Mär 16 11:20:39 DietPi kernel: WARNING: at /imxhdd/opt/1301TAG/sparky_volumio/kernel/net/sched/sch_generic.c:255 dev_watchdog+0x24c/0x26c()
Mär 16 11:20:39 DietPi kernel: NETDEV WATCHDOG: eth0 (owl-ethernet): transmit queue 0 timed out
Mär 16 11:20:39 DietPi kernel: Modules linked in: snd_usb_audio snd_hwdep snd_usbmidi_lib nls_cp437 ethernet spidev atc260x_cap_gauge atc260x_irkeypad autofs4
Mär 16 11:20:39 DietPi kernel: CPU: 0 PID: 0 Comm: swapper/0 Tainted: G        W    3.10.38 #22
Mär 16 11:20:39 DietPi kernel: [<c0015b34>] (unwind_backtrace+0x0/0x138) from [<c001304c>] (show_stack+0x24/0x2c)
Mär 16 11:20:39 DietPi kernel: [<c001304c>] (show_stack+0x24/0x2c) from [<c002beb8>] (warn_slowpath_common+0x4c/0x6c)
Mär 16 11:20:39 DietPi kernel: [<c002beb8>] (warn_slowpath_common+0x4c/0x6c) from [<c002bf6c>] (warn_slowpath_fmt+0x30/0x40)
Mär 16 11:20:39 DietPi kernel: [<c002bf6c>] (warn_slowpath_fmt+0x30/0x40) from [<c05ea148>] (dev_watchdog+0x24c/0x26c)
Mär 16 11:20:39 DietPi kernel: [<c05ea148>] (dev_watchdog+0x24c/0x26c) from [<c003a2d8>] (call_timer_fn+0x3c/0x154)
Mär 16 11:20:39 DietPi kernel: [<c003a2d8>] (call_timer_fn+0x3c/0x154) from [<c003ac90>] (run_timer_softirq+0x1c0/0x2c4)
Mär 16 11:20:39 DietPi kernel: [<c003ac90>] (run_timer_softirq+0x1c0/0x2c4) from [<c00339e0>] (__do_softirq+0xf4/0x2a0)
Mär 16 11:20:39 DietPi kernel: [<c00339e0>] (__do_softirq+0xf4/0x2a0) from [<c0033c1c>] (do_softirq+0x4c/0x58)
Mär 16 11:20:39 DietPi kernel: [<c0033c1c>] (do_softirq+0x4c/0x58) from [<c0033e90>] (irq_exit+0x90/0xc8)
Mär 16 11:20:39 DietPi kernel: [<c0033e90>] (irq_exit+0x90/0xc8) from [<c000fbf8>] (handle_IRQ+0x3c/0x94)
Mär 16 11:20:39 DietPi kernel: [<c000fbf8>] (handle_IRQ+0x3c/0x94) from [<c00085e0>] (gic_handle_irq+0x28/0x5c)
Mär 16 11:20:39 DietPi kernel: [<c00085e0>] (gic_handle_irq+0x28/0x5c) from [<c000ef40>] (__irq_svc+0x40/0x70)
Mär 16 11:20:39 DietPi kernel: Exception stack(0xc0c77f68 to 0xc0c77fb0)
Mär 16 11:20:39 DietPi kernel: 7f60:                   ffffffed 00a37000 c0c8b6e4 00000000 c0c76000 c0c76000
Mär 16 11:20:39 DietPi kernel: 7f80: c0c76000 c0d29dec c0c89ed4 414fc091 c07c6920 c0d295bd 00000000 c0c77fb0
Mär 16 11:20:39 DietPi kernel: 7fa0: c0010050 c0010048 60010013 ffffffff
Mär 16 11:20:39 DietPi kernel: [<c000ef40>] (__irq_svc+0x40/0x70) from [<c0010048>] (arch_cpu_idle+0x28/0x38)
Mär 16 11:20:39 DietPi kernel: [<c0010048>] (arch_cpu_idle+0x28/0x38) from [<c00736b8>] (cpu_startup_entry+0x68/0x24c)
Mär 16 11:20:39 DietPi kernel: [<c00736b8>] (cpu_startup_entry+0x68/0x24c) from [<c0c00a34>] (start_kernel+0x2c4/0x320)
Mär 16 11:20:39 DietPi kernel: ---[ end trace 715bce8250835476 ]---
Mär 16 11:20:40 DietPi kernel: TX ERROR status: 0x00760000

spotifyd is a precompiled version.....

@MichaIng
Copy link
Owner

MichaIng commented Mar 16, 2019 •
edited
Loading

@seniorgod
If you find some time, one thing you could try is using an alternative uImage I just found on the Sparky GitHub page while seeking for uEnv.txt documentation: https://github.com/sparkysbc/sparky_linux_images/blob/master/usbdac_mod_uImage.tar.bz2

I cannot say reliably if it is newer or older than the one from our image, since ours has overwritten timestamps from image creation date. There is no documentation about it so I have no idea what this uImage does differently than the default one, but according to the name it has something to do with USB DACs.

So if you find some time you could:

  • At best create a full SDcard clone
  • Download this uImage and place it instead of the old:
mv /boot/uImage /boot/uImage.bak
wget https://github.com/sparkysbc/sparky_linux_images/raw/master/usbdac_mod_uImage.tar.bz2
tar -xf usbdac_mod_uImage.tar.bz2
rm usbdac_mod_uImage.tar.bz2
mv uImage /boot/uImage
  • Hope that it is otherwise compatible and the system boots. Perhaps it has some positive influence on the USB DAC.
  • If the SBC does not boot or you face other issues, simply recovering /boot/uImage.bak should do the job. If some more damage happened to the system (very unlikely, as it is only the bootloader), recover the SDcard clone.

@Fourdee
Copy link
Collaborator

Fourdee commented Mar 22, 2019

@MichaIng

I cannot say reliably if it is newer or older than the one from our image

All sparky kernel updates are patched during our updates. Allo provides these to me directly. Therefor once DietPi is updated, users are running the latest kernel, as provided by Allo.

@M1m1s
Copy link

M1m1s commented May 25, 2019

Yeah I tried that too. Just goes back to “none “.
Of course: USBridge is 20 days out of warranty...

@MichaIng
Copy link
Owner

MichaIng commented May 25, 2019 •
edited
Loading

@M1m1s
I have zero experience with the USBridge but just as a general debug idea, before giving up about the hardware:

dmesg
journalctl
  • Check dmesg for red lines or anything voltage related. Who knows if not the power supply has an issue so that the USBridge doesn't run as expected or such.
  • The same for journalctl, check the first ~3 pages (boot) for any suspicious lines about USB detection/failures.

Is there another chance to test the USBridge general functionality with something else than a DAC? I guess this port is only for audio output, isn't it? Otherwise one could check if some USB flash or such get's powered at least, if you own one with LED.

Of course: USBridge is 20 days out of warranty...

😞 However always worth to still give it a try and contact Allo regardless. Perhaps they will still help 🙂.

@M1m1s
Copy link

M1m1s commented May 25, 2019 •
edited by MichaIng
Loading

@MichaIng Thanks for chiming in, in addition to @Fourdee!

These lines from dmesg may be relevant:

usb 4-1: device not accepting address 4, error -110
[   48.875340] aotg_hcd aotg_hcd.1: <EP DISABLE> ep0 index 0 from ep [in]
[   48.877044] set port reset!80
[   48.930379] USBRESET IRQ
[   48.930398] aotg_hub_irq: USB device is 2  
[   48.995293] usb 4-1: new full-speed USB device number 5 using aotg_hcd
[   48.995311] think_time:1
[   48.995321] think_time:0x14
[   48.995338] aotg_hcd aotg_hcd.1: device addr : 0x00000000
[   48.995428] irqvector:16, 0x10
[   48.995441] hcd ep err ep_num:0, is_in:0
[   48.995449] err_type :4
[   48.995465] aotg_hcd aotg_hcd.1: HC OUT ep 0 error [0x13] error type [0x04], reset it...
[   54.415285] usb 4-1: device not accepting address 5, error -110
[   54.415334] aotg_hcd aotg_hcd.1: <EP DISABLE> ep0 index 0 from ep [in]
[   54.415360] hub 4-0:1.0: unable to enumerate USB device on port 1
[   60.765504] nf_conntrack: automatic helper assignment is deprecated and it will be removed soon. Use the iptables CT target to attach helpers instead.
[  610.735611] ethernet link state:disconnected

Also:

[ 8029.636205] usb 3-1.2: Product: Benchmark DAC2 USB Audio 2.0
[ 8029.636216] usb 3-1.2: Manufacturer: Benchmark DAC2 
[ 8029.636225] usb 3-1.2: SerialNumber: 0000
[ 8279.593910] irqvector:66, 0x42
[ 8279.593925] hcd ep err ep_num:2, is_in:1
[ 8279.593934] err_type :4
[ 8279.593942] td->err_count:0
[ 8279.626012] usb 3-1.2: USB disconnect, device number 4
[ 8279.627309] aotg_hcd aotg_hcd.0: <EP DISABLE> ep0 index 0 from ep [in]
[ 8279.627330] aotg_hub_endpoint_disable
[ 8279.627341] aotg_hub_endpoint_disable, ep2 dma buf free
[ 8279.627363] aotg_hcd aotg_hcd.0: <EP DISABLE> ep4 index 2 from ep [in]

Other red lines:

[    2.894904] ----monitor_wake_lock for 10s 
[    2.968722] read_mi_head, line 429, magic 0x0, length 0, item num 0
[    2.968754] read Head null
[    2.968776] OWL_HDMI_ERR: failed to read hdcp key from secure storage
[    5.832066] FAT-fs (mmcblk0p1): codepage cp437 not found
[    5.833812] FAT-fs (mmcblk0p1): codepage cp437 not found
[    5.834952] [EXFAT] ===== ffsMountVol =====
[    5.836452] EXFAT: Codepage cp437 not found
[    7.485329] EXT3-fs (mmcblk0p2): error: couldn't mount because of unsupported optional features (240)
[    7.485904] EXT2-fs (mmcblk0p2): error: couldn't mount because of unsupported optional features (240)
[    9.599801] found sparky chip c014639ca06931b provisioned
[    9.599938] idx 1030 newmac 17f7010407
[    9.745836] ATC260X_GAUGE: [get_stored_soc] not store soc
[   11.747015] set port reset!80
[   17.415456] usb 4-1: device descriptor read/64, error -110

No mention of USB in journalctl.

Thank you!

@MichaIng
Copy link
Owner

MichaIng commented May 25, 2019 •
edited
Loading

@M1m1s
Hmm, looks like the USBridge is port 4.1 while onboard USB is port 3.1 where the DAC was recognised correctly.

[ 17.415456] usb 4-1: device descriptor read/64, error -110
[ 54.415285] usb 4-1: device not accepting address 5, error -110
[ 54.415360] hub 4-0:1.0: unable to enumerate USB device on port 1

It might not exactly apply in your case, but with some luck some recent change in the USB audio driver magically fixes the issue. At least worth to give the new testing drivers a try: #2610 (comment)

Also:

  • You do not have any other USB device attached, do you? At least nothing visible in logs and lsusb output. In case try to detach all other USB devices.
  • Do you have another power supply to test with, just to sort that out (even that there are no under-voltage errors)?

EDIT:

  • Indeed usb 4-1: device descriptor read/64, error -110 according to further research states exceeded USB power.
  • And as it is the first error message, the other ones are most likely just related follow-up errors.
  • If no other USB devices are attached and the Sparky power supply is definitely sufficient (another one has been tested), then you might want to detach the USBridge, check/clean connectors and reattach. Possibly simply some physical connection is not 100% there.
  • And of course last but not least a broken USBridge can have the same result, e.g. when some internal connection is broken. Then as mentioned above I would contact Allo and hope that they are helpful or even replace the USBridge even that you are a bid over warranty.

@M1m1s
Copy link

M1m1s commented May 27, 2019

@MichaIng @Fourdee Thank you so much for your very helpful and extensive troubleshooting help for the USBridge (over the weekend, too!). I have performed all your suggestions, as well as verified that the DAC and USB cable work properly. I'm in contact with Allo support. All your help is very appreciated and hopefully will help anyone else who might experience similar issues.

@seniorgod
Copy link
Author

Dear all,

sorry for late reply, but i was absent and afterwards "under heavy workload".
@M1m1s : Did All support reply. Do you know, if the usbridge was defect?

@MichaIng: Thank you for noticing the new driver. I installed it last week.
Because i use airplay currently very rarely, i have no problems at switching the audio source.
But i still get kernel traces when using spotifyd. I send it to the spotifyd project. One member answered and point to a network problem. It seems, when spotifyd is not getting enough data from network it get into problems. I wonder if insufficient data stream cause kernel traces. But ti be clear: I have no idea how alsa work and if insufficient pcm streams can cause kernel traces. Her is an example from yesterday. The second line after "cut here" is an warning from the network layer:

Jun 09 17:07:14 DietPi spotifyd[1343]: 17:07:14 [INFO] Track "So soll es sein" loaded
Jun 09 17:07:14 DietPi kernel: snd_pcm_mmap,default
Jun 09 17:07:14 DietPi kernel: iso_packets:0, bInterval:1, urb_interval:1, reg_con:0x4
Jun 09 17:07:14 DietPi kernel: iso_packets:0, bInterval:4, urb_interval:8, reg_con:0x4
Jun 09 17:10:16 DietPi kernel: noticd:aotg_ring_dequeue_td, IN1IRQ:0x0; OUT1IRQ:0x2
Jun 09 17:10:16 DietPi kernel: aotg_hub_endpoint_disable
Jun 09 17:10:16 DietPi kernel: aotg_hcd aotg_hcd.1: <EP DISABLE> ep1 index 1 from ep [out]
Jun 09 17:10:16 DietPi kernel: aotg_hub_endpoint_disable
Jun 09 17:10:16 DietPi kernel: aotg_hcd aotg_hcd.1: <EP DISABLE> ep1 index 3 from ep [in]
Jun 09 17:10:16 DietPi spotifyd[1343]: 17:10:16 [INFO] Loading track "Mindestens in 1000 Jahren"     with Spotify URI "spotify:track:1oKpxxe1L6YdriO8SnV6I1"
Jun 09 17:10:16 DietPi spotifyd[1343]: 17:10:16 [INFO] Track "Mindestens in 1000 Jahren" loaded
Jun 09 17:10:16 DietPi kernel: snd_pcm_mmap,default
Jun 09 17:10:16 DietPi kernel: iso_packets:0, bInterval:1, urb_interval:1, reg_con:0x4
Jun 09 17:10:16 DietPi kernel: iso_packets:0, bInterval:4, urb_interval:8, reg_con:0x4
Jun 09 17:10:21 DietPi kernel: ------------[ cut here ]------------
Jun 09 17:10:21 DietPi kernel: WARNING:at/imxhdd/opt/1301TAG/sparky_volumio/kernel/net/sched/sch_generic.c:255 dev_watchdog+0x24c/0x26c()
Jun 09 17:10:21 DietPi kernel: NETDEV WATCHDOG: eth0 (owl-ethernet): transmit queue 0 timed out
Jun 09 17:10:21 DietPi kernel: ethernet link state:linked
Jun 09 17:10:21 DietPi kernel: Modules linked in:
Jun 09 17:10:21 DietPi kernel:  snd_usb_audio snd_hwdep snd_usbmidi_lib nls_cp437 ethernet spidev atc260x_cap_gauge atc260x_irkeypad autofs4
Jun 09 17:10:21 DietPi kernel: CPU: 0 PID: 0 Comm: swapper/0 Tainted: G        W    3.10.38 #22
Jun 09 17:10:21 DietPi kernel: [<c0015b34>] (unwind_backtrace+0x0/0x138) from [<c001304c>] (show_stack+0x24/0x2c)
Jun 09 17:10:21 DietPi kernel: [<c001304c>] (show_stack+0x24/0x2c) from [<c002beb8>] (warn_slowpath_common+0x4c/0x6c)
Jun 09 17:10:21 DietPi kernel: [<c002beb8>] (warn_slowpath_common+0x4c/0x6c) from [<c002bf6c>] (warn_slowpath_fmt+0x30/0x40)
Jun 09 17:10:21 DietPi kernel: [<c002bf6c>] (warn_slowpath_fmt+0x30/0x40) from [<c05ea148>] (dev_watchdog+0x24c/0x26c)
Jun 09 17:10:21 DietPi kernel: [<c05ea148>] (dev_watchdog+0x24c/0x26c) from [<c003a2d8>] (call_timer_fn+0x3c/0x154)
Jun 09 17:10:21 DietPi kernel: [<c003a2d8>] (call_timer_fn+0x3c/0x154) from [<c003ac90>] (run_timer_softirq+0x1c0/0x2c4)
Jun 09 17:10:21 DietPi kernel: [<c003ac90>] (run_timer_softirq+0x1c0/0x2c4) from [<c00339e0>] (__do_softirq+0xf4/0x2a0)
Jun 09 17:10:21 DietPi kernel: [<c00339e0>] (__do_softirq+0xf4/0x2a0) from [<c0033c1c>] (do_softirq+0x4c/0x58)
Jun 09 17:10:21 DietPi kernel: [<c0033c1c>] (do_softirq+0x4c/0x58) from [<c0033e90>] (irq_exit+0x90/0xc8)
Jun 09 17:10:21 DietPi kernel: [<c0033e90>] (irq_exit+0x90/0xc8) from [<c000fbf8>] (handle_IRQ+0x3c/0x94)
Jun 09 17:10:21 DietPi kernel: [<c000fbf8>] (handle_IRQ+0x3c/0x94) from [<c00085e0>] (gic_handle_irq+0x28/0x5c)
Jun 09 17:10:21 DietPi kernel: [<c00085e0>] (gic_handle_irq+0x28/0x5c) from [<c000ef40>] (__irq_svc+0x40/0x70)
Jun 09 17:10:21 DietPi kernel: Exception stack(0xc0c77f68 to 0xc0c77fb0)
Jun 09 17:10:21 DietPi kernel: 7f60: ffffffed 00a37000 c0c8b6e4 00000000 c0c76000 c0c76000
Jun 09 17:10:21 DietPi kernel: 7f80: c0c76000 c0d29dec c0c89ed4 414fc091 c07c6920 c0d295bd 00000000 c0c77fb0
Jun 09 17:10:21 DietPi kernel: 7fa0: c0010050 c0010048 60010013 ffffffff
Jun 09 17:10:21 DietPi kernel: [<c000ef40>] (__irq_svc+0x40/0x70) from [<c0010048>] (arch_cpu_idle+0x28/0x38)
Jun 09 17:10:21 DietPi kernel: [<c0010048>] (arch_cpu_idle+0x28/0x38) from [<c00736b8>] (cpu_startup_entry+0x68/0x24c)
Jun 09 17:10:21 DietPi kernel: [<c00736b8>] (cpu_startup_entry+0x68/0x24c) from [<c0c00a34>] (start_kernel+0x2c4/0x320)
Jun 09 17:10:21 DietPi kernel: ---[ end trace 548b4a4b1a772f82 ]---
Jun 09 17:10:23 DietPi kernel: TX ERROR status: 0x00760000

@M1m1s
Copy link

M1m1s commented Jun 11, 2019

@seniorgod @MichaIng @Fourdee
Allo support's reply was: "usbridge board some of the LDOs failed , so the chip not detecting."

@MichaIng
Copy link
Owner

MichaIng commented Jun 11, 2019 •
edited
Loading

@M1m1s
LDOs are the linear dropout regulators. So this indeed sounds like a defective board. Perhaps a warranty case?

@MichaIng MichaIng modified the milestones: v6.25, v6.26 Jun 24, 2019
@MichaIng MichaIng modified the milestones: v6.26, v6.27 Sep 3, 2019
@MichaIng
Copy link
Owner

MichaIng commented Oct 5, 2019 •
edited
Loading

@seniorgod
Just to not forget about this, did you try to build the new shairport sync release: https://github.com/mikebrady/shairport-sync/releases
As mentioned above, the initial 3.3 release notes sound very promising:

  • Greatly improved stability when playing is interrupted by another play request, by the abrupt disappearance of the audio source or by severe network problems.

@MichaIng MichaIng mentioned this issue Oct 5, 2019
Closed
@MichaIng MichaIng modified the milestones: v6.27, v6.28 Nov 13, 2019
@MichaIng MichaIng modified the milestones: v6.28, v6.29 Jan 3, 2020
@MichaIng MichaIng mentioned this issue Jan 28, 2020
Closed
33 tasks
@MichaIng MichaIng modified the milestones: v6.29, v6.30 Mar 19, 2020
@MichaIng MichaIng modified the milestones: v6.30, v6.31 May 10, 2020
@MichaIng
Copy link
Owner

I mark this as closed as of new Sparky SBC image and new Shairport-Sync build. Feel free to reopen if required.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Sparky SBC Visual 🌹 Issues affecting only the beauty of menus and output, but not the functionality
Projects
None yet
Milestone
v6.31
Development

No branches or pull requests
5 participants
@mainrs @Fourdee @seniorgod @M1m1s @MichaIng