| Message ID | 20181214105642.673-1-cfergeau@redhat.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | [v4] log: Make glib logging go through QEMU | expand |
On Fri, Dec 14, 2018 at 11:56:42AM +0100, Christophe Fergeau wrote: > +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); QEMU itself uses glib, so what happens if *_report() emit more log messages? Can this result in an infinite loop? Stefan
Hey, On Thu, Jan 03, 2019 at 10:54:25AM +0000, Stefan Hajnoczi wrote: > On Fri, Dec 14, 2018 at 11:56:42AM +0100, Christophe Fergeau wrote: > > +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); > > QEMU itself uses glib, so what happens if *_report() emit more log > messages? Can this result in an infinite loop? If *_report try to output messages through the g_log API, glib will catch it and will abort, so not an infinite loop, but not a desirable outcome either. Some low-level logging functions which are going to dump the message without glib (or using g_log_default_handler()) are needed. The timestamping/prepending of 'error:', 'warning:' to the error message is done right below *_report (in vreport) so this looked like a good place for that. Christophe
On Thu, Jan 03, 2019 at 03:14:55PM +0100, Christophe Fergeau wrote: > Hey, > > On Thu, Jan 03, 2019 at 10:54:25AM +0000, Stefan Hajnoczi wrote: > > On Fri, Dec 14, 2018 at 11:56:42AM +0100, Christophe Fergeau wrote: > > > +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); > > > > QEMU itself uses glib, so what happens if *_report() emit more log > > messages? Can this result in an infinite loop? > > If *_report try to output messages through the g_log API, glib will > catch it and will abort, so not an infinite loop, but not a > desirable outcome either. > > Some low-level logging functions which are going to dump the message > without glib (or using g_log_default_handler()) are needed. > The timestamping/prepending of 'error:', 'warning:' to the error message > is done right below *_report (in vreport) so this looked like a good > place for that. If you're confident that QEMU will never (indirectly) emit a glib log message from the *_report() code path, then I'm happy. Stefan
On Fri, Jan 04, 2019 at 03:40:34PM +0000, Stefan Hajnoczi wrote: > On Thu, Jan 03, 2019 at 03:14:55PM +0100, Christophe Fergeau wrote: > > Hey, > > > > On Thu, Jan 03, 2019 at 10:54:25AM +0000, Stefan Hajnoczi wrote: > > > On Fri, Dec 14, 2018 at 11:56:42AM +0100, Christophe Fergeau wrote: > > > > +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); > > > > > > QEMU itself uses glib, so what happens if *_report() emit more log > > > messages? Can this result in an infinite loop? > > > > If *_report try to output messages through the g_log API, glib will > > catch it and will abort, so not an infinite loop, but not a > > desirable outcome either. > > > > Some low-level logging functions which are going to dump the message > > without glib (or using g_log_default_handler()) are needed. > > The timestamping/prepending of 'error:', 'warning:' to the error message > > is done right below *_report (in vreport) so this looked like a good > > place for that. > > If you're confident that QEMU will never (indirectly) emit a glib log > message from the *_report() code path, then I'm happy. In these codepaths, I'm confident up to void monitor_vfprintf(FILE *stream, const char *fmt, va_list ap) { if (cur_mon && !monitor_cur_is_qmp()) { monitor_vprintf(cur_mon, fmt, ap); } else { vfprintf(stream, fmt, ap); } } From there, it was not obvious to me whether the monitor_vprintf codepath can be triggered from info/warn/error_report or not. If they can, I'd feel less confident that monitor_vprintf will never indirectly call glib log functions. Christophe > > Stefan
On Mon, Jan 14, 2019 at 12:54:20PM +0100, Christophe Fergeau wrote: > On Fri, Jan 04, 2019 at 03:40:34PM +0000, Stefan Hajnoczi wrote: > > On Thu, Jan 03, 2019 at 03:14:55PM +0100, Christophe Fergeau wrote: > > > Hey, > > > > > > On Thu, Jan 03, 2019 at 10:54:25AM +0000, Stefan Hajnoczi wrote: > > > > On Fri, Dec 14, 2018 at 11:56:42AM +0100, Christophe Fergeau wrote: > > > > > +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); > > > > > > > > QEMU itself uses glib, so what happens if *_report() emit more log > > > > messages? Can this result in an infinite loop? > > > > > > If *_report try to output messages through the g_log API, glib will > > > catch it and will abort, so not an infinite loop, but not a > > > desirable outcome either. > > > > > > Some low-level logging functions which are going to dump the message > > > without glib (or using g_log_default_handler()) are needed. > > > The timestamping/prepending of 'error:', 'warning:' to the error message > > > is done right below *_report (in vreport) so this looked like a good > > > place for that. > > > > If you're confident that QEMU will never (indirectly) emit a glib log > > message from the *_report() code path, then I'm happy. > > In these codepaths, I'm confident up to > void monitor_vfprintf(FILE *stream, const char *fmt, va_list ap) > { > if (cur_mon && !monitor_cur_is_qmp()) { > monitor_vprintf(cur_mon, fmt, ap); > } else { > vfprintf(stream, fmt, ap); > } > } > > From there, it was not obvious to me whether the monitor_vprintf > codepath can be triggered from info/warn/error_report or not. If they > can, I'd feel less confident that monitor_vprintf will never indirectly > call glib log functions. I think we're okay because otherwise monitor_vprintf() -> info/warn/error_report() would already be an infinite loop today. Stefan
On Tue, Jan 15, 2019 at 02:09:12PM +0000, Stefan Hajnoczi wrote: > > In these codepaths, I'm confident up to > > void monitor_vfprintf(FILE *stream, const char *fmt, va_list ap) > > { > > if (cur_mon && !monitor_cur_is_qmp()) { > > monitor_vprintf(cur_mon, fmt, ap); > > } else { > > vfprintf(stream, fmt, ap); > > } > > } > > > > From there, it was not obvious to me whether the monitor_vprintf > > codepath can be triggered from info/warn/error_report or not. If they > > can, I'd feel less confident that monitor_vprintf will never indirectly > > call glib log functions. > > I think we're okay because otherwise monitor_vprintf() -> > info/warn/error_report() would already be an infinite loop today. Ah good point :) Christophe
On Fri, Dec 14, 2018 at 11:56:42AM +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> > --- > Changes since v3: > - Fixed style issue: removed 2 extra spaces before parens > (reported by checkpatch) > > bsd-user/main.c | 1 + > include/qemu/error-report.h | 2 ++ > linux-user/main.c | 1 + > 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, 56 insertions(+) Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com>
Patchew URL: https://patchew.org/QEMU/20181214105642.673-1-cfergeau@redhat.com/
Hi,
This series failed the docker-mingw@fedora build test. Please find the testing commands and
their output below. If you have Docker installed, you can probably reproduce it
locally.
=== TEST SCRIPT BEGIN ===
#!/bin/bash
time make docker-test-mingw@fedora SHOW_ENV=1 J=14
=== TEST SCRIPT END ===
CC vl.o
CC tpm.o
/tmp/qemu-test/src/block/sheepdog.c: In function 'find_vdi_name':
/tmp/qemu-test/src/block/sheepdog.c:1239:5: error: 'strncpy' specified bound 256 equals destination size [-Werror=stringop-truncation]
strncpy(buf + SD_MAX_VDI_LEN, tag, SD_MAX_VDI_TAG_LEN);
^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
cc1: all warnings being treated as errors
The full log is available at
http://patchew.org/logs/20181214105642.673-1-cfergeau@redhat.com/testing.docker-mingw@fedora/?type=message.
---
Email generated automatically by Patchew [http://patchew.org/].
Please send your feedback to patchew-devel@redhat.com
diff --git a/bsd-user/main.c b/bsd-user/main.c index 0d3156974c..96787b27ef 100644 --- a/bsd-user/main.c +++ b/bsd-user/main.c @@ -743,6 +743,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 923cbb753a..de9ff462e9 100644 --- a/linux-user/main.c +++ b/linux-user/main.c @@ -600,6 +600,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 ca7109652e..2cac038230 100644 --- a/qemu-nbd.c +++ b/qemu-nbd.c @@ -570,6 +570,7 @@ int main(int argc, char **argv) signal(SIGPIPE, SIG_IGN); #endif + qemu_init_logging(); module_call_init(MODULE_INIT_TRACE); 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 a5ae5f23d2..d986fd93ab 100644 --- a/vl.c +++ b/vl.c @@ -3015,6 +3015,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();