Thank you for your donation!


Solved: Bluetooth breaks autoplay on start
#1
Hi,

I intend to run the Moode player I'm just setting up in the car, to replace an old volumio installation. I have a pijuice HAT installed, so when the (ignition) power goes down the pi shuts down - when the power comes back, the pi restarts. I want the music to resume at that point, so I set "autoplay on start". It works, and it takes about 37 seconds from power on to music resume - not fantastic, but not bad either.

(As a side note - this feature doesn't actually begin to play where it left off, rather it plays the last song from the start. Not a bad feature in case I really love the song and would hate to miss a part of it, but still a bit unexpected. Is there an option that would change this to resume precisely on point?)

Now, the real problem comes in when I enable Bluetooth support. As I have mentioned before, my pi is a 2B and requires a dongle, my dongle shows as "ID 0a5c:21e8 Broadcom Corp. BCM20702A0 Bluetooth 4.0". It works, too - I can connect from my phone and play music, no problem. However, on startup it adds more than a full minute to the process. For instance:


Code:
20190109 163513 worker: Bluetooth controller started
20190109 163708 worker: Bluetooth controller initialized


The startup process blocks everything else at this point (between the two log lines above), which happens even before my USB stick is recognized for the music. And most importantly: when Bluetooth startup is finally done, the autoplay feature doesn't work! The playlist state is shown correctly if I go to the web frontend, but I have to hit Play manually to get it to do anything. 

It seems clear that the Bluetooth feature is at fault here. I don't know why the startup process takes so long, perhaps that's a sign of something bad happening? But since the system seems to wait for the process to complete, why shouldn't autoplay work anyway? Any ideas?

Thanks
Oli
Reply
#2
Your symptom(s) suggests something external to moOde software.

Below is moOde log output for powering up a Pi-3A+. The moOde portion of system start up took 13 secs. Bluetooth controller initialization took 7 secs. No issues with auto-play. Results are similar for Pi-3B+, etc.

Code:
pi@rp3:~ $ moodeutl -l
20190109 121020 worker: - Start
20190109 121021 worker: Successfully daemonized
20190109 121021 worker: Integrity check (passed)
20190109 121021 worker: ALSA volume (0%)
20190109 121021 worker: Session loaded
20190109 121021 worker: Debug logging (off)
20190109 121021 worker: - Platform
20190109 121023 worker: Rel  (Moode 4.5 2019-MM-DD)
20190109 121023 worker: Upd  (None)
20190109 121023 worker: Rasp (9.6)
20190109 121023 worker: Kern (4.14.90-v7+)
20190109 121023 worker: MPD  (0.21.4)
20190109 121023 worker: Host (rp3)
20190109 121023 worker: Hdwr (Pi-3A+ 512 MB v1.0)
20190109 121023 worker: Arch (armv7l)
20190109 121023 worker: Gov  (ondemand)
20190109 121023 worker: USB boot enabled
20190109 121023 worker: File system expanded
20190109 121023 worker: HDMI port off
20190109 121023 worker: File check ok
20190109 121023 worker: - Network
20190109 121023 worker: eth0 does not exist
20190109 121023 worker: eth0 address not assigned
20190109 121023 worker: wlan0 exists
20190109 121023 worker: wifi country (US)
20190109 121023 worker: wlan0 trying SSID (AirnetN5)
20190109 121023 worker: wlan0 (192.168.1.177)
20190109 121023 worker: - Audio
20190109 121023 worker: ALSA outputs unmuted
20190109 121023 worker: ALSA card number (0)
20190109 121023 worker: Audio out (I2S audio device)
20190109 121023 worker: Audio dev (Allo Katana DAC)
20190109 121023 worker: ALSA mixer name (Master)
20190109 121023 worker: MPD volume control (hardware)
20190109 121023 worker: Hdwr volume controller exists
20190109 121023 worker: - Services
20190109 121023 worker: Reset renderer active
20190109 121026 worker: MPD started
20190109 121026 worker: MPD scheduler policy (time-share)
20190109 121026 worker: Configure MPD outputs
20190109 121026 worker: MPD output 1 ALSA default (on)
20190109 121026 worker: MPD output 2 ALSA crossfeed (off)
20190109 121026 worker: MPD output 3 ALSA parametric eq (off)
20190109 121026 worker: MPD output 4 ALSA graphic eq (off)
20190109 121026 worker: MPD output 5 ALSA bluetooth (off)
20190109 121026 worker: MPD crossfade (off)
20190109 121026 worker: Airplay receiver started
20190109 121026 worker: Spotify receiver started
20190109 121026 worker: Rotary encoder on (100 2 3 4 5)
20190109 121026 worker: Shellinabox SSH started
20190109 121026 worker: Bluetooth controller started
20190109 121033 worker: Bluetooth controller initialized
20190109 121033 worker: - Music sources
20190109 121033 worker: USB sources (none attached)
20190109 121033 worker: NAS sources (mountall initiated)
20190109 121033 worker: - Miscellaneous
20190109 121033 worker: Volume level (15) restored
20190109 121033 worker: ALSA output (closed)
20190109 121033 worker: Auto-playing id (41)
20190109 121033 worker: Maintenance interval (21600)
20190109 121033 worker: Screen saver activation (Never)
20190109 121033 worker: Watchdog started
20190109 121033 worker: Ready
Reply
#3
Okay, I have solved the problem. Perhaps some of this can be useful to others, so I'll describe what I did.

First, I found in /var/log/syslog that the firmware for my dongle wasn't found correctly:
Code:
Jan  9 16:42:14 moode kernel: [    5.847526] bluetooth hci0: Direct firmware load for brcm/BCM20702A1-0a5c-21e8.hcd failed with error -2
Jan  9 16:42:14 moode kernel: [    5.847557] Bluetooth: hci0: BCM: Patch brcm/BCM20702A1-0a5c-21e8.hcd not found

I built the firmware files using https://github.com/winterheart/broadcom-bt-firmware and downloads from http://www.catalog.update.microsoft.com/...+bluetooth, dropping the file  BCM20702A1-0a5c-21e8.hcd into the folder /lib/firmware/brcm. Now the messages didn't come up anymore at boot. However, nothing else changed - instead I found some new startup errors:

Code:
Jan 10 09:46:04 moode systemd[1]: dev-serial1.device: Job dev-serial1.device/start timed out.
Jan 10 09:46:04 moode systemd[1]: Timed out waiting for device dev-serial1.device.
Jan 10 09:46:04 moode systemd[1]: Dependency failed for Configure Bluetooth Modems connected by UART.
Jan 10 09:46:04 moode systemd[1]: hciuart.service: Job hciuart.service/start failed with result 'dependency'.
Jan 10 09:46:04 moode systemd[1]: dev-serial1.device: Job dev-serial1.device/start failed with result 'timeout'.


I found reference to similar issues here: https://github.com/hypriot/image-builder-rpi/issues/72

In the commit that was used to fix things for that project, I found that they changed the service file hciuart.service to work with /dev/ttyAMA0 instead of /dev/serial1. ttyAMA0 existed on the pi (in fact serial0 links to it), but serial1 didn't exist - so I decided to give this a try. I changed the combination of Requires/After in /lib/systemd/system/hciuart.service to this:

Code:
Before=bluetooth.service
After=dev-ttyAMA0.device

After a restart, everything works correctly now. The Bluetooth startup process takes no time at all - not a single second between the lines in the moodelog output:

Code:
20190110 102444 worker: Bluetooth controller started
20190110 102444 worker: Bluetooth controller initialized

Bluetooth works correctly, in fact it seems quite a bit faster to connect than before. And the autoplay on start feature now works like it does without Bluetooth.

Tim - I'm wondering if your 7 second initialization is still an indication of a problem. I wonder if other pis have /dev/serial1 for some reason? Where would it come from? Perhaps the hciuart service is simply misconfigured, but this results in different symptoms on different devices and so you haven't noticed previously.

Thanks
Oli
Reply
#4
Random thoughts-

moOde is built on Raspbian and inherits both the missing firmware and the misbehaving hciuart service from Raspbian. 

I suppose the missing firmware isn't more widely discussed in the RPi community because not many end-users read the system logs carefully. As you say, "It works, too - I can connect from my phone and play music, no problem." Similarly, I suppose the hciuart.service problem is muted because so many folks now use RPis with onboard Wireless/BT.

I had to reclaim my only RPi2B and external ASUS BT400 USB-BT adapter to try to retrace your steps. I can repro the missing firmware messages (BCM0702A1-0b05-17cb.hcd in my case) and the "it works, too" observation.

Let's go to the Raspbian docs, such that they are 
https://www.raspberrypi.org/documentatio...on/uart.md

Quote:The Raspberry Pi UARTs

The SoCs used on the Raspberry Pis have two built-in UARTs, a PL011 and a mini UART. <some lines deleted>

By default, on Raspberry Pis equipped with the wireless/Bluetooth module (Raspberry Pi 3 and Raspberry Pi Zero W), the PL011 UART is connected to the Bluetooth module, while the mini UART is used as the primary UART and will have a Linux console on it. On all other models, the PL011 is used as the primary UART.

In Linux device terms, by default, /dev/ttyS0 refers to the mini UART, and /dev/ttyAMA0 refers to the PL011. The primary UART is the one assigned to the Linux console, which depends on the Raspberry Pi model as described above. There are also symlinks: /dev/serial0, which always refers to the primary UART (if enabled), and /dev/serial1, which similarly always refers to the secondary UART (if enabled).

It would seem that dealing with the possible combinations of onboard/offboard BT adapters and /dev/serial0 and /dev/serial1 is a complication the Raspbian devs didn't consider in the hciuart.service file they provide. Hardwiring it to /dev/ttyAMA0 might be sufficient but I haven't tried the experiment in the cases of an RPi3B/RPi3B+ with external BT adapter (as one might do if the moOde Player is buried in a cabinet) and onboard BT module enabled/disabled. 

Regards,
Kent
Reply
#5
Based on the description, it seems to me that /dev/ttyAMA0 should always be available if Bluetooth is installed, whether it's separate or not. The current setup assumes /dev/serial1, which is only there in some cases. The main scenario that doesn't seem to be covered when using /dev/ttyAMA0 as a dependency is that where no Bluetooth hardware is available at all - in that case the boot process is slowed down drastically because it waits for the timeout.

Oli
Reply
#6
(01-11-2019, 09:52 AM)olisturm Wrote: Based on the description, it seems to me that /dev/ttyAMA0 should always be available if Bluetooth is installed, whether it's separate or not. The current setup assumes /dev/serial1, which is only there in some cases. The main scenario that doesn't seem to be covered when using /dev/ttyAMA0 as a dependency is that where no Bluetooth hardware is available at all - in that case the boot process is slowed down drastically because it waits for the timeout.

Oli

Hi, Oli.

I don't disagree. I was just trying to think of all possibilities.

Regards,
Kent
Reply


Forum Jump: