[4.48] SDP Discovery not reset on error

I believe that SDP Discovery initiated during rfcomm_connect is left in an inconsistent state when there is an error (such as when the remote device is off).

In the log capture below, an attempt to connect (via gnome-bluetooth/bluetooth-applet) to the headset fails because the device is off. When the device is turned back on, and another attempt is made to connect, SDP discovery fails again (Operation already in progress).

Initially I was thinking that bt_cancel_discovery() needed to be called or that cleanup in one of the failed: targets in the series of functions and callbacks in common/glib_helper.c was the problem, but after a quick scan perhaps the problem lies on the SDP server side? Suggestions?

Regards,
Peter Hurley

Hi Peter,

You might want to take a hcidump output of the second connect failure, i.e. run "hcidump -XV" as root while trying to connect. It would also be interesting to know if this is reproducable with later BlueZ versions like 4.52. I tried to do a few quick tests with it but was unable to reproduce the issue.

Johan

Thanks, Johan. It hadn't occurred to me that the host controller might be in the inconsistent state in this situation. I'll work on that.

I hadn't moved to 4.52 yet because I'm still trying to track down what I think is a race condition in avdtp.

~Peter

Hi Peter,

Actually that should be an even more important reason to move to 4.52 since there's at least one AVDTP race condition fix there.

Johan

Maybe. The race I'm observing may have something to do with your auth_cb fix (tbh, I don't fully understand the sequence avdtp_confirm_cb -> avdtp_connect_cb -> session_cb and how auth_cb fits in).

Here's the daemon log (notice the "Transport endpoint is not connected (107)" errors):

Sep  4 07:30:04 dev-wkstn bluetoothd[2713]: link_key_request (sba=00:07:61:A0:08:9B, dba=00:0D:FD:1E:99:30)
Sep  4 07:30:04 dev-wkstn bluetoothd[2713]: kernel auth requirements = 0x00
Sep  4 07:30:04 dev-wkstn bluetoothd[2713]: stored link key type = 0x00
Sep  4 07:30:04 dev-wkstn bluetoothd[2713]: adapter_get_device(00:0D:FD:1E:99:30)
Sep  4 07:30:05 dev-wkstn bluetoothd[2713]: hcid_dbus_bonding_process_complete: status=00
Sep  4 07:30:05 dev-wkstn bluetoothd[2713]: adapter_get_device(00:0D:FD:1E:99:30)
Sep  4 07:30:05 dev-wkstn bluetoothd[2713]: hcid_dbus_bonding_process_complete: no pending auth request
Sep  4 07:30:05 dev-wkstn bluetoothd[2713]: State changed /org/bluez/2713/hci0/dev_00_0D_FD_1E_99_30: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
Sep  4 07:30:05 dev-wkstn bluetoothd[2713]: /org/bluez/2713/hci0/dev_00_0D_FD_1E_99_30: Connected to 00:0D:FD:1E:99:30
Sep  4 07:30:05 dev-wkstn bluetoothd[2713]: telephony-dummy: device 0x7fd0c11d4230 connected
Sep  4 07:30:05 dev-wkstn bluetoothd[2713]: State changed /org/bluez/2713/hci0/dev_00_0D_FD_1E_99_30: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: avdtp_ref(0x7fd0c11c9f50): ref=2
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: avdtp_ref(0x7fd0c11c9f50): ref=3
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: avdtp_unref(0x7fd0c11c9f50): ref=2
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: Received AT+CKPD=200
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: telephony-dummy: got key press request for 200
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: AVDTP: incoming connect from 00:0D:FD:1E:99:30
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: AVDTP: connected signaling channel to 00:0D:FD:1E:99:30
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: AVDTP imtu=672, omtu=895
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: send: Transport endpoint is not connected (107)
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: session_cb
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: Received DISCOVER_CMD
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: send: Transport endpoint is not connected (107)
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: Unable to handle command. Disconnecting
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: Disconnected from 00:0D:FD:1E:99:30
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: avdtp_unref(0x7fd0c11c9f50): ref=1
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: connect:connect XCASE detected
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: avdtp_unref(0x7fd0c11c9f50): ref=0
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: avdtp_unref(0x7fd0c11c9f50): freeing session and removing from list
Sep  4 07:30:09 dev-wkstn bluetoothd[2713]: Stream setup failed, after XCASE connect:connect

If this is related to the auth_cb fix, would you please explain how?

Regards,
Peter

Hi Peter,

<debug logs snipped>

No, it doesn't look like it's related. The "Transport endpoint is not connected" error is what's returned by the kernel when bluetoothd tries to write to the AVDTP L2CAP socket. What kernel version are you running? I remember us having a similar issue when the DEFER_SETUP socket option was originally introduced. The output of hcidump might also reveal something interesting.

Johan