2015-12-08 06:53:37

by Hsin-Yu Chao

[permalink] [raw]
Subject: [PATCH] audio/a2dp - Fix unbalanced setup ref/unref

A crash was observed with backtrace below at setup_unref() inside
a2dp_cancel(). Evidence is showing that this crash occurred after
commit 33b447d where additional setup_unref() is being called.
Remove a suspious setup_unref() call in 0889e24 which might be
the cause to this crash.

(libc-2.19.so -abort.c:89 ) abort
(libc-2.19.so -libc_fatal.c:175 ) __libc_message
(libc-2.19.so -malloc.c:4991 ) malloc_printerr
(libc-2.19.so -malloc.c:3837 ) _int_free
(bluetoothd -a2dp.c:2150 ) a2dp_cancel
(bluetoothd -transport.c:231 ) media_owner_remove
(bluetoothd -transport.c:244 ) media_transport_remove_owner
(bluetoothd -transport.c:734 ) media_transport_free
(bluetoothd -object.c:658 ) remove_interface
(bluetoothd -object.c:1382 ) g_dbus_unregister_interface
(bluetoothd -transport.c:182 ) media_transport_destroy
(bluetoothd -media.c:246 ) clear_endpoint
(bluetoothd -media.c:468 ) release_endpoint
(bluetoothd -media.c:1879 ) path_free
(bluetoothd -object.c:658 ) remove_interface
(bluetoothd -object.c:1382 ) g_dbus_unregister_interface
(libglib-2.0.so.0.3400.3 -gslist.c:894 ) g_slist_foreach
(bluetoothd -adapter.c:4171 ) adapter_remove
(bluetoothd -adapter.c:7453 ) index_removed
(bluetoothd -queue.c:251 ) queue_foreach
(bluetoothd -mgmt.c:280 ) can_read_data
(bluetoothd -io-glib.c:170 ) watch_callback
(libglib-2.0.so.0.3400.3 -gmain.c:2715 ) g_main_context_dispatch
(libglib-2.0.so.0.3400.3 -gmain.c:3290 ) g_main_context_iterate
(libglib-2.0.so.0.3400.3 -gmain.c:3484 ) g_main_loop_run
(bluetoothd -main.c:661 ) main
(libc-2.19.so -libc-start.c:292 ) __libc_start_main

Signed-off-by: Hsin-Yu Chao <[email protected]>
---
profiles/audio/a2dp.c | 2 --
1 file changed, 2 deletions(-)

diff --git a/profiles/audio/a2dp.c b/profiles/audio/a2dp.c
index 82e75bf..63c9366 100644
--- a/profiles/audio/a2dp.c
+++ b/profiles/audio/a2dp.c
@@ -450,8 +450,6 @@ done:
setup->err = NULL;
}

- setup_unref(setup);
-
return FALSE;
}

--
2.1.2



2015-12-15 17:49:05

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: [PATCH] audio/a2dp - Fix unbalanced setup ref/unref

Hi Hsin-Yu,

