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

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

[sorry for resending, I forget to add qemu-devel on first try :(]

Vladimir Sementsov-Ogievskiy (3):
  char: qemu_chr_write_log() use qemu_write_full()
  error-report: move real_time_iso8601() to header
  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         |  7 ----
 5 files changed, 70 insertions(+), 24 deletions(-)

-- 
2.48.1

[RFC PATCH 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>
---

Honestly, I'm not sure, may be EAGAIN handling is needed for some
non-linux OSes? That's why it's RFC..

The original commit 0d7708ba29cbcc34336
"qemu-char: add logfile facility to all chardev backends"
doen't mention, why should we handle EAGAIN.

 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 2/3] error-report: move real_time_iso8601() to header

[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         | 7 -------
 2 files changed, 6 insertions(+), 7 deletions(-)

diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
index 3ae2357fda..412b705898 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;
 
+static inline char *real_time_iso8601(void)
+{
+    g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
+    return g_date_time_format_iso8601(dt);
+}
+
 #endif
diff --git a/util/error-report.c b/util/error-report.c
index 1b17c11de1..20618640e8 100644
--- a/util/error-report.c
+++ b/util/error-report.c
@@ -169,13 +169,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.
-- 
2.48.1

Re: [PATCH 2/3] error-report: move real_time_iso8601() to header

[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         | 7 -------
>  2 files changed, 6 insertions(+), 7 deletions(-)
>
> diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
> index 3ae2357fda..412b705898 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;
>  
> +static inline char *real_time_iso8601(void)
> +{
> +    g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
> +    return g_date_time_format_iso8601(dt);
> +}
> +
>  #endif

Reasons for inline?  Because the function is so small?

> diff --git a/util/error-report.c b/util/error-report.c
> index 1b17c11de1..20618640e8 100644
> --- a/util/error-report.c
> +++ b/util/error-report.c
> @@ -169,13 +169,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.

Re: [PATCH 2/3] error-report: move real_time_iso8601() to header

[Vladimir Sementsov-Ogievskiy]

On 03.12.25 17:16, Markus Armbruster wrote:
> 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         | 7 -------
>>   2 files changed, 6 insertions(+), 7 deletions(-)
>>
>> diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
>> index 3ae2357fda..412b705898 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;
>>   
>> +static inline char *real_time_iso8601(void)
>> +{
>> +    g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
>> +    return g_date_time_format_iso8601(dt);
>> +}
>> +
>>   #endif
> 
> Reasons for inline?  Because the function is so small?

Yes, seems, just this.

> 
>> diff --git a/util/error-report.c b/util/error-report.c
>> index 1b17c11de1..20618640e8 100644
>> --- a/util/error-report.c
>> +++ b/util/error-report.c
>> @@ -169,13 +169,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.
> 


-- 
Best regards,
Vladimir

Re: [PATCH 2/3] error-report: move real_time_iso8601() to header

[Markus Armbruster]

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

> On 03.12.25 17:16, Markus Armbruster wrote:
>> 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         | 7 -------
>>>   2 files changed, 6 insertions(+), 7 deletions(-)
>>>
>>> diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
>>> index 3ae2357fda..412b705898 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;
>>>   
>>> +static inline char *real_time_iso8601(void)
>>> +{
>>> +    g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
>>> +    return g_date_time_format_iso8601(dt);
>>> +}
>>> +
>>>   #endif
>> 
>> Reasons for inline?  Because the function is so small?
>
> Yes, seems, just this.

I'd prefer not to.

Actually, I'd be tempted to just duplicate the two calls and call it a
day.  Up to you.

>>> diff --git a/util/error-report.c b/util/error-report.c
>>> index 1b17c11de1..20618640e8 100644
>>> --- a/util/error-report.c
>>> +++ b/util/error-report.c
>>> @@ -169,13 +169,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.
>> 

Re: [PATCH 2/3] error-report: move real_time_iso8601() to header

[Philippe Mathieu-Daudé]

Hi,

On 4/12/25 09:12, Markus Armbruster wrote:
> Vladimir Sementsov-Ogievskiy <vsementsov@yandex-team.ru> writes:
> 
>> On 03.12.25 17:16, Markus Armbruster wrote:
>>> 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         | 7 -------
>>>>    2 files changed, 6 insertions(+), 7 deletions(-)
>>>>
>>>> diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
>>>> index 3ae2357fda..412b705898 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;
>>>>    
>>>> +static inline char *real_time_iso8601(void)
>>>> +{
>>>> +    g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
>>>> +    return g_date_time_format_iso8601(dt);
>>>> +}
>>>> +
>>>>    #endif
>>>
>>> Reasons for inline?  Because the function is so small?
>>
>> Yes, seems, just this.
> 
> I'd prefer not to.
> 
> Actually, I'd be tempted to just duplicate the two calls and call it a
> day.  Up to you.

We now prefer to let the toolchain LTO do its clever job.
Better avoid duplication. To enforce this style, lets expose
the declaration with a @docstring, and keep the definition in util/.
My 2 cents.

> 
>>>> diff --git a/util/error-report.c b/util/error-report.c
>>>> index 1b17c11de1..20618640e8 100644
>>>> --- a/util/error-report.c
>>>> +++ b/util/error-report.c
>>>> @@ -169,13 +169,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);
>>>> -}

Re: [PATCH 2/3] error-report: move real_time_iso8601() to header

[Vladimir Sementsov-Ogievskiy]

On 04.12.25 11:30, Philippe Mathieu-Daudé wrote:
> Hi,
> 
> On 4/12/25 09:12, Markus Armbruster wrote:
>> Vladimir Sementsov-Ogievskiy <vsementsov@yandex-team.ru> writes:
>>
>>> On 03.12.25 17:16, Markus Armbruster wrote:
>>>> 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         | 7 -------
>>>>>    2 files changed, 6 insertions(+), 7 deletions(-)
>>>>>
>>>>> diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
>>>>> index 3ae2357fda..412b705898 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;
>>>>> +static inline char *real_time_iso8601(void)
>>>>> +{
>>>>> +    g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
>>>>> +    return g_date_time_format_iso8601(dt);
>>>>> +}
>>>>> +
>>>>>    #endif
>>>>
>>>> Reasons for inline?  Because the function is so small?
>>>
>>> Yes, seems, just this.
>>
>> I'd prefer not to.
>>
>> Actually, I'd be tempted to just duplicate the two calls and call it a
>> day.  Up to you.
> 
> We now prefer to let the toolchain LTO do its clever job.
> Better avoid duplication. To enforce this style, lets expose
> the declaration with a @docstring, and keep the definition in util/.
> My 2 cents.
> 

OK

>>
>>>>> diff --git a/util/error-report.c b/util/error-report.c
>>>>> index 1b17c11de1..20618640e8 100644
>>>>> --- a/util/error-report.c
>>>>> +++ b/util/error-report.c
>>>>> @@ -169,13 +169,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);
>>>>> -}


-- 
Best regards,
Vladimir

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