Re: bluez SEGV in current master

[Joakim Tjernlund <Joakim.Tjernlund@infinera.com>]

On Wed, 2023-06-14 at 19:00 +0200, Joakim Tjernlund wrote:
> On Wed, 2023-06-14 at 09:53 -0700, Luiz Augusto von Dentz wrote:
> > Hi Joakim,
> >
> > On Wed, Jun 14, 2023 at 9:32 AM Joakim Tjernlund
> > <Joakim.Tjernlund@infinera.com> wrote:
> > >
> > > On Wed, 2023-06-14 at 09:25 -0700, Luiz Augusto von Dentz wrote:
> > > > Hi Joakim,
> > > >
> > > > On Wed, Jun 14, 2023 at 5:36 AM Joakim Tjernlund
> > > > <Joakim.Tjernlund@infinera.com> wrote:
> > > > >
> > > > > commit bap: Add broadcast source support, 3030883, in bluez.git
> > > > >
> > > > > A co-worker see this SEGV when connecting a headset:
> > > > >
> > > > > Jun 13 13:38:15 systemd-coredump[3941]: Process 1897 (bluetoothd) of user 0 dumped core.
> > > > >                                         Module bluetoothd without build-id.
> > > > >                                         #0  0x0000556bea93277a a2dp_resume_complete (bluetoothd + 0x3e77a)
> > > > >                                         #1  0x0000556bea9210a2 finalize_resume (bluetoothd + 0x2d0a2)
> > > > >                                         #2  0x0000556bea92afaf avdtp_start_resp (bluetoothd + 0x36faf)
> > > > >                                         #6  0x0000556bea9dcc85 mainloop_run (bluetoothd + 0xe8c85)
> > > > >                                         #7  0x0000556bea9dd0dc mainloop_run_with_signal (bluetoothd + 0xe90dc)
> > > > >                                         #8  0x0000556bea91a4ef main (bluetoothd + 0x264ef)
> > > > >                                         #11 0x0000556bea91ace1 _start (bluetoothd + 0x26ce1)
> > > > > Jun 13 13:38:15 systemd[1]: bluetooth.service: Main process exited, code=dumped, status=11/SEGV
> > > > >
> > > > >
> > > > > Crash seems to be at:
> > > > >
> > > > > 342     static void a2dp_resume_complete(struct avdtp *session, int err,
> > > > > 343                                                             void *user_data)
> > > > > 344     {
> > > > > 345             struct media_owner *owner = user_data;
> > > > > 346             struct media_request *req = owner->pending;
> > > > > 347             struct media_transport *transport = owner->transport;
> > > > > 348             struct a2dp_sep *sep = media_endpoint_get_sep(transport->endpoint);
> > > > >
> > > > > A good start(but does NOT fix the problem) might be:
> > > > >
> > > > > --- bluez-9999/profiles/audio/transport.c.org   2023-06-13 18:38:14.542137531 +0200
> > > > > +++ bluez-9999/profiles/audio/transport.c       2023-06-13 18:48:32.542527882 +0200
> > > > > @@ -345,7 +345,7 @@
> > > > >         struct media_owner *owner = user_data;
> > > > >         struct media_request *req = owner->pending;
> > > > >         struct media_transport *transport = owner->transport;
> > > > > -       struct a2dp_sep *sep = media_endpoint_get_sep(transport->endpoint);
> > > > > +       struct a2dp_sep *sep;
> > > > >         struct avdtp_stream *stream;
> > > > >         int fd;
> > > > >         uint16_t imtu, omtu;
> > > > > @@ -355,7 +355,10 @@
> > > > >
> > > > >         if (err)
> > > > >                 goto fail;
> > > > > +       if (!transport)
> > > > > +               goto fail;
> > > > >
> > > > > +       sep = media_endpoint_get_sep(transport->endpoint);
> > > > >         stream = a2dp_sep_get_stream(sep);
> > > > >         if (stream == NULL)
> > > > >                 goto fail;
> > > > >
> > > > > bluez-5.66 Works fine though.
> > > > >
> > > > > Headset: WH-1000XM3
> > > > >
> > > > >   Jocke
> > > >
> > > > Weird, I don't think much has changed for A2DP, but perhaps there is
> > > > some BAP related changes affecting A2DP for some reason, any chance to
> > > > bisect the patch that introduces this problem? Or it is not always
> > > > reproducible?
> > >
> > > It is reproducible but on an remote laptop used for daily work so would disturb quite a lot.
> > > Can I turn off BAP somehow to see if it is interfering ?
> > >
> > > Any chance it is related to https://github.com/bluez/bluez/issues/533 ?
> >
> > Right, yeah that is possible since it appears to be some unbalanced
> > reference count issue, that said that was a very old version, not sure
> > if we haven't fixed that.
>
> It is not fixed in unref code discussed in that issue on master
>
>     Jocke

Managed to get a bt:
Core was generated by `/usr/libexec/bluetooth/bluetoothd'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  a2dp_resume_complete (session=0x55e437429c40, err=0, user_data=0x55e437456c90) at profiles/audio/transport.c:354

warning: Source file is more recent than executable.
354             req->id = 0;
(gdb) bt full
#0  a2dp_resume_complete (session=0x55e437429c40, err=0, user_data=0x55e437456c90) at profiles/audio/transport.c:354
        owner = 0x55e437456c90
        req = 0x0
        transport = 0x0
        sep = <optimized out>
        stream = <optimized out>
        fd = 0
        imtu = 0
        omtu = 0
        ret = <optimized out>
#1  0x000055e4367f30a2 in finalize_resume (data=0x55e43745fc90) at profiles/audio/a2dp.c:352
        cb = 0x55e437472f10
        s = 0x55e43745fc90
        l = 0x0
#2  0x000055e4367fcfaf in avdtp_start_resp (resp=0x55e437429cb3, size=0, stream=0x55e437455690, session=0x55e437429c40) at profiles/audio/avdtp.c:2868
        sep = 0x55e437411660
#3  avdtp_parse_resp (transaction=<optimized out>, size=0, buf=0x55e437429cb3, signal_id=<optimized out>, stream=0x55e437455690,
    session=0x55e437429c40) at profiles/audio/avdtp.c:2988
        next = 0x0
        get_all = 0x55e4368c19a8 ""
        next = <optimized out>
        get_all = <optimized out>
        __func__ = "avdtp_parse_resp"
        __btd_debug_desc = {file = 0x55e4368b3f97 "profiles/audio/avdtp.c", flags = 0}
        __btd_debug_desc = {file = 0x55e4368b3f97 "profiles/audio/avdtp.c", flags = 0}
        __btd_debug_desc = {file = 0x55e4368b3f97 "profiles/audio/avdtp.c", flags = 0}
        __btd_debug_desc = {file = 0x55e4368b3f97 "profiles/audio/avdtp.c", flags = 0}
        __btd_debug_desc = {file = 0x55e4368b3f97 "profiles/audio/avdtp.c", flags = 0}
        __btd_debug_desc = {file = 0x55e4368b3f97 "profiles/audio/avdtp.c", flags = 0}
        __btd_debug_desc = {file = 0x55e4368b3f97 "profiles/audio/avdtp.c", flags = 0}
        __btd_debug_desc = {file = 0x55e4368b3f97 "profiles/audio/avdtp.c", flags = 0}
        __btd_debug_desc = {file = 0x55e4368b3f97 "profiles/audio/avdtp.c", flags = 0}
        __btd_debug_desc = {file = 0x55e4368b3f97 "profiles/audio/avdtp.c", flags = 0}
        __btd_debug_desc = {file = 0x55e4368b3f97 "profiles/audio/avdtp.c", flags = 0}
#4  session_cb (chan=<optimized out>, cond=<optimized out>, data=0x55e437429c40) at profiles/audio/avdtp.c:2286
        session = 0x55e437429c40
        header = <optimized out>
--Type <RET> for more, q to quit, c to continue without paging--
        size = <optimized out>
        fd = <optimized out>
        __func__ = "session_cb"
#5  0x00007fb64c271acf in g_main_dispatch (context=0x55e43740c870) at /var/tmp/portage/dev-libs/glib-2.76.2/glib-2.76.2/glib/gmain.c:3460
        dispatch = 0x7fb64c2ca330 <g_io_unix_dispatch>
        prev_source = 0x0
        begin_time_nsec = 0
        was_in_call = 0
        user_data = 0x55e437429c40
        callback = 0x55e4367fae60 <session_cb>
        cb_funcs = <optimized out>
        cb_data = 0x55e437448570
        need_destroy = <optimized out>
        source = 0x55e437456e50
        current = 0x55e437416a00
        i = 0
        current = <optimized out>
        i = <optimized out>
        __func__ = "g_main_dispatch"
        source = <optimized out>
        _g_boolean_var_163 = <optimized out>
        was_in_call = <optimized out>
        user_data = <optimized out>
        callback = <optimized out>
        cb_funcs = <optimized out>
        cb_data = <optimized out>
        need_destroy = <optimized out>
        dispatch = <optimized out>
        prev_source = <optimized out>
        begin_time_nsec = <optimized out>
        _g_boolean_var_164 = <optimized out>
#6  g_main_context_dispatch (context=context@entry=0x55e43740c870) at /var/tmp/portage/dev-libs/glib-2.76.2/glib-2.76.2/glib/gmain.c:4200
No locals.
#7  0x00007fb64c271ea8 in g_main_context_iterate (context=0x55e43740c870, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at /var/tmp/portage/dev-libs/glib-2.76.2/glib-2.76.2/glib/gmain.c:4276
        max_priority = 2147483647
        timeout = 5952
--Type <RET> for more, q to quit, c to continue without paging--
        some_ready = 1
        nfds = <optimized out>
        allocated_nfds = 35
        fds = 0x55e437439090
        begin_time_nsec = 0
#8  0x00007fb64c27215f in g_main_loop_run (loop=0x55e43740c9e0) at /var/tmp/portage/dev-libs/glib-2.76.2/glib-2.76.2/glib/gmain.c:4479
        self = <optimized out>
        __func__ = "g_main_loop_run"
#9  0x000055e4368afb55 in mainloop_run () at src/shared/mainloop-glib.c:66
No locals.
#10 0x000055e4368affac in mainloop_run_with_signal (func=func@entry=0x55e43682f6a0 <signal_callback>, user_data=user_data@entry=0x0)
    at src/shared/mainloop-notify.c:188
        data = 0x55e437416820
        io = 0x55e437416840
        ret = <optimized out>
#11 0x000055e4367ec4ff in main (argc=<optimized out>, argv=<optimized out>) at src/main.c:1450
        context = <optimized out>
        err = 0x0
        sdp_mtu = 0
        sdp_flags = <optimized out>
        gdbus_flags = <optimized out>
        __func__ = "main"

So req is NULL and:
print *owner
$2 = {transport = 0x0, pending = 0x0, name = 0x55e437473f70 ":1.41", watch = 0}

print *session
$3 = {ref = 3, version = 259, lseps = 0x55e437425990, device = 0x55e4374313d0, state = AVDTP_SESSION_STATE_CONNECTED, io = 0x55e437458370,
  io_id = 380, seps = 0x55e4374559e0 = {0x55e437455a40, 0x55e43742bb80, 0x55e43742c1f0, 0x55e43745dad0, 0x55e43745e060}, streams = 0x55e43745db70 = {
    0x55e437455690}, req_queue = 0x0, prio_queue = 0x0, pending_open = 0x0, pending_open_io = 0x0, phy = 511, imtu = 672, omtu = 895, in = {
    active = 0, no_of_packets = 1, transaction = 3 '\003', message_type = 2 '\002', signal_id = 7 '\a',
    buf = "\004\005\334\b\030\b\f\b\b\b", '\000' <repeats 1013 times>, data_size = 0 '\000'},
  buf = 0x55e43742a0f0 "2\a\024", <incomplete sequence \334>, discover = 0x0, req = 0x55e437455b70, dc_timer = 0, dc_timeout = 1, stream_setup = 0}