Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Random crash on device reconnect #815

Closed
serfreeman1337 opened this issue Apr 15, 2024 · 4 comments
Closed

Random crash on device reconnect #815

serfreeman1337 opened this issue Apr 15, 2024 · 4 comments

Comments

@serfreeman1337
Copy link 

$ /usr/lib/bluetooth/bluetoothd -v
5.74
backtrace 1 
Core was generated by `/usr/lib/bluetooth/bluetoothd'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x000062e772fcc6ff in queue_pop_head (queue=0x30) at src/shared/queue.c:155
155             if (!queue || !queue->head)                                                                                                                                                                                                 
(gdb) bt
#0  0x000062e772fcc6ff in queue_pop_head (queue=0x30) at src/shared/queue.c:155
#1  bt_uhid_record (uhid=uhid@entry=0x62e77357c650, input=input@entry=true, ev=ev@entry=0x7ffd19918b10) at src/shared/uhid.c:117
#2  0x000062e772fcca10 in bt_uhid_get_report_reply (uhid=0x62e77357c650, id=<optimized out>, number=<optimized out>, status=<optimized out>, data=<optimized out>, size=<optimized out>) at src/shared/uhid.c:484
#3  0x000062e773001e39 in uhid_send_get_report_reply.isra.0 (idev=<optimized out>, data=<optimized out>, size=8, id=<optimized out>, err=<optimized out>) at profiles/input/device.c:285
#4  0x000062e772f51670 in hidp_recv_ctrl_data (size=9, data=0x7ffd19919c70 "\241\003d\334,&C\035m", param=1 '\001', idev=0x62e77357c220) at profiles/input/device.c:517
#5  hidp_recv_ctrl_message (chan=<optimized out>, idev=0x62e77357c220) at profiles/input/device.c:576
#6  0x000062e772f516e4 in ctrl_watch_cb (chan=0x62e773573900, cond=G_IO_IN, data=0x62e77357c220) at profiles/input/device.c:594
#7  0x00007d1f1af63199 in g_main_dispatch (context=0x62e773568800) at ../glib/glib/gmain.c:3344
#8  0x00007d1f1afc23bf in g_main_context_dispatch_unlocked (context=0x62e773568800) at ../glib/glib/gmain.c:4152
#9  g_main_context_iterate_unlocked.isra.0 (context=0x62e773568800, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../glib/glib/gmain.c:4217
#10 0x00007d1f1af63dc7 in g_main_loop_run (loop=0x62e7735689f0) at ../glib/glib/gmain.c:4419
#11 0x000062e772f23ef3 in mainloop_run () at src/shared/mainloop-glib.c:66
#12 mainloop_run_with_signal (func=0x62e772f774e0 <signal_callback>, user_data=0x0) at src/shared/mainloop-notify.c:188
#13 main (argc=<optimized out>, argv=<optimized out>) at src/main.c:1456
backtrace 2 
Core was generated by `/usr/lib/bluetooth/bluetoothd'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at pthread_kill.c:44
44            return INTERNAL_SYSCALL_ERROR_P (ret) ? INTERNAL_SYSCALL_ERRNO (ret) : 0;                                                                                                                                                     
(gdb) bt
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at pthread_kill.c:44
#1  0x0000752cc3014393 in __pthread_kill_internal (signo=6, threadid=<optimized out>) at pthread_kill.c:78
#2  0x0000752cc2fc36c8 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#3  0x0000752cc2fab4b8 in __GI_abort () at abort.c:79
#4  0x0000752cc33000f4 in g_assertion_message (domain=domain@entry=0x752cc33fe3a1 "GLib", file=file@entry=0x752cc33ffd1a "../glib/glib/gmain.c", line=line@entry=3993, 
    func=func@entry=0x752cc33a4f10 <__func__.21.lto_priv.8> "g_main_context_check_unlocked", message=message@entry=0x5c132f74ac90 "assertion failed: (i <= 0 || fds[i - 1].fd < fds[i].fd)") at ../glib/glib/gtestutils.c:3331
