Exception while executing command

Question

Exception while executing command

Opened this issue 9 months ago · 3 comments

antoniovazquezblanco commented 9 months ago

Same problem. Here is the result with -v but I tried it on my phone instead of my earbuds (didn't read enough):

░█▀▄░█░░░█░█░█▀▀░█▀▀░█▀█░█░█░
░█▀▄░█░░░█░█░█▀▀░▀▀█░█▀▀░░█░░
░▀▀░░▀▀▀░▀▀▀░▀▀▀░▀▀▀░▀░░░░▀░░
░▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀░
Bluetooth audio recording tool by Tarlogic
[I] Avoiding authentication with XX:XX:XX:XX:CA:FE...
[I] Generating shared key...
[C] sudo btmgmt bondable true
hci0 Set Bondable complete, settings: powered ssp br/edr le secure-conn cis-central cis-peripheral 

[C] sudo btmgmt pairable true
hci0 Set Bondable complete, settings: powered ssp br/edr le secure-conn cis-central cis-peripheral 

[C] sudo btmgmt linksec false
hci0 Set Link Security complete, settings: powered ssp br/edr le secure-conn cis-central cis-peripheral 

[C] sudo btmgmt pair -c 3 -t 0 XX:XX:XX:XX:CA:FE
Pairing with XX:XX:XX:XX:CA:FE (BR/EDR)
hci0 XX:XX:XX:XX:CA:FE type BR/EDR connected eir_len 20
hci0 new_link_key XX:XX:XX:XX:CA:FE type 0x07 pin_len 0 store_hint 0
Paired with XX:XX:XX:XX:CA:FE (BR/EDR)

[!] Key generated
[I] Establishing connection...
[C] bluetoothctl --timeout 2 scan on
SetDiscoveryFilter success
Discovery started
[CHG] Controller XX:XX:XX:XX:DE:AD Discovering: yes
[NEW] Device XX:XX:XX:XX:F0:0D LE-MINOR III
[CHG] Device XX:XX:XX:XX:CA:FE Modalias: bluetooth:v0075p0100d0201
[CHG] Device XX:XX:XX:XX:CA:FE UUIDs: xxxxxx05-xxxx-xxxx-xxxx-xxxxxxxxxxxx
[CHG] Device XX:XX:XX:XX:CA:FE UUIDs: xxxxxx0a-xxxx-xxxx-xxxx-xxxxxxxxxxxx
[CHG] Device XX:XX:XX:XX:CA:FE UUIDs: xxxxxx0c-xxxx-xxxx-xxxx-xxxxxxxxxxxx
[CHG] Device XX:XX:XX:XX:CA:FE UUIDs: xxxxxx0e-xxxx-xxxx-xxxx-xxxxxxxxxxxx
[CHG] Device XX:XX:XX:XX:CA:FE UUIDs: xxxxxx12-xxxx-xxxx-xxxx-xxxxxxxxxxxx
[CHG] Device XX:XX:XX:XX:CA:FE UUIDs: xxxxxx15-xxxx-xxxx-xxxx-xxxxxxxxxxxx
[CHG] Device XX:XX:XX:XX:CA:FE UUIDs: xxxxxx16-xxxx-xxxx-xxxx-xxxxxxxxxxxx
[CHG] Device XX:XX:XX:XX:CA:FE UUIDs: xxxxxx1f-xxxx-xxxx-xxxx-xxxxxxxxxxxx
[CHG] Device XX:XX:XX:XX:CA:FE UUIDs: xxxxxx2d-xxxx-xxxx-xxxx-xxxxxxxxxxxx
[CHG] Device XX:XX:XX:XX:CA:FE UUIDs: xxxxxx2f-xxxx-xxxx-xxxx-xxxxxxxxxxxx
[CHG] Device XX:XX:XX:XX:CA:FE UUIDs: xxxxxx32-xxxx-xxxx-xxxx-xxxxxxxxxxxx
[CHG] Device XX:XX:XX:XX:CA:FE UUIDs: xxxxxx00-xxxx-xxxx-xxxx-xxxxxxxxxxxx
[CHG] Device XX:XX:XX:XX:CA:FE UUIDs: xxxxxx00-xxxx-xxxx-xxxx-xxxxxxxxxxxx
[CHG] Device XX:XX:XX:XX:CA:FE UUIDs: xxxxxx01-xxxx-xxxx-xxxx-xxxxxxxxxxxx
[CHG] Device XX:XX:XX:XX:CA:FE UUIDs: xxxxxx55-xxxx-xxxx-xxxx-xxxxxxxxxxxx
[CHG] Device XX:XX:XX:XX:CA:FE ServicesResolved: yes
[CHG] Device XX:XX:XX:XX:CA:FE Paired: yes

[C] bluetoothctl connect XX:XX:XX:XX:CA:FE
Attempting to connect to XX:XX:XX:XX:CA:FE
[CHG] Device XX:XX:XX:XX:F0:0D TxPower is nil
[CHG] Device XX:XX:XX:XX:F0:0D RSSI is nil
[CHG] Controller XX:XX:XX:XX:DE:AD Discovering: no
Failed to connect: org.bluez.Error.Failed br-connection-unknown

[I] Starting audio recording...
[!] Recording!
[C] pactl set-card-profile bluez_card.XX:XX:XX:XX:CA:FE headset-head-unit-msbc

Traceback (most recent call last):
  File "/home/ache/Test/BlueSpy/BlueSpy.py", line 87, in <module>
    main()
  File "/home/ache/Test/BlueSpy/BlueSpy.py", line 77, in main
    record(target, outfile=args.outfile, verbose=args.verbose)
  File "/home/ache/Test/BlueSpy/core.py", line 128, in record
    run_and_check(
  File "/home/ache/Test/BlueSpy/core.py", line 73, in run_and_check
    raise Exception(f"Error while executing command {cmdline}", out)
Exception: ('Error while executing command pactl set-card-profile bluez_card.XX:XX:XX:XX:CA:FE headset-head-unit-msbc', '')

On my phone, I had a quick flash notification unable to pair.

Trying to get more information by adding the -m flag to bluetoothctl then relaunching the script (only the interesting part):

[C] bluetoothctl -m connect XX:XX:XX:XX:CA:FE
Unable to open logging channel
Attempting to connect to XX:XX:XX:XX:CA:FE
[DEL] Device XX:XX:XX:XX:F0:0D LE-MINOR III
[CHG] Device XX:XX:XX:XX:CA:FE Connected: yes
Failed to connect: org.bluez.Error.Failed br-connection-unknown

Humm ... Don't know why. sudo maybe ? >_<"

[C] sudo bluetoothctl -m connect XX:XX:XX:XX:CA:FE
Attempting to connect to XX:XX:XX:XX:CA:FE
hci0 device_flags_changed: 80:07:94:3C:B5:C6 (BR/EDR)
     supp: 0x00000001  curr: 0x00000000
Failed to connect: org.bluez.Error.Failed br-connection-unknown

Nope.

I tried remove XX:XX:XX:XX:CA:FE in bluetoothctl didn't work.

Using on my earbuds (with microphones):

░█▀▄░█░░░█░█░█▀▀░█▀▀░█▀█░█░█░
░█▀▄░█░░░█░█░█▀▀░▀▀█░█▀▀░░█░░
░▀▀░░▀▀▀░▀▀▀░▀▀▀░▀▀▀░▀░░░░▀░░
░▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀▀░
Bluetooth audio recording tool by Tarlogic
[I] Avoiding authentication with XX:XX:XX:XX:F0:0D...
[I] Generating shared key...
[C] sudo btmgmt bondable true
hci0 Set Bondable complete, settings: powered ssp br/edr le secure-conn cis-central cis-peripheral 

[C] sudo btmgmt pairable true
hci0 Set Bondable complete, settings: powered ssp br/edr le secure-conn cis-central cis-peripheral 

[C] sudo btmgmt linksec false
hci0 Set Link Security complete, settings: powered ssp br/edr le secure-conn cis-central cis-peripheral 

[C] sudo btmgmt pair -c 3 -t 0 XX:XX:XX:XX:F0:0D
Pairing with XX:XX:XX:XX:F0:0D (BR/EDR)
hci0 XX:XX:XX:XX:F0:0D type BR/EDR connect failed (status 0x04, Connect Failed)
Pairing with XX:XX:XX:XX:F0:0D (BR/EDR) failed. status 0x04 (Connect Failed)

Traceback (most recent call last):
  File "/home/ache/Test/BlueSpy/BlueSpy.py", line 87, in <module>
    main()
  File "/home/ache/Test/BlueSpy/BlueSpy.py", line 67, in main
    pair(target, verbose=args.verbose)
  File "/home/ache/Test/BlueSpy/core.py", line 95, in pair
    run_and_check(
  File "/home/ache/Test/BlueSpy/core.py", line 73, in run_and_check
    raise Exception(f"Error while executing command {cmdline}", out)
Exception: ('Error while executing command sudo btmgmt pair -c 3 -t 0 XX:XX:XX:XX:F0:0D', 'Pairing with XX:XX:XX:XX:F0:0D (BR/EDR)\nhci0 XX:XX:XX:XX:F0:0D type BR/EDR connect failed (status 0x04, Connect Failed)\n\x1b[0;91mPairing with XX:XX:XX:XX:F0:0D (BR/EDR) failed. status 0x04 (Connect Failed)\n\x1b[0m')

-m doesn't display more information.

I feel a little safer but still concern. Will try with another pair in two weeks.

Originally posted by @arobase-che in #1 (comment)

Answer 1 · 2024-03-26T11:52:03.000Z

Thanks for the complete report!
Beware that you seem to be reporting two errors in a single issue about two different devices...
Lets go one by one starting from the beginning.

On your first example, the problem seems to be during the connection phase:

[C] bluetoothctl connect XX:XX:XX:XX:CA:FE
Attempting to connect to XX:XX:XX:XX:CA:FE
[CHG] Device XX:XX:XX:XX:F0:0D TxPower is nil
[CHG] Device XX:XX:XX:XX:F0:0D RSSI is nil
[CHG] Controller XX:XX:XX:XX:DE:AD Discovering: no
Failed to connect: org.bluez.Error.Failed br-connection-unknown

Although this fails, we are not reporting the error to the user correctly. I am going to try and push some changes that improve this...

Also, this seems to be an error with bluez/kernel/services/drivers. I would like to know which distro, distro version, kernel version and bluez versions you have if possible.

Having dmesg/journalctl logs with related errors will help also.

Thanks!

Answer 2 · 2024-03-30T13:28:13.000Z

Hi, same issue here on garuda linux (arch based).
Here are my system spec:

  Kernel: 6.8.2-zen2-1-zen arch: x86_64 bits: 64 compiler: gcc v: 13.2.1 clocksource: tsc
    avail: hpet,acpi_pm parameters: BOOT_IMAGE=/@/boot/vmlinuz-linux-zen
    root=UUID=7636b86f-c8b8-42c9-b468-e53b5baa26eb rw rootflags=subvol=@ quiet
    resume=UUID=0497e0f5-a063-4339-8235-02e6bb796b6b loglevel=3 ibt=off
  Desktop: GNOME v: 46.0 tk: GTK v: 3.24.41 wm: gnome-shell tools: gsd-screensaver-proxy dm: GDM
    v: 46.0 Distro: Garuda base: Arch Linux
  Bluetooth:
  Device-1: Realtek 802.11ac WLAN Adapter driver: btusb v: 0.8 type: USB rev: 1.0 speed: 12 Mb/s
    lanes: 1 mode: 1.1 bus-ID: 1-5:3 chip-ID: 0bda:b00c class-ID: e001 serial: <filter>
  Report: btmgmt ID: hci0 rfk-id: 0 state: up address: <filter> bt-v: 5.1 lmp-v: 10 status:
    discoverable: no pairing: no class-ID: 6c010c

with dmesg i got this error :

[ 4151.783011] Bluetooth: hci0: SCO packet for unknown connection handle 2
[ 4240.732458] Bluetooth: hci0: AOSP extensions version v1.00
[ 4240.732471] Bluetooth: hci0: AOSP quality report is supported
[ 4250.637845] Bluetooth: hci0: AOSP extensions version v1.00
[ 4250.637859] Bluetooth: hci0: AOSP quality report is supported

and my journalctl :

mars 30 14:25:14 knightmar-garuda bluetoothd[590]: src/profile.c:ext_io_disconnected() Unable to get io data for Hands-Free unit: getpeername: Transport endpoint is not connected (107)
mars 30 14:25:14 knightmar-garuda bluetoothd[590]: profiles/audio/avdtp.c:avdtp_connect_cb() connect to D4:63:DE:07:07:90: Connection refused (111)
mars 30 14:25:14 knightmar-garuda sudo[49847]: knightmar : TTY=pts/0 ; PWD=/home/knightmar/code/BlueSpy ; USER=root ; COMMAND=/usr/bin/true
mars 30 14:25:14 knightmar-garuda sudo[49847]: pam_unix(sudo:session): session opened for user root(uid=0) by knightmar(uid=1000)
mars 30 14:25:14 knightmar-garuda sudo[49847]: pam_unix(sudo:session): session closed for user root
mars 30 14:25:17 knightmar-garuda bluetoothd[590]: profiles/audio/avdtp.c:avdtp_connect_cb() connect to D4:63:DE:07:07:90: Connection reset by peer (104)

I hope you find this information helpful.

Answer 3 · 2024-05-21T07:53:50.000Z

I still do not have strong evidence on why is this happening. It seems the remote device is closing the connection but I don't know if it is due to the kernel/drivers doing something wrong on our side. Would it be possible to obtain a pcap o a connection attempt?

Thanks