No response from pbpctrl

Question

No response from pbpctrl

Surobaki opened this issue a year ago · 3 comments

Hi,

No matter what I try it seems that when I perform any pbpctrl command e.g., pbpctrl show battery, any pbpctrl get [...] command, even when specifying -d 24:29:34:AC:9F:D1, the program just sits with no output until I CTRL+C it.

I tried both the AUR version of pbpctrl and I also tried building with Cargo as instructed. My Pixel Buds Pro are definitely connected via Bluetooth. I can listen to music and use the microphone. bluetoothctl starts with the earbuds connected. My issue occurs with the Experimental option both on and off in Bluez' config.

Is there any way to increase the verbosity of pbpctrl or is that not implemented (potential feature suggestion)?

Thanks for making this project, I appreciate it. Thanks for taking the time to read through these issues as well.

Here's the info from bluetoothctl:

Device 24:29:34:AC:9F:D1 (public)
	Name: Olivia's Pixel Buds Pro
	Alias: Olivia's Pixel Buds Pro
	Class: 0x00240404 (2360324)
	Icon: audio-headset
	Paired: yes
	Bonded: yes
	Trusted: yes
	Blocked: no
	Connected: yes
	WakeAllowed: yes
	LegacyPairing: no
	UUID: Audio Sink                (0000110b-0000-1000-8000-00805f9b34fb)
	UUID: A/V Remote Control Target (0000110c-0000-1000-8000-00805f9b34fb)
	UUID: Advanced Audio Distribu.. (0000110d-0000-1000-8000-00805f9b34fb)
	UUID: A/V Remote Control        (0000110e-0000-1000-8000-00805f9b34fb)
	UUID: Handsfree                 (0000111e-0000-1000-8000-00805f9b34fb)
	UUID: Human Interface Device... (00001124-0000-1000-8000-00805f9b34fb)
	UUID: PnP Information           (00001200-0000-1000-8000-00805f9b34fb)
	UUID: Vendor specific           (25e97ff7-24ce-4c4c-8951-f764a708f7b4)
	UUID: Vendor specific           (25e97ff7-24ce-4c4c-8951-f764a708f7b5)
	UUID: Vendor specific           (74c34f02-a774-4f6d-ae2e-dab5030b5842)
	UUID: Vendor specific           (81c2e72a-0591-443e-a1ff-05f988593351)
	UUID: Vendor specific           (df21fe2c-2515-4fdb-8886-f12c4d67927c)
	UUID: Vendor specific           (f8d1fbe4-7966-4334-8024-ff96c9330e15)
	Modalias: bluetooth:v00E0p3004d0001
	Battery Percentage: 0x4c (76)

Answer 1 · 2023-10-23T19:41:29.000Z

Any chance you could check the firmware version? This change fixed a similar issue with v5.9 firmware, but might have broken it on older ones. Can you also post the log from when you run it with the RUST_LOG environment variable set to trace (e.g. env RUST_LOG=trace pbpctrl show battery)?

Answer 2 · 2023-10-24T09:44:25.000Z

I have no idea what happened -- last night I suspended my laptop (did not shut it off), this morning I woke up, opened the laptop back up, started trying to do the steps you recommended, only to find out that the pbpctrl commands work.

The only thing that I think really changed is the fact that as I went into the settings of the Pixel Buds Pro (to check firmware version) I had to go through a 'Your Pixel Buds just got better' screen, prompting me to try out the new voice detection music pause feature.

Firmware says release_5.9_signed. My hypothesis is that something about the 5.9 firmware update did not trigger until I visited that screen and now it's fine. I don't do any development in this area so I can only speculate. Just in case I'll send a report with trace turned on below. Feel free to close the issue, but I'm happy to help if you'd like any more info on my devices or setup for diagnosis.

