Re: deadlock on console mutex in gdb

[Takashi Yano <takashi.yano@nifty.ne.jp>]

On Wed, 22 Dec 2021 11:26:54 -0400
David McFarland wrote:
> I'm seeing a deadlock when using gdb on a process with a lot of console
> output and thread creation:
> 
> Thread 1 (Thread 13016.0x2804):
> #0  0x00007ffca30ecdf4 in ntdll!ZwWaitForSingleObject () from /cygdrive/c/WINDOWS/SYSTEM32/ntdll.dll
> #1  0x00007ffca0d91a5e in WaitForSingleObjectEx () from /cygdrive/c/WINDOWS/System32/KERNELBASE.dll
> #2  0x0000000180071719 in fhandler_console::set_output_mode (m=tty::cygwin, t=0x180000028, p=0x1803a3418) at ../../../../winsup/cygwin/fhandler_console.cc:524
> #3  0x0000000180079c6e in fhandler_console::write (this=0x1803a3218, vsrc=0x800312dc0, len=26) at ../../../../winsup/cygwin/fhandler_console.cc:3115
> #4  0x000000018014a022 in write (fd=1, ptr=0x800312dc0, len=26) at ../../../../winsup/cygwin/syscalls.cc:1360
> #5  0x0000000180227349 in _write_r (ptr=0xffffd680, fd=1, buf=0x800312dc0, cnt=26) at ../../../../../newlib/libc/reent/writer.c:49
> #6  0x00000001801e8e0c in __swrite64 (ptr=0xffffd680, cookie=0x180273c70 <reent_data+1520>, buf=0x800312dc0 "[New Thread 11424.0x244c]\ne/c/cygwin64/home/David_M/src/nix/test/bin/nix build -f nixpkgs/test --log-format raw -vvvvvvvvv\n", n=26) at ../../../../../newlib/libc/stdio64/stdio64.c:69
> #7  0x00000001801d13cf in __sflush_r (ptr=0xffffd680, fp=0x180273c70 <reent_data+1520>) at ../../../../../newlib/libc/stdio/fflush.c:224
> #8  0x00000001801d14d5 in _fflush_r (ptr=0xffffd680, fp=0x180273c70 <reent_data+1520>) at ../../../../../newlib/libc/stdio/fflush.c:278
> #9  0x00000001801d8bbd in __sfvwrite_r (ptr=0xffffd680, fp=0x180273c70 <reent_data+1520>, uio=0xffffbbb0) at ../../../../../newlib/libc/stdio/fvwrite.c:251
> #10 0x00000001801d5026 in _fputs_r (ptr=0xffffd680, s=0x10097cdd5 <bright_colors+3413> "\n", fp=0x180273c70 <reent_data+1520>) at ../../../../../newlib/libc/stdio/fputs.c:107
> #11 0x00000001801d509d in fputs (s=0x10097cdd5 <bright_colors+3413> "\n", fp=0x180273c70 <reent_data+1520>) at ../../../../../newlib/libc/stdio/fputs.c:140
> #12 0x00000001801a6beb in _sigfe () at sigfe.s:37
> #13 0x0000000100716246 in fputs_maybe_filtered (linebuffer=<optimized out>, stream=0x8002f8910, filter=0) at /usr/src/debug/gdb-10.2-1/gdb/utils.c:1828
> #14 0x00000001007174db in vfprintf_styled_no_gdbfmt (stream=0x8002f8910, style=..., filter=<optimized out>, format=<optimized out>, args=0xffffbe18 "") at /usr/lib/gcc/x86_64-pc-cygwin/10/include/c++/bits/basic_string.h:3360
> #15 0x0000000100482e57 in cli_ui_out::do_message (args=0xffffbe18 "", format=0x808ba1359 "]\n", style=..., this=0xffffbf30) at /usr/lib/gcc/x86_64-pc-cygwin/10/include/c++/bits/stl_iterator.h:953
> #16 cli_ui_out::do_message (this=0xffffbf30, style=..., format=0x808ba1359 "]\n", args=0xffffbe18 "") at /usr/src/debug/gdb-10.2-1/gdb/cli-out.c:227
> #17 0x000000010070f21e in ui_out::call_do_message (this=this@entry=0xffffbf30, style=..., format=<optimized out>) at /usr/src/debug/gdb-10.2-1/gdb/ui-out.c:597
> #18 0x000000010070f9db in ui_out::vmessage (this=this@entry=0xffffbf30, in_style=..., format=<optimized out>, format@entry=0x100970683 <dummy_target_info+1779> "[New %s]\n", args=0xffffc170 "\030", args@entry=0xffffc168 "8ĵ\t\b") at /usr/src/debug/gdb-10.2-1/gdb/ui-out.c:778
> #19 0x000000010071634c in vfprintf_maybe_filtered (stream=stream@entry=0x8002f8910, format=format@entry=0x100970683 <dummy_target_info+1779> "[New %s]\n", args=args@entry=0xffffc168 "8ĵ\t\b", filter=filter@entry=false, gdbfmt=gdbfmt@entry=true) at /usr/src/debug/gdb-10.2-1/gdb/utils.c:2064
> #20 0x00000001007154dc in vfprintf_unfiltered (stream=0x8002f8910, format=format@entry=0x100970683 <dummy_target_info+1779> "[New %s]\n", args=args@entry=0xffffc168 "8ĵ\t\b") at /usr/src/debug/gdb-10.2-1/gdb/utils.c:2107
> #21 0x0000000100715878 in printf_unfiltered (format=0x100970683 <dummy_target_info+1779> "[New %s]\n") at /usr/src/debug/gdb-10.2-1/gdb/utils.c:2218
> #22 0x00000001006e1f86 in add_thread_with_info (targ=targ@entry=0x100893b80 <the_windows_nat_target>, ptid=..., priv=priv@entry=0x0) at /usr/src/debug/gdb-10.2-1/gdb/thread.c:297
> #23 0x00000001006e2023 in add_thread (targ=targ@entry=0x100893b80 <the_windows_nat_target>, ptid=<error reading variable: Cannot access memory at address 0x0>) at /usr/src/debug/gdb-10.2-1/gdb/thread.c:306
> #24 0x000000010073906c in windows_add_thread (ptid=..., h=<optimized out>, tlb=<optimized out>, main_thread_p=main_thread_p@entry=false) at /usr/src/debug/gdb-10.2-1/gdb/windows-nat.c:451
> #25 0x000000010073999c in windows_nat_target::get_windows_debug_event (this=this@entry=0x100893b80 <the_windows_nat_target>, pid=pid@entry=-1, ourstatus=ourstatus@entry=0xffffca28) at /usr/src/debug/gdb-10.2-1/gdb/../gdbsupport/ptid.h:49
> #26 0x0000000100739c72 in windows_nat_target::wait (this=0x100893b80 <the_windows_nat_target>, ptid=..., ourstatus=0xffffca28, options=0) at /usr/src/debug/gdb-10.2-1/gdb/windows-nat.c:1801
> #27 0x00000001006d91cf in target_wait (ptid=..., status=status@entry=0xffffca28, options=options@entry=0) at /usr/src/debug/gdb-10.2-1/gdb/target.c:2017
> #28 0x0000000100593c2e in do_target_wait_1 (inf=inf@entry=0x800262c70, ptid=..., status=status@entry=0xffffca28, options=0, options@entry=1) at /usr/src/debug/gdb-10.2-1/gdb/infrun.c:3544
> #29 0x0000000100594058 in operator() (inf=0x800262c70, __closure=<synthetic pointer>) at /usr/src/debug/gdb-10.2-1/gdb/infrun.c:3606
> #30 do_target_wait (wait_ptid=..., ecs=ecs@entry=0xffffca00, options=options@entry=1) at /usr/src/debug/gdb-10.2-1/gdb/infrun.c:3619
> #31 0x00000001005a1f26 in fetch_inferior_event () at /usr/src/debug/gdb-10.2-1/gdb/infrun.c:3905
> #32 0x0000000100435d76 in check_async_event_handlers () at /usr/src/debug/gdb-10.2-1/gdb/async-event.c:295
> #33 0x0000000100803522 in gdb_do_one_event () at /usr/src/debug/gdb-10.2-1/gdbsupport/event-loop.cc:194
> #34 0x00000001005c0a1d in start_event_loop () at /usr/src/debug/gdb-10.2-1/gdb/main.c:356
> #35 captured_command_loop () at /usr/src/debug/gdb-10.2-1/gdb/main.c:416
> #36 0x00000001005c2b25 in captured_main (data=0xffffcb90) at /usr/src/debug/gdb-10.2-1/gdb/main.c:1253
> #37 gdb_main (args=args@entry=0xffffcbf0) at /usr/src/debug/gdb-10.2-1/gdb/main.c:1268
> #38 0x000000010087c3d9 in main (argc=9, argv=0xffffcc50) at /usr/src/debug/gdb-10.2-1/gdb/gdb.c:32
> 
> No other threads appear to be doing anything relevant. I believe the
> inferior process holds the mutex, but I haven't 100% confirmed that. I
> can't attach another debugger to it, so I'm not sure how I'd do that.
> 
> It looks like gdb is getting a new thread event (and trying to log it)
> while the inferior process has a lock on the inter-process output mutex.
> I'm not sure how we'd avoid a deadlock in that case.
> 
> I can reproduce this on 3.3.3 as well as master.
> 
> The mutexes were added in:
> 
> commit f4b47827cf87f055687a0c52a3485d42b3e2b941
> Author: Takashi Yano <takashi.yano@nifty.ne.jp>
> Date:   Mon Apr 1 00:47:48 2019 +0900
> 
>     Cygwin: console: Make I/O functions thread-safe
> 
>     - POSIX states I/O functions shall be thread-safe, however, cygwin
>       console I/O functions were not. This patch makes console I/O
>       functions thread-safe.

Thanks for the report.
Could you provide simple test case in C?

-- 
Takashi Yano <takashi.yano@nifty.ne.jp>