[PATCH v2 0/3] char: add option to inject timestamps into logfile

[PATCH v2 0/3] char: add option to inject timestamps into logfile

[Vladimir Sementsov-Ogievskiy]

Hi all!

The ability to correlate the QEMU log and the guest log can be useful
for investigating problems. So, I suggest an option to inject timestimps
into logfile while writing it.

v2: do not make real_time_iso8601 static inline

Vladimir Sementsov-Ogievskiy (3):
  char: qemu_chr_write_log() use qemu_write_full()
  error-report: make real_time_iso8601() public
  chardev: add logtimestamp option

 chardev/char.c              | 73 +++++++++++++++++++++++++++++--------
 include/chardev/char.h      |  2 +
 include/qemu/error-report.h |  6 +++
 qapi/char.json              |  6 ++-
 util/error-report.c         |  3 +-
 5 files changed, 71 insertions(+), 19 deletions(-)

-- 
2.48.1

[PATCH v2 1/3] char: qemu_chr_write_log() use qemu_write_full()

[Vladimir Sementsov-Ogievskiy]

logfd is blocking, so we don't need to care about EAGAIN.
Let's simply use qemu_write_full().

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@yandex-team.ru>
---
 chardev/char.c | 22 +++++-----------------
 1 file changed, 5 insertions(+), 17 deletions(-)

diff --git a/chardev/char.c b/chardev/char.c
index 3e432195a5..64006a3119 100644
--- a/chardev/char.c
+++ b/chardev/char.c
@@ -82,29 +82,17 @@ void qemu_chr_be_event(Chardev *s, QEMUChrEvent event)
     CHARDEV_GET_CLASS(s)->chr_be_event(s, event);
 }
 
-/* Not reporting errors from writing to logfile, as logs are
- * defined to be "best effort" only */
 static void qemu_chr_write_log(Chardev *s, const uint8_t *buf, size_t len)
 {
-    size_t done = 0;
-    ssize_t ret;
-
     if (s->logfd < 0) {
         return;
     }
 
-    while (done < len) {
-    retry:
-        ret = write(s->logfd, buf + done, len - done);
-        if (ret == -1 && errno == EAGAIN) {
-            g_usleep(100);
-            goto retry;
-        }
-
-        if (ret <= 0) {
-            return;
-        }
-        done += ret;
+    if (qemu_write_full(s->logfd, buf, len) < len) {
+        /*
+         * qemu_write_full() is defined with G_GNUC_WARN_UNUSED_RESULT,
+         * but logging is best‑effort, we do ignore errors.
+         */
     }
 }
 
-- 
2.48.1

[PATCH v2 2/3] error-report: make real_time_iso8601() public

[Vladimir Sementsov-Ogievskiy]

To be reused in the following commit.

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@yandex-team.ru>
---
 include/qemu/error-report.h | 6 ++++++
 util/error-report.c         | 3 +--
 2 files changed, 7 insertions(+), 2 deletions(-)

diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
index 3ae2357fda..bcd542a118 100644
--- a/include/qemu/error-report.h
+++ b/include/qemu/error-report.h
@@ -74,4 +74,10 @@ extern bool message_with_timestamp;
 extern bool error_with_guestname;
 extern const char *error_guest_name;
 
+/*
+ * Returns current datetime in ISO 8601 format.
+ * Caller is responsible to g_free() the returned string.
+ */
+char *real_time_iso8601(void);
+
 #endif
diff --git a/util/error-report.c b/util/error-report.c
index 1b17c11de1..d6b7448183 100644
--- a/util/error-report.c
+++ b/util/error-report.c
@@ -169,8 +169,7 @@ static void print_loc(void)
     }
 }
 
