| Message ID | 20190121170434.13592-1-cfergeau@redhat.com |
|---|---|
| State | New |
| Headers | show |
| Series | [v5] log: Make glib logging go through QEMU | expand |
On Mon, Jan 21, 2019 at 06:04:35PM +0100, Christophe Fergeau wrote: > This commit adds a qemu_init_logging() helper which calls > g_log_set_default_handler() so that glib logs (g_log, g_warning, ...) > are handled similarly to other QEMU logs. This means they will get a > timestamp if timestamps are enabled, and they will go through the > monitor if one is configured. > This commit also adds a call to qemu_init_logging() to the binaries > installed by QEMU. > glib debug messages are enabled through G_MESSAGES_DEBUG similarly to > glib default log handler. > > At the moment, this change will mostly impact SPICE logging if your > spice version is >= 0.14.1. With older spice versions, this is not going > to work as expected, but will not have any ill effect, so this call is > not conditional on the SPICE version. > > Signed-off-by: Christophe Fergeau <cfergeau@redhat.com> > Reviewed-by: Daniel P. Berrangé <berrange@redhat.com> > Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com> > --- > One more iteration of the patch as it hit CI failures > (https://patchew.org/QEMU/20181214105642.673-1-cfergeau@redhat.com/ ) > Only difference from v4 is the addition of #include "qemu/error-report.h" > in bsd-user and linux-user. > > > bsd-user/main.c | 2 ++ > include/qemu/error-report.h | 2 ++ > linux-user/main.c | 2 ++ > qemu-img.c | 1 + > qemu-io.c | 1 + > qemu-nbd.c | 1 + > scsi/qemu-pr-helper.c | 1 + > util/qemu-error.c | 47 +++++++++++++++++++++++++++++++++++++ > vl.c | 1 + > 9 files changed, 58 insertions(+) Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com>
Christophe Fergeau <cfergeau@redhat.com> writes: > This commit adds a qemu_init_logging() helper which calls > g_log_set_default_handler() so that glib logs (g_log, g_warning, ...) > are handled similarly to other QEMU logs. This means they will get a > timestamp if timestamps are enabled, and they will go through the > monitor if one is configured. > This commit also adds a call to qemu_init_logging() to the binaries > installed by QEMU. > glib debug messages are enabled through G_MESSAGES_DEBUG similarly to > glib default log handler. > > At the moment, this change will mostly impact SPICE logging if your > spice version is >= 0.14.1. With older spice versions, this is not going > to work as expected, but will not have any ill effect, so this call is > not conditional on the SPICE version. > > Signed-off-by: Christophe Fergeau <cfergeau@redhat.com> > Reviewed-by: Daniel P. Berrangé <berrange@redhat.com> > Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com> Do you expect this to go through my tree? Hint: if you do, cc'ing me tends to help ;) scripts/get_maintainer.pl can be your friend.
Hey, On Thu, Jan 24, 2019 at 10:38:37AM +0100, Markus Armbruster wrote: > Christophe Fergeau <cfergeau@redhat.com> writes: > > > This commit adds a qemu_init_logging() helper which calls > > g_log_set_default_handler() so that glib logs (g_log, g_warning, ...) > > are handled similarly to other QEMU logs. This means they will get a > > timestamp if timestamps are enabled, and they will go through the > > monitor if one is configured. > > This commit also adds a call to qemu_init_logging() to the binaries > > installed by QEMU. > > glib debug messages are enabled through G_MESSAGES_DEBUG similarly to > > glib default log handler. > > > > At the moment, this change will mostly impact SPICE logging if your > > spice version is >= 0.14.1. With older spice versions, this is not going > > to work as expected, but will not have any ill effect, so this call is > > not conditional on the SPICE version. > > > > Signed-off-by: Christophe Fergeau <cfergeau@redhat.com> > > Reviewed-by: Daniel P. Berrangé <berrange@redhat.com> > > Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com> > > Do you expect this to go through my tree? To be honest, I don't know through whose tree this should go. > Hint: if you do, cc'ing me tends to help ;) > > scripts/get_maintainer.pl can be your friend. I ran it, but it returned a few too many names given that it touches files in various subsystems, I was not sure I should cc: everyone. Now that I look again, at least "(supporter:Error reporting)" would have made sense. Thanks for noticing this patch without the cc: :) Christophe
Christophe Fergeau <cfergeau@redhat.com> writes: > Hey, > > On Thu, Jan 24, 2019 at 10:38:37AM +0100, Markus Armbruster wrote: >> Christophe Fergeau <cfergeau@redhat.com> writes: >> >> > This commit adds a qemu_init_logging() helper which calls >> > g_log_set_default_handler() so that glib logs (g_log, g_warning, ...) >> > are handled similarly to other QEMU logs. This means they will get a >> > timestamp if timestamps are enabled, and they will go through the >> > monitor if one is configured. >> > This commit also adds a call to qemu_init_logging() to the binaries >> > installed by QEMU. >> > glib debug messages are enabled through G_MESSAGES_DEBUG similarly to >> > glib default log handler. >> > >> > At the moment, this change will mostly impact SPICE logging if your >> > spice version is >= 0.14.1. With older spice versions, this is not going >> > to work as expected, but will not have any ill effect, so this call is >> > not conditional on the SPICE version. >> > >> > Signed-off-by: Christophe Fergeau <cfergeau@redhat.com> >> > Reviewed-by: Daniel P. Berrangé <berrange@redhat.com> >> > Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com> >> >> Do you expect this to go through my tree? > > To be honest, I don't know through whose tree this should go. The bulk of the patch is in qemu-error.c, which suggests my tree. >> Hint: if you do, cc'ing me tends to help ;) >> >> scripts/get_maintainer.pl can be your friend. > > I ran it, but it returned a few too many names given that it touches > files in various subsystems, I was not sure I should cc: everyone. You were right to doubt. > Now that I look again, at least "(supporter:Error reporting)" would have > made sense. > > Thanks for noticing this patch without the cc: :) No problem :)
Christophe Fergeau <cfergeau@redhat.com> writes: > This commit adds a qemu_init_logging() helper which calls > g_log_set_default_handler() so that glib logs (g_log, g_warning, ...) > are handled similarly to other QEMU logs. This means they will get a > timestamp if timestamps are enabled, and they will go through the > monitor if one is configured. s/monitor/HMP monitor/ I see why one would like to extend the timestamp feature to GLib log messages. Routing them through the HMP monitor is perhaps debatable. Cc: Dave in case he has an opinion. > This commit also adds a call to qemu_init_logging() to the binaries > installed by QEMU. > glib debug messages are enabled through G_MESSAGES_DEBUG similarly to > glib default log handler. > > At the moment, this change will mostly impact SPICE logging if your > spice version is >= 0.14.1. With older spice versions, this is not going > to work as expected, but will not have any ill effect, so this call is > not conditional on the SPICE version. > > Signed-off-by: Christophe Fergeau <cfergeau@redhat.com> > Reviewed-by: Daniel P. Berrangé <berrange@redhat.com> > Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com> > --- > One more iteration of the patch as it hit CI failures > (https://patchew.org/QEMU/20181214105642.673-1-cfergeau@redhat.com/ ) > Only difference from v4 is the addition of #include "qemu/error-report.h" > in bsd-user and linux-user. > > > bsd-user/main.c | 2 ++ > include/qemu/error-report.h | 2 ++ > linux-user/main.c | 2 ++ > qemu-img.c | 1 + > qemu-io.c | 1 + > qemu-nbd.c | 1 + > scsi/qemu-pr-helper.c | 1 + > util/qemu-error.c | 47 +++++++++++++++++++++++++++++++++++++ > vl.c | 1 + > 9 files changed, 58 insertions(+) > > diff --git a/bsd-user/main.c b/bsd-user/main.c > index 0d3156974c..0df5c853d3 100644 > --- a/bsd-user/main.c > +++ b/bsd-user/main.c > @@ -24,6 +24,7 @@ > #include "qapi/error.h" > #include "qemu.h" > #include "qemu/config-file.h" > +#include "qemu/error-report.h" > #include "qemu/path.h" > #include "qemu/help_option.h" > #include "cpu.h" > @@ -743,6 +744,7 @@ int main(int argc, char **argv) > if (argc <= 1) > usage(); > > + qemu_init_logging(); > module_call_init(MODULE_INIT_TRACE); > qemu_init_cpu_list(); > module_call_init(MODULE_INIT_QOM); > diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h > index 0a8d9cc9ea..2852e9df2a 100644 > --- a/include/qemu/error-report.h > +++ b/include/qemu/error-report.h > @@ -49,6 +49,8 @@ bool error_report_once_cond(bool *printed, const char *fmt, ...) > bool warn_report_once_cond(bool *printed, const char *fmt, ...) > GCC_FMT_ATTR(2, 3); > > +void qemu_init_logging(void); > + > /* > * Similar to error_report(), except it prints the message just once. > * Return true when it prints, false otherwise. > diff --git a/linux-user/main.c b/linux-user/main.c > index a0aba9cb1e..d9b3ffd1f4 100644 > --- a/linux-user/main.c > +++ b/linux-user/main.c > @@ -27,6 +27,7 @@ > #include "qemu/path.h" > #include "qemu/config-file.h" > #include "qemu/cutils.h" > +#include "qemu/error-report.h" > #include "qemu/help_option.h" > #include "cpu.h" > #include "exec/exec-all.h" > @@ -600,6 +601,7 @@ int main(int argc, char **argv, char **envp) > int ret; > int execfd; > > + qemu_init_logging(); > module_call_init(MODULE_INIT_TRACE); > qemu_init_cpu_list(); > module_call_init(MODULE_INIT_QOM); > diff --git a/qemu-img.c b/qemu-img.c > index ad04f59565..9214392565 100644 > --- a/qemu-img.c > +++ b/qemu-img.c > @@ -4912,6 +4912,7 @@ int main(int argc, char **argv) > signal(SIGPIPE, SIG_IGN); > #endif > > + qemu_init_logging(); > module_call_init(MODULE_INIT_TRACE); > error_set_progname(argv[0]); > qemu_init_exec_dir(argv[0]); > diff --git a/qemu-io.c b/qemu-io.c > index 6df7731af4..ad38d12e68 100644 > --- a/qemu-io.c > +++ b/qemu-io.c > @@ -524,6 +524,7 @@ int main(int argc, char **argv) > signal(SIGPIPE, SIG_IGN); > #endif > > + qemu_init_logging(); > module_call_init(MODULE_INIT_TRACE); > progname = g_path_get_basename(argv[0]); > qemu_init_exec_dir(argv[0]); > diff --git a/qemu-nbd.c b/qemu-nbd.c > index 51b55f2e06..274b22d445 100644 > --- a/qemu-nbd.c > +++ b/qemu-nbd.c > @@ -581,6 +581,7 @@ int main(int argc, char **argv) > signal(SIGPIPE, SIG_IGN); > #endif > > + qemu_init_logging(); > module_call_init(MODULE_INIT_TRACE); > error_set_progname(argv[0]); > qcrypto_init(&error_fatal); > diff --git a/scsi/qemu-pr-helper.c b/scsi/qemu-pr-helper.c > index e7af637232..523f8b237c 100644 > --- a/scsi/qemu-pr-helper.c > +++ b/scsi/qemu-pr-helper.c > @@ -895,6 +895,7 @@ int main(int argc, char **argv) > > signal(SIGPIPE, SIG_IGN); > > + qemu_init_logging(); > module_call_init(MODULE_INIT_TRACE); > module_call_init(MODULE_INIT_QOM); > qemu_add_opts(&qemu_trace_opts); > diff --git a/util/qemu-error.c b/util/qemu-error.c > index fcbe8a1f74..1118ed4695 100644 > --- a/util/qemu-error.c > +++ b/util/qemu-error.c > @@ -345,3 +345,50 @@ bool warn_report_once_cond(bool *printed, const char *fmt, ...) > va_end(ap); > return true; > } > + > +static char *qemu_glog_domains; > + > +static void qemu_log_func(const gchar *log_domain, > + GLogLevelFlags log_level, > + const gchar *message, > + gpointer user_data) > +{ > + switch (log_level & G_LOG_LEVEL_MASK) { > + case G_LOG_LEVEL_DEBUG: > + /* Use same G_MESSAGES_DEBUG logic as glib to enable/disable debug > + * messages > + */ Wing both ends of the comment, please. > + if (qemu_glog_domains == NULL) { > + break; > + } > + if (strcmp(qemu_glog_domains, "all") != 0 && > + (log_domain == NULL || !strstr(qemu_glog_domains, log_domain))) { > + break; > + } > + /* Fall through */ > + case G_LOG_LEVEL_INFO: > + /* Fall through */ g_log_default_handler() applies G_MESSAGES_DEBUG suppression logic to G_LOG_LEVEL_INFO messages, too. Do you deviate intentionally? > + case G_LOG_LEVEL_MESSAGE: > + info_report("%s: %s", log_domain, message); @log_domain can be null. You even check for that above. > + break; > + case G_LOG_LEVEL_WARNING: > + warn_report("%s: %s", log_domain, message); > + break; > + case G_LOG_LEVEL_CRITICAL: > + /* Fall through */ > + case G_LOG_LEVEL_ERROR: > + error_report("%s: %s", log_domain, message); > + break; Sure we don't need to check for G_LOG_FLAG_RECURSION? g_log_default_handler() has a conditional for that... Not sure it has anything for G_LOG_FLAG_FATAL; it's code is surprisingly complex. > + } > +} > + > +/* > + * Init QEMU logging subsystem. This sets up glib logging so libraries using it > + * also print their logs through {info,warn,error}_report. > + */ Format like the other function comments: /* * Init QEMU logging subsystem. * This sets up glib logging so libraries using it also print their logs * through error_report(), warn_report(), info_report(). */ Braces expanded for better grepability. > +void qemu_init_logging(void) Naming is hard... Yes, this "initializes logging" in a sense: it installs a GLib default log handler that routes GLib log messages through this module. But that's detail; the callers don't care what this function does, all they care for is "must call early". If this module ever grows a need to initialize something else before it gets used, we'll regret naming its initialization function qemu_init_logging(). Hmm, it has already grown such a need: initializing @progname. error_set_progname() does it. Asking a module's users to call *two* initializtion functions is not nice. Fuse the two into error_init(const char *argv0)? > +{ > + g_log_set_default_handler(qemu_log_func, NULL); > + g_warn_if_fail(qemu_glog_domains == NULL); > + qemu_glog_domains = g_strdup(g_getenv("G_MESSAGES_DEBUG")); > +} > diff --git a/vl.c b/vl.c > index bc9fbec654..f03f20e060 100644 > --- a/vl.c > +++ b/vl.c > @@ -3039,6 +3039,7 @@ int main(int argc, char **argv, char **envp) > QSIMPLEQ_HEAD(, BlockdevOptions_queue) bdo_queue > = QSIMPLEQ_HEAD_INITIALIZER(bdo_queue); > > + qemu_init_logging(); > module_call_init(MODULE_INIT_TRACE); > > qemu_init_cpu_list();
* Markus Armbruster (armbru@redhat.com) wrote: > Christophe Fergeau <cfergeau@redhat.com> writes: > > > This commit adds a qemu_init_logging() helper which calls > > g_log_set_default_handler() so that glib logs (g_log, g_warning, ...) > > are handled similarly to other QEMU logs. This means they will get a > > timestamp if timestamps are enabled, and they will go through the > > monitor if one is configured. > > s/monitor/HMP monitor/ > > I see why one would like to extend the timestamp feature to GLib log > messages. Routing them through the HMP monitor is perhaps debatable. > Cc: Dave in case he has an opinion. Yes, it's a little odd; what's wrong with stderr for this type of thing? My experience has been that things like spice errors are fairly asynchronous rather than directly triggered by commands, so maybe less suitable for interleaving in the monitor. While stderr and hmp output are normally the same, if someone has HMP wired to a script, I'd assume this is more likely to break it. Dave > > This commit also adds a call to qemu_init_logging() to the binaries > > installed by QEMU. > > glib debug messages are enabled through G_MESSAGES_DEBUG similarly to > > glib default log handler. > > > > At the moment, this change will mostly impact SPICE logging if your > > spice version is >= 0.14.1. With older spice versions, this is not going > > to work as expected, but will not have any ill effect, so this call is > > not conditional on the SPICE version. > > > > Signed-off-by: Christophe Fergeau <cfergeau@redhat.com> > > Reviewed-by: Daniel P. Berrangé <berrange@redhat.com> > > Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com> > > --- > > One more iteration of the patch as it hit CI failures > > (https://patchew.org/QEMU/20181214105642.673-1-cfergeau@redhat.com/ ) > > Only difference from v4 is the addition of #include "qemu/error-report.h" > > in bsd-user and linux-user. > > > > > > bsd-user/main.c | 2 ++ > > include/qemu/error-report.h | 2 ++ > > linux-user/main.c | 2 ++ > > qemu-img.c | 1 + > > qemu-io.c | 1 + > > qemu-nbd.c | 1 + > > scsi/qemu-pr-helper.c | 1 + > > util/qemu-error.c | 47 +++++++++++++++++++++++++++++++++++++ > > vl.c | 1 + > > 9 files changed, 58 insertions(+) > > > > diff --git a/bsd-user/main.c b/bsd-user/main.c > > index 0d3156974c..0df5c853d3 100644 > > --- a/bsd-user/main.c > > +++ b/bsd-user/main.c > > @@ -24,6 +24,7 @@ > > #include "qapi/error.h" > > #include "qemu.h" > > #include "qemu/config-file.h" > > +#include "qemu/error-report.h" > > #include "qemu/path.h" > > #include "qemu/help_option.h" > > #include "cpu.h" > > @@ -743,6 +744,7 @@ int main(int argc, char **argv) > > if (argc <= 1) > > usage(); > > > > + qemu_init_logging(); > > module_call_init(MODULE_INIT_TRACE); > > qemu_init_cpu_list(); > > module_call_init(MODULE_INIT_QOM); > > diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h > > index 0a8d9cc9ea..2852e9df2a 100644 > > --- a/include/qemu/error-report.h > > +++ b/include/qemu/error-report.h > > @@ -49,6 +49,8 @@ bool error_report_once_cond(bool *printed, const char *fmt, ...) > > bool warn_report_once_cond(bool *printed, const char *fmt, ...) > > GCC_FMT_ATTR(2, 3); > > > > +void qemu_init_logging(void); > > + > > /* > > * Similar to error_report(), except it prints the message just once. > > * Return true when it prints, false otherwise. > > diff --git a/linux-user/main.c b/linux-user/main.c > > index a0aba9cb1e..d9b3ffd1f4 100644 > > --- a/linux-user/main.c > > +++ b/linux-user/main.c > > @@ -27,6 +27,7 @@ > > #include "qemu/path.h" > > #include "qemu/config-file.h" > > #include "qemu/cutils.h" > > +#include "qemu/error-report.h" > > #include "qemu/help_option.h" > > #include "cpu.h" > > #include "exec/exec-all.h" > > @@ -600,6 +601,7 @@ int main(int argc, char **argv, char **envp) > > int ret; > > int execfd; > > > > + qemu_init_logging(); > > module_call_init(MODULE_INIT_TRACE); > > qemu_init_cpu_list(); > > module_call_init(MODULE_INIT_QOM); > > diff --git a/qemu-img.c b/qemu-img.c > > index ad04f59565..9214392565 100644 > > --- a/qemu-img.c > > +++ b/qemu-img.c > > @@ -4912,6 +4912,7 @@ int main(int argc, char **argv) > > signal(SIGPIPE, SIG_IGN); > > #endif > > > > + qemu_init_logging(); > > module_call_init(MODULE_INIT_TRACE); > > error_set_progname(argv[0]); > > qemu_init_exec_dir(argv[0]); > > diff --git a/qemu-io.c b/qemu-io.c > > index 6df7731af4..ad38d12e68 100644 > > --- a/qemu-io.c > > +++ b/qemu-io.c > > @@ -524,6 +524,7 @@ int main(int argc, char **argv) > > signal(SIGPIPE, SIG_IGN); > > #endif > > > > + qemu_init_logging(); > > module_call_init(MODULE_INIT_TRACE); > > progname = g_path_get_basename(argv[0]); > > qemu_init_exec_dir(argv[0]); > > diff --git a/qemu-nbd.c b/qemu-nbd.c > > index 51b55f2e06..274b22d445 100644 > > --- a/qemu-nbd.c > > +++ b/qemu-nbd.c > > @@ -581,6 +581,7 @@ int main(int argc, char **argv) > > signal(SIGPIPE, SIG_IGN); > > #endif > > > > + qemu_init_logging(); > > module_call_init(MODULE_INIT_TRACE); > > error_set_progname(argv[0]); > > qcrypto_init(&error_fatal); > > diff --git a/scsi/qemu-pr-helper.c b/scsi/qemu-pr-helper.c > > index e7af637232..523f8b237c 100644 > > --- a/scsi/qemu-pr-helper.c > > +++ b/scsi/qemu-pr-helper.c > > @@ -895,6 +895,7 @@ int main(int argc, char **argv) > > > > signal(SIGPIPE, SIG_IGN); > > > > + qemu_init_logging(); > > module_call_init(MODULE_INIT_TRACE); > > module_call_init(MODULE_INIT_QOM); > > qemu_add_opts(&qemu_trace_opts); > > diff --git a/util/qemu-error.c b/util/qemu-error.c > > index fcbe8a1f74..1118ed4695 100644 > > --- a/util/qemu-error.c > > +++ b/util/qemu-error.c > > @@ -345,3 +345,50 @@ bool warn_report_once_cond(bool *printed, const char *fmt, ...) > > va_end(ap); > > return true; > > } > > + > > +static char *qemu_glog_domains; > > + > > +static void qemu_log_func(const gchar *log_domain, > > + GLogLevelFlags log_level, > > + const gchar *message, > > + gpointer user_data) > > +{ > > + switch (log_level & G_LOG_LEVEL_MASK) { > > + case G_LOG_LEVEL_DEBUG: > > + /* Use same G_MESSAGES_DEBUG logic as glib to enable/disable debug > > + * messages > > + */ > > Wing both ends of the comment, please. > > > + if (qemu_glog_domains == NULL) { > > + break; > > + } > > + if (strcmp(qemu_glog_domains, "all") != 0 && > > + (log_domain == NULL || !strstr(qemu_glog_domains, log_domain))) { > > + break; > > + } > > + /* Fall through */ > > + case G_LOG_LEVEL_INFO: > > + /* Fall through */ > > g_log_default_handler() applies G_MESSAGES_DEBUG suppression logic to > G_LOG_LEVEL_INFO messages, too. Do you deviate intentionally? > > > + case G_LOG_LEVEL_MESSAGE: > > + info_report("%s: %s", log_domain, message); > > @log_domain can be null. You even check for that above. > > > + break; > > + case G_LOG_LEVEL_WARNING: > > + warn_report("%s: %s", log_domain, message); > > + break; > > + case G_LOG_LEVEL_CRITICAL: > > + /* Fall through */ > > + case G_LOG_LEVEL_ERROR: > > + error_report("%s: %s", log_domain, message); > > + break; > > Sure we don't need to check for G_LOG_FLAG_RECURSION? > g_log_default_handler() has a conditional for that... > > Not sure it has anything for G_LOG_FLAG_FATAL; it's code is surprisingly > complex. > > > + } > > +} > > + > > +/* > > + * Init QEMU logging subsystem. This sets up glib logging so libraries using it > > + * also print their logs through {info,warn,error}_report. > > + */ > > Format like the other function comments: > > /* > * Init QEMU logging subsystem. > * This sets up glib logging so libraries using it also print their logs > * through error_report(), warn_report(), info_report(). > */ > > Braces expanded for better grepability. > > > +void qemu_init_logging(void) > > Naming is hard... Yes, this "initializes logging" in a sense: it > installs a GLib default log handler that routes GLib log messages > through this module. But that's detail; the callers don't care what > this function does, all they care for is "must call early". If this > module ever grows a need to initialize something else before it gets > used, we'll regret naming its initialization function > qemu_init_logging(). > > Hmm, it has already grown such a need: initializing @progname. > error_set_progname() does it. Asking a module's users to call *two* > initializtion functions is not nice. > > Fuse the two into error_init(const char *argv0)? > > > +{ > > + g_log_set_default_handler(qemu_log_func, NULL); > > + g_warn_if_fail(qemu_glog_domains == NULL); > > + qemu_glog_domains = g_strdup(g_getenv("G_MESSAGES_DEBUG")); > > +} > > diff --git a/vl.c b/vl.c > > index bc9fbec654..f03f20e060 100644 > > --- a/vl.c > > +++ b/vl.c > > @@ -3039,6 +3039,7 @@ int main(int argc, char **argv, char **envp) > > QSIMPLEQ_HEAD(, BlockdevOptions_queue) bdo_queue > > = QSIMPLEQ_HEAD_INITIALIZER(bdo_queue); > > > > + qemu_init_logging(); > > module_call_init(MODULE_INIT_TRACE); > > > > qemu_init_cpu_list(); -- Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK
"Dr. David Alan Gilbert" <dgilbert@redhat.com> writes: > * Markus Armbruster (armbru@redhat.com) wrote: >> Christophe Fergeau <cfergeau@redhat.com> writes: >> >> > This commit adds a qemu_init_logging() helper which calls >> > g_log_set_default_handler() so that glib logs (g_log, g_warning, ...) >> > are handled similarly to other QEMU logs. This means they will get a >> > timestamp if timestamps are enabled, and they will go through the >> > monitor if one is configured. >> >> s/monitor/HMP monitor/ >> >> I see why one would like to extend the timestamp feature to GLib log >> messages. Routing them through the HMP monitor is perhaps debatable. >> Cc: Dave in case he has an opinion. > > Yes, it's a little odd; what's wrong with stderr for this type of thing? > My experience has been that things like spice errors are fairly > asynchronous rather than directly triggered by commands, so maybe less > suitable for interleaving in the monitor. Fortunately, error_printf() & friends print to an HMP monitor only when the current thread is running in HMP monitor context. > While stderr and hmp output are normally the same, if someone has > HMP wired to a script, I'd assume this is more likely to break it. Programs consuming HMP output are brittle. While we don't break them just because we can, we do change HMP output without worrying about them whenever we feel the change is an improvement for *human* readers. Another possible concern is messages vanishing from stderr.
On Thu, Jan 24, 2019 at 05:10:28PM +0100, Markus Armbruster wrote: > Christophe Fergeau <cfergeau@redhat.com> writes: > > > This commit adds a qemu_init_logging() helper which calls > > g_log_set_default_handler() so that glib logs (g_log, g_warning, ...) > > are handled similarly to other QEMU logs. This means they will get a > > timestamp if timestamps are enabled, and they will go through the > > monitor if one is configured. > > s/monitor/HMP monitor/ > > I see why one would like to extend the timestamp feature to GLib log > messages. Routing them through the HMP monitor is perhaps debatable. > Cc: Dave in case he has an opinion. Yep, I don't mind whether this goes through HMP or not, this definitely was not one of my goals when writing this patch. I mention it in the commit log because this is what the current code is going to do. > > [snip] > > diff --git a/util/qemu-error.c b/util/qemu-error.c > > index fcbe8a1f74..1118ed4695 100644 > > --- a/util/qemu-error.c > > +++ b/util/qemu-error.c > > @@ -345,3 +345,50 @@ bool warn_report_once_cond(bool *printed, const char *fmt, ...) > > va_end(ap); > > return true; > > } > > + > > +static char *qemu_glog_domains; > > + > > +static void qemu_log_func(const gchar *log_domain, > > + GLogLevelFlags log_level, > > + const gchar *message, > > + gpointer user_data) > > +{ > > + switch (log_level & G_LOG_LEVEL_MASK) { > > + case G_LOG_LEVEL_DEBUG: > > + /* Use same G_MESSAGES_DEBUG logic as glib to enable/disable debug > > + * messages > > + */ > > Wing both ends of the comment, please. Fixed. > > > + if (qemu_glog_domains == NULL) { > > + break; > > + } > > + if (strcmp(qemu_glog_domains, "all") != 0 && > > + (log_domain == NULL || !strstr(qemu_glog_domains, log_domain))) { > > + break; > > + } > > + /* Fall through */ > > + case G_LOG_LEVEL_INFO: > > + /* Fall through */ > > g_log_default_handler() applies G_MESSAGES_DEBUG suppression logic to > G_LOG_LEVEL_INFO messages, too. Do you deviate intentionally? Nope, I thought INFO and MESSAGE were equivalent. Fixed now. > > > + case G_LOG_LEVEL_MESSAGE: > > + info_report("%s: %s", log_domain, message); > > @log_domain can be null. You even check for that above. Fixed. > > > + break; > > + case G_LOG_LEVEL_WARNING: > > + warn_report("%s: %s", log_domain, message); > > + break; > > + case G_LOG_LEVEL_CRITICAL: > > + /* Fall through */ > > + case G_LOG_LEVEL_ERROR: > > + error_report("%s: %s", log_domain, message); > > + break; > > Sure we don't need to check for G_LOG_FLAG_RECURSION? > g_log_default_handler() has a conditional for that... > > Not sure it has anything for G_LOG_FLAG_FATAL; it's code is surprisingly > complex. Both are filtered out from the switch() through G_LOG_LEVEL_MASK: switch (log_level & G_LOG_LEVEL_MASK) { and https://developer.gnome.org/glib/2.58/glib-Message-Logging.html#G-LOG-FLAG-RECURSION:CAPS documents G_LOG_FLAG_FATAL and G_LOG_FLAG_RECURSION as fatal. However, g_log_set_handler() then mentions handling them anyways: https://developer.gnome.org/glib/2.58/glib-Message-Logging.html#g-log-set-handler "Sets the log handler for a domain and a set of log levels. To handle fatal and recursive messages the log_levels parameter must be combined with the G_LOG_FLAG_FATAL and G_LOG_FLAG_RECURSION bit flags." My understanding of glib's code is if any of these 2 flags is set, glib is going to abort anyways, so handling or not handling these flags is not going to make a big difference. > > > + } > > +} > > + > > +/* > > + * Init QEMU logging subsystem. This sets up glib logging so libraries using it > > + * also print their logs through {info,warn,error}_report. > > + */ > > Format like the other function comments: > > /* > * Init QEMU logging subsystem. > * This sets up glib logging so libraries using it also print their logs > * through error_report(), warn_report(), info_report(). > */ > > Braces expanded for better grepability. > > > +void qemu_init_logging(void) > > Naming is hard... Yes, this "initializes logging" in a sense: it > installs a GLib default log handler that routes GLib log messages > through this module. But that's detail; the callers don't care what > this function does, all they care for is "must call early". If this > module ever grows a need to initialize something else before it gets > used, we'll regret naming its initialization function > qemu_init_logging(). > > Hmm, it has already grown such a need: initializing @progname. > error_set_progname() does it. Asking a module's users to call *two* > initializtion functions is not nice. > > Fuse the two into error_init(const char *argv0)? Ok, I've done that now, I'll send a v6. Thanks for the review, Christophe
diff --git a/bsd-user/main.c b/bsd-user/main.c index 0d3156974c..0df5c853d3 100644 --- a/bsd-user/main.c +++ b/bsd-user/main.c @@ -24,6 +24,7 @@ #include "qapi/error.h" #include "qemu.h" #include "qemu/config-file.h" +#include "qemu/error-report.h" #include "qemu/path.h" #include "qemu/help_option.h" #include "cpu.h" @@ -743,6 +744,7 @@ int main(int argc, char **argv) if (argc <= 1) usage(); + qemu_init_logging(); module_call_init(MODULE_INIT_TRACE); qemu_init_cpu_list(); module_call_init(MODULE_INIT_QOM); diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h index 0a8d9cc9ea..2852e9df2a 100644 --- a/include/qemu/error-report.h +++ b/include/qemu/error-report.h @@ -49,6 +49,8 @@ bool error_report_once_cond(bool *printed, const char *fmt, ...) bool warn_report_once_cond(bool *printed, const char *fmt, ...) GCC_FMT_ATTR(2, 3); +void qemu_init_logging(void); + /* * Similar to error_report(), except it prints the message just once. * Return true when it prints, false otherwise. diff --git a/linux-user/main.c b/linux-user/main.c index a0aba9cb1e..d9b3ffd1f4 100644 --- a/linux-user/main.c +++ b/linux-user/main.c @@ -27,6 +27,7 @@ #include "qemu/path.h" #include "qemu/config-file.h" #include "qemu/cutils.h" +#include "qemu/error-report.h" #include "qemu/help_option.h" #include "cpu.h" #include "exec/exec-all.h" @@ -600,6 +601,7 @@ int main(int argc, char **argv, char **envp) int ret; int execfd; + qemu_init_logging(); module_call_init(MODULE_INIT_TRACE); qemu_init_cpu_list(); module_call_init(MODULE_INIT_QOM); diff --git a/qemu-img.c b/qemu-img.c index ad04f59565..9214392565 100644 --- a/qemu-img.c +++ b/qemu-img.c @@ -4912,6 +4912,7 @@ int main(int argc, char **argv) signal(SIGPIPE, SIG_IGN); #endif + qemu_init_logging(); module_call_init(MODULE_INIT_TRACE); error_set_progname(argv[0]); qemu_init_exec_dir(argv[0]); diff --git a/qemu-io.c b/qemu-io.c index 6df7731af4..ad38d12e68 100644 --- a/qemu-io.c +++ b/qemu-io.c @@ -524,6 +524,7 @@ int main(int argc, char **argv) signal(SIGPIPE, SIG_IGN); #endif + qemu_init_logging(); module_call_init(MODULE_INIT_TRACE); progname = g_path_get_basename(argv[0]); qemu_init_exec_dir(argv[0]); diff --git a/qemu-nbd.c b/qemu-nbd.c index 51b55f2e06..274b22d445 100644 --- a/qemu-nbd.c +++ b/qemu-nbd.c @@ -581,6 +581,7 @@ int main(int argc, char **argv) signal(SIGPIPE, SIG_IGN); #endif + qemu_init_logging(); module_call_init(MODULE_INIT_TRACE); error_set_progname(argv[0]); qcrypto_init(&error_fatal); diff --git a/scsi/qemu-pr-helper.c b/scsi/qemu-pr-helper.c index e7af637232..523f8b237c 100644 --- a/scsi/qemu-pr-helper.c +++ b/scsi/qemu-pr-helper.c @@ -895,6 +895,7 @@ int main(int argc, char **argv) signal(SIGPIPE, SIG_IGN); + qemu_init_logging(); module_call_init(MODULE_INIT_TRACE); module_call_init(MODULE_INIT_QOM); qemu_add_opts(&qemu_trace_opts); diff --git a/util/qemu-error.c b/util/qemu-error.c index fcbe8a1f74..1118ed4695 100644 --- a/util/qemu-error.c +++ b/util/qemu-error.c @@ -345,3 +345,50 @@ bool warn_report_once_cond(bool *printed, const char *fmt, ...) va_end(ap); return true; } + +static char *qemu_glog_domains; + +static void qemu_log_func(const gchar *log_domain, + GLogLevelFlags log_level, + const gchar *message, + gpointer user_data) +{ + switch (log_level & G_LOG_LEVEL_MASK) { + case G_LOG_LEVEL_DEBUG: + /* Use same G_MESSAGES_DEBUG logic as glib to enable/disable debug + * messages + */ + if (qemu_glog_domains == NULL) { + break; + } + if (strcmp(qemu_glog_domains, "all") != 0 && + (log_domain == NULL || !strstr(qemu_glog_domains, log_domain))) { + break; + } + /* Fall through */ + case G_LOG_LEVEL_INFO: + /* Fall through */ + case G_LOG_LEVEL_MESSAGE: + info_report("%s: %s", log_domain, message); + break; + case G_LOG_LEVEL_WARNING: + warn_report("%s: %s", log_domain, message); + break; + case G_LOG_LEVEL_CRITICAL: + /* Fall through */ + case G_LOG_LEVEL_ERROR: + error_report("%s: %s", log_domain, message); + break; + } +} + +/* + * Init QEMU logging subsystem. This sets up glib logging so libraries using it + * also print their logs through {info,warn,error}_report. + */ +void qemu_init_logging(void) +{ + g_log_set_default_handler(qemu_log_func, NULL); + g_warn_if_fail(qemu_glog_domains == NULL); + qemu_glog_domains = g_strdup(g_getenv("G_MESSAGES_DEBUG")); +} diff --git a/vl.c b/vl.c index bc9fbec654..f03f20e060 100644 --- a/vl.c +++ b/vl.c @@ -3039,6 +3039,7 @@ int main(int argc, char **argv, char **envp) QSIMPLEQ_HEAD(, BlockdevOptions_queue) bdo_queue = QSIMPLEQ_HEAD_INITIALIZER(bdo_queue); + qemu_init_logging(); module_call_init(MODULE_INIT_TRACE); qemu_init_cpu_list();