#5  0x0000752cc3367d90 in g_assertion_message_expr (domain=0x752cc33fe3a1 "GLib", file=0x752cc33ffd1a "../glib/glib/gmain.c", line=3993, func=0x752cc33a4f10 <__func__.21.lto_priv.8> "g_main_context_check_unlocked", 
    expr=<optimized out>) at ../glib/glib/gtestutils.c:3357
#6  0x0000752cc333df8d in g_main_context_check_unlocked (context=0x5c132f709800, max_priority=2147483647, fds=<optimized out>, n_fds=7) at ../glib/glib/gmain.c:3993
#7  0x0000752cc339c21e in g_main_context_iterate_unlocked.isra.0 (context=0x5c132f709800, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../glib/glib/gmain.c:4214
#8  0x0000752cc333ddc7 in g_main_loop_run (loop=0x5c132f7099f0) at ../glib/glib/gmain.c:4419
#9  0x00005c132d9b3ef3 in mainloop_run () at src/shared/mainloop-glib.c:66
#10 mainloop_run_with_signal (func=0x5c132da074e0 <signal_callback>, user_data=0x0) at src/shared/mainloop-notify.c:188
#11 main (argc=<optimized out>, argv=<optimized out>) at src/main.c:1456
backtrace 3 
Core was generated by `/usr/lib/bluetooth/bluetoothd'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at pthread_kill.c:44
44            return INTERNAL_SYSCALL_ERROR_P (ret) ? INTERNAL_SYSCALL_ERRNO (ret) : 0;                                                                                                                                                     
(gdb) bt
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at pthread_kill.c:44
#1  0x0000796022ddd393 in __pthread_kill_internal (signo=6, threadid=<optimized out>) at pthread_kill.c:78
#2  0x0000796022d8c6c8 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#3  0x0000796022d744b8 in __GI_abort () at abort.c:79
#4  0x0000796022d75395 in __libc_message_impl (fmt=fmt@entry=0x796022eed2ea "%s\n") at ../sysdeps/posix/libc_fatal.c:132
#5  0x0000796022de72a7 in malloc_printerr (str=str@entry=0x796022eeaffe "corrupted double-linked list") at malloc.c:5772
#6  0x0000796022de7de4 in unlink_chunk (p=<optimized out>, av=<optimized out>) at malloc.c:1617
#7  0x0000796022de7f70 in malloc_consolidate (av=av@entry=0x796022f28ac0 <main_arena>) at malloc.c:4876
#8  0x0000796022dea578 in _int_malloc (av=av@entry=0x796022f28ac0 <main_arena>, bytes=bytes@entry=4380) at malloc.c:4041
#9  0x0000796022deb8ea in __GI___libc_malloc (bytes=bytes@entry=4380) at malloc.c:3328
#10 0x00006255d0ffd602 in util_malloc (size=4380) at src/shared/util.c:46
#11 util_memdup (size=4380, src=0x7ffdcc7b71c0) at src/shared/util.c:64
#12 bt_uhid_record (uhid=uhid@entry=0x6255d1c2b630, input=input@entry=false, ev=ev@entry=0x7ffdcc7b71c0) at src/shared/uhid.c:129
#13 0x00006255d0ffd87d in uhid_read_handler (io=<optimized out>, user_data=0x6255d1c2b630) at src/shared/uhid.c:158
#14 0x00006255d101f6c9 in watch_callback (channel=<optimized out>, cond=<optimized out>, user_data=<optimized out>) at src/shared/io-glib.c:157
#15 0x0000796023106199 in g_main_dispatch (context=0x6255d1c1a800) at ../glib/glib/gmain.c:3344
#16 0x00007960231653bf in g_main_context_dispatch_unlocked (context=0x6255d1c1a800) at ../glib/glib/gmain.c:4152
#17 g_main_context_iterate_unlocked.isra.0 (context=0x6255d1c1a800, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../glib/glib/gmain.c:4217
#18 0x0000796023106dc7 in g_main_loop_run (loop=0x6255d1c1a9f0) at ../glib/glib/gmain.c:4419
#19 0x00006255d0f54ef3 in mainloop_run () at src/shared/mainloop-glib.c:66
#20 mainloop_run_with_signal (func=0x6255d0fa84e0 <signal_callback>, user_data=0x0) at src/shared/mainloop-notify.c:188
#21 main (argc=<optimized out>, argv=<optimized out>) at src/main.c:1456
backtrace 4 
Core was generated by `/usr/lib/bluetooth/bluetoothd'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at pthread_kill.c:44
44            return INTERNAL_SYSCALL_ERROR_P (ret) ? INTERNAL_SYSCALL_ERRNO (ret) : 0;                                                                                                                                                     
(gdb) bt
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at pthread_kill.c:44
#1  0x000071bff22be393 in __pthread_kill_internal (signo=6, threadid=<optimized out>) at pthread_kill.c:78
#2  0x000071bff226d6c8 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#3  0x000071bff22554b8 in __GI_abort () at abort.c:79
#4  0x000071bff25aa0f4 in g_assertion_message (domain=domain@entry=0x71bff26a83a1 "GLib", file=file@entry=0x71bff26a9d1a "../glib/glib/gmain.c", line=line@entry=3993, 
    func=func@entry=0x71bff264ef10 <__func__.21.lto_priv.8> "g_main_context_check_unlocked", message=message@entry=0x5ba9e1be4720 "assertion failed: (i <= 0 || fds[i - 1].fd < fds[i].fd)") at ../glib/glib/gtestutils.c:3331
