2008-11-25 04:10:00

by Sam Lin

[permalink] [raw]
Subject: HBH-PV270 headset get locked

Hi All,

I tried Sony Ericsson HBH-PV720 with aplay and found something wrong.
Log as attachment.

from first try (timestamp in log 11:24:23 - 11:24:31 ) it works fine.
sound played.

but since 2nd try (timestamp in log 11:25:21 - 11:25:26) SCO packets
flow but no sound played.
something outstanding is:

Nov 25 11:25:25 itrs-ubuntu bluetoothd[10399]: Unable to lock headset
Nov 25 11:25:25 itrs-ubuntu bluetoothd[10399]: config failed

then headset works no more, SCO packets keep flow until powerdown headset.

would you please give any hint on this ?

Sam Lin


Attachments:
bluez-debug.log (16.82 kB)

2008-11-26 13:05:22

by Johan Hedberg

[permalink] [raw]
Subject: Re: HBH-PV270 headset get locked

Hi,

On Nov 26, 2008, at 12:06, Sam Lin wrote:

> 1. so do you suggest to just remove the client->dev = NULL statement
> in headset_setup_complete() and headset_resume_complete() ?

There were already fixes pushed to the git for this. Please test them
and let us know if they help.

Johan

2008-11-26 10:06:08

by Sam Lin

[permalink] [raw]
Subject: Re: HBH-PV270 headset get locked

1. so do you suggest to just remove the client->dev = NULL statement in
headset_setup_complete() and headset_resume_complete() ?

2. for the file descriptor sending issue have you any suggestion ?
(a hint to trigger this is repeatly run aplay, what i found is while
finishing aplay the hcidump still takes some time to make traffics
settle down (about 3-7 secs), if i repeat aplay in this period it's easy
to trigger the problem)

Thanks,

Sam Lin


Luiz Augusto von Dentz 提到:
> yep, client->dev = NULL seems to be a bug, although by looking the log
> it seems there is another problem, the sco connection doesn't succeed
> but it still attempt to send the file descriptor. The logic on a2dp is
> a little different, since it doesn't start the stream on
> BT_SETCONFIGURATION_REQ and unlock the sep in any possible error.
>
> Btw, I couldn't reproduce the problem here by using aplay, arecord or
> even both together.
>
>


2008-11-26 00:09:02

by Sam Lin

[permalink] [raw]
Subject: Re: HBH-PV270 headset get locked

I have several headset to try and only HBH-PV270 has this problem.
So it seems to be device dependant and causes compatibility problem.

Sam Lin


Luiz Augusto von Dentz 提到:
> yep, client->dev = NULL seems to be a bug, although by looking the log
> it seems there is another problem, the sco connection doesn't succeed
> but it still attempt to send the file descriptor. The logic on a2dp is
> a little different, since it doesn't start the stream on
> BT_SETCONFIGURATION_REQ and unlock the sep in any possible error.
>
> Btw, I couldn't reproduce the problem here by using aplay, arecord or
> even both together.
>
>


2008-11-25 14:34:35

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: HBH-PV270 headset get locked

yep, client->dev = NULL seems to be a bug, although by looking the log
it seems there is another problem, the sco connection doesn't succeed
but it still attempt to send the file descriptor. The logic on a2dp is
a little different, since it doesn't start the stream on
BT_SETCONFIGURATION_REQ and unlock the sep in any possible error.

Btw, I couldn't reproduce the problem here by using aplay, arecord or
even both together.

--
Luiz Augusto von Dentz
Engenheiro de Computa??o

2008-11-25 09:15:59

by Johan Hedberg

[permalink] [raw]
Subject: Re: HBH-PV270 headset get locked

Hi,

Thanks for taking the time to investigate this.

On Nov 25, 2008, at 10:14, Sam Lin wrote:
> I traced code and found in some case headset is not unlocked well.
> for example when something goes wrong in headset_resume_complete(),
> client->dev = NULL
>
> so client_cb() will skip headset_unlock()
>
> then headset will be locked forever until restart bluetoothd.
>
> I have no idea what's the lock idea behind, BTW still unclear how the
> problem happens to cause this.

The lock part is used for making sure that only one unix socket client
can have read or write access to a remote device at a time. The part
that's setting client->dev to NULL seems definitely wrong to me but
I'll let Luiz comment on it before making any changes (since according
to git blame he was the last one to touch this part of the code). The
A2DP resume function has similar logic so it probably needs fixing too.

Johan

2008-11-25 08:14:42

by Sam Lin

[permalink] [raw]
Subject: Re: HBH-PV270 headset get locked

Hi All,

I traced code and found in some case headset is not unlocked well.
for example when something goes wrong in headset_resume_complete(),
client->dev = NULL

so client_cb() will skip headset_unlock()

then headset will be locked forever until restart bluetoothd.

I have no idea what's the lock idea behind, BTW still unclear how the
problem happens to cause this.

Please help to provide idea.

log:

