[Bug dap/31386] New: [gdb/dap] Race between dap startup and dap log file initialization

[Bug dap/31386] New: [gdb/dap] Race between dap startup and dap log file initialization

[vries at gcc dot gnu.org]

https://sourceware.org/bugzilla/show_bug.cgi?id=31386

            Bug ID: 31386
           Summary: [gdb/dap] Race between dap startup and dap log file
                    initialization
           Product: gdb
           Version: HEAD
            Status: NEW
          Severity: normal
          Priority: P2
         Component: dap
          Assignee: unassigned at sourceware dot org
          Reporter: vries at gcc dot gnu.org
  Target Milestone: ---

In dap-support.exp, 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, that's
not the order in which things happen.

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

The logging procs are setup to just do nothing if the log file is not yet
initialized.

I found this by adding this to gdb.dap/eof.exp (dap_check_log_file_re not yet
in trunk):
...
diff --git a/gdb/testsuite/gdb.dap/eof.exp b/gdb/testsuite/gdb.dap/eof.exp
index 9c17725c0d0..a64ac227880 100644
--- a/gdb/testsuite/gdb.dap/eof.exp
+++ b/gdb/testsuite/gdb.dap/eof.exp
@@ -35,3 +35,8 @@ catch "wait -i $gdb_spawn_id"
 unset gdb_spawn_id

 dap_check_log_file
+dap_check_log_file_re "JSON writer: terminating"
+dap_check_log_file_re "JSON reader: terminating"
+dap_check_log_file_re "DAP: terminating"
+dap_check_log_file_re "WROTE:"
+dap_check_log_file_re "READ:"
...
and the last check fails regularly, because the initial request:
...
READ: <<<{"seq": 1, "type": "request", "command": "initialize", "arguments":
{"clientID": "gdb testsuite", "supportsVariableType": true,
"supportsVariablePaging": true, "supportsMemoryReferences": true}}>>>
...
is often not logged.

I also tried using -eiex but that happens before interpreter setup, which means
the "set debug dap-log-file" command hasn't been setup yet, so there's no log
file at all.

I wondered whether to classify with component testsuite, but I think it should
be dap because it's a bug if we can't log a complete dap session.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug dap/31386] [gdb/dap] Race between dap startup and dap log file initialization

[vries at gcc dot gnu.org]

https://sourceware.org/bugzilla/show_bug.cgi?id=31386

--- Comment #1 from Tom de Vries <vries at gcc dot gnu.org> ---
One way to address this is to keep the log in a string until a file is set.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug dap/31386] [gdb/dap] Race between dap startup and dap log file initialization

[tromey at sourceware dot org]

https://sourceware.org/bugzilla/show_bug.cgi?id=31386

Tom Tromey <tromey at sourceware dot org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |tromey at sourceware dot org

--- Comment #2 from Tom Tromey <tromey at sourceware dot org> ---
(In reply to Tom de Vries from comment #1)
> One way to address this is to keep the log in a string until a file is set.

That may never happen, so we'd end up accumulating a large string.

There should probably be some way for the DAP interpreter to not
start accepting requests until all the command-line options have
been handled.  Maybe a new interpreter method is needed.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug dap/31386] [gdb/dap] Race between dap startup and dap log file initialization

[vries at gcc dot gnu.org]

https://sourceware.org/bugzilla/show_bug.cgi?id=31386

