firmware-brcm80211 +rpt3 breaks bluetooth on RPi4 for some devices

[DataGhost]

I'm trying to get my phone (Samsung Galaxy S9) to stream a2dp to my RPi4 and ran into some trouble the past couple of days, where my phone wouldn't keep the connection to the RPi. At first I thought it was because of some things I changed and I backtracked and tried so incredibly many things that didn't solve it... :( but luckily someone managed to find the problem and I verified it.

I made a clean testing setup with the 2019-09-26-raspbian-buster-lite.img as a base, I installed bluealsa, let that run with -p a2dp-sink, configured the bluetoothd service to run with --debug=*, set up an agent to authorize ADVANCED_AUDIO_UUID and then paired my S9 to the RPi4. For this example, I'm not even running bluealsa-aplay or listening to any sound, just looking at the syslog. Everything works fine. However, doing a dist-upgrade bumps firmware-brcm80211 to +rpt3 and this is where things start going wrong. I can still pair and connect my S9, and start playing music. I can play/pause from my phone and from the RPi using dbus calls. But when the connection goes idle, it dies within a couple of seconds. When I send dbus calls to pause every second, the first one pauses the stream and causes the media transport to be closed. Subsequent calls show a few press and release event pairs, until the release events stop showing and I only get request timeouts. The same thing happens when I just wait long enough, the pause every second was just to see that it doesn't break immediately but rather after 3-10 seconds. Syslog for bluetoothd shows:

...
12:16:09: profiles/audio/player.c:media_player_set_status() paused
12:16:10: profiles/audio/avctp.c:avctp_passthrough_press() PAUSE
12:16:10: profiles/audio/avctp.c:avctp_passthrough_release() PAUSE
12:16:11: profiles/audio/avctp.c:avctp_passthrough_press() PAUSE
12:16:11: profiles/audio/avctp.c:avctp_passthrough_release() PAUSE
12:16:12: profiles/audio/avctp.c:avctp_passthrough_press() PAUSE
12:16:14: profiles/audio/avctp.c:avctp_passthrough_press() PAUSE
12:16:15: profiles/audio/avctp.c:req_timeout() transaction 13 retry false

When this happens, the connection doesn't respond at all anymore. If I press play on my phone, it'll start playing, but when I pause it, the track position jumps back to where it was before I pressed play. After 30 seconds, the connection will drop (reason 1 = timeout) and it'll reconnect. If no audio is sent from my phone within a few seconds after connecting, it dies again. I made some dumps with wireshark on the RPi and got a similar log from my phone. They're both HCI logs though, so I can only see the high-level stuff that actually worked. The only notable difference is that the press-packets appear in the RPi log as sent packets, but don't show up in the log from my phone. But I guess they're just not sent for whatever reason. In both the HCI logs, I see an HCI_EVT for a disconnect complete because of a timeout, about 20 seconds after the last successfully sent pause, less than 300ms(!) apart on both devices so at least they seem to be in agreement about something, but it doesn't look like any packet went over the line for that.

My S9 has zero issues with other devices. Also, I tried streaming to my RPi4 from my Windows 10 PC and from an iPhone, and those both worked without any issues. I can pause the stream for several minutes without any disconnects, and then resume it from either end. The syslog looks identical when pausing/resuming. I didn't see any obvious differences in the HCI logs either, but there are so many packets that I could have easily missed something. I put the SD-card in my RPi3B and could stream without any issues from my S9. So it seems to be some specific devices that don't work well with this new driver on the RPi4.

I have seen two threads on the forums where people have trouble with their BT keyboards and someone traced it to this package, after which I tested and confirmed that package to be the problem. The symptoms in those threads are very similar to what I'm experiencing, so I'm going to assume it's the same issue.
https://www.raspberrypi.org/forums/viewtopic.php?f=28&t=255207
https://www.raspberrypi.org/forums/viewtopic.php?f=66&t=254523

I did apt-mark hold firmware-brcm80211 before doing a dist-upgrade from the clean and working test setup, and after running said upgrade everything was still working. I did an unhold, dist-upgrade and I got the broken behaviour again. Restoring brcmfmac43455* from the 2019-09-26 buster image to /lib/firmware/brcm/ fixes the problem. I see no difference in dmesg | grep -iE "brcm|blue" other than the firmware version string. Unfortunately, that's where my debugging skills stop, I have little knowledge of bluetooth and the firmware is a binary blob so I can't make it any more specific than this.

I'd love to provide specific logs, wireshark dumps, etc and run specific tests if they are deemed useful and in case you don't have any device that exhibits this behaviour. I didn't attach any of mine because I see little relevance in them for now (and no relevant/obvious differences that point to a culprit).

[pelwell]

@carpa5, here's the preferred thread for tracking raspberrypi/linux#3313.

[pelwell]

@XECDesign What's the best, Debian-compliant way to revert this?

[XECDesign]

Revert the last few commits and bump the version number in the chsngelog. I'll do it in a bit.

[XECDesign]

The updated package should be public within an hour.

[DataGhost]

Best thing, of course, would be to get the bug gone from the new firmware, but I'm going to guess that won't be an easy thing to (make the company responsible) do?

[XECDesign]

I don't know. The best we can do is notify them of the issue and see what happens.