diff mbox series

[BlueZ,3/3] avdtp: Remove use of G_PRIORITY_LOW

Message ID 20210216233337.859955-3-luiz.dentz@gmail.com
State New
Headers show
Series [BlueZ,1/3] avdtp: Fix setting disconnect timer when there is no local endpoints | expand

Commit Message

Luiz Augusto von Dentz Feb. 16, 2021, 11:33 p.m. UTC 
From: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>

G_PRIORITY_LOW was used in order to prioritize the AVDTP media transport
channel over the signalling channel but this has the side effect of
delaying the dispatching of other conditions such as HUP/NVAL, so now
that BtIO use G_PRIORITY_HIGH for its watches we no longer need to
deprioritize session_cb.
---
 profiles/audio/avdtp.c | 13 ++-----------
 1 file changed, 2 insertions(+), 11 deletions(-)

Comments

Miao-chen Chou Feb. 17, 2021, 8:24 p.m. UTC | #1 
Hi Luiz,

Thanks for reforming the fix. I tested the series on my DUT and it
works as expected where the paired device persists throughout the
suspend and resume. However I observed the following sequence in the
logs.
Given that this series raises the priority of avdtp's IO, session_cb()
got poked immediately after the index was removed, and that triggers
avdtp_free() early. About ~100ms later, avdtp_unregister_sep was
called with a non-NULL pointer to the sep with A2DP. However, that sep
is no longer valid since avdtp_free() freed all the seps. I wonder if
this can be a potential issue?

= Close Index: 5C:3A:45:9C:CF:8A
                            [hci0] 2021-02-17 11:52:02.607860
@ MGMT Event: Index Removed (0x0005) plen 0
                   {0x0003} [hci0] 2021-02-17 11:52:02.607866
...
= Delete Index: 5C:3A:45:9C:CF:8A
                            [hci0] 2021-02-17 11:52:02.607876
= bluetoothd: Unable to get io data for Hands-Free Voice gateway:
getpeername: Transport endpoint is...   2021-02-17 11:52:02.618425
= bluetoothd: src/service.c:change_state() 0x56093254dff0: device
28:11:A5:E1:4F:67 profile Hands-Fre..   2021-02-17 11:52:02.618480
= bluetoothd: src/service.c:btd_service_unref() 0x56093254dff0: ref=2
                                   2021-02-17 11:52:02.618486
= bluetoothd: profiles/audio/avdtp.c:session_cb()
                                   2021-02-17 11:52:02.618497
= bluetoothd: profiles/audio/avdtp.c:avdtp_ref() 0x560932556830: ref=2
                                   2021-02-17 11:52:02.618585
= bluetoothd: profiles/audio/avdtp.c:connection_lost() Disconnected
from 28:11:A5:E1:4F:67                2021-02-17 11:52:02.618594
= bluetoothd: profiles/audio/a2dp.c:abort_cfm() Source 0x5609324c36b0:
Abort_Cfm                          2021-02-17 11:52:02.618600
= bluetoothd: profiles/audio/avdtp.c:avdtp_sep_set_state() stream
state changed: OPEN -> IDLE             2021-02-17 11:52:02.618605
= bluetoothd: src/service.c:change_state() 0x560932552490: device
28:11:A5:E1:4F:67 profile a2dp-sink..   2021-02-17 11:52:02.621466
= bluetoothd: profiles/audio/avdtp.c:avdtp_unref() 0x560932556830:
ref=1                                  2021-02-17 11:52:02.621492
= bluetoothd: profiles/audio/sink.c:sink_set_state() State changed
/org/bluez/hci0/dev_28_11_A5_E1_4F..   2021-02-17 11:52:02.621500
= bluetoothd: profiles/audio/a2dp.c:channel_remove() chan
0x5609324a7930                                  2021-02-17
11:52:02.621539
= bluetoothd: profiles/audio/avdtp.c:avdtp_unref() 0x560932556830:
ref=0                                  2021-02-17 11:52:02.621546
= New Index: 00:00:00:00:00:00 (Primary,USB,hci0)
                            [hci0] 2021-02-17 11:52:02.619195
= bluetoothd: profiles/audio/avdtp.c:avdtp_free() 0x560932556830
                                   2021-02-17 11:52:02.621615