On Tue, Dec 8, 2015 at 4:53 AM, Hsin-Yu Chao <[email protected]> wrote:
> A crash was observed with backtrace below at setup_unref() inside
> a2dp_cancel(). Evidence is showing that this crash occurred after
> commit 33b447d where additional setup_unref() is being called.
> Remove a suspious setup_unref() call in 0889e24 which might be
> the cause to this crash.
>
> (libc-2.19.so -abort.c:89 ) abort
> (libc-2.19.so -libc_fatal.c:175 ) __libc_message
> (libc-2.19.so -malloc.c:4991 ) malloc_printerr
> (libc-2.19.so -malloc.c:3837 ) _int_free
> (bluetoothd -a2dp.c:2150 ) a2dp_cancel
> (bluetoothd -transport.c:231 ) media_owner_remove
> (bluetoothd -transport.c:244 ) media_transport_remove_owner
> (bluetoothd -transport.c:734 ) media_transport_free
> (bluetoothd -object.c:658 ) remove_interface
> (bluetoothd -object.c:1382 ) g_dbus_unregister_interface
> (bluetoothd -transport.c:182 ) media_transport_destroy
> (bluetoothd -media.c:246 ) clear_endpoint
> (bluetoothd -media.c:468 ) release_endpoint
> (bluetoothd -media.c:1879 ) path_free
> (bluetoothd -object.c:658 ) remove_interface
> (bluetoothd -object.c:1382 ) g_dbus_unregister_interface
> (libglib-2.0.so.0.3400.3 -gslist.c:894 ) g_slist_foreach
> (bluetoothd -adapter.c:4171 ) adapter_remove
> (bluetoothd -adapter.c:7453 ) index_removed
> (bluetoothd -queue.c:251 ) queue_foreach
> (bluetoothd -mgmt.c:280 ) can_read_data
> (bluetoothd -io-glib.c:170 ) watch_callback
> (libglib-2.0.so.0.3400.3 -gmain.c:2715 ) g_main_context_dispatch
> (libglib-2.0.so.0.3400.3 -gmain.c:3290 ) g_main_context_iterate
> (libglib-2.0.so.0.3400.3 -gmain.c:3484 ) g_main_loop_run
> (bluetoothd -main.c:661 ) main
> (libc-2.19.so -libc-start.c:292 ) __libc_start_main
>
> Signed-off-by: Hsin-Yu Chao <[email protected]>
> ---
> profiles/audio/a2dp.c | 2 --
> 1 file changed, 2 deletions(-)
>
> diff --git a/profiles/audio/a2dp.c b/profiles/audio/a2dp.c
> index 82e75bf..63c9366 100644
> --- a/profiles/audio/a2dp.c
> +++ b/profiles/audio/a2dp.c
> @@ -450,8 +450,6 @@ done:
> setup->err = NULL;
> }
>
> - setup_unref(setup);

Im not following why this one would be causing the problem,
auto_config would only be called by endpoint_setconf_cb but that
doesn't show in the backtrace? There is something wrong if that is
happening since that means there is a pending AVDTP SetConfiguration
indication being cancelled by the a2dp_cancel which should only cancel
outgoing requests, anyway a better fix would be check if setup is
valid:

diff --git a/profiles/audio/a2dp.c b/profiles/audio/a2dp.c
index b0fea7c..9fa952f 100644
--- a/profiles/audio/a2dp.c
+++ b/profiles/audio/a2dp.c
@@ -419,6 +419,10 @@ static gboolean auto_config(gpointer data)
struct btd_device *dev = NULL;
struct btd_service *service;

+ /* Check if setup is valid */
+ if (!g_slist_find(setups, setup))
+ return FALSE;
+
/* Check if configuration was aborted */
if (setup->sep->stream == NULL)
return FALSE;
--
Luiz Augusto von Dentz

2016-03-24 12:43:32

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: [PATCH] audio/a2dp - Fix unbalanced setup ref/unref

Hi Hsin-yu,

On Thu, Mar 24, 2016 at 12:58 PM, Hsin-yu Chao <[email protected]> wrote:
> Hi Luiz,
> I suppose you mean the plugin/policy.c and yes we are using it. We got
> reports about this crash from end user, however the crash rate is low
> and not happening for me either. Since BT adapters are built-in for
> almost all Chromebooks, I don't think the 'adapter removal' should
> happen except cases that there's any problem in driver/FW.

That seems to be the reason in the first trace:

(bluetoothd -adapter.c:4171 ) adapter_remove
(bluetoothd -adapter.c:7453 ) index_removed

> I spent some time look at this backtrace and check code around the
> path of a2dp_cancel() -> avdtp_abort().
> The crash happens in a2dp_cancel() where the setup_unref() is called,
> seems because of the a2dp_setup pointer is already freed. My first
> guess is that code from avdtp_abort() somehow decreases the
> a2dp_setup's refcount to zero.
> Function avdtp_abort() could return cancel_request(session,
> ECANCELED); if session->req is non-null. And depending on the
> req->signal_id, corresponding callback function in a2dp.c(e.g
> reconf_cfm) got called, and eventually called setup_cb_free() and
> setup_unref() so that the associated a2dp_setup object got free'd.
>
> However these calls to setup_cb_free() shouldn't be blamed, because
> the refcount has always been increased earlier when each a2dp_setup_cb
> is allocated. And that makes me guess there's unbalanced manipulation
> of a2dp_setup's refcount elsewhere.