Nov 25 15:55:50 itrs-ubuntu bluetoothd[26202]: Accepted new client
connection on unix socket (fd=22)
Nov 25 15:55:50 itrs-ubuntu bluetoothd[26202]: Audio API: received
BT_GETCAPABILITIES_REQ
Nov 25 15:55:50 itrs-ubuntu bluetoothd[26202]: Audio API: sending
BT_GETCAPABILITIES_RSP
Nov 25 15:55:50 itrs-ubuntu bluetoothd[26202]: Audio API: received
BT_SETCONFIGURATION_REQ
Nov 25 15:55:50 itrs-ubuntu bluetoothd[26202]: config sco - device =
00:1E:DC:AB:6D:3F access_mode = 2
Nov 25 15:55:50 itrs-ubuntu bluetoothd[26202]:
/org/bluez/hci0/dev_00_1E_DC_AB_6D_3F: Connecting to 00:1E:DC:AB:6D:3F
channel 1
Nov 25 15:55:50 itrs-ubuntu bluetoothd[26202]: State changed
/org/bluez/hci0/dev_00_1E_DC_AB_6D_3F: HEADSET_STATE_DISCONNECTED ->
HEADSET_STATE_CONNECT_IN_PROGRESS
Nov 25 15:56:09 itrs-ubuntu bluetoothd[26202]:
/org/bluez/hci0/dev_00_1E_DC_AB_6D_3F: Connected to 00:1E:DC:AB:6D:3F
Nov 25 15:56:09 itrs-ubuntu bluetoothd[26202]: telephony-dummy: device
0xb8486ba8 connected
Nov 25 15:56:09 itrs-ubuntu bluetoothd[26202]: State changed
/org/bluez/hci0/dev_00_1E_DC_AB_6D_3F: HEADSET_STATE_CONNECT_IN_PROGRESS
-> HEADSET_STATE_CONNECTED
Nov 25 15:56:09 itrs-ubuntu bluetoothd[26202]: State changed
/org/bluez/hci0/dev_00_1E_DC_AB_6D_3F: HEADSET_STATE_CONNECTED ->
HEADSET_STATE_PLAY_IN_PROGRESS
Nov 25 15:56:12 itrs-ubuntu bluetoothd[26202]: connect(): Connection
refused (111)
Nov 25 15:56:12 itrs-ubuntu bluetoothd[26202]: headset_lock(before):
hs->lock:0, lock:2, state:3
Nov 25 15:56:12 itrs-ubuntu bluetoothd[26202]: headset_lock: pass lock check
Nov 25 15:56:12 itrs-ubuntu bluetoothd[26202]: headset_lock(after):
hs->lock:2, lock:2, state:3
Nov 25 15:56:12 itrs-ubuntu bluetoothd[26202]: Audio API: sending
BT_SETCONFIGURATION_RSP
Nov 25 15:56:12 itrs-ubuntu bluetoothd[26202]: State changed
/org/bluez/hci0/dev_00_1E_DC_AB_6D_3F: HEADSET_STATE_PLAY_IN_PROGRESS ->
HEADSET_STATE_CONNECTED
Nov 25 15:56:12 itrs-ubuntu bluetoothd[26202]: Audio API: received
BT_STREAMSTART_REQ
Nov 25 15:56:12 itrs-ubuntu bluetoothd[26202]: Audio API: sending
BT_STREAMSTART_RSP
Nov 25 15:56:12 itrs-ubuntu bluetoothd[26202]: Audio API: sending
BT_STREAMFD_IND
Nov 25 15:56:12 itrs-ubuntu bluetoothd[26202]: unix_sendmsg_fd: Bad file
descriptor(9)
Nov 25 15:56:12 itrs-ubuntu bluetoothd[26202]: resume failed
(headset_resume_complete)
Nov 25 15:56:12 itrs-ubuntu bluetoothd[26202]: Audio API: sending
BT_STREAMSTART_RSP
Nov 25 15:56:12 itrs-ubuntu bluetoothd[26202]: Unix client disconnected
(fd=22), type:1, dev:
Nov 25 15:56:17 itrs-ubuntu bluetoothd[26202]: Received AT+CLIP=1
Nov 25 15:56:17 itrs-ubuntu bluetoothd[26202]: Received AT+CSCS="UTF-8"
Nov 25 15:56:17 itrs-ubuntu bluetoothd[26202]: Badly formated or
unrecognized command: AT+CSCS="UTF-8"
Nov 25 15:56:17 itrs-ubuntu bluetoothd[26202]: Received
AT*SEAM="HBH-PV720",13
Nov 25 15:56:17 itrs-ubuntu bluetoothd[26202]: Badly formated or
unrecognized command: AT*SEAM="HBH-PV720",13
Nov 25 15:56:17 itrs-ubuntu bluetoothd[26202]: Received AT+CLAN?
Nov 25 15:56:17 itrs-ubuntu bluetoothd[26202]: Badly formated or
unrecognized command: AT+CLAN?
Nov 25 15:56:17 itrs-ubuntu bluetoothd[26202]: Received AT*EIPS=2,1
321,48 77%

......


Sam Lin

Sam Lin ????:
> Hi All,
>
> I tried Sony Ericsson HBH-PV720 with aplay and found something wrong.
> Log as attachment.
>
> from first try (timestamp in log 11:24:23 - 11:24:31 ) it works fine.
> sound played.
>
> but since 2nd try (timestamp in log 11:25:21 - 11:25:26) SCO packets
> flow but no sound played.
> something outstanding is:
>
> Nov 25 11:25:25 itrs-ubuntu bluetoothd[10399]: Unable to lock headset
> Nov 25 11:25:25 itrs-ubuntu bluetoothd[10399]: config failed
>
> then headset works no more, SCO packets keep flow until powerdown headset.
>
> would you please give any hint on this ?
>
> Sam Lin
>
>