= bluetoothd: Endpoint unregistered: sender=:1.50
path=/org/chromium/Cras/Bluetooth/A2DPSource            2021-02-17
11:52:02.764766
= bluetoothd: profiles/audio/media.c:media_endpoint_destroy()
sender=:1.50 path=/org/chromium/Cras/Bl..   2021-02-17 11:52:02.764792
= bluetoothd: profiles/audio/avdtp.c:avdtp_unregister_sep() SEP
0x5609324c36b0 unregistered: type:0 c..   2021-02-17 11:52:02.764797
= bluetoothd: profiles/audio/media.c:media_player_destroy()
sender=:1.50 path=/org/chromium/Cras/Blue..   2021-02-17
11:52:02.771347

On Tue, Feb 16, 2021 at 3:35 PM Luiz Augusto von Dentz
<luiz.dentz@gmail.com> wrote:
>

> From: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>

>

> G_PRIORITY_LOW was used in order to prioritize the AVDTP media transport

> channel over the signalling channel but this has the side effect of

> delaying the dispatching of other conditions such as HUP/NVAL, so now

> that BtIO use G_PRIORITY_HIGH for its watches we no longer need to

> deprioritize session_cb.

> ---

>  profiles/audio/avdtp.c | 13 ++-----------

>  1 file changed, 2 insertions(+), 11 deletions(-)

>

> diff --git a/profiles/audio/avdtp.c b/profiles/audio/avdtp.c

> index 9ddcd6464..088ca58b3 100644

> --- a/profiles/audio/avdtp.c

> +++ b/profiles/audio/avdtp.c

> @@ -2378,19 +2378,10 @@ static void avdtp_connect_cb(GIOChannel *chan, GError *err, gpointer user_data)

>                 if (session->io_id)

>                         g_source_remove(session->io_id);

>

> -               /* This watch should be low priority since otherwise the

> -                * connect callback might be dispatched before the session

> -                * callback if the kernel wakes us up at the same time for

> -                * them. This could happen if a headset is very quick in

> -                * sending the Start command after connecting the stream

> -                * transport channel.

> -                */

> -               session->io_id = g_io_add_watch_full(chan,

> -                                               G_PRIORITY_LOW,

> +               session->io_id = g_io_add_watch(chan,

>                                                 G_IO_IN | G_IO_ERR | G_IO_HUP

>                                                 | G_IO_NVAL,

> -                                               (GIOFunc) session_cb, session,

> -                                               NULL);

> +                                               (GIOFunc) session_cb, session);

>

>                 if (session->stream_setup)

>                         set_disconnect_timer(session);

> --

> 2.29.2

>

Regards,
Miao
Luiz Augusto von Dentz Feb. 17, 2021, 9:21 p.m. UTC | #2 
Hi Miao,

On Wed, Feb 17, 2021 at 12:24 PM Miao-chen Chou <mcchou@chromium.org> wrote:
>

> Hi Luiz,

>

> Thanks for reforming the fix. I tested the series on my DUT and it

> works as expected where the paired device persists throughout the

> suspend and resume. However I observed the following sequence in the

> logs.

> Given that this series raises the priority of avdtp's IO, session_cb()

> got poked immediately after the index was removed, and that triggers

> avdtp_free() early. About ~100ms later, avdtp_unregister_sep was

> called with a non-NULL pointer to the sep with A2DP. However, that sep

> is no longer valid since avdtp_free() freed all the seps. I wonder if

> this can be a potential issue?


Are you referring to the local sep or the remote ones? avdtp_free
should not have free any local ones as it just have a reference to the
queue and that afaik was never meant to be free by avdtp_free.

> = Close Index: 5C:3A:45:9C:CF:8A

>                             [hci0] 2021-02-17 11:52:02.607860

> @ MGMT Event: Index Removed (0x0005) plen 0

>                    {0x0003} [hci0] 2021-02-17 11:52:02.607866

> ...

> = Delete Index: 5C:3A:45:9C:CF:8A

>                             [hci0] 2021-02-17 11:52:02.607876

> = bluetoothd: Unable to get io data for Hands-Free Voice gateway:

> getpeername: Transport endpoint is...   2021-02-17 11:52:02.618425

> = bluetoothd: src/service.c:change_state() 0x56093254dff0: device

> 28:11:A5:E1:4F:67 profile Hands-Fre..   2021-02-17 11:52:02.618480

> = bluetoothd: src/service.c:btd_service_unref() 0x56093254dff0: ref=2

>                                    2021-02-17 11:52:02.618486

> = bluetoothd: profiles/audio/avdtp.c:session_cb()

