Bluetooth no longer working after fresh install

psyke83

@charleszimm said in Bluetooth no longer working after fresh install:

@psyke83 Oh yeah good point. It was more of a laziness thing on my part I won't lie. :-)
pi@theaterretropie:~/RetroPie-Setup $ git remote -v
origin	https://github.com/RetroPie/RetroPie-Setup.git (fetch)
origin	https://github.com/RetroPie/RetroPie-Setup.git (push)

Really bizarre. The only possibility I can think of is that you somehow have a shallow copy of the repository, so it doesn't include the history of commits up to what we need.

Make sure you're on the master branch, then try to force the whole history to be downloaded:

git checkout master
git pull --unshallow

You can see what the oldest commit is via git log --reverse - in my case, it shows the very first commit to the repository from 2012.

psyke83

Ah yes that makes complete sense! Our instructions will have you clone a shallow copy (--depth=1): https://github.com/RetroPie/RetroPie-Setup/blob/master/README.md

Forcing an unshallow will fix the issue.

charleszimm

@psyke83 Hey that worked!

HEAD is now at 179e2f37... Merge pull request #2591 from cmitu/dolphin-build

When I go into the Setup script, the last commit is now listed as three weeks ago along with the HEAD number. I cleaned out the entire registered Bluetooth device list in bluetoothctl. Let me do some testing and get back to you.

charleszimm

@charleszimm Hung at the Searching... loop. That's what we expected to see, right?

psyke83

@charleszimm said in Bluetooth no longer working after fresh install:

@charleszimm Hung at the Searching... loop. That's what we expected to see, right?

Maybe, yes. To bypass that, make sure to remove any devices that are causing the Connected: yes/no messages to loop in bluetoothctl before selecting the "Register" menu option.

It might be OK to run a bluetoothctl session in a separate shell if you want to monitor what's happening in the Bluetooth stack at the same time as you're running the script.

charleszimm

@psyke83 Okay I lied. It didn't hang but it takes about roughly 2 minutes before it completed searching. I left the Searching... screen up in the SSH session, went to grab a drink, came back, and the results were there.

I was able to connect the controller without problems in Switch mode through the setup script without any problems (which that was always how I had my SN30 Pro setup, even back when I was running Jessie). Restarted the Pi and was able to reconnect the controller without any problems.

So what has changed between the commits?

Bluetooth.service still gives some weird messages that don't leave me warm and fuzzy however.