#5  0x000071bff2611d90 in g_assertion_message_expr (domain=0x71bff26a83a1 "GLib", file=0x71bff26a9d1a "../glib/glib/gmain.c", line=3993, func=0x71bff264ef10 <__func__.21.lto_priv.8> "g_main_context_check_unlocked", 
    expr=<optimized out>) at ../glib/glib/gtestutils.c:3357
#6  0x000071bff25e7f8d in g_main_context_check_unlocked (context=0x5ba9e1b95800, max_priority=2147483647, fds=<optimized out>, n_fds=7) at ../glib/glib/gmain.c:3993
#7  0x000071bff264621e in g_main_context_iterate_unlocked.isra.0 (context=0x5ba9e1b95800, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../glib/glib/gmain.c:4214
#8  0x000071bff25e7dc7 in g_main_loop_run (loop=0x5ba9e1b959f0) at ../glib/glib/gmain.c:4419
#9  0x00005ba9e0d6aef3 in mainloop_run () at src/shared/mainloop-glib.c:66
#10 mainloop_run_with_signal (func=0x5ba9e0dbe4e0 <signal_callback>, user_data=0x0) at src/shared/mainloop-notify.c:188
#11 main (argc=<optimized out>, argv=<optimized out>) at src/main.c:145

backtrace 4 related log:

bluetoothd[586]: profiles/input/device.c:hidp_send_message() BT socket not connected
kernel: apple XXXX:XXXX:XXXX.XXXX: unknown main item tag 0x0
kernel: apple XXXX:XXXX:XXXX.XXXX: Non-apple keyboard detected; function keys will default to fnmode=2 behavior
kernel: input: Keychron K1 SE as /devices/virtual/misc/uhid/XXXX:XXXX:XXXX.XXXX/input/input30
kernel: apple XXXX:XXXX:XXXX.XXXX: input,hidraw5: BLUETOOTH HID v1.03 Keyboard [Keychron K1 SE] on xx:xx:xx:xx:xx:xx
bluetoothd[586]: **
bluetoothd[586]: GLib:ERROR:../glib/glib/gmain.c:3993:g_main_context_check_unlocked: assertion failed: (i <= 0 || fds[i - 1].fd < fds[i].fd)
bluetoothd[586]: Bail out! GLib:ERROR:../glib/glib/gmain.c:3993:g_main_context_check_unlocked: assertion failed: (i <= 0 || fds[i - 1].fd < fds[i].fd)
systemd[1]: Created slice Slice /system/systemd-coredump.
systemd[1]: Started Process Core Dump (PID 2421/UID 0).
systemd-logind[413]: Watching system buttons on /dev/input/event21 (Keychron K1 SE)
systemd-coredump[2429]: [🡕] Process 586 (bluetoothd) of user 0 dumped core.
@Vudentz
Copy link
Contributor