Yep, that is always protected by a reference so it should be causing a problem.

> I checked other places where an a2dp_setup is ref/unref'ed, and there
> are a few places I don't understand.
> - a2dp.c: transport_cb() has a setup_unref() call which decreases the
> refcont of a2dp_setup. But it's not clear to me why this call is
> needed.
> - a2dp.c: open_ind() has a2dp_setup_get() call which increases the
> refcount of a2dp_setup, while this a2dp_setup pointer is not assigned
> to new place.

They are related, open_ind will reference the setup while the
transport channel is being connected which is why there is a call to
setup_unref in the transport_cb.

> Could you share with me any idea or hint?

Did you check my patches?

2016-03-24 10:58:43

by Hsin-Yu Chao

[permalink] [raw]
Subject: Re: [PATCH] audio/a2dp - Fix unbalanced setup ref/unref

Hi Luiz,
I suppose you mean the plugin/policy.c and yes we are using it. We got
reports about this crash from end user, however the crash rate is low
and not happening for me either. Since BT adapters are built-in for
almost all Chromebooks, I don't think the 'adapter removal' should
happen except cases that there's any problem in driver/FW.

I spent some time look at this backtrace and check code around the
path of a2dp_cancel() -> avdtp_abort().
The crash happens in a2dp_cancel() where the setup_unref() is called,
seems because of the a2dp_setup pointer is already freed. My first
guess is that code from avdtp_abort() somehow decreases the
a2dp_setup's refcount to zero.
Function avdtp_abort() could return cancel_request(session,
ECANCELED); if session->req is non-null. And depending on the
req->signal_id, corresponding callback function in a2dp.c(e.g
reconf_cfm) got called, and eventually called setup_cb_free() and
setup_unref() so that the associated a2dp_setup object got free'd.

However these calls to setup_cb_free() shouldn't be blamed, because
the refcount has always been increased earlier when each a2dp_setup_cb
is allocated. And that makes me guess there's unbalanced manipulation
of a2dp_setup's refcount elsewhere.

I checked other places where an a2dp_setup is ref/unref'ed, and there
are a few places I don't understand.
- a2dp.c: transport_cb() has a setup_unref() call which decreases the
refcont of a2dp_setup. But it's not clear to me why this call is
needed.
- a2dp.c: open_ind() has a2dp_setup_get() call which increases the
refcount of a2dp_setup, while this a2dp_setup pointer is not assigned
to new place.

Could you share with me any idea or hint?

Thanks!
Hsin-yu


