deadlock on console mutex in gdb

Wed Dec 22 15:26:54 GMT 2021

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.