>                                    2021-02-17 11:52:02.618497

> = bluetoothd: profiles/audio/avdtp.c:avdtp_ref() 0x560932556830: ref=2

>                                    2021-02-17 11:52:02.618585

> = bluetoothd: profiles/audio/avdtp.c:connection_lost() Disconnected

> from 28:11:A5:E1:4F:67                2021-02-17 11:52:02.618594

> = bluetoothd: profiles/audio/a2dp.c:abort_cfm() Source 0x5609324c36b0:

> Abort_Cfm                          2021-02-17 11:52:02.618600

> = bluetoothd: profiles/audio/avdtp.c:avdtp_sep_set_state() stream

> state changed: OPEN -> IDLE             2021-02-17 11:52:02.618605

> = bluetoothd: src/service.c:change_state() 0x560932552490: device

> 28:11:A5:E1:4F:67 profile a2dp-sink..   2021-02-17 11:52:02.621466

> = bluetoothd: profiles/audio/avdtp.c:avdtp_unref() 0x560932556830:

> ref=1                                  2021-02-17 11:52:02.621492

> = bluetoothd: profiles/audio/sink.c:sink_set_state() State changed

> /org/bluez/hci0/dev_28_11_A5_E1_4F..   2021-02-17 11:52:02.621500

> = bluetoothd: profiles/audio/a2dp.c:channel_remove() chan

> 0x5609324a7930                                  2021-02-17

> 11:52:02.621539

> = bluetoothd: profiles/audio/avdtp.c:avdtp_unref() 0x560932556830:

> ref=0                                  2021-02-17 11:52:02.621546

> = New Index: 00:00:00:00:00:00 (Primary,USB,hci0)

>                             [hci0] 2021-02-17 11:52:02.619195

> = bluetoothd: profiles/audio/avdtp.c:avdtp_free() 0x560932556830

>                                    2021-02-17 11:52:02.621615

> = bluetoothd: Endpoint unregistered: sender=:1.50

> path=/org/chromium/Cras/Bluetooth/A2DPSource            2021-02-17

> 11:52:02.764766

> = bluetoothd: profiles/audio/media.c:media_endpoint_destroy()

> sender=:1.50 path=/org/chromium/Cras/Bl..   2021-02-17 11:52:02.764792

> = bluetoothd: profiles/audio/avdtp.c:avdtp_unregister_sep() SEP

> 0x5609324c36b0 unregistered: type:0 c..   2021-02-17 11:52:02.764797

> = bluetoothd: profiles/audio/media.c:media_player_destroy()

> sender=:1.50 path=/org/chromium/Cras/Blue..   2021-02-17

> 11:52:02.771347

>

> On Tue, Feb 16, 2021 at 3:35 PM Luiz Augusto von Dentz

> <luiz.dentz@gmail.com> wrote:

> >

> > From: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>

> >

> > G_PRIORITY_LOW was used in order to prioritize the AVDTP media transport

> > channel over the signalling channel but this has the side effect of

> > delaying the dispatching of other conditions such as HUP/NVAL, so now

> > that BtIO use G_PRIORITY_HIGH for its watches we no longer need to

> > deprioritize session_cb.

> > ---

> >  profiles/audio/avdtp.c | 13 ++-----------

> >  1 file changed, 2 insertions(+), 11 deletions(-)

> >

> > diff --git a/profiles/audio/avdtp.c b/profiles/audio/avdtp.c

> > index 9ddcd6464..088ca58b3 100644

> > --- a/profiles/audio/avdtp.c

> > +++ b/profiles/audio/avdtp.c

> > @@ -2378,19 +2378,10 @@ static void avdtp_connect_cb(GIOChannel *chan, GError *err, gpointer user_data)

> >                 if (session->io_id)

> >                         g_source_remove(session->io_id);

> >

> > -               /* This watch should be low priority since otherwise the

> > -                * connect callback might be dispatched before the session

> > -                * callback if the kernel wakes us up at the same time for

> > -                * them. This could happen if a headset is very quick in

> > -                * sending the Start command after connecting the stream

> > -                * transport channel.

> > -                */

> > -               session->io_id = g_io_add_watch_full(chan,

> > -                                               G_PRIORITY_LOW,

> > +               session->io_id = g_io_add_watch(chan,

> >                                                 G_IO_IN | G_IO_ERR | G_IO_HUP

> >                                                 | G_IO_NVAL,

> > -                                               (GIOFunc) session_cb, session,

> > -                                               NULL);

> > +                                               (GIOFunc) session_cb, session);