On Wed, Mar 23, 2016 at 9:12 PM, Luiz Augusto von Dentz
<[email protected]> wrote:
> Hi Hsin-yu,
>
> On Wed, Mar 23, 2016 at 12:33 PM, Luiz Augusto von Dentz
> <[email protected]> wrote:
>> Hi Hsin-yu,
>>
>> On Wed, Mar 23, 2016 at 8:01 AM, Hsin-yu Chao <[email protected]> wrote:
>>> Hi Luiz,
>>> We're now observing below crash pretty often on Chrome OS, and I still
>>> couldn't figure out the root cause.
>>> The only clue I got is that this crash happens after your commit 33b447d
>>> "audio: Fix possible crash when removing device".
>>>
>>> Thread 0 CRASHED [SIGABRT @ 0x00000000 ] MAGIC SIGNATURE THREAD
>>> 0x00007f6c4b0c7b82 (libc-2.19.so -raise.c:56 ) raise
>>> 0x00007f6c4b0c989f (libc-2.19.so -abort.c:89 ) abort
>>> 0x00007f6c4b10d527 (libc-2.19.so -libc_fatal.c:175 ) __libc_message
>>> 0x00007f6c4b113e08 (libc-2.19.so -malloc.c:4991 ) malloc_printerr
>>> 0x00007f6c4b11461a (libc-2.19.so -malloc.c:3837 ) _int_free
>>> 0x00007f6c4ba9d2d5 (bluetoothd -a2dp.c:2150 ) a2dp_cancel
>>> 0x00007f6c4baa68ab (bluetoothd -transport.c:231 ) media_owner_remove
>>> 0x00007f6c4baa6f64 (bluetoothd -transport.c:244 )
>>> media_transport_remove_owner
>>> 0x00007f6c4baa73b0 (bluetoothd -transport.c:734 ) media_transport_free
>>> 0x00007f6c4bb0ddac (bluetoothd -object.c:658 ) remove_interface
>>> 0x00007f6c4bb0eb6c (bluetoothd -object.c:1382 ) g_dbus_unregister_interface
>>> 0x00007f6c4baa7620 (bluetoothd -transport.c:182 ) media_transport_destroy
>>> 0x00007f6c4baa436f (bluetoothd -media.c:246 ) clear_endpoint
>>> 0x00007f6c4baa46f1 (bluetoothd -media.c:468 ) release_endpoint
>>> 0x00007f6c4baa61ef (bluetoothd -media.c:1879 ) path_free
>>> 0x00007f6c4bb0ddac (bluetoothd -object.c:658 ) remove_interface
>>> 0x00007f6c4bb0eb6c (bluetoothd -object.c:1382 ) g_dbus_unregister_interface
>>> 0x00007f6c4b9b1ad4 (libglib-2.0.so.0.3400.3 -gslist.c:894 ) g_slist_foreach
>>> 0x00007f6c4bada802 (bluetoothd -adapter.c:4171 ) adapter_remove
>>> 0x00007f6c4bae88a3 (bluetoothd -adapter.c:7453 ) index_removed
>>> 0x00007f6c4bb12c6f (bluetoothd -queue.c:251 ) queue_foreach
>>> 0x00007f6c4bb14386 (bluetoothd -mgmt.c:280 ) can_read_data
>>> 0x00007f6c4bb20ff5 (bluetoothd -io-glib.c:170 ) watch_callback
>>> 0x00007f6c4b991c7e (libglib-2.0.so.0.3400.3 -gmain.c:2715 )
>>> g_main_context_dispatch
>>> 0x00007f6c4b992087 (libglib-2.0.so.0.3400.3 -gmain.c:3290 )
>>> g_main_context_iterate
>>> 0x00007f6c4b9924f9 (libglib-2.0.so.0.3400.3 -gmain.c:3484 ) g_main_loop_run
>>> 0x00007f6c4ba94f90 (bluetoothd -main.c:661 ) main
>>> 0x00007f6c4b0b2fb5 (libc-2.19.so -libc-start.c:292 ) __libc_start_main
>>> 0x00007f6c4ba95770 (bluetoothd + 0x00019770 )
>>> 0x00007ffdd7f667b7
>>>
>>> Could you share any idea or hint on this crash?
>>
>> Try with valgrind it usually give a much better picture what is going
>> on. If the patch you mention is related to the problem then you would
>> see:
>>
>> bluetoothd[31136]: profiles/audio/a2dp.c:a2dp_cancel() aborting setup 0x8856b10
>> bluetoothd[31136]: profiles/audio/a2dp.c:setup_unref() 0x8856b10: ref=0
>> bluetoothd[31136]: profiles/audio/a2dp.c:setup_free() 0x8856b10
>> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_unref() 0x884f9d0: ref=1
>> bluetoothd[31136]: src/service.c:change_state() 0x870fa80: device
>> 94:20:53:2E:08:CE profile a2dp-sink state changed: disconnecting ->
>> disconnected (0)
>> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_unref() 0x884f9d0: ref=0
>> bluetoothd[31136]: src/service.c:change_state() 0x8a4b3b0: device
>> 94:20:53:2E:08:CE profile Headset Voice gateway state changed:
>> connected -> disconnecting (0)
>> bluetoothd[31136]: src/service.c:change_state() 0x8a4b3b0: device
>> 94:20:53:2E:08:CE profile Headset Voice gateway state changed:
>> disconnecting -> disconnected (0)
>> bluetoothd[31136]: src/service.c:btd_service_unref() 0x8a4b3b0: ref=2
>> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP:
>> connected signaling channel to 94:20:53:2E:08:CE
>> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP
>> imtu=672, omtu=895
>> bluetoothd[31136]: profiles/audio/avdtp.c:session_cb()
>> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_parse_resp() DISCOVER
>> request succeeded
>> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 5
>> type 1 media 0 in use 0
>> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 3
>> type 1 media 0 in use 0
>> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 2
>> type 1 media 0 in use 0
>> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 1
>> type 1 media 0 in use 0
>> bluetoothd[31136]: profiles/audio/avdtp.c:session_cb()
>> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_parse_resp()
>> GET_CAPABILITIES request succeeded
>> bluetoothd[31136]:
>> profiles/audio/avdtp.c:avdtp_get_capabilities_resp() seid 5 type 1
>> media 0
>> bluetoothd[31136]: profiles/audio/avdtp.c:session_cb()
>> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_parse_resp()
>> GET_CAPABILITIES request succeeded
>> bluetoothd[31136]:
>> profiles/audio/avdtp.c:avdtp_get_capabilities_resp() seid 3 type 1
>> media 0
>> bluetoothd[31136]: profiles/audio/avdtp.c:session_cb()
>> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_parse_resp()
>> GET_CAPABILITIES request succeeded
>> bluetoothd[31136]:
>> profiles/audio/avdtp.c:avdtp_get_capabilities_resp() seid 2 type 1
>> media 0
>> bluetoothd[31136]: profiles/audio/avdtp.c:session_cb()
>> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_parse_resp()
>> GET_CAPABILITIES request succeeded
>> bluetoothd[31136]:
>> profiles/audio/avdtp.c:avdtp_get_capabilities_resp() seid 1 type 1
>> media 0
>> bluetoothd[31136]: profiles/audio/avdtp.c:connection_lost()
>> Disconnected from 94:20:53:2E:08:CE
>>
>> It is not completely correct because it seems we are not able to
>> cancel the connection request itself, but it doesn't crash for me.
>
> Ive sent a patch-set regarding this, it should fix a couple of problem
> that may or may not be related to your crash. Btw, are you guys using
> our the connection policy plugin in chrome OS? That seems to have some
> problem when the adapter disappear while connecting.
>
> --
> Luiz Augusto von Dentz