pi@theaterretropie:~ $ systemctl status bluetooth.service
● bluetooth.service - Bluetooth service
   Loaded: loaded (/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2019-02-20 13:20:59 EST; 2min 38s ago
     Docs: man:bluetoothd(8)
 Main PID: 515 (bluetoothd)
   Status: "Running"
   CGroup: /system.slice/bluetooth.service
           └─515 /usr/lib/bluetooth/bluetoothd

Feb 20 13:20:59 theaterretropie bluetoothd[515]: Starting SDP server
Feb 20 13:20:59 theaterretropie bluetoothd[515]: Bluetooth management interface 1.14 initialized
Feb 20 13:20:59 theaterretropie bluetoothd[515]: Failed to obtain handles for "Service Changed" characteristic
Feb 20 13:20:59 theaterretropie bluetoothd[515]: setsockopt(L2CAP_OPTIONS): Invalid argument (22)
Feb 20 13:20:59 theaterretropie bluetoothd[515]: avrcp-controller: Protocol not supported (93)
Feb 20 13:20:59 theaterretropie bluetoothd[515]: setsockopt(L2CAP_OPTIONS): Invalid argument (22)
Feb 20 13:20:59 theaterretropie bluetoothd[515]: audio-avrcp-target: Protocol not supported (93)
Feb 20 13:20:59 theaterretropie bluetoothd[515]: Sap driver initialization failed.
Feb 20 13:20:59 theaterretropie bluetoothd[515]: sap-server: Operation not permitted (1)
Feb 20 13:21:01 theaterretropie bluetoothd[515]: Failed to set privacy: Rejected (0x0b)

psyke83

My daemon log shows similar (but not all of your) errors:

● bluetooth.service - Bluetooth service
   Loaded: loaded (/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled)
   Active: active (running) since Tue 2019-02-19 17:57:35 GMT; 24h ago
     Docs: man:bluetoothd(8)
 Main PID: 527 (bluetoothd)
   Status: "Running"
   CGroup: /system.slice/bluetooth.service
           └─527 /usr/lib/bluetooth/bluetoothd

Feb 19 17:57:35 retropie systemd[1]: Starting Bluetooth service...
Feb 19 17:57:35 retropie bluetoothd[527]: Bluetooth daemon 5.43
Feb 19 17:57:35 retropie systemd[1]: Started Bluetooth service.
Feb 19 17:57:35 retropie bluetoothd[527]: Starting SDP server
Feb 19 17:57:35 retropie bluetoothd[527]: Bluetooth management interface 1.14 initialized
Feb 19 17:57:35 retropie bluetoothd[527]: Failed to obtain handles for "Service Changed" characteristic
Feb 19 17:57:35 retropie bluetoothd[527]: Sap driver initialization failed.
Feb 19 17:57:35 retropie bluetoothd[527]: sap-server: Operation not permitted (1)
Feb 19 17:57:35 retropie bluetoothd[527]: Endpoint registered: sender=:1.5 path=/A2DP/SBC/Source/1
Feb 19 17:57:35 retropie bluetoothd[527]: Failed to set privacy: Rejected (0x0b)

Are you absolutely certain that you tested the latest master script, making sure to remove the device before registration?

Again, to return to master:

git checkout master

I can't really see how my changes would negatively affect the authentication phase, as I didn't change anything in that part of the script.

charleszimm

@psyke83 I'm positive. I looked through the commit log and I agree: It doesn't quite look like any of the changes that were made should really affect the handoff between the device and the service.

I removed the controller, checked back out to master, confirmed in the Setup script that we're at 5dff90ef, and tried to resync the controller through the Bluetooth menu. With the controller in the same mode (Switch) that worked on 179e2f37, I'm back to getting the message:

An error occurred connecting to the bluetooth device (Creating device failed: org.bluez.Error.AuthenicationFailed: Authentication Failed)

If I go into bluetoothctl, I get the familiar Yes/No:

[bluetooth]# connect 98:B6:E9:42:4B:35
Attempting to connect to 98:B6:E9:42:4B:35
[CHG] Device 98:B6:E9:42:4B:35 Connected: yes
[CHG] Device 98:B6:E9:42:4B:35 Connected: no

I'm not sure where you're located but I'm in the northeast of the US and we're getting pounded with snow so I'm going to start our digging out. Let me know if you want me try anything else today!

psyke83

@charleszimm

We can try to zero in on what may possibly cause the issue.
See this test change: https://github.com/RetroPie/RetroPie-Setup/compare/master...psyke83:bluez_test

This will break sixaxis pairing, but let's see if it helps in your case.

You can test by adding my repo as a remote and then check out the branch:

git remote add psyke https://github.com/psyke83/RetroPie-Setup.git
git fetch psyke
git checkout psyke/bluez_test

As far as I can tell, enabling and setting the default-agent takes effect for the active bluetoothctl session only, and should be unregistered as soon as the scanning has finished... so I'm skeptical as to whether this is the root of the issue.

I've also created another commit on a separate branch that will still set up the agent, but only removes the part that responds to authorization challenges: https://github.com/RetroPie/RetroPie-Setup/compare/master...psyke83:bluez_test2

To test this one (assuming you've already added the psyke remote):

git checkout psyke/bluez_test2

I'd appreciate if you could try both and let me know which ones work (or not), and we can move on from there.

I suspect that both will work, and might see the potential issue. If your device is actually producing an authorization prompt, the final "disconnect" command may be turning off your controller just before you reach the security type section. But, let's wait and see.

Good luck with the excavation and keep safe! :)

charleszimm

@psyke83 Okay I have survived clearing my driveway and have a whiskey in hand so let's continue.

I cleared out the devices from bluetoothctl and on the psyke/bluez_test build (854a114e), I get the bluez Authentication Failed message, along with the Connected Yes/No in bluetoothctl.

Moving on to bluez_test2 (f2d44077), same result. Authentication failed, Connected Yes/No in bluetoothctl.

psyke83

@charleszimm

I'm a bit stumped, then. I don't see any significant changes to explain why you're having this problem.

Am I missing something obvious?

git diff master 2c9fa79a1ae41c2988d21bd179c33ce515e29245 -- scriptmodules/supplementary/bluetooth.sh

The only behaviour difference is the method in which commands are redirected to the bluetoothctl shell (with a deliberate 1 second pause between lines), but I really don't see why that'd cause this issue, as it only affects the "Scanning" phase and not the subsequent authorization which is done via bluez-simple-agent.

You're certain that for each test you've followed the same procedure to remove/register, turned on the controller in the appropriate mode and selected the same security type? Was the successful pairing with the older version of the script a fluke or does it work reliably every time?

I'm not sure what else to suggest as the bluez_test branch has very little changed apart from the "slow echo" code which I don't think would change anything.

charleszimm

@psyke83 Positive same scenario. Here's the results from the git diff:

diff --git a/scriptmodules/supplementary/bluetooth.sh b/scriptmodules/supplementary/bluetooth.sh
index f0c0b3d5..3cdd4c49 100644
--- a/scriptmodules/supplementary/bluetooth.sh
+++ b/scriptmodules/supplementary/bluetooth.sh
@@ -46,37 +46,34 @@ function get_script_bluetooth() {
     echo "$name"
 }
 
-function _slowecho_bluetooth() {
-    local line
-
-    IFS=$'\n'
-    for line in $(echo -e "${1}"); do
-        echo -e "$line"
-        sleep 1
-    done
-    unset IFS
-}
-
 function bluez_cmd_bluetooth() {
     # create a named pipe & fd for input for bluetoothctl
     local fifo="$(mktemp -u)"
     mkfifo "$fifo"
     exec 3<>"$fifo"
     local line
-    while true; do
-        _slowecho_bluetooth "$1" >&3
-        # collect output for specified amount of time, then echo it
-        while read -r line; do
-            printf '%s\n' "$line"
-            # (slow) reply to any optional challenges
-            if [[ -n "$3" && "$line" =~ $3 ]]; then
-                _slowecho_bluetooth "$4" >&3
+    while read -r line; do
+        if [[ "$line" == *"[bluetooth]"* ]]; then
+            echo -e "$1" >&3
+            read -r line
+            if [[ -n "$2" ]]; then
+                # collect output for specified amount of time, then echo it
+                local buf
+                while read -r -t "$2" line; do
+                    buf+=("$line")
+                    # reply to any optional challenges
+                    if [[ -n "$4" && "$line" == *"$3"* ]]; then
+                        echo -e "$4" >&3
+                    fi
+                done
+                printf '%s\n' "${buf[@]}"
             fi
-        done
-        _slowecho_bluetooth "quit\n" >&3
-        break
+            sleep 1
+            echo -e "quit" >&3
+            break
+        fi
     # read from bluetoothctl buffered line by line
-    done < <(timeout "$2" stdbuf -oL bluetoothctl --agent=NoInputNoOutput <&3)
+    done < <(stdbuf -oL bluetoothctl <&3)
     exec 3>&-
 }
 
@@ -86,15 +83,16 @@ function list_available_bluetooth() {
     local info_text="\n\nSearching ..."
 
     # sixaxis: add USB pairing information
-    [[ -n "$(lsmod | grep hid_sony)" ]] && info_text="Searching ...\n\nDualShock registration: while this text is visible, unplug and replug the controller, then press the PS/SHARE button."
+    [[ -n "$(lsmod | grep hid_sony)" ]] && info_text="Searching ...\n\n(To register a DualShock controller, please unplug and replug your controller while this text is visible...)"
 
     dialog --backtitle "$__backtitle" --infobox "$info_text" 7 60 >/dev/tty
     if hasPackage bluez 5; then
         # sixaxis: reply to authorization challenge on USB cable connect
+        [[ -n "$(lsmod | grep hid_sony)" ]] && bluez_cmd_bluetooth "default-agent" "10" "Authorize" "yes" >/dev/null &
         while read mac_address; read device_name; do
             echo "$mac_address"
             echo "$device_name"
-        done < <(bluez_cmd_bluetooth "default-agent\nscan on" "15" "Authorize service$" "yes\ntrust\ndisconnect" >/dev/null; bluez_cmd_bluetooth "devices" "3" | grep "^Device " | cut -d" " -f2,3- | sed 's/ /\n/')
+        done < <(bluez_cmd_bluetooth "scan on" "10" >/dev/null; bluez_cmd_bluetooth "devices" "2" | grep "^Device " | cut -d" " -f2,3- | sed 's/ /\n/')
     else
         while read; read mac_address; read device_name; do
             echo "$mac_address"
@@ -400,7 +398,7 @@ function gui_bluetooth() {
         local choice=$("${cmd[@]}" "${options[@]}" 2>&1 >/dev/tty)
         if [[ -n "$choice" ]]; then
             # temporarily restore Bluetooth stack (if needed)
-            service sixad status &>/dev/null && sixad -r
+            service sixad status >/dev/null && sixad -r
             case "$choice" in
                 R)
                     register_bluetooth
@@ -427,7 +425,7 @@ function gui_bluetooth() {
             esac
         else
             # restart sixad (if running)
-            service sixad status &>/dev/null && service sixad restart && printMsgs "dialog" "NOTICE: The ps3controller driver was temporarily interrupted in order to allow compatibility with standard Bluetooth peripherals. Please re-pair your Dual Shock controller to continue (or disregard this message if currently using another controller)."
+            service sixad status >/dev/null && service sixad restart && printMsgs "dialog" "NOTICE: The ps3controller driver was temporarily interrupted in order to allow compatibility with standard Bluetooth peripherals. Please re-pair your Dual Shock controller to continue (or disregard this message if currently using another controller)."
             break
         fi
     done

psyke83

@charleszimm

We're kind of grasping at straws now, but try the bluez_test3 branch:

git fetch psyke
git checkout psyke/bluez_test3

That branch just reverts the code adding the new "slow echo" function in case it's somehow causing the issue.

charleszimm

@psyke83 said in Bluetooth no longer working after fresh install:

git checkout psyke/bluez_test3

Okay so same thing with the Authentication Failure. Made sure that the controller wasn't in the Display Registered & Connected Bluetooth Devices menu as well as not in bluetoothctl before getting into that branch.

In bluetoothctl when I look at info:

[bluetooth]# info 98:B6:E9:42:4B:35
Device 98:B6:E9:42:4B:35
	Name: Pro Controller
	Alias: Pro Controller
	Class: 0x002508
	Icon: input-gaming
	Paired: yes
	Trusted: no
	Blocked: no
	Connected: no
	LegacyPairing: no
[bluetooth]# trust 98:B6:E9:42:4B:35
[CHG] Device 98:B6:E9:42:4B:35 Trusted: yes
Changing 98:B6:E9:42:4B:35 trust succeeded
[CHG] Device 98:B6:E9:42:4B:35 Connected: yes
[CHG] Device 98:B6:E9:42:4B:35 Connected: no

So I removed your branches and brought back down the code from 12cb7eb1bc9d810e98adbc8ec7f9a8369ed1f25e, then removed the controller:

pi@theaterretropie:~/RetroPie-Setup $ git checkout 12cb7eb1bc9d810e98adbc8ec7f9a8369ed1f25e^
Previous HEAD position was 45645719... bluetooth test3
HEAD is now at 179e2f37... Merge pull request #2591 from cmitu/dolphin-build
pi@theaterretropie:~/RetroPie-Setup $ bluetoothctl 
[NEW] Controller B8:27:EB:81:C7:4C theaterretropie [default]
[NEW] Device 98:B6:E9:42:4B:35 Pro Controller
[bluetooth]# remove 98:B6:E9:42:4B:35
[DEL] Device 98:B6:E9:42:4B:35 Pro Controller
Device has been removed
[bluetooth]# exit
[DEL] Controller B8:27:EB:81:C7:4C theaterretropie [default]

Confirmed in that version of the setup script (HEAD 179e2f37) that no devices were connected and then tried to connect the controller. Remember when you said it might have been a fluke that it worked before? I think you might be right. Authentication Failure again.

There's obviously other people besides me, you, and @BuZz viewing this. Has anyone else besides @snoogans had this issue?

psyke83

@charleszimm

Dive back into bluetoothctl-only for a moment...

I suspect that the authorization is failing via the script, but when you manually "trust" via the shell, it will work... with the important caveat that you power cycle (or disconnect) the controller afterwards, and then allow it to start over with a fresh pairing. Give it a shot and see.

mitu

@charleszimm Try an older firmware for the controller ? 1.26 or older.

charleszimm

@psyke83 Hi didn't forget about this. Got busy doing other things last night. I'll probably be able to give it a shot some time this evening once I get home.

@mitu I wouldn't mind trying that but I have a few questions: I was on an older firmware (I think 1.19) when this whole thing started and wasn't able to connect. Now of course I wasn't monitoring bluetoothctl and the associated Bluetooth services, but I'm not sure the firmware is the culprit here.

mitu

@charleszimm I mentioned the firmware downgrade because of this topic. There was also a discussion on the LIbretro forums about the 1.29 version changing the button mappings (https://forums.libretro.com/t/8bitdo-sn-30-pro-firmware-1-29-changes/20162).

charleszimm

@psyke83 bluetoothctl can't connect it either now. Something is either weird with the controller or the entire Bluetooth stack.

[bluetooth]# connect 98:B6:E9:42:4B:35
Attempting to connect to 98:B6:E9:42:4B:35
Failed to connect: org.bluez.Error.Failed
[CHG] Device 98:B6:E9:42:4B:35 Connected: yes
[CHG] Device 98:B6:E9:42:4B:35 Connected: no

I'm debating on reimaging the SD card with the latest image available from the site and before loading any other content or updates to it trying to connect the controller through bluetoothctl.

I reboot the Pi and same Connected Yes/No message. I boot it into the Android mode and this happens:

[bluetooth]# connect E4:17:D8:49:FD:83
Attempting to connect to E4:17:D8:49:FD:83
Failed to connect: org.bluez.Error.Failed
[CHG] Device E4:17:D8:49:FD:83 Connected: yes
[CHG] Device E4:17:D8:49:FD:83 Paired: yes
[CHG] Device E4:17:D8:49:FD:83 Connected: no

I'm at a loss at this point. Do you agree with the reimage idea?

psyke83

@charleszimm

I'm 99% certain that a re-image is pointless. Once you "remove" a profile in bluetoothctl, there is nothing left persistent that can realistically screw up future pairings.

There's a plausible explanation for what's happening to you:

You were on firmware 1.19, which was working fine.
You updated the script to a version dated somewhere between Feb 3rd-7th, where the Bluetooth script was temporarily broken for some devices (caused by this commit, and then fixed by this commit).
Before the fix was applied on the 7th, you upgraded your firmware to 1.29 as a troubleshooting measure, but the new firmware is defective (or at least requires different steps to pair correctly than before).

My advice is to try a firmware downgrade as @mitu suggested, or at least try all other pair modes available besides Switch on your existing firmware.

Alternatively, you might be experiencing issues that are related to the differences between jessie and stretch in the kernel and bluez stack. At this stage I'm 99% certain that the Bluetooth script in RetroPie is not the source of your problems.