> >

> >                 if (session->stream_setup)

> >                         set_disconnect_timer(session);

> > --

> > 2.29.2

> >

> Regards,

> Miao




-- 
Luiz Augusto von Dentz
Miao-chen Chou Feb. 17, 2021, 9:41 p.m. UTC | #3 
Hi Luiz,

On Wed, Feb 17, 2021 at 1:21 PM Luiz Augusto von Dentz
<luiz.dentz@gmail.com> wrote:
>

> Hi Miao,

>

> On Wed, Feb 17, 2021 at 12:24 PM Miao-chen Chou <mcchou@chromium.org> wrote:

> >

> > Hi Luiz,

> >

> > Thanks for reforming the fix. I tested the series on my DUT and it

> > works as expected where the paired device persists throughout the

> > suspend and resume. However I observed the following sequence in the

> > logs.

> > Given that this series raises the priority of avdtp's IO, session_cb()

> > got poked immediately after the index was removed, and that triggers

> > avdtp_free() early. About ~100ms later, avdtp_unregister_sep was

> > called with a non-NULL pointer to the sep with A2DP. However, that sep

> > is no longer valid since avdtp_free() freed all the seps. I wonder if

> > this can be a potential issue?

>

> Are you referring to the local sep or the remote ones? avdtp_free

> should not have free any local ones as it just has a reference to the

> queue and that afaik was never meant to be free by avdtp_free.

That actually answers my question. There might not be concern then,
since avdtp_free() frees the remote one but not the local one while
avdtp_unregister_sep() frees the local one.
All is good. Thanks for the fix.
>

> > = Close Index: 5C:3A:45:9C:CF:8A

> >                             [hci0] 2021-02-17 11:52:02.607860

> > @ MGMT Event: Index Removed (0x0005) plen 0

> >                    {0x0003} [hci0] 2021-02-17 11:52:02.607866

> > ...

> > = Delete Index: 5C:3A:45:9C:CF:8A

> >                             [hci0] 2021-02-17 11:52:02.607876

> > = bluetoothd: Unable to get io data for Hands-Free Voice gateway:

> > getpeername: Transport endpoint is...   2021-02-17 11:52:02.618425

> > = bluetoothd: src/service.c:change_state() 0x56093254dff0: device

> > 28:11:A5:E1:4F:67 profile Hands-Fre..   2021-02-17 11:52:02.618480

> > = bluetoothd: src/service.c:btd_service_unref() 0x56093254dff0: ref=2

> >                                    2021-02-17 11:52:02.618486

> > = bluetoothd: profiles/audio/avdtp.c:session_cb()

> >                                    2021-02-17 11:52:02.618497

> > = bluetoothd: profiles/audio/avdtp.c:avdtp_ref() 0x560932556830: ref=2

> >                                    2021-02-17 11:52:02.618585

> > = bluetoothd: profiles/audio/avdtp.c:connection_lost() Disconnected

> > from 28:11:A5:E1:4F:67                2021-02-17 11:52:02.618594

> > = bluetoothd: profiles/audio/a2dp.c:abort_cfm() Source 0x5609324c36b0:

> > Abort_Cfm                          2021-02-17 11:52:02.618600

> > = bluetoothd: profiles/audio/avdtp.c:avdtp_sep_set_state() stream

> > state changed: OPEN -> IDLE             2021-02-17 11:52:02.618605

> > = bluetoothd: src/service.c:change_state() 0x560932552490: device

> > 28:11:A5:E1:4F:67 profile a2dp-sink..   2021-02-17 11:52:02.621466

> > = bluetoothd: profiles/audio/avdtp.c:avdtp_unref() 0x560932556830:

> > ref=1                                  2021-02-17 11:52:02.621492

> > = bluetoothd: profiles/audio/sink.c:sink_set_state() State changed

> > /org/bluez/hci0/dev_28_11_A5_E1_4F..   2021-02-17 11:52:02.621500

> > = bluetoothd: profiles/audio/a2dp.c:channel_remove() chan

> > 0x5609324a7930                                  2021-02-17

> > 11:52:02.621539

> > = bluetoothd: profiles/audio/avdtp.c:avdtp_unref() 0x560932556830:

> > ref=0                                  2021-02-17 11:52:02.621546

> > = New Index: 00:00:00:00:00:00 (Primary,USB,hci0)

