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

[PATCH v3 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.

v3:
02: fix s/Returns/Return, add r-b by Markus

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.52.0

[PATCH v3 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.52.0

[PATCH v3 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>
Reviewed-by: Markus Armbruster <armbru@redhat.com>
---
 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..dc423d3607 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;
 
+/*
+ * Return 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.52.0

[PATCH v3 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 192cad67d4..86636b4d09 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.52.0

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

[Daniel P. Berrangé]

On Sun, Feb 01, 2026 at 08:36:29PM +0300, Vladimir Sementsov-Ogievskiy wrote:
> logfd is blocking, so we don't need to care about EAGAIN.
> Let's simply use qemu_write_full().

Are you sure logfd is always blocking ?  It can be an FD passed in
from outside QEMU, and off-hand, I'm not sure where we force that to
be blocking. Though we could argue it is the client't fault if they
passed a non-blocking FD to QEMU.

NB, we can *not* assume logfd is a plain file as libvirt will pass
in a pipe to send logging via virtlogd.


> 
> 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.52.0
> 

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 :|

Re: [PATCH v3 3/3] chardev: add logtimestamp option

[Markus Armbruster]

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

> 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>

[...]

> 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' } }

We prefer to separate words with hyphens in member names (see
docs/devel/qapi-code-gen.rst), but local consistency trumps that rule.

>  
>  ##
>  # @ChardevFile:

QAPI schema
Acked-by: Markus Armbruster <armbru@redhat.com>

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

[Marc-André Lureau]

Hi

On Sun, Feb 1, 2026 at 9:38 PM Vladimir Sementsov-Ogievskiy
<vsementsov@yandex-team.ru> 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.
>
> v3:
> 02: fix s/Returns/Return, add r-b by Markus
>
> 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.52.0
>
>

Reviewed-by: Marc-André Lureau <marcandre.lureau@redhat.com>


--
Marc-André Lureau

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

[Vladimir Sementsov-Ogievskiy]

On 02.02.26 14:26, Daniel P. Berrangé wrote:
> On Sun, Feb 01, 2026 at 08:36:29PM +0300, Vladimir Sementsov-Ogievskiy wrote:
>> logfd is blocking, so we don't need to care about EAGAIN.
>> Let's simply use qemu_write_full().
> 
> Are you sure logfd is always blocking ?  It can be an FD passed in
> from outside QEMU, and off-hand, I'm not sure where we force that to
> be blocking. Though we could argue it is the client't fault if they
> passed a non-blocking FD to QEMU.
> 
> NB, we can *not* assume logfd is a plain file as libvirt will pass
> in a pipe to send logging via virtlogd.
> 

I'm sorry I missed the email. And the commit is in master now.

And, I missed the fact that

    qemu_create(common->logfile, flags, 0666, errp);

Can actually chose fd from "fdset". All named fds in monitor are set blocking
explicitly except for the case when QIO_CHANNEL_READ_FLAG_FD_PRESERVE_BLOCKING flag
take place.. But fds coming through add-fd commandline options are not handled
this way, as I can see.


Looking through:

1. util/oslib-posix.c: qemu_write_pidfile()

Uses qemu_write_full(), *unprepared* to non-blocking.

2. ui/ui-qmp-cmds.c: qmp_screendump()

2.1. png_save() wraps the fd to fdopen(), which I assume should work well
with blocking and non-blocking fds

2.2. ppm_save() wraps it into qio_channel_file_new_fd()

qio_channel_write_all() -> qio_channel_writev_full_all() do handle QIO_CHANNEL_ERR_BLOCK

3. qio_channel_file_new_path()

In general qio-channels are prepared to work with non-blocking fds.

qio_channel_file_new_path() is used (except for 2.2 and tests) from migration code, which
I think should be prepared to non-blocking fds. At least, qemu_fill_buffer()
handles QIO_CHANNEL_ERR_BLOCK.

4. hw/usb/bus.c: usb_qdev_realize()

Wraps by fdopen()

5. hw/uefi/var-service-pcap.c: uefi_vars_pcap_init()

Wraps by fdopen()

6. hw/uefi/var-service-json.c: uefi_vars_json_init()

Use write() and don't handle EAGAIN: *unprepared* for non-blocking.

7. dump/dump.c: qmp_dump_guest_memory()

Use qemu_write_full() - *unprepared*

8. chardev/char.c: logfd - *unprepared* after my commit

9. block/file-posix.c: raw_co_create()

May use write() and not handle EAGAIN during raw_regular_truncate() - unprepared.


What to do with it? I see several possibilities:

1. simply support EAGAIN in qemu_write_full()? Like it was in qemu_chr_write_log()
- with g_usleep(100)?

2. switch to qio_channel_file_new_path() + qio_channel_write_all()

3. call qemu_set_blocking() on fd for *unprepared* cases

> 
>>
>> 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.52.0
>>
> 
> With regards,
> Daniel


-- 
Best regards,
Vladimir

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

[Vladimir Sementsov-Ogievskiy]

On 19.02.26 21:07, Vladimir Sementsov-Ogievskiy wrote:
> 
> 
> Looking through:

"Looking through usages of qemu_create()" I mean

-- 
Best regards,
Vladimir

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

[Daniel P. Berrangé]

On Thu, Feb 19, 2026 at 09:07:07PM +0300, Vladimir Sementsov-Ogievskiy wrote:
> On 02.02.26 14:26, Daniel P. Berrangé wrote:
> > On Sun, Feb 01, 2026 at 08:36:29PM +0300, Vladimir Sementsov-Ogievskiy wrote:
> > > logfd is blocking, so we don't need to care about EAGAIN.
> > > Let's simply use qemu_write_full().
> > 
> > Are you sure logfd is always blocking ?  It can be an FD passed in
> > from outside QEMU, and off-hand, I'm not sure where we force that to
> > be blocking. Though we could argue it is the client't fault if they
> > passed a non-blocking FD to QEMU.
> > 
> > NB, we can *not* assume logfd is a plain file as libvirt will pass
> > in a pipe to send logging via virtlogd.
> > 
> 
> I'm sorry I missed the email. And the commit is in master now.
> 
> And, I missed the fact that
> 
>    qemu_create(common->logfile, flags, 0666, errp);
> 
> Can actually chose fd from "fdset". All named fds in monitor are set blocking
> explicitly except for the case when QIO_CHANNEL_READ_FLAG_FD_PRESERVE_BLOCKING flag
> take place.. But fds coming through add-fd commandline options are not handled
> this way, as I can see.

> Looking through:
> 
> 1. util/oslib-posix.c: qemu_write_pidfile()
> 
> Uses qemu_write_full(), *unprepared* to non-blocking.
> 
> 2. ui/ui-qmp-cmds.c: qmp_screendump()
> 
> 2.1. png_save() wraps the fd to fdopen(), which I assume should work well
> with blocking and non-blocking fds
> 
> 2.2. ppm_save() wraps it into qio_channel_file_new_fd()
> 
> qio_channel_write_all() -> qio_channel_writev_full_all() do handle QIO_CHANNEL_ERR_BLOCK
> 
> 3. qio_channel_file_new_path()
> 
> In general qio-channels are prepared to work with non-blocking fds.
> 
> qio_channel_file_new_path() is used (except for 2.2 and tests) from migration code, which
> I think should be prepared to non-blocking fds. At least, qemu_fill_buffer()
> handles QIO_CHANNEL_ERR_BLOCK.
> 
> 4. hw/usb/bus.c: usb_qdev_realize()
> 
> Wraps by fdopen()
> 
> 5. hw/uefi/var-service-pcap.c: uefi_vars_pcap_init()
> 
> Wraps by fdopen()
> 
> 6. hw/uefi/var-service-json.c: uefi_vars_json_init()
> 
> Use write() and don't handle EAGAIN: *unprepared* for non-blocking.
> 
> 7. dump/dump.c: qmp_dump_guest_memory()
> 
> Use qemu_write_full() - *unprepared*
> 
> 8. chardev/char.c: logfd - *unprepared* after my commit
> 
> 9. block/file-posix.c: raw_co_create()
> 
> May use write() and not handle EAGAIN during raw_regular_truncate() - unprepared.
> 
> 
> What to do with it? I see several possibilities:
> 
> 1. simply support EAGAIN in qemu_write_full()? Like it was in qemu_chr_write_log()
> - with g_usleep(100)?
> 
> 2. switch to qio_channel_file_new_path() + qio_channel_write_all()
> 
> 3. call qemu_set_blocking() on fd for *unprepared* cases

IMHO, use of FDs in non-blocking mode should always be an explicit
opt-in decision by the code in question.  So my preference is to
ensure FDs coming via -add-fd get forced into blocking mode, the
same as we do for FDs coming via the monitor (or any socket recv
when QIO_CHANNEL_READ_FLAG_FD_PRESERVE_BLOCKING is NOT set)

With regards,
Daniel
-- 
|: https://berrange.com       ~~        https://hachyderm.io/@berrange :|
|: https://libvirt.org          ~~          https://entangle-photo.org :|
|: https://pixelfed.art/berrange   ~~    https://fstop138.berrange.com :|