[PATCH 1/2] error-report: make real_time_iso8601() non-static

[PATCH 1/2] error-report: make real_time_iso8601() non-static

[Dongli Zhang]

To make real_time_iso8601() a non-static function so that it can be used by
other files later.

No functional change.

Cc: Joe Jin <joe.jin@oracle.com>
Signed-off-by: Dongli Zhang <dongli.zhang@oracle.com>
---
 include/qemu/error-report.h | 2 ++
 util/error-report.c         | 3 +--
 2 files changed, 3 insertions(+), 2 deletions(-)

diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
index 3ae2357..cc73b99 100644
--- a/include/qemu/error-report.h
+++ b/include/qemu/error-report.h
@@ -30,6 +30,8 @@ void loc_set_none(void);
 void loc_set_cmdline(char **argv, int idx, int cnt);
 void loc_set_file(const char *fname, int lno);
 
+char *real_time_iso8601(void);
+
 int error_vprintf(const char *fmt, va_list ap) G_GNUC_PRINTF(1, 0);
 int error_printf(const char *fmt, ...) G_GNUC_PRINTF(1, 2);
 
diff --git a/util/error-report.c b/util/error-report.c
index 5edb2e6..63862cd 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)
 {
 #if GLIB_CHECK_VERSION(2,62,0)
     g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
-- 
1.8.3.1

[PATCH 2/2] util/log: add timestamp to logs via qemu_log()

[Dongli Zhang]

The qemu_log is very helpful for diagnostic. Add the timestamp to the log
when it is enabled (e.g., "-msg timestamp=on").

While there are many other places that may print to log file, this patch is
only for qemu_log(), e.g., the developer may add qemu_log/qemu_log_mask to
selected locations to diagnose QEMU issue.

Cc: Joe Jin <joe.jin@oracle.com>
Signed-off-by: Dongli Zhang <dongli.zhang@oracle.com>
---
Please let me know if we should use 'error_with_guestname' as well.

 util/log.c | 7 +++++++
 1 file changed, 7 insertions(+)

diff --git a/util/log.c b/util/log.c
index d6eb037..f0a081a 100644
--- a/util/log.c
+++ b/util/log.c
@@ -129,8 +129,15 @@ void qemu_log(const char *fmt, ...)
 {
     FILE *f = qemu_log_trylock();
     if (f) {
+        gchar *timestr;
         va_list ap;
 
+        if (message_with_timestamp) {
+            timestr = real_time_iso8601();
+            fprintf(f, "%s ", timestr);
+            g_free(timestr);
+        }
+
         va_start(ap, fmt);
         vfprintf(f, fmt, ap);
         va_end(ap);
-- 
1.8.3.1

Re: [PATCH 2/2] util/log: add timestamp to logs via qemu_log()

[Markus Armbruster]

Dongli Zhang <dongli.zhang@oracle.com> writes:

> The qemu_log is very helpful for diagnostic. Add the timestamp to the log
> when it is enabled (e.g., "-msg timestamp=on").
>
> While there are many other places that may print to log file, this patch is
> only for qemu_log(), e.g., the developer may add qemu_log/qemu_log_mask to
> selected locations to diagnose QEMU issue.

Opinions on the new feature, anyone?

> Cc: Joe Jin <joe.jin@oracle.com>
> Signed-off-by: Dongli Zhang <dongli.zhang@oracle.com>
> ---
> Please let me know if we should use 'error_with_guestname' as well.
>
>  util/log.c | 7 +++++++
>  1 file changed, 7 insertions(+)
>
> diff --git a/util/log.c b/util/log.c
> index d6eb037..f0a081a 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -129,8 +129,15 @@ void qemu_log(const char *fmt, ...)
>  {
>      FILE *f = qemu_log_trylock();
>      if (f) {
> +        gchar *timestr;
>          va_list ap;
>  
> +        if (message_with_timestamp) {
> +            timestr = real_time_iso8601();
> +            fprintf(f, "%s ", timestr);
> +            g_free(timestr);
> +        }
> +
>          va_start(ap, fmt);
>          vfprintf(f, fmt, ap);
>          va_end(ap);

This extends -msg timestamp=on to apply to log messages without
documenting it in -help or anywhere else.  Needs fixing.

Re: [PATCH 2/2] util/log: add timestamp to logs via qemu_log()

[Richard Henderson]

On 8/30/22 04:09, Markus Armbruster wrote:
> Dongli Zhang <dongli.zhang@oracle.com> writes:
> 
>> The qemu_log is very helpful for diagnostic. Add the timestamp to the log
>> when it is enabled (e.g., "-msg timestamp=on").
>>
>> While there are many other places that may print to log file, this patch is
>> only for qemu_log(), e.g., the developer may add qemu_log/qemu_log_mask to
>> selected locations to diagnose QEMU issue.
> 
> Opinions on the new feature, anyone?
> 
>> Cc: Joe Jin <joe.jin@oracle.com>
>> Signed-off-by: Dongli Zhang <dongli.zhang@oracle.com>
>> ---
>> Please let me know if we should use 'error_with_guestname' as well.
>>
>>   util/log.c | 7 +++++++
>>   1 file changed, 7 insertions(+)
>>
>> diff --git a/util/log.c b/util/log.c
>> index d6eb037..f0a081a 100644
>> --- a/util/log.c
>> +++ b/util/log.c
>> @@ -129,8 +129,15 @@ void qemu_log(const char *fmt, ...)
>>   {
>>       FILE *f = qemu_log_trylock();
>>       if (f) {
>> +        gchar *timestr;
>>           va_list ap;
>>   
>> +        if (message_with_timestamp) {
>> +            timestr = real_time_iso8601();
>> +            fprintf(f, "%s ", timestr);
>> +            g_free(timestr);
>> +        }
>> +
>>           va_start(ap, fmt);
>>           vfprintf(f, fmt, ap);
>>           va_end(ap);
> 
> This extends -msg timestamp=on to apply to log messages without
> documenting it in -help or anywhere else.  Needs fixing.

I think this is a poor place to add the timestamp.

You'll find that qemu_log is used many times to assemble pieces, e.g.

linux-user/thunk.c:360:            qemu_log("%" PRIu64, tswap64(val));

linux-user/thunk.c:376:                qemu_log("\"");

linux-user/thunk.c:379:                qemu_log("[");

linux-user/thunk.c:384:                    qemu_log(",");

linux-user/thunk.c:391:                qemu_log("\"");

linux-user/thunk.c:393:                qemu_log("]");

linux-user/thunk.c:417:                qemu_log("{");

linux-user/thunk.c:420:                        qemu_log(",");

linux-user/thunk.c:424:                qemu_log("}");


Not the best idea, really, but the replacement for this is to avoid qemu_log entirely, and use

     f = qemu_log_trylock();
     if (f) {
         fprintf
         some
         stuff
         qemu_log_unlock(f);
     }

at which point you don't get your timestamp either.  You'd need to explicitly add 
timestamps to individual locations.

It would probably be easier to add timestamps to tracepoints, which are always emitted as 
a unit.


r~

Re: [PATCH 2/2] util/log: add timestamp to logs via qemu_log()

[Dongli Zhang]

Hi Markus and Richard,

Thank you very much for the feedback. I agree this is not a good solution. I
will look for alternatives to add timestamp.

Thank you very much!

Dongli Zhang

On 8/30/22 8:31 AM, Richard Henderson wrote:
> On 8/30/22 04:09, Markus Armbruster wrote:
>> Dongli Zhang <dongli.zhang@oracle.com> writes:
>>
>>> The qemu_log is very helpful for diagnostic. Add the timestamp to the log
>>> when it is enabled (e.g., "-msg timestamp=on").
>>>
>>> While there are many other places that may print to log file, this patch is
>>> only for qemu_log(), e.g., the developer may add qemu_log/qemu_log_mask to
>>> selected locations to diagnose QEMU issue.
>>
>> Opinions on the new feature, anyone?
>>
>>> Cc: Joe Jin <joe.jin@oracle.com>
>>> Signed-off-by: Dongli Zhang <dongli.zhang@oracle.com>
>>> ---
>>> Please let me know if we should use 'error_with_guestname' as well.
>>>
>>>   util/log.c | 7 +++++++
>>>   1 file changed, 7 insertions(+)
>>>
>>> diff --git a/util/log.c b/util/log.c
>>> index d6eb037..f0a081a 100644
>>> --- a/util/log.c
>>> +++ b/util/log.c
>>> @@ -129,8 +129,15 @@ void qemu_log(const char *fmt, ...)
>>>   {
>>>       FILE *f = qemu_log_trylock();
>>>       if (f) {
>>> +        gchar *timestr;
>>>           va_list ap;
>>>   +        if (message_with_timestamp) {
>>> +            timestr = real_time_iso8601();
>>> +            fprintf(f, "%s ", timestr);
>>> +            g_free(timestr);
>>> +        }
>>> +
>>>           va_start(ap, fmt);
>>>           vfprintf(f, fmt, ap);
>>>           va_end(ap);
>>
>> This extends -msg timestamp=on to apply to log messages without
>> documenting it in -help or anywhere else.  Needs fixing.
> 
> I think this is a poor place to add the timestamp.
> 
> You'll find that qemu_log is used many times to assemble pieces, e.g.
> 
> linux-user/thunk.c:360:            qemu_log("%" PRIu64, tswap64(val));
> 
> linux-user/thunk.c:376:                qemu_log("\"");
> 
> linux-user/thunk.c:379:                qemu_log("[");
> 
> linux-user/thunk.c:384:                    qemu_log(",");
> 
> linux-user/thunk.c:391:                qemu_log("\"");
> 
> linux-user/thunk.c:393:                qemu_log("]");
> 
> linux-user/thunk.c:417:                qemu_log("{");
> 
> linux-user/thunk.c:420:                        qemu_log(",");
> 
> linux-user/thunk.c:424:                qemu_log("}");
> 
> 
> Not the best idea, really, but the replacement for this is to avoid qemu_log
> entirely, and use
> 
>     f = qemu_log_trylock();
>     if (f) {
>         fprintf
>         some
>         stuff
>         qemu_log_unlock(f);
>     }
> 
> at which point you don't get your timestamp either.  You'd need to explicitly
> add timestamps to individual locations.
> 
> It would probably be easier to add timestamps to tracepoints, which are always
> emitted as a unit.
> 
> 
> r~
>