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).
> Sep 3 21:21:52 dev-wkstn bluetoothd[2724]: State changed /org/bluez/2724/hci0/dev_00_0D_FD_1E_99_30: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
> Sep 3 21:21:57 dev-wkstn bluetoothd[2724]: adapter_get_device(00:0D:FD:1E:99:30)
> Sep 3 21:21:57 dev-wkstn bluetoothd[2724]: Unable to get service record: Host is down (112)
> Sep 3 21:21:57 dev-wkstn bluetoothd[2724]: telephony-dummy: device 0x7f71751e8230 disconnected
> Sep 3 21:21:57 dev-wkstn bluetoothd[2724]: State changed /org/bluez/2724/hci0/dev_00_0D_FD_1E_99_30: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
> Sep 3 21:23:00 dev-wkstn bluetoothd[2724]: State changed /org/bluez/2724/hci0/dev_00_0D_FD_1E_99_30: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
> Sep 3 21:23:00 dev-wkstn bluetoothd[2724]: Unable to get service record: Operation already in progress (114)
> Sep 3 21:23:00 dev-wkstn bluetoothd[2724]: telephony-dummy: device 0x7f71751e8230 disconnected
> Sep 3 21:23:00 dev-wkstn bluetoothd[2724]: State changed /org/bluez/2724/hci0/dev_00_0D_FD_1E_99_30: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
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,
On Fri, Sep 04, 2009, Peter Hurley wrote:
> 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):
>
<debug logs snipped>
> If this is related to the auth_cb fix, would you please explain how?
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
Johan Hedberg wrote:
> Hi Peter,
>
> On Fri, Sep 04, 2009, Peter Hurley wrote:
>
>> 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.
>>
>
> 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,
On Fri, Sep 04, 2009, Peter Hurley wrote:
> 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.
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
Johan Hedberg wrote:
> 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,
On Thu, Sep 03, 2009, Peter Hurley wrote:
> 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).
>
>> Sep 3 21:21:52 dev-wkstn bluetoothd[2724]: State changed /org/bluez/2724/hci0/dev_00_0D_FD_1E_99_30: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
>> Sep 3 21:21:57 dev-wkstn bluetoothd[2724]: adapter_get_device(00:0D:FD:1E:99:30)
>> Sep 3 21:21:57 dev-wkstn bluetoothd[2724]: Unable to get service record: Host is down (112)
>> Sep 3 21:21:57 dev-wkstn bluetoothd[2724]: telephony-dummy: device 0x7f71751e8230 disconnected
>> Sep 3 21:21:57 dev-wkstn bluetoothd[2724]: State changed /org/bluez/2724/hci0/dev_00_0D_FD_1E_99_30: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
>> Sep 3 21:23:00 dev-wkstn bluetoothd[2724]: State changed /org/bluez/2724/hci0/dev_00_0D_FD_1E_99_30: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
>> Sep 3 21:23:00 dev-wkstn bluetoothd[2724]: Unable to get service record: Operation already in progress (114)
>> Sep 3 21:23:00 dev-wkstn bluetoothd[2724]: telephony-dummy: device 0x7f71751e8230 disconnected
>> Sep 3 21:23:00 dev-wkstn bluetoothd[2724]: State changed /org/bluez/2724/hci0/dev_00_0D_FD_1E_99_30: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
>
> 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?
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