> >                             [hci0] 2021-02-17 11:52:02.619195

> > = bluetoothd: profiles/audio/avdtp.c:avdtp_free() 0x560932556830

> >                                    2021-02-17 11:52:02.621615

> > = bluetoothd: Endpoint unregistered: sender=:1.50

> > path=/org/chromium/Cras/Bluetooth/A2DPSource            2021-02-17

> > 11:52:02.764766

> > = bluetoothd: profiles/audio/media.c:media_endpoint_destroy()

> > sender=:1.50 path=/org/chromium/Cras/Bl..   2021-02-17 11:52:02.764792

> > = bluetoothd: profiles/audio/avdtp.c:avdtp_unregister_sep() SEP

> > 0x5609324c36b0 unregistered: type:0 c..   2021-02-17 11:52:02.764797

> > = bluetoothd: profiles/audio/media.c:media_player_destroy()

> > sender=:1.50 path=/org/chromium/Cras/Blue..   2021-02-17

> > 11:52:02.771347

> >

> > On Tue, Feb 16, 2021 at 3:35 PM Luiz Augusto von Dentz

> > <luiz.dentz@gmail.com> wrote:

> > >

> > > From: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>

> > >

> > > G_PRIORITY_LOW was used in order to prioritize the AVDTP media transport

> > > channel over the signalling channel but this has the side effect of

> > > delaying the dispatching of other conditions such as HUP/NVAL, so now

> > > that BtIO use G_PRIORITY_HIGH for its watches we no longer need to

> > > deprioritize session_cb.

> > > ---

> > >  profiles/audio/avdtp.c | 13 ++-----------

> > >  1 file changed, 2 insertions(+), 11 deletions(-)

> > >

> > > diff --git a/profiles/audio/avdtp.c b/profiles/audio/avdtp.c

> > > index 9ddcd6464..088ca58b3 100644

> > > --- a/profiles/audio/avdtp.c

> > > +++ b/profiles/audio/avdtp.c

> > > @@ -2378,19 +2378,10 @@ static void avdtp_connect_cb(GIOChannel *chan, GError *err, gpointer user_data)

> > >                 if (session->io_id)

> > >                         g_source_remove(session->io_id);

> > >

> > > -               /* This watch should be low priority since otherwise the

> > > -                * connect callback might be dispatched before the session

> > > -                * callback if the kernel wakes us up at the same time for

> > > -                * them. This could happen if a headset is very quick in

> > > -                * sending the Start command after connecting the stream

> > > -                * transport channel.

> > > -                */

> > > -               session->io_id = g_io_add_watch_full(chan,

> > > -                                               G_PRIORITY_LOW,

> > > +               session->io_id = g_io_add_watch(chan,

> > >                                                 G_IO_IN | G_IO_ERR | G_IO_HUP

> > >                                                 | G_IO_NVAL,

> > > -                                               (GIOFunc) session_cb, session,

> > > -                                               NULL);

> > > +                                               (GIOFunc) session_cb, session);

> > >

> > >                 if (session->stream_setup)

> > >                         set_disconnect_timer(session);

> > > --

> > > 2.29.2

> > >

> > Regards,

> > Miao

>

>

>

> --

> Luiz Augusto von Dentz

Regards,
Miao
diff mbox series

Patch

diff --git a/profiles/audio/avdtp.c b/profiles/audio/avdtp.c
index 9ddcd6464..088ca58b3 100644
--- a/profiles/audio/avdtp.c
+++ b/profiles/audio/avdtp.c
@@ -2378,19 +2378,10 @@  static void avdtp_connect_cb(GIOChannel *chan, GError *err, gpointer user_data)
 		if (session->io_id)
 			g_source_remove(session->io_id);
 
-		/* This watch should be low priority since otherwise the
-		 * connect callback might be dispatched before the session
-		 * callback if the kernel wakes us up at the same time for
-		 * them. This could happen if a headset is very quick in
-		 * sending the Start command after connecting the stream
-		 * transport channel.
-		 */
-		session->io_id = g_io_add_watch_full(chan,
-						G_PRIORITY_LOW,
+		session->io_id = g_io_add_watch(chan,
 						G_IO_IN | G_IO_ERR | G_IO_HUP
 						| G_IO_NVAL,
-						(GIOFunc) session_cb, session,
-						NULL);
+						(GIOFunc) session_cb, session);
 
 		if (session->stream_setup)
 			set_disconnect_timer(session);