2016-03-23 13:12:11

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: [PATCH] audio/a2dp - Fix unbalanced setup ref/unref

Hi Hsin-yu,

On Wed, Mar 23, 2016 at 12:33 PM, Luiz Augusto von Dentz
<[email protected]> wrote:
> Hi Hsin-yu,
>
> On Wed, Mar 23, 2016 at 8:01 AM, Hsin-yu Chao <[email protected]> wrote:
>> Hi Luiz,
>> We're now observing below crash pretty often on Chrome OS, and I still
>> couldn't figure out the root cause.
>> The only clue I got is that this crash happens after your commit 33b447d
>> "audio: Fix possible crash when removing device".
>>
>> Thread 0 CRASHED [SIGABRT @ 0x00000000 ] MAGIC SIGNATURE THREAD
>> 0x00007f6c4b0c7b82 (libc-2.19.so -raise.c:56 ) raise
>> 0x00007f6c4b0c989f (libc-2.19.so -abort.c:89 ) abort
>> 0x00007f6c4b10d527 (libc-2.19.so -libc_fatal.c:175 ) __libc_message
>> 0x00007f6c4b113e08 (libc-2.19.so -malloc.c:4991 ) malloc_printerr
>> 0x00007f6c4b11461a (libc-2.19.so -malloc.c:3837 ) _int_free
>> 0x00007f6c4ba9d2d5 (bluetoothd -a2dp.c:2150 ) a2dp_cancel
>> 0x00007f6c4baa68ab (bluetoothd -transport.c:231 ) media_owner_remove
>> 0x00007f6c4baa6f64 (bluetoothd -transport.c:244 )
>> media_transport_remove_owner
>> 0x00007f6c4baa73b0 (bluetoothd -transport.c:734 ) media_transport_free
>> 0x00007f6c4bb0ddac (bluetoothd -object.c:658 ) remove_interface
>> 0x00007f6c4bb0eb6c (bluetoothd -object.c:1382 ) g_dbus_unregister_interface
>> 0x00007f6c4baa7620 (bluetoothd -transport.c:182 ) media_transport_destroy
>> 0x00007f6c4baa436f (bluetoothd -media.c:246 ) clear_endpoint
>> 0x00007f6c4baa46f1 (bluetoothd -media.c:468 ) release_endpoint
>> 0x00007f6c4baa61ef (bluetoothd -media.c:1879 ) path_free
>> 0x00007f6c4bb0ddac (bluetoothd -object.c:658 ) remove_interface
>> 0x00007f6c4bb0eb6c (bluetoothd -object.c:1382 ) g_dbus_unregister_interface
>> 0x00007f6c4b9b1ad4 (libglib-2.0.so.0.3400.3 -gslist.c:894 ) g_slist_foreach
>> 0x00007f6c4bada802 (bluetoothd -adapter.c:4171 ) adapter_remove
>> 0x00007f6c4bae88a3 (bluetoothd -adapter.c:7453 ) index_removed
>> 0x00007f6c4bb12c6f (bluetoothd -queue.c:251 ) queue_foreach
>> 0x00007f6c4bb14386 (bluetoothd -mgmt.c:280 ) can_read_data
>> 0x00007f6c4bb20ff5 (bluetoothd -io-glib.c:170 ) watch_callback
>> 0x00007f6c4b991c7e (libglib-2.0.so.0.3400.3 -gmain.c:2715 )
>> g_main_context_dispatch
>> 0x00007f6c4b992087 (libglib-2.0.so.0.3400.3 -gmain.c:3290 )
>> g_main_context_iterate
>> 0x00007f6c4b9924f9 (libglib-2.0.so.0.3400.3 -gmain.c:3484 ) g_main_loop_run
>> 0x00007f6c4ba94f90 (bluetoothd -main.c:661 ) main
>> 0x00007f6c4b0b2fb5 (libc-2.19.so -libc-start.c:292 ) __libc_start_main
>> 0x00007f6c4ba95770 (bluetoothd + 0x00019770 )
>> 0x00007ffdd7f667b7
>>
>> Could you share any idea or hint on this crash?
>
> Try with valgrind it usually give a much better picture what is going
> on. If the patch you mention is related to the problem then you would
> see:
>
> bluetoothd[31136]: profiles/audio/a2dp.c:a2dp_cancel() aborting setup 0x8856b10
> bluetoothd[31136]: profiles/audio/a2dp.c:setup_unref() 0x8856b10: ref=0
> bluetoothd[31136]: profiles/audio/a2dp.c:setup_free() 0x8856b10
> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_unref() 0x884f9d0: ref=1
> bluetoothd[31136]: src/service.c:change_state() 0x870fa80: device
> 94:20:53:2E:08:CE profile a2dp-sink state changed: disconnecting ->
> disconnected (0)
> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_unref() 0x884f9d0: ref=0
> bluetoothd[31136]: src/service.c:change_state() 0x8a4b3b0: device
> 94:20:53:2E:08:CE profile Headset Voice gateway state changed:
> connected -> disconnecting (0)
> bluetoothd[31136]: src/service.c:change_state() 0x8a4b3b0: device
> 94:20:53:2E:08:CE profile Headset Voice gateway state changed:
> disconnecting -> disconnected (0)
> bluetoothd[31136]: src/service.c:btd_service_unref() 0x8a4b3b0: ref=2
> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP:
> connected signaling channel to 94:20:53:2E:08:CE
> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP
> imtu=672, omtu=895
> bluetoothd[31136]: profiles/audio/avdtp.c:session_cb()
> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_parse_resp() DISCOVER
> request succeeded
> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 5
> type 1 media 0 in use 0
> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 3
> type 1 media 0 in use 0
> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 2
> type 1 media 0 in use 0
> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 1
> type 1 media 0 in use 0
> bluetoothd[31136]: profiles/audio/avdtp.c:session_cb()
> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_parse_resp()
> GET_CAPABILITIES request succeeded
> bluetoothd[31136]:
> profiles/audio/avdtp.c:avdtp_get_capabilities_resp() seid 5 type 1
> media 0
> bluetoothd[31136]: profiles/audio/avdtp.c:session_cb()
> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_parse_resp()
> GET_CAPABILITIES request succeeded
> bluetoothd[31136]:
> profiles/audio/avdtp.c:avdtp_get_capabilities_resp() seid 3 type 1
> media 0
> bluetoothd[31136]: profiles/audio/avdtp.c:session_cb()
> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_parse_resp()
> GET_CAPABILITIES request succeeded
> bluetoothd[31136]:
> profiles/audio/avdtp.c:avdtp_get_capabilities_resp() seid 2 type 1
> media 0
> bluetoothd[31136]: profiles/audio/avdtp.c:session_cb()
> bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_parse_resp()
> GET_CAPABILITIES request succeeded
> bluetoothd[31136]:
> profiles/audio/avdtp.c:avdtp_get_capabilities_resp() seid 1 type 1
> media 0
> bluetoothd[31136]: profiles/audio/avdtp.c:connection_lost()
> Disconnected from 94:20:53:2E:08:CE
>
> It is not completely correct because it seems we are not able to
> cancel the connection request itself, but it doesn't crash for me.