oweston@Tanheku  ~  env RUST_LOG=trace pbpctrl show battery
2023-10-24T09:42:23.536665Z TRACE bluer::session: Connected to D-Bus with unique name :1.142
2023-10-24T09:42:23.537479Z TRACE bluer::session: Starting event loop for :1.142
2023-10-24T09:42:23.539607Z DEBUG pbpctrl: no device specified, searching for compatible one
2023-10-24T09:42:23.542011Z TRACE bluer::device: /org/bluez/hci0/dev_20_DF_B9_3D_26_A2: org.bluez.Device1.Class = 2884608
2023-10-24T09:42:23.542342Z TRACE bluer::device: /org/bluez/hci0/dev_CC_98_8B_1B_48_67: org.bluez.Device1.Class = 2360324
2023-10-24T09:42:23.542688Z TRACE bluer::device: /org/bluez/hci0/dev_CC_98_8B_1B_48_67: org.bluez.Device1.UUIDs = ["00000000-deca-fade-deca-deafdecacaff", "00001108-0000-1000-8000-00805f9b34fb", "0000110b-0000-1000-8000-00805f9b34fb", "0000110c-0000-1000-8000-00805f9b34fb", "0000110e-0000-1000-8000-00805f9b34fb", "0000111e-0000-1000-8000-00805f9b34fb", "00001200-0000-1000-8000-00805f9b34fb", "00001800-0000-1000-8000-00805f9b34fb", "00001801-0000-1000-8000-00805f9b34fb", "0000fe03-0000-1000-8000-00805f9b34fb", "5b833e05-6bc7-4802-8e9a-723ceca4bd8f", "5b833e06-6bc7-4802-8e9a-723ceca4bd8f", "69a7f243-e52f-4443-a7f9-cb4d053c74d6", "7b265b0e-2232-4d45-bef4-bb8ae62f813d", "81c2e72a-0591-443e-a1ff-05f988593351", "91c10d9c-aaef-42bd-b6d6-8a648c19213d", "931c7e8a-540f-4686-b798-e8df0a2ad9f7", "96cc203e-5068-46ad-b32d-e316f5e069ba", "b9b213ce-eeab-49e4-8fd9-aa478ed1b26b", "f8d1fbe4-7966-4334-8024-ff96c9330e15", "fe59bfa8-7fe3-4a05-9d94-99fadc69faff"]
2023-10-24T09:42:23.543053Z TRACE bluer::device: /org/bluez/hci0/dev_24_29_34_AC_9F_D1: org.bluez.Device1.Class = 2360324
2023-10-24T09:42:23.543406Z TRACE bluer::device: /org/bluez/hci0/dev_24_29_34_AC_9F_D1: org.bluez.Device1.UUIDs = ["0000110b-0000-1000-8000-00805f9b34fb", "0000110c-0000-1000-8000-00805f9b34fb", "0000110d-0000-1000-8000-00805f9b34fb", "0000110e-0000-1000-8000-00805f9b34fb", "0000111e-0000-1000-8000-00805f9b34fb", "00001124-0000-1000-8000-00805f9b34fb", "00001200-0000-1000-8000-00805f9b34fb", "25e97ff7-24ce-4c4c-8951-f764a708f7b4", "25e97ff7-24ce-4c4c-8951-f764a708f7b5", "74c34f02-a774-4f6d-ae2e-dab5030b5842", "81c2e72a-0591-443e-a1ff-05f988593351", "df21fe2c-2515-4fdb-8886-f12c4d67927c", "f8d1fbe4-7966-4334-8024-ff96c9330e15"]
2023-10-24T09:42:23.543457Z DEBUG pbpctrl::bt: found compatible device address=24:29:34:AC:9F:D1
2023-10-24T09:42:23.543471Z DEBUG pbpctrl::bt: registering maestro profile
2023-10-24T09:42:23.543540Z TRACE bluer::rfcomm::profile: Publishing profile at /org/bluez/bluer/profile/832bdd15fda944f39d882cefc13acfc2
2023-10-24T09:42:23.543565Z TRACE bluer::rfcomm::profile: Registering profile at /org/bluez/bluer/profile/832bdd15fda944f39d882cefc13acfc2
2023-10-24T09:42:23.544463Z DEBUG pbpctrl::bt: connecting to maestro profile
2023-10-24T09:42:23.544487Z TRACE bluer::device: /org/bluez/hci0/dev_24_29_34_AC_9F_D1: org.bluez.Device1.ConnectProfile ("25e97ff7-24ce-4c4c-8951-f764a708f7b5",)
2023-10-24T09:42:23.721944Z TRACE bluer: /org/bluez/bluer/profile/832bdd15fda944f39d882cefc13acfc2: org.bluez.Profile1.NewConnection (Path("/org/bluez/hci0/dev_24_29_34_AC_9F_D1\0"), File { fd: 12, path: "socket:[109470]", read: true, write: true }, {"Version": Variant(258)})
2023-10-24T09:42:23.722000Z DEBUG pbpctrl::bt: received new profile connection request address=24:29:34:AC:9F:D1
2023-10-24T09:42:23.722009Z DEBUG pbpctrl::bt: accepting profile connection request address=24:29:34:AC:9F:D1
2023-10-24T09:42:23.722035Z TRACE bluer: /org/bluez/bluer/profile/832bdd15fda944f39d882cefc13acfc2: org.bluez.Profile1.NewConnection (...) -> Ok(())
2023-10-24T09:42:23.722895Z TRACE bluer::device: /org/bluez/hci0/dev_24_29_34_AC_9F_D1: org.bluez.Device1.ConnectProfile (...) -> Ok(())
2023-10-24T09:42:23.722918Z DEBUG pbpctrl::bt: maestro profile connected address=24:29:34:AC:9F:D1
2023-10-24T09:42:23.722952Z TRACE maestro::protocol::utils: resolving channel
2023-10-24T09:42:23.722981Z TRACE maestro::pwrpc::client: opening rpc: channel_id=0x12, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff
2023-10-24T09:42:23.722990Z TRACE maestro::pwrpc::client: opening rpc: channel_id=0x13, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff
2023-10-24T09:42:23.722997Z TRACE maestro::pwrpc::client: opening rpc: channel_id=0x15, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff
2023-10-24T09:42:23.723003Z TRACE maestro::pwrpc::client: opening rpc: channel_id=0x17, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff
2023-10-24T09:42:23.723011Z TRACE maestro::pwrpc::client: opening rpc: channel_id=0x18, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff
2023-10-24T09:42:23.723017Z TRACE maestro::pwrpc::client: opening rpc: channel_id=0x1a, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff
2023-10-24T09:42:23.723034Z TRACE bluer::rfcomm::profile: Unregistering profile at /org/bluez/bluer/profile/832bdd15fda944f39d882cefc13acfc2
2023-10-24T09:42:23.723947Z TRACE bluer::rfcomm::profile: Unpublishing profile at /org/bluez/bluer/profile/832bdd15fda944f39d882cefc13acfc2
2023-10-24T09:42:23.747717Z TRACE tokio_util::codec::framed_impl: attempting to decode a frame
2023-10-24T09:42:23.747755Z TRACE tokio_util::codec::framed_impl: frame decoded from buffer
2023-10-24T09:42:23.747765Z TRACE maestro::pwrpc::client: received packet: type=0x01, channel_id=0x15, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff
2023-10-24T09:42:23.747779Z TRACE maestro::pwrpc::client: completing rpc: channel_id=0x15, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff
2023-10-24T09:42:23.747795Z TRACE tokio_util::codec::framed_impl: attempting to decode a frame
2023-10-24T09:42:23.747827Z TRACE maestro::protocol::utils: channel resolved channel=21
2023-10-24T09:42:23.747859Z TRACE maestro::pwrpc::client: cancelling active rpc with code: channel_id=0x12, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff, code=1
2023-10-24T09:42:23.747868Z TRACE maestro::pwrpc::client: cannot send call update, caller is gone: channel_id=0x12, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff, update=error, error=1
2023-10-24T09:42:23.747881Z TRACE maestro::pwrpc::client: cancelling active rpc with code: channel_id=0x13, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff, code=1
2023-10-24T09:42:23.747890Z TRACE maestro::pwrpc::client: cannot send call update, caller is gone: channel_id=0x13, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff, update=error, error=1
2023-10-24T09:42:23.747901Z TRACE maestro::pwrpc::client: cancelling active rpc with code: channel_id=0x17, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff, code=1
2023-10-24T09:42:23.747911Z TRACE maestro::pwrpc::client: cannot send call update, caller is gone: channel_id=0x17, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff, update=error, error=1
2023-10-24T09:42:23.747923Z TRACE maestro::pwrpc::client: cancelling active rpc with code: channel_id=0x18, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff, code=1
2023-10-24T09:42:23.747932Z TRACE maestro::pwrpc::client: cannot send call update, caller is gone: channel_id=0x18, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff, update=error, error=1
2023-10-24T09:42:23.747943Z TRACE maestro::pwrpc::client: cancelling active rpc with code: channel_id=0x1a, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff, code=1
2023-10-24T09:42:23.747953Z TRACE maestro::pwrpc::client: cannot send call update, caller is gone: channel_id=0x1a, service_id=0x7ede71ea, method_id=0x7199fa44, call_id=0xffffffff, update=error, error=1
2023-10-24T09:42:23.747965Z TRACE maestro::pwrpc::client: starting rpc: channel_id=0x15, service_id=0x7ede71ea, method_id=0xe61e8290, call_id=0x00
2023-10-24T09:42:23.747979Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2023-10-24T09:42:23.747987Z TRACE tokio_util::codec::framed_impl: writing; remaining=22
2023-10-24T09:42:23.748008Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2023-10-24T09:42:23.771116Z TRACE tokio_util::codec::framed_impl: attempting to decode a frame
2023-10-24T09:42:23.771146Z TRACE tokio_util::codec::framed_impl: frame decoded from buffer
2023-10-24T09:42:23.771151Z TRACE maestro::pwrpc::client: received packet: type=0x07, channel_id=0x15, service_id=0x7ede71ea, method_id=0xe61e8290, call_id=0x00
2023-10-24T09:42:23.771159Z TRACE maestro::pwrpc::client: pushing server stream packet to caller: channel_id=0x15, service_id=0x7ede71ea, method_id=0xe61e8290, call_id=0x00
2023-10-24T09:42:23.771169Z TRACE tokio_util::codec::framed_impl: attempting to decode a frame
case:      95% (not charging)
left bud:  79% (charging)
right bud: 93% (not charging)
2023-10-24T09:42:23.771202Z TRACE pbpctrl: task terminated successfully
2023-10-24T09:42:23.771209Z TRACE maestro::pwrpc::client: terminating client
2023-10-24T09:42:23.771214Z TRACE maestro::pwrpc::client: cannot send call update, caller is gone: channel_id=0x15, service_id=0x7ede71ea, method_id=0xe61e8290, call_id=0x00, update=error, error=1
2023-10-24T09:42:23.771224Z TRACE maestro::pwrpc::client: sending client error packet: status=1, channel_id=0x15, service_id=0x7ede71ea, method_id=0xe61e8290, call_id=0x00
2023-10-24T09:42:23.771233Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2023-10-24T09:42:23.771238Z TRACE tokio_util::codec::framed_impl: writing; remaining=26
2023-10-24T09:42:23.771277Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2023-10-24T09:42:23.771286Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2023-10-24T09:42:23.771292Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2023-10-24T09:42:23.771311Z TRACE pbpctrl: client terminated successfully

Answer 3 · 2023-10-24T10:00:11.000Z

Thanks! I guess it might not have been on the latest version before. Let me know if that happens again. I'll try to make the part that broke more robust.