[4.48] SDP Discovery not reset on error

[4.48] SDP Discovery not reset on error

[Peter Hurley]

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

Re: [4.48] SDP Discovery not reset on error

[Johan Hedberg]

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

Re: [4.48] SDP Discovery not reset on error

[Peter Hurley]

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

Re: [4.48] SDP Discovery not reset on error

[Johan Hedberg]

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

Re: [4.48] SDP Discovery not reset on error

[Peter Hurley]

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

Re: [4.48] SDP Discovery not reset on error

[Johan Hedberg]

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