Ive sent a patch-set regarding this, it should fix a couple of problem
that may or may not be related to your crash. Btw, are you guys using
our the connection policy plugin in chrome OS? That seems to have some
problem when the adapter disappear while connecting.

--
Luiz Augusto von Dentz

2016-03-23 10:33:40

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: [PATCH] audio/a2dp - Fix unbalanced setup ref/unref

Hi Hsin-yu,

On Wed, Mar 23, 2016 at 8:01 AM, Hsin-yu Chao <[email protected]> wrote:
> Hi Luiz,
> We're now observing below crash pretty often on Chrome OS, and I still
> couldn't figure out the root cause.
> The only clue I got is that this crash happens after your commit 33b447d
> "audio: Fix possible crash when removing device".
>
> Thread 0 CRASHED [SIGABRT @ 0x00000000 ] MAGIC SIGNATURE THREAD
> 0x00007f6c4b0c7b82 (libc-2.19.so -raise.c:56 ) raise
> 0x00007f6c4b0c989f (libc-2.19.so -abort.c:89 ) abort
> 0x00007f6c4b10d527 (libc-2.19.so -libc_fatal.c:175 ) __libc_message
> 0x00007f6c4b113e08 (libc-2.19.so -malloc.c:4991 ) malloc_printerr
> 0x00007f6c4b11461a (libc-2.19.so -malloc.c:3837 ) _int_free
> 0x00007f6c4ba9d2d5 (bluetoothd -a2dp.c:2150 ) a2dp_cancel
> 0x00007f6c4baa68ab (bluetoothd -transport.c:231 ) media_owner_remove
> 0x00007f6c4baa6f64 (bluetoothd -transport.c:244 )
> media_transport_remove_owner
> 0x00007f6c4baa73b0 (bluetoothd -transport.c:734 ) media_transport_free
> 0x00007f6c4bb0ddac (bluetoothd -object.c:658 ) remove_interface
> 0x00007f6c4bb0eb6c (bluetoothd -object.c:1382 ) g_dbus_unregister_interface
> 0x00007f6c4baa7620 (bluetoothd -transport.c:182 ) media_transport_destroy
> 0x00007f6c4baa436f (bluetoothd -media.c:246 ) clear_endpoint
> 0x00007f6c4baa46f1 (bluetoothd -media.c:468 ) release_endpoint
> 0x00007f6c4baa61ef (bluetoothd -media.c:1879 ) path_free
> 0x00007f6c4bb0ddac (bluetoothd -object.c:658 ) remove_interface
> 0x00007f6c4bb0eb6c (bluetoothd -object.c:1382 ) g_dbus_unregister_interface
> 0x00007f6c4b9b1ad4 (libglib-2.0.so.0.3400.3 -gslist.c:894 ) g_slist_foreach
> 0x00007f6c4bada802 (bluetoothd -adapter.c:4171 ) adapter_remove
> 0x00007f6c4bae88a3 (bluetoothd -adapter.c:7453 ) index_removed
> 0x00007f6c4bb12c6f (bluetoothd -queue.c:251 ) queue_foreach
> 0x00007f6c4bb14386 (bluetoothd -mgmt.c:280 ) can_read_data
> 0x00007f6c4bb20ff5 (bluetoothd -io-glib.c:170 ) watch_callback
> 0x00007f6c4b991c7e (libglib-2.0.so.0.3400.3 -gmain.c:2715 )
> g_main_context_dispatch
> 0x00007f6c4b992087 (libglib-2.0.so.0.3400.3 -gmain.c:3290 )
> g_main_context_iterate
> 0x00007f6c4b9924f9 (libglib-2.0.so.0.3400.3 -gmain.c:3484 ) g_main_loop_run
> 0x00007f6c4ba94f90 (bluetoothd -main.c:661 ) main
> 0x00007f6c4b0b2fb5 (libc-2.19.so -libc-start.c:292 ) __libc_start_main
> 0x00007f6c4ba95770 (bluetoothd + 0x00019770 )
> 0x00007ffdd7f667b7
>
> Could you share any idea or hint on this crash?