Vudentz commented Apr 15, 2024 

$ /usr/lib/bluetooth/bluetoothd -v
5.74

backtrace 1

This one seems that is crashing on a NULL pointer in queue_pop_head but the if statement is exactly checking for NULL pointer so it really beats me what is going on, can you try running it under valgrind?

backtrace 2
backtrace 3
backtrace 4

backtrace 4 related log:

bluetoothd[586]: profiles/input/device.c:hidp_send_message() BT socket not connected
kernel: apple XXXX:XXXX:XXXX.XXXX: unknown main item tag 0x0
kernel: apple XXXX:XXXX:XXXX.XXXX: Non-apple keyboard detected; function keys will default to fnmode=2 behavior
kernel: input: Keychron K1 SE as /devices/virtual/misc/uhid/XXXX:XXXX:XXXX.XXXX/input/input30
kernel: apple XXXX:XXXX:XXXX.XXXX: input,hidraw5: BLUETOOTH HID v1.03 Keyboard [Keychron K1 SE] on xx:xx:xx:xx:xx:xx
bluetoothd[586]: **
bluetoothd[586]: GLib:ERROR:../glib/glib/gmain.c:3993:g_main_context_check_unlocked: assertion failed: (i <= 0 || fds[i - 1].fd < fds[i].fd)
bluetoothd[586]: Bail out! GLib:ERROR:../glib/glib/gmain.c:3993:g_main_context_check_unlocked: assertion failed: (i <= 0 || fds[i - 1].fd < fds[i].fd)
systemd[1]: Created slice Slice /system/systemd-coredump.
systemd[1]: Started Process Core Dump (PID 2421/UID 0).
systemd-logind[413]: Watching system buttons on /dev/input/event21 (Keychron K1 SE)
systemd-coredump[2429]: [🡕] Process 586 (bluetoothd) of user 0 dumped core.

Well these other logs are crashing inside glib so I wonder what is going on here since I never seem anything like that, we don't even enable threading so the presence of pthread in the traces is really not expected.

@serfreeman1337
Copy link
Author

valgrind.txt

