Bluetooth connection/paring stopped working - moOde 8.3.9 - jakste - 04-07-2024
Hi all,
I installed moOde 8.3.9 on a Pi-3B 1.2 1GB running 11.9 Bullseye 64-bit yesterday.
Everything worked fine. We paired with 3 different (Android) phones, and we were able to play music from the phones over BT to the USB-audio interface on the Pi. Great stuff, love it !
Today, when we wanted to play music again, but all of us were unable to connect to BT again. The Pi have been powered on all the time since yesterday. Depending on phone model, nothing happened when you tried to connect or the phone said you have not supplied the right pin code/key to be able to pair/connect.
So, I unpaired the unit and tried to pair again. Same thing, nothing happened and we were unable to pair.
So, from the moOde web interface, I restarted the BT agent and removed any previously paired phones. And, now I was able to pair and connect again.
I have an external Asus BT5.0 USB dongle that I use (not the build in BT).
I assume this will happen again (?!!), what type of log(s) should I try to catch to help the fault tracing?
Code: 20240406 171946 worker: --
20240406 171946 worker: -- Start moOde 8 series
20240406 171946 worker: --
20240406 171946 worker: Successfully daemonized
20240406 171946 worker: Wait for Linux startup...
20240406 172016 worker: Linux startup complete
20240406 172017 worker: Boot config backed up
20240406 172019 worker: Session loaded
20240406 172023 worker: Package holds applied
20240406 172024 worker: File check complete
20240406 172024 worker: Debug logging off
20240406 172024 worker: Reduced logging off
20240406 172024 worker: --
20240406 172024 worker: -- Audio debug
20240406 172024 worker: --
20240406 172024 worker: ALSA cards: 0:b1 | 1:Headphones | 2:Device | 3:empty
20240406 172024 worker: MPD config: 2:USB Audio Device | mixer:Speaker | cardnum:2
20240406 172024 worker: Mixer name: [Speaker]
20240406 172025 worker: Hdwr volume: set to 0%
20240406 172025 worker: Volume knob: 0
20240406 172025 worker: --
20240406 172025 worker: -- System
20240406 172025 worker: --
20240406 172028 worker: Host: moode
20240406 172028 worker: Model: Pi-3B 1.2 1GB
20240406 172028 worker: moOde: 8.3.9 2024-02-23
20240406 172028 worker: RaspiOS: 11.9 Bullseye 64-bit
20240406 172028 worker: Kernel: 6.1.21 64-bit
20240406 172028 worker: MPD ver: 0.23.14
20240406 172028 worker: CPU gov: ondemand
20240406 172028 worker: Userid: kennedy
20240406 172028 worker: Homedir: /home/kennedy
20240406 172028 worker: Timezone: Europe/Stockholm
20240406 172028 worker: Keyboard: se
20240406 172028 worker: USB boot: not enabled yet
20240406 172028 worker: File sys: expanded
20240406 172028 worker: HDMI out: on
20240406 172028 worker: Sys LED0: on
20240406 172028 worker: Sys LED1: on
20240406 172028 worker: --
20240406 172028 worker: -- Network
20240406 172028 worker: --
20240406 172028 worker: Eth: adapter exists
20240406 172028 worker: Eth: timeout off
20240406 172028 worker: Eth: address not assigned
20240406 172029 worker: Wlan: adapter exists
20240406 172029 worker: Wlan: country SE
20240406 172029 worker: Wlan: SSID Jakobs phone
20240406 172029 worker: Wlan: other ONTHEAIR
20240406 172029 worker: Wlan: router off
20240406 172029 worker: Wlan: timeout up to 30 secs
20240406 172100 worker: Wlan: address not assigned
20240406 172100 worker: Wlan: AP mode activating
20240406 172133 worker: Wlan: timeout up to 30 secs
20240406 172137 worker: Wlan: AP mode activated using SSID KennedyBluetooth
20240406 172137 worker: Wlan: sleep disabled
20240406 172137 worker: Wlan: method dhcp
20240406 172137 worker: Wlan: address 172.24.1.1
20240406 172137 worker: Wlan: netmask 255.255.255.0
20240406 172137 worker: Wlan: gateway 0.0.0.0
20240406 172137 worker: Wlan: pri DNS 127.0.0.1
20240406 172137 worker: Wlan: domain
20240406 172137 worker: --
20240406 172137 worker: -- Software update
20240406 172137 worker: --
20240406 172137 worker: Automatic check off
20240406 172137 worker: --
20240406 172137 worker: -- File sharing
20240406 172137 worker: --
20240406 172137 worker: SMB file sharing: off
20240406 172137 worker: NFS file sharing: off
20240406 172137 worker: DLNA file sharing: off
20240406 172137 worker: --
20240406 172137 worker: -- Audio config
20240406 172137 worker: --
20240406 172137 worker: MPD config: update skipped (USB audio device)
20240406 172137 worker: Audio device: USB Audio Device
20240406 172138 worker: Formats: S16_LE
20240406 172138 worker: Mixer type Software
20240406 172138 worker: Mixer name Speaker
20240406 172138 worker: Hdwr volume: controller detected
20240406 172138 worker: ALSA max vol: 100%
20240406 172138 worker: ALSA card: 2
20240406 172138 worker: ALSA mode: Default
20240406 172138 worker: ALSA loopback: off
20240406 172138 worker: CamillaDSP: off
20240406 172138 worker: Renderers: active flags reset
20240406 172138 worker: --
20240406 172138 worker: -- MPD startup
20240406 172138 worker: --
20240406 172139 worker: MPD service: started
20240406 172139 worker: MPD port 6600: accepting connections
20240406 172139 worker: MPD ALSA Default: on
20240406 172139 worker: MPD ALSA Bluetooth: off
20240406 172139 worker: MPD HTTP Server: off
20240406 172139 worker: MPD crossfade: off
20240406 172139 worker: MPD ignore CUE: no
20240406 172139 worker: MPD CDSP volsync: off
20240406 172139 worker: MPD CDSP volrange: 60 dB
20240406 172139 worker: --
20240406 172139 worker: -- Music sources
20240406 172139 worker: --
20240406 172139 worker: USB auto-mount: udisks-glue
20240406 172139 worker: USB drives: no drives found
20240406 172139 worker: NAS sources: no music sources defined
20240406 172139 worker: --
20240406 172139 worker: -- Feature availability
20240406 172139 worker: --
20240406 172139 worker: Input select: available, src MPD, out USB Audio Device
20240406 172140 worker: Bluetooth: started, Pairing Agent started, ALSA mode Default
20240406 172140 worker: AirPlay: available
20240406 172140 worker: Spotify Connect: started
20240406 172140 worker: Squeezelite: available
20240406 172140 worker: RoonBridge: not installed
20240406 172140 worker: Multiroom: available
20240406 172140 worker: UPnP client: available
20240406 172140 worker: GPIO buttons: available
20240406 172140 worker: HTTPS mode: available
20240406 172140 worker: Stream recorder: n/a
20240406 172140 worker: --
20240406 172140 worker: -- Volume levels
20240406 172140 worker: --
20240406 172140 worker: Volume knob: 0
20240406 172140 worker: Saved MPD vol: -1
20240406 172140 worker: Saved SRC vol: 0
20240406 172140 worker: Mixer type: software
20240406 172140 worker: Hdwr volume: 100%
20240406 172140 worker: CDSP volume: 0.0dB
20240406 172140 worker: --
20240406 172140 worker: -- Peripherals
20240406 172140 worker: --
20240406 172141 worker: Local display: off
20240406 172141 worker: On-screen kbd: off
20240406 172141 worker: Rotary encoder: off
20240406 172141 worker: USB volume knob: off
20240406 172141 worker: LCD updater: off
20240406 172141 worker: --
20240406 172141 worker: -- Miscellaneous
20240406 172141 worker: --
20240406 172141 worker: Auto-CoverView: off
20240406 172141 worker: CoverView timeout: Never
20240406 172141 worker: Auto-shuffle: off
20240406 172141 worker: Auto-play: off
20240406 172141 worker: Web SSH server: on
20240406 172141 worker: Maintenance task: 360 mins
20240406 172141 worker: Current view: reset to Playback
20240406 172141 worker: Session check: ok
20240406 172141 worker: --
20240406 172141 worker: -- Startup complete
20240406 172141 worker: --
20240406 172141 worker: Mount monitor: off
20240406 172141 worker: Radio monitor: off
20240406 172142 worker: Watchdog monitor: started
20240406 172142 worker: Responsiveness: Default
20240406 172142 worker: Ready
Thanks!
/J
RE: Bluetooth connection/paring stopped working - moOde 8.3.9 - jakste - 04-07-2024
I had some time to test a bit more and tried to catcth some logs. I've not been able to reproduce the exact same scenario as described above (yet).
One thing I did notice is that:
if a phone unpairs from moOde it can't pair back again until it's manually deleted from the BT trust list. Is this the intended behaviour?
This will cause an issue since the moOde UI is not accessible for anyone in this training facility.
I'm not familiar with this application so I'm not sure if any of the logging helps.
DCERPC_NCA_S_OP_RNG_ERROR - Machine is not connected to Internet, seems maybe related?
Code: Apr 7 11:59:46 moode winbindd[516]: [2024/04/07 11:59:46.782060, 0] ../../source3/rpc_server/rpc_ncacn_np.c:454(rpcint_dispatch)
Apr 7 11:59:46 moode winbindd[516]: rpcint_dispatch: DCE/RPC fault in call lsarpc:32 - DCERPC_NCA_S_OP_RNG_ERROR
Apr 7 11:59:46 moode winbindd[516]: [2024/04/07 11:59:46.783622, 0] ../../source3/rpc_server/rpc_ncacn_np.c:454(rpcint_dispatch)
Apr 7 11:59:46 moode winbindd[516]: rpcint_dispatch: DCE/RPC fault in call lsarpc:32 - DCERPC_NCA_S_OP_RNG_ERROR
Apr 7 12:00:03 moode systemd[1]: Starting system activity accounting tool...
Apr 7 12:00:03 moode systemd[1]: sysstat-collect.service: Succeeded.
Apr 7 12:00:03 moode systemd[1]: Finished system activity accounting tool.
Apr 7 12:04:46 moode winbindd[516]: [2024/04/07 12:04:46.787448, 0] ../../source3/rpc_server/rpc_ncacn_np.c:454(rpcint_dispatch)
Apr 7 12:04:46 moode winbindd[516]: rpcint_dispatch: DCE/RPC fault in call lsarpc:32 - DCERPC_NCA_S_OP_RNG_ERROR
Apr 7 12:04:46 moode winbindd[516]: [2024/04/07 12:04:46.788879, 0] ../../source3/rpc_server/rpc_ncacn_np.c:454(rpcint_dispatch)
Apr 7 12:04:46 moode winbindd[516]: rpcint_dispatch: DCE/RPC fault in call lsarpc:32 - DCERPC_NCA_S_OP_RNG_ERROR
Apr 7 12:09:46 moode winbindd[516]: [2024/04/07 12:09:46.791393, 0] ../../source3/rpc_server/rpc_ncacn_np.c:454(rpcint_dispatch)
Apr 7 12:09:46 moode winbindd[516]: rpcint_dispatch: DCE/RPC fault in call lsarpc:32 - DCERPC_NCA_S_OP_RNG_ERROR
Apr 7 12:09:46 moode winbindd[516]: [2024/04/07 12:09:46.793202, 0] ../../source3/rpc_server/rpc_ncacn_np.c:454(rpcint_dispatch)
Apr 7 12:09:46 moode winbindd[516]: rpcint_dispatch: DCE/RPC fault in call lsarpc:32 - DCERPC_NCA_S_OP_RNG_ERROR
Apr 7 12:10:03 moode systemd[1]: Starting system activity accounting tool...
Apr 7 12:10:03 moode systemd[1]: sysstat-collect.service: Succeeded.
Apr 7 12:10:03 moode systemd[1]: Finished system activity accounting tool.
Apr 7 12:14:46 moode winbindd[516]: [2024/04/07 12:14:46.795272, 0] ../../source3/rpc_server/rpc_ncacn_np.c:454(rpcint_dispatch)
Apr 7 12:14:47 moode winbindd[516]: rpcint_dispatch: DCE/RPC fault in call lsarpc:32 - DCERPC_NCA_S_OP_RNG_ERROR
Apr 7 12:14:47 moode winbindd[516]: [2024/04/07 12:14:46.796712, 0] ../../source3/rpc_server/rpc_ncacn_np.c:454(rpcint_dispatch)
Apr 7 12:14:47 moode winbindd[516]: rpcint_dispatch: DCE/RPC fault in call lsarpc:32 - DCERPC_NCA_S_OP_RNG_ERROR
Apr 7 12:19:43 moode rngd[448]: stats: bits received from HRNG source: 620064
Apr 7 12:19:43 moode rngd[448]: stats: bits sent to kernel pool: 570240
Apr 7 12:19:43 moode rngd[448]: stats: entropy added to kernel pool: 570240
Apr 7 12:19:43 moode rngd[448]: stats: FIPS 140-2 successes: 31
Apr 7 12:19:43 moode rngd[448]: stats: FIPS 140-2 failures: 0
Apr 7 12:19:43 moode rngd[448]: stats: FIPS 140-2(2001-10-10) Monobit: 0
Apr 7 12:19:43 moode rngd[448]: stats: FIPS 140-2(2001-10-10) Poker: 0
Apr 7 12:19:43 moode rngd[448]: stats: FIPS 140-2(2001-10-10) Runs: 0
Apr 7 12:19:43 moode rngd[448]: stats: FIPS 140-2(2001-10-10) Long run: 0
Apr 7 12:19:43 moode rngd[448]: stats: FIPS 140-2(2001-10-10) Continuous run: 0
Apr 7 12:19:43 moode rngd[448]: stats: HRNG source speed: (min=300.740; avg=819.994; max=925.696)Kibits/s
Apr 7 12:19:43 moode rngd[448]: stats: FIPS tests speed: (min=22.952; avg=40.457; max=51.550)Mibits/s
Apr 7 12:19:43 moode rngd[448]: stats: Lowest ready-buffers level: 2
Apr 7 12:19:43 moode rngd[448]: stats: Entropy starvations: 0
Apr 7 12:19:43 moode rngd[448]: stats: Time spent starving for entropy: (min=0; avg=0.000; max=0)us
Apr 7 12:19:46 moode winbindd[516]: [2024/04/07 12:19:46.799776, 0] ../../source3/rpc_server/rpc_ncacn_np.c:454(rpcint_dispatch)
Apr 7 12:19:46 moode winbindd[516]: rpcint_dispatch: DCE/RPC fault in call lsarpc:32 - DCERPC_NCA_S_OP_RNG_ERROR
Apr 7 12:19:46 moode winbindd[516]: [2024/04/07 12:19:46.801214, 0] ../../source3/rpc_server/rpc_ncacn_np.c:454(rpcint_dispatch)
Apr 7 12:19:46 moode winbindd[516]: rpcint_dispatch: DCE/RPC fault in call lsarpc:32 - DCERPC_NCA_S_OP_RNG_ERROR
Apr 7 12:20:03 moode systemd[1]: Starting system activity accounting tool...
Please remove executable permission bits. Unknown vendor codec.
Code: Apr 7 17:08:26 moode bluealsa[479]: bluealsa: [479] D: bluez.c:1304: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
Apr 7 17:08:26 moode bluealsa[479]: bluealsa: [479] D: bluez.c:1304: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
Apr 7 17:08:26 moode bluealsa[479]: bluealsa: [479] D: bluez.c:1304: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
Apr 7 17:08:26 moode systemd[1]: Configuration file /etc/systemd/system/bluealsa-aplay@.service is marked executable. Please remove executable permission bits. Proceed
ing anyway.
Apr 7 17:08:26 moode systemd[1]: Configuration file /etc/systemd/system/bluealsa-aplay@.service is marked executable. Please remove executable permission bits. Proceed
ing anyway.
Apr 7 17:08:26 moode systemd[1]: Configuration file /etc/systemd/system/bluealsa-aplay@.service is marked executable. Please remove executable permission bits. Proceed
ing anyway.
Apr 7 17:08:29 moode bluealsa[479]: bluealsa: [479] D: bluez.c:1193: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Apr 7 17:08:29 moode bluealsa[479]: bluealsa: [479] D: bluez.c:1289: Adding new Stream End-Point: D4:3A:2C:A4:4A:96: SBC
Apr 7 17:08:29 moode bluealsa[479]: bluealsa: [479] D: bluez.c:1193: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Apr 7 17:08:29 moode bluealsa[479]: bluealsa: [479] D: bluez.c:1289: Adding new Stream End-Point: D4:3A:2C:A4:4A:96: AAC
Apr 7 17:08:29 moode bluealsa[479]: bluealsa: [479] D: bluez.c:1193: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Apr 7 17:08:29 moode bluealsa[479]: bluealsa: [479] D: bluez.c:1289: Adding new Stream End-Point: D4:3A:2C:A4:4A:96: aptX
Apr 7 17:08:29 moode bluealsa[479]: bluealsa: [479] D: bluez.c:1193: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Apr 7 17:08:29 moode bluealsa[479]: bluealsa: [479] D: bluez.c:1289: Adding new Stream End-Point: D4:3A:2C:A4:4A:96: LDAC
Apr 7 17:08:29 moode bluealsa[479]: bluealsa: [479] D: bluez.c:1193: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Apr 7 17:08:29 moode bluealsa[479]: bluealsa: [479] D: a2dp.c:289: Unknown vendor codec [len=7]: e0000000010092
Apr 7 17:08:29 moode bluealsa[479]: bluealsa: [479] D: bluez.c:1289: Adding new Stream End-Point: D4:3A:2C:A4:4A:96: (null)
Apr 7 17:08:29 moode bluealsa[479]: bluealsa: [479] D: bluez.c:1193: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Apr 7 17:08:29 moode blueaq
Couldn't open ALSA mixer: Mixer element not found
Code: Apr 7 17:08:38 moode bluealsa[479]: bluealsa: [479] D: ba-transport.c:448: Created BT socket duplicate: [15]: 18
Apr 7 17:08:38 moode bluealsa[479]: bluealsa: [25266] D: a2dp-aptx-hd.c:278: IO loop: START: a2dp_aptx_hd_dec_thread: A2DP Sink (aptX HD)
Apr 7 17:08:38 moode bluealsa[479]: bluealsa: [479] D: ba-transport.c:1949: Created new IO thread [ba-a2dp-aptx-hd]: A2DP Sink (aptX HD)
Apr 7 17:08:38 moode bluealsa-aplay[25231]: bluealsa-aplay: [25233] D: aplay.c:649: Opening ALSA playback PCM: name=_audioout channels=2 rate=48000
Apr 7 17:08:38 moode bluealsa-aplay[25231]: bluealsa-aplay: [25233] D: aplay.c:664: Opening ALSA mixer: name=default elem=Master index=0
Apr 7 17:08:38 moode bluealsa-aplay[25231]: bluealsa-aplay: [25233] W: aplay.c:668: Couldn't open ALSA mixer: Mixer element not found
Apr 7 17:09:04 moode winbindd[539]: [2024/04/07 17:09:04.603930, 0] ../../source3/rpc_server/rpc_ncacn_np.c:454(rpcint_dispatch)
Apr 7 17:09:04 moode winbindd[539]: rpcint_dispatch: DCE/RPC fault in call lsarpc:32 - DCERPC_NCA_S_OP_RNG_ERROR
Apr 7 17:09:04 moode winbindd[539]: [2024/04/07 17:09:04.605560, 0] ../../source3/rpc_server/rpc_ncacn_np.c:454(rpcint_dispatch)
Apr 7 17:09:04 moode winbindd[539]: rpcint_dispatch: DCE/RPC fault in call lsarpc:32 - DCERPC_NCA_S_OP_RNG_ERROR
Apr 7 17:10:03 moode systemd[1]: Starting system activity accounting tool...
Apr 7 17:10:03 moode systemd[1]: sysstat-collect.service: Succeeded.
Apr 7 17:10:03 moode systemd[1]: Finished system activity accounting tool.
/th-cmd --socket /var/run/thd.socket --passfd --udev' failed
Code: Apr 7 16:48:03 moode systemd[1]: Started Music Player Daemon.
Apr 7 16:48:03 moode systemd[1]: Configuration file /etc/systemd/system/bluealsa-aplay@.service is marked executable. Please remove executable permission bits. Proceed
ing anyway.
Apr 7 16:48:03 moode systemd[1]: Started Bluealsa-aplay.
Apr 7 16:48:03 moode bluealsa-aplay[22260]: bluealsa-aplay: [22260] D: aplay.c:1181: Starting main loop
Apr 7 16:48:03 moode systemd-udevd[22241]: event1: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
Apr 7 16:48:03 moode bluealsa[479]: bluealsa: [479] D: bluez.c:1193: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Apr 7 16:48:03 moode bluealsa[479]: bluealsa: [479] D: dbus.c:47: Called: org.bluez.MediaEndpoint1.SetConfiguration() on /org/bluez/hci0/A2DP/SBC/sink/1
Apr 7 16:48:03 moode bluealsa[479]: bluealsa: [479] D: a2dp.c:383: Selected A2DP SBC bit-pool range: [2, 53]
Apr 7 16:48:03 moode bluealsa[479]: bluealsa: [479] D: storage.c:117: Loading storage: /var/lib/bluealsa/B8:7B:C5:AE:FD:08
Apr 7 16:48:03 moode bluealsa[479]: bluealsa: [479] D: bluez.c:412: A2DP Sink (SBC) configured for device B8:7B:C5:AE:FD:08
Apr 7 16:48:03 moode bluealsa[479]: bluealsa: [479] D: bluez.c:415: A2DP selected configuration blob [len=4]: 21150235
Apr 7 16:48:03 moode bluealsa[479]: bluealsa: [479] D: bluez.c:417: PCM configuration: channels: 2, sampling: 44100
Apr 7 16:48:03 moode bluealsa[479]: bluealsa: [479] D: bluez.c:590: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/sink/3
Apr 7 16:48:03 moode bluealsa[479]: bluealsa: [479] D: bluez.c:501: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/sink/3
Apr 7 16:48:03 moode bluealsa-aplay[22260]: bluealsa-aplay: [22260] D: aplay.c:831: Creating IO worker B8:7B:C5:AE:FD:08
Apr 7 16:48:03 moode bluealsa-aplay[22260]: bluealsa-aplay: [22266] D: aplay.c:499: Opening BlueALSA source PCM: /org/bluealsa/hci0/dev_B8_7B_C5_AE_FD_08/a2dpsnk/sourc
e
RE: Bluetooth connection/paring stopped working - moOde 8.3.9 - Tim Curtis - 04-08-2024
Did you leave the pairing agent on?
RE: Bluetooth connection/paring stopped working - moOde 8.3.9 - jakste - 04-08-2024
Yes, I did leave the agent on.
But, in the end I could not acheive what i wanted with Moode Player so I moved to another solution.
I followed this guide: https://forums.raspberrypi.com/viewtopic.php?t=235519 to create a "BT Speaker" from my Raspberry.
I can now, if I want, use a PIN code for the paring. And after the addition below I can also repair a device without the need to manually delete it first.
Code: sudo nano /etc/bluetooth/main.conf
# Add the following to enable repairing
# Specify the policy to the JUST-WORKS repairing initiated by peer
# Possible values: "never", "confirm", "always"
# Defaults to "never"
JustWorksRepairing = always
I really liked the Moode player, and maybe I will move back some day if the Bluetooth capabilites have been improved/updated a bit.
Thanks for all you great work!
|