Both the error-report and log APIs can optional emit a timestamp
as a prefix on messages, with the '-msg timestamp=on' command
line flag is set.

Convert them to the new message API for formatting the context
prefix, guaranteeign they will have matching behaviour going
forward.

There is no change in output format for either logs or errors
with this conversion.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 include/qemu/error-report.h    |  1 -
 system/vl.c                    |  7 ++++++-
 tests/unit/test-error-report.c |  3 ++-
 util/error-report.c            | 18 +++---------------
 util/log.c                     | 20 +++++++-------------
 5 files changed, 18 insertions(+), 31 deletions(-)

diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
index 3ae2357fda..c8000778ec 100644
--- a/include/qemu/error-report.h
+++ b/include/qemu/error-report.h
@@ -70,7 +70,6 @@ void error_init(const char *argv0);
                               fmt, ##__VA_ARGS__);      \
     })
 
-extern bool message_with_timestamp;
 extern bool error_with_guestname;
 extern const char *error_guest_name;
 
diff --git a/system/vl.c b/system/vl.c
index a64fd90d4a..696dd92669 100644
--- a/system/vl.c
+++ b/system/vl.c
@@ -26,6 +26,7 @@
 #include "qemu/help-texts.h"
 #include "qemu/datadir.h"
 #include "qemu/units.h"
+#include "qemu/message.h"
 #include "qemu/module.h"
 #include "qemu/target-info.h"
 #include "exec/cpu-common.h"
@@ -813,8 +814,12 @@ static void realtime_init(void)
 
 static void configure_msg(QemuOpts *opts)
 {
-    message_with_timestamp = qemu_opt_get_bool(opts, "timestamp", false);
+    int flags = 0;
+    if (qemu_opt_get_bool(opts, "timestamp", false)) {
+        flags |= QMESSAGE_FORMAT_TIMESTAMP;
+    }
     error_with_guestname = qemu_opt_get_bool(opts, "guest-name", false);
+    qmessage_set_format(flags);
 }
 
 
diff --git a/tests/unit/test-error-report.c b/tests/unit/test-error-report.c
index 54319c86c9..78f8b57660 100644
--- a/tests/unit/test-error-report.c
+++ b/tests/unit/test-error-report.c
@@ -13,6 +13,7 @@
 
 #include "qemu/error-report.h"
 #include "qapi/error.h"
+#include "qemu/message.h"
 
 static void
 test_error_report_simple(void)
@@ -90,7 +91,7 @@ static void
 test_error_report_timestamp(void)
 {
     if (g_test_subprocess()) {
-        message_with_timestamp = true;
+        qmessage_set_format(QMESSAGE_FORMAT_TIMESTAMP);
         warn_report("warn");
         error_report("err");
         return;
diff --git a/util/error-report.c b/util/error-report.c
index 1b17c11de1..932af5d9f5 100644
--- a/util/error-report.c
+++ b/util/error-report.c
@@ -13,6 +13,7 @@
 #include "qemu/osdep.h"
 #include "monitor/monitor.h"
 #include "qemu/error-report.h"
+#include "qemu/message.h"
 
 /*
  * @report_type is the type of message: error, warning or
@@ -24,8 +25,6 @@ typedef enum {
     REPORT_TYPE_INFO,
 } report_type;
 
-/* Prepend timestamp to messages */
-bool message_with_timestamp;
 bool error_with_guestname;
 const char *error_guest_name;
 
@@ -169,13 +168,6 @@ static void print_loc(void)
     }
 }
 