Also another backtrace 
Core was generated by `/usr/lib/bluetooth/bluetoothd'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  queue_push_tail (queue=0x591305100110 <ctrl_watch_cb>, data=0x591306143eb0) at src/shared/queue.c:85
85                      queue->tail->next = entry;
(gdb) bt
#0  queue_push_tail (queue=0x591305100110 <ctrl_watch_cb>, data=0x591306143eb0) at src/shared/queue.c:85
#1  0x000059130517dfef in bt_uhid_record (uhid=uhid@entry=0x5913061183e0, input=input@entry=false, ev=ev@entry=0x7ffcde473de0) at src/shared/uhid.c:129
#2  0x000059130517e12d in uhid_read_handler (io=<optimized out>, user_data=0x5913061183e0) at src/shared/uhid.c:158
#3  0x00005913051a6a65 in watch_callback (channel=<optimized out>, cond=<optimized out>, user_data=<optimized out>) at src/shared/io-glib.c:157
#4  0x000075aca7f89199 in g_main_dispatch (context=0x5913060f8800) at ../glib/glib/gmain.c:3344
#5  0x000075aca7fe83bf in g_main_context_dispatch_unlocked (context=0x5913060f8800) at ../glib/glib/gmain.c:4152
#6  g_main_context_iterate_unlocked.isra.0 (context=0x5913060f8800, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../glib/glib/gmain.c:4217
#7  0x000075aca7f89dc7 in g_main_loop_run (loop=0x5913060f89f0) at ../glib/glib/gmain.c:4419
#8  0x00005913051a70f5 in mainloop_run () at src/shared/mainloop-glib.c:66
#9  0x00005913051a754c in mainloop_run_with_signal (func=func@entry=0x59130511bfa0 <signal_callback>, user_data=user_data@entry=0x0) at src/shared/mainloop-notify.c:188
#10 0x00005913050d26d5 in main (argc=<optimized out>, argv=<optimized out>) at src/main.c:1456

github-actions bot pushed a commit to tedd-an/bluez-upstream-test that referenced this issue Apr 15, 2024
@Vudentz @tedd-an
shared/uhid: Fix crash if bt_uhid_destroy free replay structure
78afcc7 
Id replay structured has been allocated it shall be set back to NULL
after calling uhid_replay_free otherwise it may cause the following
crash:

Invalid read of size 1
   at 0x1D8FC4: bt_uhid_record (uhid.c:116)
   by 0x1D912C: uhid_read_handler (uhid.c:158)
   by 0x201A64: watch_callback (io-glib.c:157)
   by 0x48D4198: g_main_dispatch.lto_priv.0 (gmain.c:3344)
   by 0x49333BE: UnknownInlinedFun (gmain.c:4152)
   by 0x49333BE: g_main_context_iterate_unlocked.isra.0 (gmain.c:4217)
   by 0x48D4DC6: g_main_loop_run (gmain.c:4419)
   by 0x2020F4: mainloop_run (mainloop-glib.c:66)
   by 0x20254B: mainloop_run_with_signal (mainloop-notify.c:188)
   by 0x12D6D4: main (main.c:1456)
 Address 0x53ae9c0 is 0 bytes inside a block of size 40 free'd
   at 0x48468CF: free (vg_replace_malloc.c:985)
   by 0x1D8E19: uhid_replay_free (uhid.c:68)
   by 0x1D8E19: uhid_replay_free (uhid.c:59)
   by 0x1D8E19: bt_uhid_destroy (uhid.c:509)
   by 0x1591F5: uhid_disconnect (device.c:183)

Fixes: bluez/bluez#815
@tedd-an tedd-an mentioned this issue Apr 15, 2024
Closed
github-actions bot pushed a commit to BluezTestBot/bluez that referenced this issue Apr 15, 2024
@Vudentz @tedd-an
shared/uhid: Fix crash if bt_uhid_destroy free replay structure
57cd527 
Id replay structured has been allocated it shall be set back to NULL
after calling uhid_replay_free otherwise it may cause the following
crash:

Invalid read of size 1
   at 0x1D8FC4: bt_uhid_record (uhid.c:116)
   by 0x1D912C: uhid_read_handler (uhid.c:158)
   by 0x201A64: watch_callback (io-glib.c:157)
   by 0x48D4198: g_main_dispatch.lto_priv.0 (gmain.c:3344)
   by 0x49333BE: UnknownInlinedFun (gmain.c:4152)
   by 0x49333BE: g_main_context_iterate_unlocked.isra.0 (gmain.c:4217)
   by 0x48D4DC6: g_main_loop_run (gmain.c:4419)
   by 0x2020F4: mainloop_run (mainloop-glib.c:66)
   by 0x20254B: mainloop_run_with_signal (mainloop-notify.c:188)
   by 0x12D6D4: main (main.c:1456)
 Address 0x53ae9c0 is 0 bytes inside a block of size 40 free'd
   at 0x48468CF: free (vg_replace_malloc.c:985)
   by 0x1D8E19: uhid_replay_free (uhid.c:68)
   by 0x1D8E19: uhid_replay_free (uhid.c:59)
   by 0x1D8E19: bt_uhid_destroy (uhid.c:509)
   by 0x1591F5: uhid_disconnect (device.c:183)

Fixes: bluez#815
@BluezTestBot BluezTestBot mentioned this issue Apr 15, 2024
Closed
@Vudentz
Copy link
Contributor

Vudentz commented Apr 15, 2024

@serfreeman1337 any chance to test the changes above?

@serfreeman1337
Copy link
Author

Looks good. bluetoothd no longer crashes

This was referenced Apr 16, 2024
Closed
Open
@Vudentz Vudentz mentioned this issue May 13, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
2 participants
@serfreeman1337 @Vudentz