-static char *
-real_time_iso8601(void)
+char *real_time_iso8601(void)
 {
     g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
     return g_date_time_format_iso8601(dt);
-- 
2.48.1

[PATCH v2 3/3] chardev: add logtimestamp option

[Vladimir Sementsov-Ogievskiy]

Add an option to inject timestamps into serial log file.
That simplifies debugging a lot, when you can simply compare
QEMU logs with guest console logs.

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@yandex-team.ru>
---
 chardev/char.c         | 63 ++++++++++++++++++++++++++++++++++++++----
 include/chardev/char.h |  2 ++
 qapi/char.json         |  6 +++-
 3 files changed, 65 insertions(+), 6 deletions(-)

diff --git a/chardev/char.c b/chardev/char.c
index 64006a3119..57c65544d0 100644
--- a/chardev/char.c
+++ b/chardev/char.c
@@ -82,12 +82,8 @@ void qemu_chr_be_event(Chardev *s, QEMUChrEvent event)
     CHARDEV_GET_CLASS(s)->chr_be_event(s, event);
 }
 
-static void qemu_chr_write_log(Chardev *s, const uint8_t *buf, size_t len)
+static void do_write_log(Chardev *s, const uint8_t *buf, size_t len)
 {
-    if (s->logfd < 0) {
-        return;
-    }
-
     if (qemu_write_full(s->logfd, buf, len) < len) {
         /*
          * qemu_write_full() is defined with G_GNUC_WARN_UNUSED_RESULT,
@@ -96,6 +92,55 @@ static void qemu_chr_write_log(Chardev *s, const uint8_t *buf, size_t len)
     }
 }
 
+static void do_write_log_timestamps(Chardev *s, const uint8_t *buf, size_t len)
+{
+    g_autofree char *timestr = NULL;
+
+    while (len) {
+        size_t i;
+
+        if (s->log_line_start) {
+            if (!timestr) {
+                timestr = real_time_iso8601();
+            }
+            do_write_log(s, (const uint8_t *)timestr, strlen(timestr));
+            do_write_log(s, (const uint8_t *)" ", 1);
+            s->log_line_start = false;
+        }
+
+        for (i = 0; i < len; i++) {
+            if (buf[i] == '\n') {
+                break;
+            }
+        }
+
+        if (i == len) {
+            /* not found \n */
+            do_write_log(s, buf, len);
+            return;
+        }
+
+        i += 1;
+        do_write_log(s, buf, i);
+        buf += i;
+        len -= i;
+        s->log_line_start = true;
+    }
+}
+
+static void qemu_chr_write_log(Chardev *s, const uint8_t *buf, size_t len)
+{
+    if (s->logfd < 0) {
+        return;
+    }
+
+    if (s->logtimestamp) {
+        do_write_log_timestamps(s, buf, len);
+    } else {
+        do_write_log(s, buf, len);
+    }
+}
+
 static int qemu_chr_write_buffer(Chardev *s,
                                  const uint8_t *buf, int len,
                                  int *offset, bool write_all)
@@ -249,6 +294,7 @@ static void qemu_char_open(Chardev *chr, ChardevBackend *backend,
         } else {
             flags |= O_TRUNC;
         }
