Re: [PATCH v6 00/27] util: sync error_report & qemu_log output more closely

[Markus Armbruster <armbru@redhat.com>]

Daniel P. Berrangé <berrange@redhat.com> writes:

> This series is a tangent that came out of discussion in
>
>    https://lists.nongnu.org/archive/html/qemu-devel/2025-08/msg00903.html

This was about error messages providing sufficient information both for
users and for developers.

Manos proposed to print a stack backtrace on programming errors and
fatal errors (&error_abort and &error_fatal), enabled at configure time.
He found this useful for debugging a use-after-free.

Daniel pointed out that GDB shows better stack backtraces, and that we
could not enable this feature in distro builds.  He wondered whether
showing just thread names would do.

> In thinking about adding thread info to error_report,

I understand why that can be useful for developers in certain scenarios,
but I feel it results in error reporting that is overly vebose and
unwieldy for users.  I'd prefer optional, default off.

>                                                       I
> came to realize we should likely make qemu_log behave
> consistently with error_report & friends. We already
> honour '-msg timestamp=on', but don't honour 'guest-name=on'
> and also don't include the binary name.

I'm willing to accept a message format common to error reporting and log
if that's useful.  Backed by shared code, obviously.

Why could it be useful, and to whom?

Error messages are both for users and developers.  Both need them to be
clear and detailed enough to figure out what's gone wrong, and what to
do about it.

Developers can use additional detail.  Lots and lots of it at times.  No
excuse for dumping it all on users.

Carefully designed logs can also be for both.  Much of what QEMU can log
is just for developers, and that's *fine*.  Sometimes developers want to
log lots of detail per message, sometimes they don't, to keep the logs
managable, as Peter pointed out.

When the error message needs of users and developers conflict, I put
users first.

When the logging needs of users and developers conflict, I put
developers first.

> As an example of the current state, consider mixing error and
> log output today:

Having the errors in the log can clearly be useful.  The easiest way to
have them in the log is --- wait for it --- logging them.

We don't do that now.  Instead, you can log to stderr, or you can piece
together log file contents and error messages.  The format differences
can be inconvenient either way.

Could we log errors?

> - Default context:
>
>   # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish \
>                        -d 'trace:qcrypto*'
>   qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55ac6d97f700 dir=fish
>   qcrypto_tls_creds_get_path TLS creds path creds=0x55ac6d97f700 filename=ca-cert.pem path=<none>
>   qemu-system-x86_64: Unable to access credentials fish/ca-cert.pem: No such file or directory
>
> - Full context:
>
>   # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish \
>                        -d 'trace:qcrypto*' \
>                        -msg guest-name=on,timestamp=on \
>                        -name "fish food"
>   2025-08-19T20:14:16.791413Z qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55e9a3458d10 dir=fish
>   2025-08-19T20:14:16.791429Z qcrypto_tls_creds_get_path TLS creds path creds=0x55e9a3458d10 filename=ca-cert.pem path=<none>
>   2025-08-19T20:14:16.791433Z fish food qemu-system-x86_64: Unable to access credentials fish/ca-cert.pem: No such file or directory
>
> And after this series is complete:
>
> - Default context:
>
>   # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish \
>                       -d 'trace:qcrypto*'
>   qemu-system-x86_64(1184284:main): qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55a24ad5cb30 dir=fish
>   qemu-system-x86_64(1184284:main): qcrypto_tls_creds_get_path TLS creds path creds=0x55a24ad5cb30 filename=ca-cert.pem path=<none>
>   qemu-system-x86_64(1184284:main): Unable to access credentials fish/ca-cert.pem: No such file or directory
>
> - Full context:
>
>   # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish \
>                       -d 'trace:qcrypto*' \
>                       -msg guest-name=on,timestamp=on \
>                       -name "fish food"
>   2025-08-19T20:12:50.211823Z [fish food] qemu-system-x86_64(1168876:main): qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x5582183d8760 dir=fish
>   2025-08-19T20:12:50.211842Z [fish food] qemu-system-x86_64(1168876:main): qcrypto_tls_creds_get_path TLS creds path creds=0x5582183d8760 filename=ca-cert.pem
> +path=<none>
>   2025-08-19T20:12:50.211846Z [fish food] qemu-system-x86_64(1168876:main): Unable to access credentials fish/ca-cert.pem: No such file or directory
>
> The main things to note:
>
>  * error_report/warn_report/qemu_log share the same
>    output format and -msg applies to both

I fear this is a bad idea.  I apologize for being so late with this.  I
didn't think hard enough until now.

Unified format with separate configuration controls and defaults could
be okay.

>  * -msg debug-threads=on is now unconditionally enabled
>    and thus the param is deprecated & ignored

This part just makes sense.

>  * Thread ID and name are unconditionally enabled
>
>  * Guest name is surrounded in [...] brackets
>
>  * The default output lines are typically 15 chars
>    wider given that we always include the thread
>    ID + name now
>
>  * This takes the liberty of assigning the new file
>    to the existing error-report.c maintainer (Markus)
>    Since splitting it off into message.c instead of
>    putting it all in error-report.c felt slightly
>    nicer.
>
> One thing I didn't tackle is making the location
> info get reported for qemu_log. This is used to
> give context for error messages when parsing some
> CLI args, and could be interesting for log messages
> associated with those same CLI args.