| Message ID | 20210216233337.859955-3-luiz.dentz@gmail.com (mailing list archive) |
|---|---|
| State | Accepted |
| Delegated to: | Luiz Von Dentz |
| Headers | show |
| Series | [BlueZ,1/3] avdtp: Fix setting disconnect timer when there is no local endpoints | expand |
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
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
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 --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);
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(-)