+        chr->logtimestamp = common->has_logtimestamp && common->logtimestamp;
         chr->logfd = qemu_create(common->logfile, flags, 0666, errp);
         if (chr->logfd < 0) {
             return;
@@ -266,6 +312,7 @@ static void char_init(Object *obj)
 
     chr->handover_yank_instance = false;
     chr->logfd = -1;
+    chr->log_line_start = true;
     qemu_mutex_init(&chr->chr_write_lock);
 
     /*
@@ -505,6 +552,9 @@ void qemu_chr_parse_common(QemuOpts *opts, ChardevCommon *backend)
     backend->logfile = g_strdup(logfile);
     backend->has_logappend = true;
     backend->logappend = qemu_opt_get_bool(opts, "logappend", false);
+
+    backend->has_logtimestamp = true;
+    backend->logtimestamp = qemu_opt_get_bool(opts, "logtimestamp", false);
 }
 
 static const ChardevClass *char_get_class(const char *driver, Error **errp)
@@ -956,6 +1006,9 @@ QemuOptsList qemu_chardev_opts = {
         },{
             .name = "logappend",
             .type = QEMU_OPT_BOOL,
+        },{
+            .name = "logtimestamp",
+            .type = QEMU_OPT_BOOL,
         },{
             .name = "mouse",
             .type = QEMU_OPT_BOOL,
diff --git a/include/chardev/char.h b/include/chardev/char.h
index b65e9981c1..6a5318c918 100644
--- a/include/chardev/char.h
+++ b/include/chardev/char.h
@@ -64,6 +64,8 @@ struct Chardev {
     char *label;
     char *filename;
     int logfd;
+    bool logtimestamp;
+    bool log_line_start;
     int be_open;
     /* used to coordinate the chardev-change special-case: */
     bool handover_yank_instance;
diff --git a/qapi/char.json b/qapi/char.json
index 140614f82c..a4abafa680 100644
--- a/qapi/char.json
+++ b/qapi/char.json
@@ -197,11 +197,15 @@
 # @logappend: true to append instead of truncate (default to false to
 #     truncate)
 #
+# @logtimestamp: true to insert timestamps into logfile
+#     (default false) (since 11.0)
+#
 # Since: 2.6
 ##
 { 'struct': 'ChardevCommon',
   'data': { '*logfile': 'str',
-            '*logappend': 'bool' } }
+            '*logappend': 'bool',
+            '*logtimestamp': 'bool' } }
 
 ##
 # @ChardevFile:
-- 
2.48.1

Re: [PATCH v2 0/3] char: add option to inject timestamps into logfile

[Vladimir Sementsov-Ogievskiy]

Ping !)

On 04.12.25 23:26, Vladimir Sementsov-Ogievskiy wrote:
> Hi all!
> 
> The ability to correlate the QEMU log and the guest log can be useful
> for investigating problems. So, I suggest an option to inject timestimps
> into logfile while writing it.
> 
> v2: do not make real_time_iso8601 static inline
> 
> Vladimir Sementsov-Ogievskiy (3):
>    char: qemu_chr_write_log() use qemu_write_full()
>    error-report: make real_time_iso8601() public
>    chardev: add logtimestamp option
> 
>   chardev/char.c              | 73 +++++++++++++++++++++++++++++--------
>   include/chardev/char.h      |  2 +
>   include/qemu/error-report.h |  6 +++
>   qapi/char.json              |  6 ++-
>   util/error-report.c         |  3 +-
>   5 files changed, 71 insertions(+), 19 deletions(-)
> 


-- 
Best regards,
Vladimir

Re: [PATCH v2 2/3] error-report: make real_time_iso8601() public

[Markus Armbruster]

Vladimir Sementsov-Ogievskiy <vsementsov@yandex-team.ru> writes:

> To be reused in the following commit.
>
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@yandex-team.ru>
> ---
>  include/qemu/error-report.h | 6 ++++++
>  util/error-report.c         | 3 +--
>  2 files changed, 7 insertions(+), 2 deletions(-)
>
> diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
> index 3ae2357fda..bcd542a118 100644
> --- a/include/qemu/error-report.h
> +++ b/include/qemu/error-report.h
> @@ -74,4 +74,10 @@ extern bool message_with_timestamp;
>  extern bool error_with_guestname;
>  extern const char *error_guest_name;
>  
> +/*
> + * Returns current datetime in ISO 8601 format.

Imperative mood, please: Return current ...

> + * Caller is responsible to g_free() the returned string.
> + */
> +char *real_time_iso8601(void);
> +
>  #endif
> diff --git a/util/error-report.c b/util/error-report.c
> index 1b17c11de1..d6b7448183 100644
> --- a/util/error-report.c
> +++ b/util/error-report.c
> @@ -169,8 +169,7 @@ static void print_loc(void)
>      }
>  }
>  
> -static char *
> -real_time_iso8601(void)
> +char *real_time_iso8601(void)
>  {
>      g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
>      return g_date_time_format_iso8601(dt);

With the comment tweak:
Reviewed-by: Markus Armbruster <armbru@redhat.com>