--- Comment #3 from Tom de Vries <vries at gcc dot gnu.org> ---
(In reply to Tom Tromey from comment #2)
> (In reply to Tom de Vries from comment #1)
> > One way to address this is to keep the log in a string until a file is set.
> 

I have a patch for this.

> That may never happen, so we'd end up accumulating a large string.
> 
> There should probably be some way for the DAP interpreter to not
> start accepting requests until all the command-line options have
> been handled.  Maybe a new interpreter method is needed.

I've written a patch adding a gdb_starting_session observer/event (based on
gdb_exiting), which can be used for this.

However, when trying to use this into dap I noticed that the first log is done
by dap setup in the gdb main thread, so that's too early to fix in this way.

The way to fix this is start log output in a string.  At the
gdb_starting_session event, we either:
- have switched over to a log file, in which case the string is already
printed, or,
- have not switched over to a log file, in which case we discard the string and
  stop collecting the output in a string.

So, I'll combine the two patches to fix this.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug dap/31386] [gdb/dap] Race between dap startup and dap log file initialization

[vries at gcc dot gnu.org]

https://sourceware.org/bugzilla/show_bug.cgi?id=31386

--- Comment #4 from Tom de Vries <vries at gcc dot gnu.org> ---
FYI, I have a fix as part of this (
https://github.com/vries/gdb/pull/new/dap/exiting-race-4 ) branch.  To be
submitted once cleaned up.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug dap/31386] [gdb/dap] Race between dap startup and dap log file initialization

[tromey at sourceware dot org]

https://sourceware.org/bugzilla/show_bug.cgi?id=31386

--- Comment #5 from Tom Tromey <tromey at sourceware dot org> ---
I don't think you need a new event, just a new interpreter
method; and then split the DAP initialization in two.
Very early logging (before the "true" startup) probably
isn't interesting anyway.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug dap/31386] [gdb/dap] Race between dap startup and dap log file initialization

[vries at gcc dot gnu.org]

https://sourceware.org/bugzilla/show_bug.cgi?id=31386

--- Comment #6 from Tom de Vries <vries at gcc dot gnu.org> ---
Fix submitted as part of this (
https://sourceware.org/pipermail/gdb-patches/2024-February/206652.html )
series.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug dap/31386] [gdb/dap] Race between dap startup and dap log file initialization

[vries at gcc dot gnu.org]

https://sourceware.org/bugzilla/show_bug.cgi?id=31386

--- Comment #7 from Tom de Vries <vries at gcc dot gnu.org> ---
(In reply to Tom Tromey from comment #5)
> I don't think you need a new event, just a new interpreter
> method; and then split the DAP initialization in two.

I managed to use the existing interpreter method pre_command_loop.

> Very early logging (before the "true" startup) probably
> isn't interesting anyway.

Not sure what the true start is, but AFAICT the first thing DAP does is log a
message with the command it's about to run:
...
def run():
    """Main entry point for the DAP server.                                     
    This is called by the GDB DAP interpreter."""
    startup.exec_and_log("set python print-stack full")
...

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug dap/31386] [gdb/dap] Race between dap startup and dap log file initialization

[cvs-commit at gcc dot gnu.org]

https://sourceware.org/bugzilla/show_bug.cgi?id=31386

--- Comment #8 from Sourceware Commits <cvs-commit at gcc dot gnu.org> ---
The master branch has been updated by Tom de Vries <vries@sourceware.org>:

https://sourceware.org/git/gitweb.cgi?p=binutils-gdb.git;h=05bf17f03b890424312163463754de63cee73074

commit 05bf17f03b890424312163463754de63cee73074
Author: Tom de Vries <tdevries@suse.de>
Date:   Thu Feb 22 11:35:26 2024 +0100

    [gdb/dap] Fix race between dap startup and dap log file

    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.

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

    PR dap/31386
    Bug: https://sourceware.org/bugzilla/show_bug.cgi?id=31386

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug dap/31386] [gdb/dap] Race between dap startup and dap log file initialization

[vries at gcc dot gnu.org]

https://sourceware.org/bugzilla/show_bug.cgi?id=31386

Tom de Vries <vries at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
   Target Milestone|---                         |15.1
             Status|NEW                         |RESOLVED
         Resolution|---                         |FIXED

--- Comment #9 from Tom de Vries <vries at gcc dot gnu.org> ---
Fixed.

-- 
You are receiving this mail because:
You are on the CC list for the bug.