-static char *
-real_time_iso8601(void)
-{
-    g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
-    return g_date_time_format_iso8601(dt);
-}
-
 /*
  * Print a message to current monitor if we have one, else to stderr.
  * @report_type is the type of message: error, warning or informational.
@@ -186,13 +178,9 @@ real_time_iso8601(void)
 G_GNUC_PRINTF(2, 0)
 static void vreport(report_type type, const char *fmt, va_list ap)
 {
-    gchar *timestr;
+    g_autofree gchar *context = qmessage_context(QMESSAGE_CONTEXT_SKIP_MONITOR);
 
-    if (message_with_timestamp && !monitor_cur()) {
-        timestr = real_time_iso8601();
-        error_printf("%s ", timestr);
-        g_free(timestr);
-    }
+    error_printf("%s", context);
 
     /* Only prepend guest name if -msg guest-name and -name guest=... are set */
     if (error_with_guestname && error_guest_name && !monitor_cur()) {
diff --git a/util/log.c b/util/log.c
index abdcb6b311..435d1c7135 100644
--- a/util/log.c
+++ b/util/log.c
@@ -22,6 +22,7 @@
 #include "qemu/range.h"
 #include "qemu/error-report.h"
 #include "qapi/error.h"
+#include "qemu/message.h"
 #include "qemu/cutils.h"
 #include "trace/control.h"
 #include "qemu/thread.h"
@@ -146,26 +147,19 @@ void qemu_log_unlock(FILE *logfile)
 void qemu_log(const char *fmt, ...)
 {
     FILE *f;
-    g_autofree const char *timestr = NULL;
-
     /*
-     * Prepare the timestamp *outside* the logging
-     * lock so it better reflects when the message
-     * was emitted if we are delayed acquiring the
-     * mutex
+     * Prepare the context *outside* the logging
+     * lock so any timestamp better reflects when
+     * the message was emitted if we are delayed
+     * acquiring the mutex
      */
-    if (message_with_timestamp) {
-        g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
-        timestr = g_date_time_format_iso8601(dt);
-    }
+    g_autofree const char *context = qmessage_context(0);
 
     f = qemu_log_trylock();
     if (f) {
         va_list ap;
 
-        if (timestr) {
-            fprintf(f, "%s ", timestr);
-        }
+        fwrite(context, 1, strlen(context), f);
 
         va_start(ap, fmt);
         vfprintf(f, fmt, ap);
-- 
2.50.1

On 8/20/25 06:27, Daniel P. Berrangé wrote:
>   void qemu_log(const char *fmt, ...)
>   {
>       FILE *f;
> -    g_autofree const char *timestr = NULL;
> -
>       /*
> -     * Prepare the timestamp*outside* the logging
> -     * lock so it better reflects when the message
> -     * was emitted if we are delayed acquiring the
> -     * mutex
> +     * Prepare the context*outside* the logging
> +     * lock so any timestamp better reflects when
> +     * the message was emitted if we are delayed
> +     * acquiring the mutex
>        */
> -    if (message_with_timestamp) {
> -        g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
> -        timestr = g_date_time_format_iso8601(dt);
> -    }

Something that really ought to be handled better is that we currently use qemu_log to 
print pieces of a larger message.  E.g. looping over the general registers to print the 
whole cpu state.

(1) We don't want timestamps in the middle, and
(2) we don't want unnecessary memory allocation in the middle.


r~

On Wed, Aug 20, 2025 at 08:02:14AM +1000, Richard Henderson wrote:
> On 8/20/25 06:27, Daniel P. Berrangé wrote:
> >   void qemu_log(const char *fmt, ...)
> >   {
> >       FILE *f;
> > -    g_autofree const char *timestr = NULL;
> > -
> >       /*
> > -     * Prepare the timestamp*outside* the logging
> > -     * lock so it better reflects when the message
> > -     * was emitted if we are delayed acquiring the
> > -     * mutex
> > +     * Prepare the context*outside* the logging
> > +     * lock so any timestamp better reflects when
> > +     * the message was emitted if we are delayed
> > +     * acquiring the mutex
> >        */
> > -    if (message_with_timestamp) {
> > -        g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
> > -        timestr = g_date_time_format_iso8601(dt);
> > -    }
> 
> Something that really ought to be handled better is that we currently use
> qemu_log to print pieces of a larger message.  E.g. looping over the general
> registers to print the whole cpu state.
> 
> (1) We don't want timestamps in the middle, and
> (2) we don't want unnecessary memory allocation in the middle.

This turned out to be surprisingly simple to fix - don't emit the
prefix if the previous qemu_log() call lacked a terminating newline
character.

With regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

On Wed, Aug 20, 2025 at 08:02:14AM +1000, Richard Henderson wrote:
> On 8/20/25 06:27, Daniel P. Berrangé wrote:
> >   void qemu_log(const char *fmt, ...)
> >   {
> >       FILE *f;
> > -    g_autofree const char *timestr = NULL;
> > -
> >       /*
> > -     * Prepare the timestamp*outside* the logging
> > -     * lock so it better reflects when the message
> > -     * was emitted if we are delayed acquiring the
> > -     * mutex
> > +     * Prepare the context*outside* the logging
> > +     * lock so any timestamp better reflects when
> > +     * the message was emitted if we are delayed
> > +     * acquiring the mutex
> >        */
> > -    if (message_with_timestamp) {
> > -        g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
> > -        timestr = g_date_time_format_iso8601(dt);
> > -    }
> 
> Something that really ought to be handled better is that we currently use
> qemu_log to print pieces of a larger message.  E.g. looping over the general
> registers to print the whole cpu state.
> 
> (1) We don't want timestamps in the middle, and
> (2) we don't want unnecessary memory allocation in the middle.

Interestingly I found that for CPU_LOG_TB_CPU we don't use the qemu_log()
function at all. TCG calls qemu_log_try_lock() to acquire the raw FILE *
handle and writes directly to it, so we miss all prefix info entirely.
If other parts of QEMU that do big multi-line log dumps do the same,
then we're ok.

With regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|