[Bug 2051993] Re: bluetoothd: connect/disconnect - "AVRCP PDU parameters length don't match"

Thu Feb 1 22:29:25 UTC 2024

Sorry for the noise, but this info may be useful?
(I've put my bluetoothd into debug verbosity)

Below are parts and the full copy of the /var/syslog part when trying to
connect, then disconnecting.

The first part looks really good (IMO).
Then "something" happens - and *disconnected*.

# Highlights (summary):

```
SINK_STATE_DISCONNECTED -> SINK_STATE_CONNECTING
AVDTP: connected signaling channel to 40:EF:4C:C5:1B:6C
DISCOVER request succeeded
SET_CONFIGURATION request succeeded
TRANSPORT_STATE_REQUESTING -> TRANSPORT_STATE_ACTIVE
SINK_STATE_CONNECTED -> SINK_STATE_PLAYING
AVCTP Connected
```

**...followed immediately by:**

```
40:EF:4C:C5:1B:6C: No service update

bluetoothd[1000416]: profiles/audio/avrcp.c:handle_vendordep_pdu() AVRCP PDU 0x10, company 0x001958 len 0x0001
bluetoothd[1000416]: profiles/audio/avrcp.c:handle_vendordep_pdu() AVRCP PDU parameters length don't match
bluetoothd[1000416]: profiles/audio/avrcp.c:handle_vendordep_pdu() AVRCP PDU 0x30, company 0x001958 len 0x0000
```

**And then it all goes down:**

```
Device 40:EF:4C:C5:1B:6C disconnected, reason 0
STREAMING -> IDLE
TRANSPORT_STATE_ACTIVE -> TRANSPORT_STATE_IDLE
connected -> disconnected (0)
disconnecting -> disconnected (0)
AVCTP: closing uinput for 40:EF:4C:C5:1B:6C
acpid: input device has been disconnected, fd 26
SINK_STATE_PLAYING -> SINK_STATE_DISCONNECTED
```

Here's the full log:
=============================

```
Jan 29 19:31:13 silverstar bluetoothd[1000416]: src/device.c:connect_profiles() /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C (all), client :1.291165
Jan 29 19:31:13 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:a2dp_sink_connect() path /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C
Jan 29 19:31:13 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_ref() 0x562e5c523e10: ref=1
Jan 29 19:31:13 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_ref() 0x562e5c523e10: ref=2
Jan 29 19:31:13 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:setup_ref() 0x562e5c511f50: ref=1
Jan 29 19:31:13 silverstar bluetoothd[1000416]: profiles/audio/sink.c:sink_set_state() State changed /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C: SINK_STATE_DISCONNECTED -> SINK_STATE_CONNECTING
Jan 29 19:31:13 silverstar bluetoothd[1000416]: profiles/audio/sink.c:sink_connect() stream creation in progress
Jan 29 19:31:13 silverstar bluetoothd[1000416]: src/service.c:change_state() 0x562e5c4ff310: device 40:EF:4C:C5:1B:6C profile a2dp-sink state changed: disconnected -> connecting (0)
Jan 29 19:31:14 silverstar bluetoothd[1000416]: src/adapter.c:connected_callback() hci0 device 40:EF:4C:C5:1B:6C connected eir_len 24
Jan 29 19:31:14 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP: connected signaling channel to 40:EF:4C:C5:1B:6C
Jan 29 19:31:14 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP imtu=672, omtu=672
Jan 29 19:31:14 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_register_remote_sep() seid 1 type 1 media 0
Jan 29 19:31:14 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:register_remote_sep() Found remote SEP: /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C/sep1
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:session_cb() 
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_parse_resp() DISCOVER request succeeded
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 1 type 1 media 0 in use 0
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:discover_cb() err (nil)
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/sink.c:discovery_complete() Discovery complete
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:setup_ref() 0x562e5c511f50: ref=2
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:setup_ref() 0x562e5c511f50: ref=3
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/media.c:media_endpoint_async_call() Calling SelectConfiguration: name = :1.76 path = /MediaEndpoint/A2DPSource/sbc
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:setup_unref() 0x562e5c511f50: ref=2
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:a2dp_config() a2dp_config: selected SEP 0x562e5c50d4a0
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:setup_ref() 0x562e5c511f50: ref=3
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_set_configuration() 0x562e5c523e10: int_seid=2, acp_seid=1
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:setup_unref() 0x562e5c511f50: ref=2
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:setup_unref() 0x562e5c511f50: ref=1
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:session_cb() 
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_parse_resp() SET_CONFIGURATION request succeeded
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:setconf_cfm() Source 0x562e5c50d4a0: Set_Configuration_Cfm
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:setup_ref() 0x562e5c511f50: ref=2
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/media.c:media_endpoint_async_call() Calling SetConfiguration: name = :1.76 path = /MediaEndpoint/A2DPSource/sbc
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed: IDLE -> CONFIGURED
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:setup_unref() 0x562e5c511f50: ref=1
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/transport.c:media_owner_create() Owner created: sender=:1.76
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_ref() 0x562e5c523e10: ref=3
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:a2dp_sep_lock() SEP 0x562e5c50d4a0 locked
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:setup_ref() 0x562e5c511f50: ref=2
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/transport.c:transport_set_state() State changed /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C/sep1/fd1: TRANSPORT_STATE_IDLE -> TRANSPORT_STATE_REQUESTING
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/transport.c:media_request_create() Request created: method=Acquire id=8
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/transport.c:media_owner_add() Owner :1.76 Request Acquire
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/transport.c:media_transport_set_owner() Transport /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C/sep1/fd1 Owner :1.76
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:session_cb() 
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_parse_resp() OPEN request succeeded
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP: connected transport channel to 40:EF:4C:C5:1B:6C
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:handle_transport_connect() Flushable packets enabled
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:handle_transport_connect() sk 43, omtu 672, send buffer size 106496
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:open_cfm() Source 0x562e5c50d4a0: Open_Cfm
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:setup_unref() 0x562e5c511f50: ref=1
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed: CONFIGURED -> OPEN
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/service.c:change_state() 0x562e5c4ff310: device 40:EF:4C:C5:1B:6C profile a2dp-sink state changed: connecting -> connected (0)
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/device.c:device_profile_connected() a2dp-sink Success (0)
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/device.c:device_profile_connected() returning response to :1.291165
Jan 29 19:31:15 silverstar bluetoothd[1000416]: plugins/policy.c:policy_connect() /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C profile avrcp-controller
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avrcp.c:avrcp_connect() path /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avctp.c:avctp_set_state() AVCTP Connecting
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/service.c:change_state() 0x562e5c501240: device 40:EF:4C:C5:1B:6C profile avrcp-controller state changed: disconnected -> connecting (0)
Jan 29 19:31:15 silverstar bluetoothd[1000416]: plugins/policy.c:service_cb() Added a2dp-sink reconnect 0
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/sink.c:sink_set_state() State changed /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C: SINK_STATE_CONNECTING -> SINK_STATE_CONNECTED
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/transport.c:transport_update_playing() /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C/sep1/fd1 State=TRANSPORT_STATE_REQUESTING Playing=0
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:session_cb() 
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_parse_resp() START request succeeded
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:start_cfm() Source 0x562e5c50d4a0: Start_Cfm
Jan 29 19:31:15 silverstar bluetoothd[1000416]: /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C/sep1/fd1: fd(43) ready
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/transport.c:media_owner_remove() Owner :1.76 Request Acquire
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/transport.c:transport_set_state() State changed /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C/sep1/fd1: TRANSPORT_STATE_REQUESTING -> TRANSPORT_STATE_ACTIVE

Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:setup_unref() 0x562e5c511f50: ref=0
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:setup_free() 0x562e5c511f50
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_unref() 0x562e5c523e10: ref=2
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed: OPEN -> STREAMING
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/sink.c:sink_set_state() State changed /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C: SINK_STATE_CONNECTED -> SINK_STATE_PLAYING
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/transport.c:transport_update_playing() /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C/sep1/fd1 State=TRANSPORT_STATE_ACTIVE Playing=1
Jan 29 19:31:15 silverstar rtkit-daemon[1476]: Supervising 1 threads of 1 processes of 1 users.
Jan 29 19:31:15 silverstar rtkit-daemon[1476]: Successfully made thread 1000546 of process 2689 owned by '1000' RT at priority 5.
Jan 29 19:31:15 silverstar rtkit-daemon[1476]: Supervising 2 threads of 2 processes of 1 users.
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avctp.c:avctp_connect_cb() AVCTP: connected to 40:EF:4C:C5:1B:6C
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avctp.c:init_uinput() AVRCP: uinput initialized for Get Together Mini
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avrcp.c:controller_init() 0x562e5c4ee5f0 version 0x0105
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/service.c:change_state() 0x562e5c4f45c0: device 40:EF:4C:C5:1B:6C profile audio-avrcp-target state changed: disconnected -> connected (0)
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avrcp.c:target_init() 0x562e5c505920 version 0x0105
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/service.c:change_state() 0x562e5c501240: device 40:EF:4C:C5:1B:6C profile avrcp-controller state changed: connecting -> connected (0)
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/device.c:device_profile_connected() avrcp-controller Success (0)
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avctp.c:avctp_set_state() AVCTP Connected

Jan 29 19:31:15 silverstar kernel: [116508.547105] input: Get Together
Mini (AVRCP) as /devices/virtual/input/input100

--------------------------- HERE is where it breaks?

Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/device.c:search_cb() 40:EF:4C:C5:1B:6C: No service update
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/device.c:device_svc_resolved() /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C err 0

Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avrcp.c:handle_vendordep_pdu() AVRCP PDU 0x10, company 0x001958 len 0x0001
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avrcp.c:handle_vendordep_pdu() AVRCP PDU parameters length don't match
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avrcp.c:handle_vendordep_pdu() AVRCP PDU 0x30, company 0x001958 len 0x0000

Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/adapter.c:dev_disconnected() Device 40:EF:4C:C5:1B:6C disconnected, reason 0
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/adapter.c:adapter_remove_connection() 
Jan 29 19:31:15 silverstar bluetoothd[1000416]: plugins/policy.c:disconnect_cb() reason 0
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 40:EF:4C:C5:1B:6C type 0 status 0xe
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/device.c:device_bonding_failed() status 14
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/adapter.c:resume_discovery() 
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed: STREAMING -> IDLE
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/transport.c:media_transport_remove_owner() Transport /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C/sep1/fd1 Owner :1.76
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/transport.c:media_owner_free() Owner :1.76
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/transport.c:transport_set_state() State changed /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C/sep1/fd1: TRANSPORT_STATE_ACTIVE -> TRANSPORT_STATE_IDLE
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:a2dp_sep_unlock() SEP 0x562e5c50d4a0 unlocked
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_unref() 0x562e5c523e10: ref=1
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/service.c:change_state() 0x562e5c4ff310: device 40:EF:4C:C5:1B:6C profile a2dp-sink state changed: connected -> disconnected (0)

Jan 29 19:31:15 silverstar bluetoothd[1000416]: plugins/policy.c:policy_disconnect() /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C profile avrcp-controller
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/service.c:change_state() 0x562e5c501240: device 40:EF:4C:C5:1B:6C profile avrcp-controller state changed: connected -> disconnecting (0)
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avrcp.c:avrcp_disconnect() path /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/service.c:change_state() 0x562e5c4f45c0: device 40:EF:4C:C5:1B:6C profile audio-avrcp-target state changed: connected -> disconnected (0)
Jan 29 19:31:15 silverstar bluetoothd[1000416]: src/service.c:change_state() 0x562e5c501240: device 40:EF:4C:C5:1B:6C profile avrcp-controller state changed: disconnecting -> disconnected (0)
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avrcp.c:controller_destroy() 0x562e5c4ee5f0
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avrcp.c:target_destroy() 0x562e5c505920
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avctp.c:avctp_set_state() AVCTP Disconnected
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avctp.c:avctp_disconnected() AVCTP: closing uinput for 40:EF:4C:C5:1B:6C
Jan 29 19:31:15 silverstar acpid: input device has been disconnected, fd 26
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_unref() 0x562e5c523e10: ref=0
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:set_disconnect_timer() timeout 0
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_ref() 0x562e5c523e10: ref=1
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:connection_lost() Disconnected from 40:EF:4C:C5:1B:6C
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/sink.c:sink_set_state() State changed /org/bluez/hci0/dev_40_EF_4C_C5_1B_6C: SINK_STATE_PLAYING -> SINK_STATE_DISCONNECTED
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/a2dp.c:channel_remove() chan 0x562e5c517520
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_unref() 0x562e5c523e10: ref=0
Jan 29 19:31:15 silverstar bluetoothd[1000416]: profiles/audio/avdtp.c:avdtp_free() 0x562e5c523e10
```

-- 
You received this bug notification because you are a member of
Bluetooth, which is subscribed to bluez-btsco in Ubuntu.
https://bugs.launchpad.net/bugs/2051993

Title:
  bluetoothd: connect/disconnect - "AVRCP PDU parameters length don't
  match"

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/bluez-btsco/+bug/2051993/+subscriptions