[PATCH 0/4] Change how stdlog timestamps are written

[PATCH 0/4] Change how stdlog timestamps are written

[Tom Tromey]

I've been looking at the GDB ui_file and pager system to see if it can
be made more understandable -- right now it's fairly spaghetti-ish,
with ui_file calling into functions in util.c, that then dispatch back
to ui_file.  My vision for the endpoint is something along the lines
of Java's stream writers, where additional functionality is provided
by just instantiating some new writer to wrap an existing one.

This series is a step toward that long-term goal.  It changes how
gdb_stdlog timestamps are written, moving this into a new ui_file
subclass.  This avoids a special case (which may in some situations be
incorrect, see patch #4) in vfprintf_unfiltered.

Regression tested on x86-64 Fedora 34.

Let me know what you think.

Tom

[PATCH 1/4] Simplify the CLI set_logging logic

[Tom Tromey]

The CLI's set_logging logic seemed unnecessarily complicated to me.
This patch simplifies it, with an eye toward changing it to use RAII
objects in a subsequent patch.

I did not touch the corresponding MI code.  That code seems incorrect
(nothing ever uses raw_stdlog, and nothing ever sets
saved_raw_stdlog).  I didn't attempt to fix this, because I question
whether this is even useful for MI.
---
 gdb/cli/cli-interp.c | 20 ++++----------------
 1 file changed, 4 insertions(+), 16 deletions(-)

diff --git a/gdb/cli/cli-interp.c b/gdb/cli/cli-interp.c
index 47d1eff0547..3094775c9f5 100644
--- a/gdb/cli/cli-interp.c
+++ b/gdb/cli/cli-interp.c
@@ -412,31 +412,19 @@ cli_interp_base::set_logging (ui_file_up logfile, bool logging_redirect,
       saved_output.log = gdb_stdlog;
       saved_output.targ = gdb_stdtarg;
       saved_output.targerr = gdb_stdtargerr;
-
-      /* If something is being redirected, then grab logfile.  */
-      ui_file *logfile_p = nullptr;
-      if (logging_redirect || debug_redirect)
-	{
-	  logfile_p = logfile.get ();
-	  saved_output.file_to_delete = logfile_p;
-	}
+      gdb_assert (saved_output.file_to_delete == nullptr);
 
       /* If something is not being redirected, then a tee containing both the
 	 logfile and stdout.  */
+      ui_file *logfile_p = logfile.get ();
       ui_file *tee = nullptr;
       if (!logging_redirect || !debug_redirect)
 	{
 	  tee = new tee_file (gdb_stdout, std::move (logfile));
 	  saved_output.file_to_delete = tee;
 	}
-
-      /* Make sure that the call to logfile's dtor does not delete the
-         underlying pointer if we still keep a reference to it.  If
-         logfile_p is not referenced as the file_to_delete, then either
-         the logfile is not used (no redirection) and it should be
-         deleted, or a tee took ownership of the pointer. */
-      if (logfile_p != nullptr && saved_output.file_to_delete == logfile_p)
-	logfile.release ();
+      else
+	saved_output.file_to_delete = logfile.release ();
 
       gdb_stdout = logging_redirect ? logfile_p : tee;
       gdb_stdlog = debug_redirect ? logfile_p : tee;
-- 
2.31.1

[PATCH 2/4] Use unique_ptr in CLI logging code

[Tom Tromey]

This changes the CLI logging code to avoid manual memory management
(to the extent possible) by using unique_ptr in a couple of spots.
This will come in handy in a later patch.
---
 gdb/cli/cli-interp.c | 43 +++++++++++++++++--------------------------
 1 file changed, 17 insertions(+), 26 deletions(-)

diff --git a/gdb/cli/cli-interp.c b/gdb/cli/cli-interp.c
index 3094775c9f5..031ab10aea6 100644
--- a/gdb/cli/cli-interp.c
+++ b/gdb/cli/cli-interp.c
@@ -395,9 +395,9 @@ struct saved_output_files
   ui_file *log;
   ui_file *targ;
   ui_file *targerr;
-  ui_file *file_to_delete;
+  ui_file_up file_to_delete;
 };
-static saved_output_files saved_output;
+static std::unique_ptr<saved_output_files> saved_output;
 
 /* See cli-interp.h.  */
 
@@ -407,12 +407,12 @@ cli_interp_base::set_logging (ui_file_up logfile, bool logging_redirect,
 {
   if (logfile != nullptr)
     {
-      saved_output.out = gdb_stdout;
-      saved_output.err = gdb_stderr;
-      saved_output.log = gdb_stdlog;
-      saved_output.targ = gdb_stdtarg;
-      saved_output.targerr = gdb_stdtargerr;
-      gdb_assert (saved_output.file_to_delete == nullptr);
+      saved_output.reset (new saved_output_files);
+      saved_output->out = gdb_stdout;
+      saved_output->err = gdb_stderr;
+      saved_output->log = gdb_stdlog;
+      saved_output->targ = gdb_stdtarg;
+      saved_output->targerr = gdb_stdtargerr;
 
       /* If something is not being redirected, then a tee containing both the
 	 logfile and stdout.  */
@@ -421,10 +421,10 @@ cli_interp_base::set_logging (ui_file_up logfile, bool logging_redirect,
       if (!logging_redirect || !debug_redirect)
 	{
 	  tee = new tee_file (gdb_stdout, std::move (logfile));
-	  saved_output.file_to_delete = tee;
+	  saved_output->file_to_delete.reset (tee);
 	}
       else
-	saved_output.file_to_delete = logfile.release ();
+	saved_output->file_to_delete = std::move (logfile);
 
       gdb_stdout = logging_redirect ? logfile_p : tee;
       gdb_stdlog = debug_redirect ? logfile_p : tee;
@@ -434,22 +434,13 @@ cli_interp_base::set_logging (ui_file_up logfile, bool logging_redirect,
     }
   else
     {
-      /* Delete the correct file.  If it's the tee then the logfile will also
-	 be deleted.  */
-      delete saved_output.file_to_delete;
-
-      gdb_stdout = saved_output.out;
-      gdb_stderr = saved_output.err;
-      gdb_stdlog = saved_output.log;
-      gdb_stdtarg = saved_output.targ;
-      gdb_stdtargerr = saved_output.targerr;
-
-      saved_output.out = nullptr;
-      saved_output.err = nullptr;
-      saved_output.log = nullptr;
-      saved_output.targ = nullptr;
-      saved_output.targerr = nullptr;
-      saved_output.file_to_delete = nullptr;
+      gdb_stdout = saved_output->out;
+      gdb_stderr = saved_output->err;
+      gdb_stdlog = saved_output->log;
+      gdb_stdtarg = saved_output->targ;
+      gdb_stdtargerr = saved_output->targerr;
+
+      saved_output.reset (nullptr);
     }
 }
 
-- 
2.31.1

[PATCH 3/4] Add new timestamped_file class

[Tom Tromey]

This adds a "timestamped_file" subclass of ui_file.  This class adds a
timestamp to its output when appropriate.  That is, it follows the
rule already used in vfprintf_unfiltered of adding a timestamp at most
once per write.

The new class is not yet used.
---
 gdb/ui-file.c | 29 +++++++++++++++++++++++++++++
 gdb/ui-file.h | 24 ++++++++++++++++++++++++
 gdb/utils.c   |  2 +-
 gdb/utils.h   |  3 +++
 4 files changed, 57 insertions(+), 1 deletion(-)

diff --git a/gdb/ui-file.c b/gdb/ui-file.c
index eb1d72bf8b3..d0e3ef87d6a 100644
--- a/gdb/ui-file.c
+++ b/gdb/ui-file.c
@@ -25,6 +25,7 @@
 #include "gdbsupport/gdb_select.h"
 #include "gdbsupport/filestuff.h"
 #include "cli/cli-style.h"
+#include <chrono>
 
 null_file null_stream;
 
@@ -386,3 +387,31 @@ no_terminal_escape_file::puts (const char *buf)
   if (*buf != '\0')
     this->stdio_file::write (buf, strlen (buf));
 }
+
+void
+timestamped_file::write (const char *buf, long len)
+{
+  if (debug_timestamp)
+    {
+      /* Print timestamp if previous print ended with a \n.  */
+      if (m_needs_timestamp)
+	{
+	  using namespace std::chrono;
+
+	  steady_clock::time_point now = steady_clock::now ();
+	  seconds s = duration_cast<seconds> (now.time_since_epoch ());
+	  microseconds us = duration_cast<microseconds> (now.time_since_epoch () - s);
+	  std::string timestamp = string_printf ("%ld.%06ld ",
+						 (long) s.count (),
+						 (long) us.count ());
+	  m_stream->puts (timestamp.c_str ());
+	}
+
+      /* Print the message.  */
+      m_stream->write (buf, len);
+
+      m_needs_timestamp = (len > 0 && buf[len - 1] == '\n');
+    }
+  else
+    m_stream->write (buf, len);
+}
diff --git a/gdb/ui-file.h b/gdb/ui-file.h
index 0faf84996aa..07b79995540 100644
--- a/gdb/ui-file.h
+++ b/gdb/ui-file.h
@@ -320,4 +320,28 @@ class no_terminal_escape_file : public stdio_file
   void puts (const char *linebuffer) override;
 };
 
+/* A ui_file that optionally puts a timestamp at the start of each
+   line of output.  */
+
+class timestamped_file : public ui_file
+{
+public:
+  explicit timestamped_file (ui_file *stream)
+    : m_stream (stream)
+  {
+  }
+
+  DISABLE_COPY_AND_ASSIGN (timestamped_file);
+
+  void write (const char *buf, long len) override;
+
+private:
+
+  /* Output is sent here.  */
+  ui_file *m_stream;
+
+  /* True if the next output should be timestamped.  */
+  bool m_needs_timestamp = true;
+};
+
 #endif
diff --git a/gdb/utils.c b/gdb/utils.c
index f8c898dd502..fc460d20321 100644
--- a/gdb/utils.c
+++ b/gdb/utils.c
@@ -102,7 +102,7 @@ static std::chrono::steady_clock::duration prompt_for_continue_wait_time;
 
 /* A flag indicating whether to timestamp debugging messages.  */
 
-static bool debug_timestamp = false;
+bool debug_timestamp = false;
 
 /* True means that strings with character values >0x7F should be printed
    as octal escapes.  False means just print the value (e.g. it's an
diff --git a/gdb/utils.h b/gdb/utils.h
index 54cf090974a..35287c999d5 100644
--- a/gdb/utils.h
+++ b/gdb/utils.h
@@ -377,6 +377,9 @@ extern int get_chars_per_line ();
 
 extern bool pagination_enabled;
 
+/* A flag indicating whether to timestamp debugging messages.  */
+extern bool debug_timestamp;
+
 extern struct ui_file **current_ui_gdb_stdout_ptr (void);
 extern struct ui_file **current_ui_gdb_stdin_ptr (void);
 extern struct ui_file **current_ui_gdb_stderr_ptr (void);
-- 
2.31.1

[PATCH 4/4] Switch gdb_stdlog to use timestamped_file

[Tom Tromey]

Currently, timestamps for logging are done by looking for the use of
gdb_stdlog in vfprintf_unfiltered.  This seems potentially buggy, in
that during logging or other redirects (like execute_fn_to_ui_file) we
might have gdb_stdout==gdb_stdlog and so, conceivably, wind up with
timestamps in a log when they were not desired.

It seems better, instead, for timestamps to be a property of the
ui_file itself.

This patch changes gdb to use the new timestamped_file for gdb_stdlog
where appropriate, and removes the special case from
vfprintf_unfiltered.

Note that this may somewhat change the output in some cases -- in
particular, when going through execute_fn_to_ui_file (or the _string
variant), timestamps won't be emitted.  This could be fixed in those
functions, but it wasn't clear to me whether this is really desirable.

Note also that this changes the TUI to send gdb_stdlog to gdb_stderr.
I imagine that the previous use of gdb_stdout here was inadvertent.
(And in any case it probably doesn't matter.)
---
 gdb/cli/cli-interp.c |  6 +++++-
 gdb/event-top.c      |  2 +-
 gdb/tui/tui-io.c     |  8 ++++++--
 gdb/utils.c          | 30 +-----------------------------
 4 files changed, 13 insertions(+), 33 deletions(-)

diff --git a/gdb/cli/cli-interp.c b/gdb/cli/cli-interp.c
index 031ab10aea6..c52a5f10a18 100644
--- a/gdb/cli/cli-interp.c
+++ b/gdb/cli/cli-interp.c
@@ -396,6 +396,7 @@ struct saved_output_files
   ui_file *targ;
   ui_file *targerr;
   ui_file_up file_to_delete;
+  ui_file_up log_to_delete;
 };
 static std::unique_ptr<saved_output_files> saved_output;
 
@@ -426,8 +427,11 @@ cli_interp_base::set_logging (ui_file_up logfile, bool logging_redirect,
       else
 	saved_output->file_to_delete = std::move (logfile);
 
+      saved_output->log_to_delete.reset
+	(new timestamped_file (debug_redirect ? logfile_p : tee));
+
       gdb_stdout = logging_redirect ? logfile_p : tee;
-      gdb_stdlog = debug_redirect ? logfile_p : tee;
+      gdb_stdlog = saved_output->log_to_delete.get ();
       gdb_stderr = logging_redirect ? logfile_p : tee;
       gdb_stdtarg = logging_redirect ? logfile_p : tee;
       gdb_stdtargerr = logging_redirect ? logfile_p : tee;
diff --git a/gdb/event-top.c b/gdb/event-top.c
index 530ea298247..80ac1e4a61e 100644
--- a/gdb/event-top.c
+++ b/gdb/event-top.c
@@ -1285,7 +1285,7 @@ gdb_setup_readline (int editing)
   if (!batch_silent)
     gdb_stdout = new stdio_file (ui->outstream);
   gdb_stderr = new stderr_file (ui->errstream);
-  gdb_stdlog = gdb_stderr;  /* for moment */
+  gdb_stdlog = new timestamped_file (gdb_stderr);
   gdb_stdtarg = gdb_stderr; /* for moment */
   gdb_stdtargerr = gdb_stderr; /* for moment */
 
diff --git a/gdb/tui/tui-io.c b/gdb/tui/tui-io.c
index bd443dc0c0c..58996df7924 100644
--- a/gdb/tui/tui-io.c
+++ b/gdb/tui/tui-io.c
@@ -108,11 +108,13 @@ key_is_start_sequence (int ch)
 /* TUI output files.  */
 static struct ui_file *tui_stdout;
 static struct ui_file *tui_stderr;
+static struct ui_file *tui_stdlog;
 struct ui_out *tui_out;
 
 /* GDB output files in non-curses mode.  */
 static struct ui_file *tui_old_stdout;
 static struct ui_file *tui_old_stderr;
+static struct ui_file *tui_old_stdlog;
 cli_ui_out *tui_old_uiout;
 
 /* Readline previous hooks.  */
@@ -828,13 +830,14 @@ tui_setup_io (int mode)
       /* Keep track of previous gdb output.  */
       tui_old_stdout = gdb_stdout;
       tui_old_stderr = gdb_stderr;
+      tui_old_stdlog = gdb_stdlog;
       tui_old_uiout = dynamic_cast<cli_ui_out *> (current_uiout);
       gdb_assert (tui_old_uiout != nullptr);
 
       /* Reconfigure gdb output.  */
       gdb_stdout = tui_stdout;
       gdb_stderr = tui_stderr;
-      gdb_stdlog = gdb_stdout;	/* for moment */
+      gdb_stdlog = tui_stdlog;
       gdb_stdtarg = gdb_stderr;	/* for moment */
       gdb_stdtargerr = gdb_stderr;	/* for moment */
       current_uiout = tui_out;
@@ -847,7 +850,7 @@ tui_setup_io (int mode)
       /* Restore gdb output.  */
       gdb_stdout = tui_old_stdout;
       gdb_stderr = tui_old_stderr;
-      gdb_stdlog = gdb_stdout;	/* for moment */
+      gdb_stdlog = tui_old_stdlog;
       gdb_stdtarg = gdb_stderr;	/* for moment */
       gdb_stdtargerr = gdb_stderr;	/* for moment */
       current_uiout = tui_old_uiout;
@@ -902,6 +905,7 @@ tui_initialize_io (void)
   /* Create tui output streams.  */
   tui_stdout = new tui_file (stdout);
   tui_stderr = new tui_file (stderr);
+  tui_stdlog = new timestamped_file (tui_stderr);
   tui_out = tui_out_new (tui_stdout);
 
   /* Create the default UI.  */
diff --git a/gdb/utils.c b/gdb/utils.c
index fc460d20321..13d431c5301 100644
--- a/gdb/utils.c
+++ b/gdb/utils.c
@@ -2060,35 +2060,7 @@ vfprintf_filtered (struct ui_file *stream, const char *format, va_list args)
 void
 vfprintf_unfiltered (struct ui_file *stream, const char *format, va_list args)
 {
-  if (debug_timestamp && stream == gdb_stdlog)
-    {
-      static bool needs_timestamp = true;
-
-      /* Print timestamp if previous print ended with a \n.  */
-      if (needs_timestamp)
-	{
-	  using namespace std::chrono;
-
-	  steady_clock::time_point now = steady_clock::now ();
-	  seconds s = duration_cast<seconds> (now.time_since_epoch ());
-	  microseconds us = duration_cast<microseconds> (now.time_since_epoch () - s);
-	  std::string timestamp = string_printf ("%ld.%06ld ",
-						 (long) s.count (),
-						 (long) us.count ());
-	  fputs_unfiltered (timestamp.c_str (), stream);
-	}
-
-      /* Print the message.  */
-      string_file sfile;
-      cli_ui_out (&sfile, 0).vmessage (ui_file_style (), format, args);
-      std::string linebuffer = std::move (sfile.string ());
-      fputs_unfiltered (linebuffer.c_str (), stream);
-
-      size_t len = linebuffer.length ();
-      needs_timestamp = (len > 0 && linebuffer[len - 1] == '\n');
-    }
-  else
-    vfprintf_maybe_filtered (stream, format, args, false);
+  vfprintf_maybe_filtered (stream, format, args, false);
 }
 
 void
-- 
2.31.1

Re: [PATCH 0/4] Change how stdlog timestamps are written

[Tom Tromey]

>>>>> "Tom" == Tom Tromey <tom@tromey.com> writes:

Tom> I've been looking at the GDB ui_file and pager system to see if it can
Tom> be made more understandable -- right now it's fairly spaghetti-ish,
Tom> with ui_file calling into functions in util.c, that then dispatch back
Tom> to ui_file.  My vision for the endpoint is something along the lines
Tom> of Java's stream writers, where additional functionality is provided
Tom> by just instantiating some new writer to wrap an existing one.

Tom> This series is a step toward that long-term goal.  It changes how
Tom> gdb_stdlog timestamps are written, moving this into a new ui_file
Tom> subclass.  This avoids a special case (which may in some situations be
Tom> incorrect, see patch #4) in vfprintf_unfiltered.

I'm going to push this soon, probably next week, as it is needed for the
pager-as-ui-file series.

Tom

Re: [PATCH 0/4] Change how stdlog timestamps are written

[Tom Tromey]

>>>>> "Tom" == Tom Tromey <tom@tromey.com> writes:

Tom> This series is a step toward that long-term goal.  It changes how
Tom> gdb_stdlog timestamps are written, moving this into a new ui_file
Tom> subclass.  This avoids a special case (which may in some situations be
Tom> incorrect, see patch #4) in vfprintf_unfiltered.

> I'm going to push this soon, probably next week, as it is needed for the
> pager-as-ui-file series.

I'm doing this now.
I've re-regression tested this series on x86-64 Fedora 34.

Tom