Try with valgrind it usually give a much better picture what is going
on. If the patch you mention is related to the problem then you would
see:

bluetoothd[31136]: profiles/audio/a2dp.c:a2dp_cancel() aborting setup 0x8856b10
bluetoothd[31136]: profiles/audio/a2dp.c:setup_unref() 0x8856b10: ref=0
bluetoothd[31136]: profiles/audio/a2dp.c:setup_free() 0x8856b10
bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_unref() 0x884f9d0: ref=1
bluetoothd[31136]: src/service.c:change_state() 0x870fa80: device
94:20:53:2E:08:CE profile a2dp-sink state changed: disconnecting ->
disconnected (0)
bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_unref() 0x884f9d0: ref=0
bluetoothd[31136]: src/service.c:change_state() 0x8a4b3b0: device
94:20:53:2E:08:CE profile Headset Voice gateway state changed:
connected -> disconnecting (0)
bluetoothd[31136]: src/service.c:change_state() 0x8a4b3b0: device
94:20:53:2E:08:CE profile Headset Voice gateway state changed:
disconnecting -> disconnected (0)
bluetoothd[31136]: src/service.c:btd_service_unref() 0x8a4b3b0: ref=2
bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP:
connected signaling channel to 94:20:53:2E:08:CE
bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP
imtu=672, omtu=895
bluetoothd[31136]: profiles/audio/avdtp.c:session_cb()
bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_parse_resp() DISCOVER
request succeeded
bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 5
type 1 media 0 in use 0
bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 3
type 1 media 0 in use 0
bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 2
type 1 media 0 in use 0
bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 1
type 1 media 0 in use 0
bluetoothd[31136]: profiles/audio/avdtp.c:session_cb()
bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_parse_resp()
GET_CAPABILITIES request succeeded
bluetoothd[31136]:
profiles/audio/avdtp.c:avdtp_get_capabilities_resp() seid 5 type 1
media 0
bluetoothd[31136]: profiles/audio/avdtp.c:session_cb()
bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_parse_resp()
GET_CAPABILITIES request succeeded
bluetoothd[31136]:
profiles/audio/avdtp.c:avdtp_get_capabilities_resp() seid 3 type 1
media 0
bluetoothd[31136]: profiles/audio/avdtp.c:session_cb()
bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_parse_resp()
GET_CAPABILITIES request succeeded
bluetoothd[31136]:
profiles/audio/avdtp.c:avdtp_get_capabilities_resp() seid 2 type 1
media 0
bluetoothd[31136]: profiles/audio/avdtp.c:session_cb()
bluetoothd[31136]: profiles/audio/avdtp.c:avdtp_parse_resp()
GET_CAPABILITIES request succeeded
bluetoothd[31136]:
profiles/audio/avdtp.c:avdtp_get_capabilities_resp() seid 1 type 1
media 0
bluetoothd[31136]: profiles/audio/avdtp.c:connection_lost()
Disconnected from 94:20:53:2E:08:CE

It is not completely correct because it seems we are not able to
cancel the connection request itself, but it doesn't crash for me.