[PATCH v2 1/3] [gdb/dap] Factor out thread_log

[PATCH v2 1/3] [gdb/dap] Factor out thread_log

[Tom de Vries]

In thread_wrapper I used a style where a message is prefixed with the thread
name.

Factor this out into a new function thread_log.

Also treat the GDB main thread special, because it's usual name is MainThread:
...
MainThread: <msg>
...
which is the default name assigned by python, so instead use the more
explicit:
...
GDB main: <msg>
...

Tested on aarch64-linux.
---
 gdb/python/lib/gdb/dap/startup.py | 15 ++++++++++++---
 1 file changed, 12 insertions(+), 3 deletions(-)

diff --git a/gdb/python/lib/gdb/dap/startup.py b/gdb/python/lib/gdb/dap/startup.py
index 0a42c91e8f4..29fe78ecd53 100644
--- a/gdb/python/lib/gdb/dap/startup.py
+++ b/gdb/python/lib/gdb/dap/startup.py
@@ -64,7 +64,6 @@ def start_thread(name, target, args=()):
     correctly blocked."""
 
     def thread_wrapper(*args):
-        thread_name = threading.current_thread().name
         # Catch any exception, and log it.  If we let it escape here, it'll be
         # printed in gdb_stderr, which is not safe to access from anywhere but
         # gdb's main thread.
@@ -72,11 +71,11 @@ def start_thread(name, target, args=()):
             target(*args)
         except Exception as err:
             err_string = "%s, %s" % (err, type(err))
-            log(thread_name + ": caught exception: " + err_string)
+            thread_log("caught exception: " + err_string)
             log_stack()
         finally:
             # Log when a thread terminates.
-            log(thread_name + ": terminating")
+            thread_log("terminating")
 
     result = gdb.Thread(name=name, target=thread_wrapper, args=args, daemon=True)
     result.start()
@@ -178,6 +177,16 @@ def log(something, level=LogLevel.DEFAULT):
             dap_log.log_file.flush()
 
 
+def thread_log(something, level=LogLevel.DEFAULT):
+    """Log SOMETHING to the log file, if logging is enabled, and prefix
+    the thread name."""
+    if threading.current_thread() is _gdb_thread:
+        thread_name = "GDB main"
+    else:
+        thread_name = threading.current_thread().name
+    log(thread_name + ": " + something, level)
+
+
 def log_stack(level=LogLevel.DEFAULT):
     """Log a stack trace to the log file, if logging is enabled."""
     with dap_log.lock:

base-commit: 7c34de9efdb13fff482ed0c4de0dffee1e1880f3
-- 
2.35.3

[PATCH v2 2/3] [gdb/dap] Fix race between dap startup and dap log file

[Tom de Vries]

In dap_gdb_start we do:
...
        append GDBFLAGS " -iex \"set debug dap-log-file $logfile\" -q -i=dap"
...

While the dap log file setting comes before the dap interpreter setting,
the order is the other way around:
- first, the dap interpreter is started
- second, the -iex commands are executed and the log file is initialized.

Consequently, there's a race between dap interpreter startup and dap log file
initialization.

This cannot be fixed by using -eiex instead.  Before the interpreter is
started, the "set debug dap-log-file" command is not yet registered.

Fix this by postponing the start of the DAP server until GDB has processed all
command files.

Tested on aarch64-linux.

PR dap/31386
Bug: https://sourceware.org/bugzilla/show_bug.cgi?id=31386
---
 gdb/python/lib/gdb/dap/__init__.py | 20 +++++++++++++++++++-
 gdb/python/py-dap.c                | 23 ++++++++++++++++++++---
 gdb/testsuite/gdb.dap/eof.exp      |  3 +++
 gdb/testsuite/lib/dap-support.exp  | 10 ++++++++++
 4 files changed, 52 insertions(+), 4 deletions(-)

diff --git a/gdb/python/lib/gdb/dap/__init__.py b/gdb/python/lib/gdb/dap/__init__.py
index f60b3fda1db..86da9b8ef3c 100644
--- a/gdb/python/lib/gdb/dap/__init__.py
+++ b/gdb/python/lib/gdb/dap/__init__.py
@@ -69,5 +69,23 @@ def run():
     os.close(wfd)
 
     # Note the inferior output is opened in text mode.
+    global server
     server = Server(open(saved_in, "rb"), open(saved_out, "wb"), open(rfd, "r"))
-    startup.start_dap(server.main_loop)
+
+
+# Whether the interactive session has started.
+session_started = False
+
+
+def pre_command_loop():
+    """DAP's pre_command_loop interpreter hook.  This is called by the GDB DAP
+    interpreter."""
+    global session_started
+    if not session_started:
+        # The pre_command_loop interpreter hook can be called several times.
+        # The first time it's called, it means we're starting an interactive
+        # session.
+        session_started = True
+        startup.thread_log("starting DAP server")
+        global server
+        startup.start_dap(server.main_loop)
diff --git a/gdb/python/py-dap.c b/gdb/python/py-dap.c
index 5757c150165..2034105c939 100644
--- a/gdb/python/py-dap.c
+++ b/gdb/python/py-dap.c
@@ -61,13 +61,18 @@ class dap_interp final : public interp
     return m_ui_out.get ();
   }
 
+  void pre_command_loop () override;
+
 private:
 
   std::unique_ptr<ui_out> m_ui_out;
 };
 
-void
-dap_interp::init (bool top_level)
+
+/* Call function FN_NAME from module gdb.dap. */
+
+static void
+call_dap_fn (const char *fn_name)
 {
   gdbpy_enter enter_py;
 
@@ -75,18 +80,30 @@ dap_interp::init (bool top_level)
   if (dap_module == nullptr)
     gdbpy_handle_exception ();
 
-  gdbpy_ref<> func (PyObject_GetAttrString (dap_module.get (), "run"));
+  gdbpy_ref<> func (PyObject_GetAttrString (dap_module.get (), fn_name));
   if (func == nullptr)
     gdbpy_handle_exception ();
 
   gdbpy_ref<> result_obj (PyObject_CallObject (func.get (), nullptr));
   if (result_obj == nullptr)
     gdbpy_handle_exception ();
+}
+
+void
+dap_interp::init (bool top_level)
+{
+  call_dap_fn ("run");
 
   current_ui->input_fd = -1;
   current_ui->m_input_interactive_p = false;
 }
 
+void
+dap_interp::pre_command_loop ()
+{
+  call_dap_fn ("pre_command_loop");
+}
+
 void _initialize_py_interp ();
 void
 _initialize_py_interp ()
diff --git a/gdb/testsuite/gdb.dap/eof.exp b/gdb/testsuite/gdb.dap/eof.exp
index 9c17725c0d0..a84b1d21e04 100644
--- a/gdb/testsuite/gdb.dap/eof.exp
+++ b/gdb/testsuite/gdb.dap/eof.exp
@@ -35,3 +35,6 @@ catch "wait -i $gdb_spawn_id"
 unset gdb_spawn_id
 
 dap_check_log_file
+
+# Check that first log message is present.
+dap_check_log_file_re [string_to_regexp "starting DAP server"]
diff --git a/gdb/testsuite/lib/dap-support.exp b/gdb/testsuite/lib/dap-support.exp
index 31f036eddf2..5818d815df3 100644
--- a/gdb/testsuite/lib/dap-support.exp
+++ b/gdb/testsuite/lib/dap-support.exp
@@ -366,6 +366,16 @@ proc dap_check_log_file {} {
     }
 }
 
+# Read the most recent DAP log file and check that regexp RE matches.
+proc dap_check_log_file_re { re } {
+    set fd [open [current_dap_log_file]]
+    set contents [read $fd]
+    close $fd
+
+    set ok [regexp $re $contents]
+    gdb_assert {$ok} "log file matched $re"
+}
+
 # Cleanly shut down gdb.  TERMINATE is passed as the terminateDebuggee
 # parameter to the request.
 proc dap_shutdown {{terminate false}} {
-- 
2.35.3

Re: [PATCH v2 2/3] [gdb/dap] Fix race between dap startup and dap log file

[Tom Tromey]

>>>>> "Tom" == Tom de Vries <tdevries@suse.de> writes:

Tom> Fix this by postponing the start of the DAP server until GDB has processed all
Tom> command files.

Looks good, thanks.
Approved-By: Tom Tromey <tom@tromey.com>

Tom

[PATCH v2 3/3] [gdb/dap] Fix race between dap exit and gdb exit

[Tom de Vries]

When DAP shuts down due to an EOF event, there's a race between:
- gdb's main thread handling a SIGHUP, and
- the DAP main thread exiting.

Fix this by waiting for DAP's main thread exit during the gdb_exiting event.

Tested on aarch64-linux.

PR dap/31380
Bug: https://sourceware.org/bugzilla/show_bug.cgi?id=31380
---
 gdb/python/lib/gdb/dap/startup.py | 20 +++++++++++++++++++-
 gdb/testsuite/gdb.dap/eof.exp     |  9 +++++++++
 2 files changed, 28 insertions(+), 1 deletion(-)

diff --git a/gdb/python/lib/gdb/dap/startup.py b/gdb/python/lib/gdb/dap/startup.py
index 29fe78ecd53..38a2e295e07 100644
--- a/gdb/python/lib/gdb/dap/startup.py
+++ b/gdb/python/lib/gdb/dap/startup.py
@@ -93,7 +93,9 @@ def start_dap(target):
         _dap_thread = threading.current_thread()
         target()
 
-    start_thread("DAP", really_start_dap)
+    # Note that we set _dap_thread in both the DAP and the GDB main thread.
+    global _dap_thread
+    _dap_thread = start_thread("DAP", really_start_dap)
 
 
 def in_gdb_thread(func):
@@ -208,6 +210,22 @@ def exec_and_log(cmd):
         log_stack()
 
 
+@in_gdb_thread
+def _on_gdb_exiting(event):
+    if _dap_thread is None:
+        # This can happen if the DAP module is imported, but the server not
+        # started.
+        thread_log("no dap thread to join")
+        return
+
+    thread_log("joining dap thread ...")
+    _dap_thread.join()
+    thread_log("joining dap thread done")
+
+
+gdb.events.gdb_exiting.connect(_on_gdb_exiting)
+
+
 class Invoker(object):
     """A simple class that can invoke a gdb command."""
 
diff --git a/gdb/testsuite/gdb.dap/eof.exp b/gdb/testsuite/gdb.dap/eof.exp
index a84b1d21e04..05048f2762a 100644
--- a/gdb/testsuite/gdb.dap/eof.exp
+++ b/gdb/testsuite/gdb.dap/eof.exp
@@ -38,3 +38,12 @@ dap_check_log_file
 
 # Check that first log message is present.
 dap_check_log_file_re [string_to_regexp "starting DAP server"]
+
+# There should be one "READ:" for the initialize request, and at least one
+# "WROTE:" for the initialize response.
+dap_check_log_file_re "READ:"
+dap_check_log_file_re "WROTE:"
+
+# Check that all thread termination messages are there.
+dap_check_log_file_re "JSON writer: terminating"
+dap_check_log_file_re "DAP: terminating"
-- 
2.35.3

Re: [PATCH v2 3/3] [gdb/dap] Fix race between dap exit and gdb exit

[Tom Tromey]

>>>>> "Tom" == Tom de Vries <tdevries@suse.de> writes:

Tom> When DAP shuts down due to an EOF event, there's a race between:
Tom> - gdb's main thread handling a SIGHUP, and
Tom> - the DAP main thread exiting.

Tom> Fix this by waiting for DAP's main thread exit during the gdb_exiting event.

Tom> Tested on aarch64-linux.

Thanks, this is ok.
Approved-By: Tom Tromey <tom@tromey.com>

Tom> -    start_thread("DAP", really_start_dap)
Tom> +    # Note that we set _dap_thread in both the DAP and the GDB main thread.
Tom> +    global _dap_thread
Tom> +    _dap_thread = start_thread("DAP", really_start_dap)

Tom> +@in_gdb_thread
Tom> +def _on_gdb_exiting(event):
Tom> +    if _dap_thread is None:
Tom> +        # This can happen if the DAP module is imported, but the server not
Tom> +        # started.
Tom> +        thread_log("no dap thread to join")
Tom> +        return
Tom> +
Tom> +    thread_log("joining dap thread ...")
Tom> +    _dap_thread.join()
Tom> +    thread_log("joining dap thread done")
Tom> +
Tom> +
Tom> +gdb.events.gdb_exiting.connect(_on_gdb_exiting)

Originally I'd just pictured something like:

  local = start_thread("DAP", ...)
  gdb.events.gdb_exiting.connect(local.join)

... but wanting logging makes sense I suppose.
The global could still be removed if you care by a nested function.

Tom

Re: [PATCH v2 3/3] [gdb/dap] Fix race between dap exit and gdb exit

[Tom de Vries]

[-- Attachment #1: Type: text/plain, Size: 1632 bytes --]

On 2/21/24 22:10, Tom Tromey wrote:
>>>>>> "Tom" == Tom de Vries <tdevries@suse.de> writes:
> 
> Tom> When DAP shuts down due to an EOF event, there's a race between:
> Tom> - gdb's main thread handling a SIGHUP, and
> Tom> - the DAP main thread exiting.
> 
> Tom> Fix this by waiting for DAP's main thread exit during the gdb_exiting event.
> 
> Tom> Tested on aarch64-linux.
> 
> Thanks, this is ok.
> Approved-By: Tom Tromey <tom@tromey.com>
> 

Thanks for the review.

> Tom> -    start_thread("DAP", really_start_dap)
> Tom> +    # Note that we set _dap_thread in both the DAP and the GDB main thread.
> Tom> +    global _dap_thread
> Tom> +    _dap_thread = start_thread("DAP", really_start_dap)
> 
> Tom> +@in_gdb_thread
> Tom> +def _on_gdb_exiting(event):
> Tom> +    if _dap_thread is None:
> Tom> +        # This can happen if the DAP module is imported, but the server not
> Tom> +        # started.
> Tom> +        thread_log("no dap thread to join")
> Tom> +        return
> Tom> +
> Tom> +    thread_log("joining dap thread ...")
> Tom> +    _dap_thread.join()
> Tom> +    thread_log("joining dap thread done")
> Tom> +
> Tom> +
> Tom> +gdb.events.gdb_exiting.connect(_on_gdb_exiting)
> 
> Originally I'd just pictured something like:
> 
>    local = start_thread("DAP", ...)
>    gdb.events.gdb_exiting.connect(local.join)
> 

Aha, I see.

> ... but wanting logging makes sense I suppose.
> The global could still be removed if you care by a nested function.

Done.

I've also make changed the log messages to use DAP upper-case, to be in 
sync with other uses in the log file.

Committed as attached.

Thanks,
- Tom

[-- Attachment #2: 0003-gdb-dap-Fix-race-between-dap-exit-and-gdb-exit.patch --]
[-- Type: text/x-patch, Size: 2127 bytes --]

From a32972a8a52463d5e5779b107dfd3a7c4edf0f55 Mon Sep 17 00:00:00 2001
From: Tom de Vries <tdevries@suse.de>
Date: Sat, 17 Feb 2024 14:04:43 +0100
Subject: [PATCH 3/3] [gdb/dap] Fix race between dap exit and gdb exit

When DAP shuts down due to an EOF event, there's a race between:
- gdb's main thread handling a SIGHUP, and
- the DAP main thread exiting.

Fix this by waiting for DAP's main thread exit during the gdb_exiting event.

Tested on aarch64-linux.

Approved-By: Tom Tromey <tom@tromey.com>

PR dap/31380
Bug: https://sourceware.org/bugzilla/show_bug.cgi?id=31380
---
 gdb/python/lib/gdb/dap/startup.py | 10 +++++++++-
 gdb/testsuite/gdb.dap/eof.exp     |  9 +++++++++
 2 files changed, 18 insertions(+), 1 deletion(-)

diff --git a/gdb/python/lib/gdb/dap/startup.py b/gdb/python/lib/gdb/dap/startup.py
index 29fe78ecd53..a2b68996dba 100644
--- a/gdb/python/lib/gdb/dap/startup.py
+++ b/gdb/python/lib/gdb/dap/startup.py
@@ -93,7 +93,15 @@ def start_dap(target):
         _dap_thread = threading.current_thread()
         target()
 
-    start_thread("DAP", really_start_dap)
+    # Note: unlike _dap_thread, dap_thread is a local variable.
+    dap_thread = start_thread("DAP", really_start_dap)
+
+    def _on_gdb_exiting(event):
+        thread_log("joining DAP thread ...")
+        dap_thread.join()
+        thread_log("joining DAP thread done")
+
+    gdb.events.gdb_exiting.connect(_on_gdb_exiting)
 
 
 def in_gdb_thread(func):
diff --git a/gdb/testsuite/gdb.dap/eof.exp b/gdb/testsuite/gdb.dap/eof.exp
index a84b1d21e04..05048f2762a 100644
--- a/gdb/testsuite/gdb.dap/eof.exp
+++ b/gdb/testsuite/gdb.dap/eof.exp
@@ -38,3 +38,12 @@ dap_check_log_file
 
 # Check that first log message is present.
 dap_check_log_file_re [string_to_regexp "starting DAP server"]
+
+# There should be one "READ:" for the initialize request, and at least one
+# "WROTE:" for the initialize response.
+dap_check_log_file_re "READ:"
+dap_check_log_file_re "WROTE:"
+
+# Check that all thread termination messages are there.
+dap_check_log_file_re "JSON writer: terminating"
+dap_check_log_file_re "DAP: terminating"
-- 
2.35.3

Re: [PATCH v2 1/3] [gdb/dap] Factor out thread_log

[Tom Tromey]

>>>>> "Tom" == Tom de Vries <tdevries@suse.de> writes:

Tom> In thread_wrapper I used a style where a message is prefixed with the thread
Tom> name.

Tom> Factor this out into a new function thread_log.

Tom> Also treat the GDB main thread special, because it's usual name is MainThread:
Tom> ...
Tom> MainThread: <msg>
Tom> ...
Tom> which is the default name assigned by python, so instead use the more
Tom> explicit:
Tom> ...
Tom> GDB main: <msg>
Tom> ...

Thanks, this is ok.
Approved-By: Tom Tromey <tom@tromey.com>

Tom