| Message ID | 1457954501-26528-7-git-send-email-den@openvz.org (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
On 14/03/2016 12:21, Denis V. Lunev wrote: > From: Pavel Butsykin <pbutsykin@virtuozzo.com> > > This log would be very welcome for long-term diagnostics of the system > in the production. This log is at least necessary to understand what > has been happened on the system and to identify issues at higher-level > subsystems (libvirt, etc). > > These messages will be quite useful to understand how things are going. There is now a logging mechanism for qemu-char.c. Have you looked into making libvirt provide a QMP log based on it? The timestamping of patch 9 could be useful for character devices as well. Paolo
On Mon, Mar 14, 2016 at 03:33:53PM +0100, Paolo Bonzini wrote: > > > On 14/03/2016 12:21, Denis V. Lunev wrote: > > From: Pavel Butsykin <pbutsykin@virtuozzo.com> > > > > This log would be very welcome for long-term diagnostics of the system > > in the production. This log is at least necessary to understand what > > has been happened on the system and to identify issues at higher-level > > subsystems (libvirt, etc). > > > > These messages will be quite useful to understand how things are going. > > There is now a logging mechanism for qemu-char.c. Have you looked into > making libvirt provide a QMP log based on it? > > The timestamping of patch 9 could be useful for character devices as well. libvirt QEMU driver already has logging support for recording all the data it both sends and receives over QMP, which should be sufficient for any day to day troubleshooting of QMP issues. So I doubt duplicating that info from QEMU side too is really beneficial for debugging issues when libvirt is in use. In libvirtd set log_filters="1:qemu_monitor" and it'll capture everything on the QMP monitor in the default libvirtd log file. The QMP data is also fed into the libvirt tracing backend, so you can write systemtap scripts that hook on any QMP message, reply or event. We ship a sample monitoring script examples/systemtap/qemu-monitor.stp for this too. Regards, Daniel
On 03/14/2016 05:38 PM, Daniel P. Berrange wrote: > On Mon, Mar 14, 2016 at 03:33:53PM +0100, Paolo Bonzini wrote: >> >> On 14/03/2016 12:21, Denis V. Lunev wrote: >>> From: Pavel Butsykin <pbutsykin@virtuozzo.com> >>> >>> This log would be very welcome for long-term diagnostics of the system >>> in the production. This log is at least necessary to understand what >>> has been happened on the system and to identify issues at higher-level >>> subsystems (libvirt, etc). >>> >>> These messages will be quite useful to understand how things are going. >> There is now a logging mechanism for qemu-char.c. Have you looked into >> making libvirt provide a QMP log based on it? >> >> The timestamping of patch 9 could be useful for character devices as well. > libvirt QEMU driver already has logging support for recording all the data > it both sends and receives over QMP, which should be sufficient for any > day to day troubleshooting of QMP issues. So I doubt duplicating that > info from QEMU side too is really beneficial for debugging issues when > libvirt is in use. > > In libvirtd set > > log_filters="1:qemu_monitor" > > and it'll capture everything on the QMP monitor in the default libvirtd > log file. > > The QMP data is also fed into the libvirt tracing backend, so you can > write systemtap scripts that hook on any QMP message, reply or event. > We ship a sample monitoring script examples/systemtap/qemu-monitor.stp > for this too. > > Regards, > Daniel you definitely sold this to me :) Thank you for pointing this out. OK. This means that patches 5-9 are not that necessary. Den
On 03/14/2016 05:38 PM, Daniel P. Berrange wrote: > On Mon, Mar 14, 2016 at 03:33:53PM +0100, Paolo Bonzini wrote: >> >> On 14/03/2016 12:21, Denis V. Lunev wrote: >>> From: Pavel Butsykin <pbutsykin@virtuozzo.com> >>> >>> This log would be very welcome for long-term diagnostics of the system >>> in the production. This log is at least necessary to understand what >>> has been happened on the system and to identify issues at higher-level >>> subsystems (libvirt, etc). >>> >>> These messages will be quite useful to understand how things are going. >> There is now a logging mechanism for qemu-char.c. Have you looked into >> making libvirt provide a QMP log based on it? >> >> The timestamping of patch 9 could be useful for character devices as well. > libvirt QEMU driver already has logging support for recording all the data > it both sends and receives over QMP, which should be sufficient for any > day to day troubleshooting of QMP issues. So I doubt duplicating that > info from QEMU side too is really beneficial for debugging issues when > libvirt is in use. > > In libvirtd set > > log_filters="1:qemu_monitor" > > and it'll capture everything on the QMP monitor in the default libvirtd > log file. > > The QMP data is also fed into the libvirt tracing backend, so you can > write systemtap scripts that hook on any QMP message, reply or event. > We ship a sample monitoring script examples/systemtap/qemu-monitor.stp > for this too. > > Regards, > Daniel you definitely sold this to me :) Thank you for pointing this out. There is the only differences in the approaches: - for example you have 20-50 VMs on the node - you have 1 problematic VM to be debugged by support (not development) In this case with my approach the load to the host IO subsystem will be less (logs from 1 VM will be written only). I can drop patches 5-9 if this is not important :) Den
On Mon, Mar 14, 2016 at 06:05:07PM +0300, Denis V. Lunev wrote: > On 03/14/2016 05:38 PM, Daniel P. Berrange wrote: > >On Mon, Mar 14, 2016 at 03:33:53PM +0100, Paolo Bonzini wrote: > >> > >>On 14/03/2016 12:21, Denis V. Lunev wrote: > >>>From: Pavel Butsykin <pbutsykin@virtuozzo.com> > >>> > >>>This log would be very welcome for long-term diagnostics of the system > >>>in the production. This log is at least necessary to understand what > >>>has been happened on the system and to identify issues at higher-level > >>>subsystems (libvirt, etc). > >>> > >>>These messages will be quite useful to understand how things are going. > >>There is now a logging mechanism for qemu-char.c. Have you looked into > >>making libvirt provide a QMP log based on it? > >> > >>The timestamping of patch 9 could be useful for character devices as well. > >libvirt QEMU driver already has logging support for recording all the data > >it both sends and receives over QMP, which should be sufficient for any > >day to day troubleshooting of QMP issues. So I doubt duplicating that > >info from QEMU side too is really beneficial for debugging issues when > >libvirt is in use. > > > >In libvirtd set > > > > log_filters="1:qemu_monitor" > > > >and it'll capture everything on the QMP monitor in the default libvirtd > >log file. > > > >The QMP data is also fed into the libvirt tracing backend, so you can > >write systemtap scripts that hook on any QMP message, reply or event. > >We ship a sample monitoring script examples/systemtap/qemu-monitor.stp > >for this too. > > > you definitely sold this to me :) Thank you for pointing this out. > > There is the only differences in the approaches: > - for example you have 20-50 VMs on the node > - you have 1 problematic VM to be debugged by support (not development) > > In this case with my approach the load to the host IO subsystem will > be less (logs from 1 VM will be written only). Yep I can see your point but not sure how critical it is in practice. In my experiance people often tend to just enable libvirt's QEMU debugging permanently on the basis that by the time you notice a fault with a VM it is too late to enable it. You often can't reproduce it, so can't just turn it on for 1 VM once a probem occurs, you have to proactively collect the data. In case where you do want to target a single VM though, there is the systemtap approach to collect info which may be sufficient Regards, Daniel
On 03/14/2016 06:26 PM, Daniel P. Berrange wrote: > On Mon, Mar 14, 2016 at 06:05:07PM +0300, Denis V. Lunev wrote: >> On 03/14/2016 05:38 PM, Daniel P. Berrange wrote: >>> On Mon, Mar 14, 2016 at 03:33:53PM +0100, Paolo Bonzini wrote: >>>> On 14/03/2016 12:21, Denis V. Lunev wrote: >>>>> From: Pavel Butsykin <pbutsykin@virtuozzo.com> >>>>> >>>>> This log would be very welcome for long-term diagnostics of the system >>>>> in the production. This log is at least necessary to understand what >>>>> has been happened on the system and to identify issues at higher-level >>>>> subsystems (libvirt, etc). >>>>> >>>>> These messages will be quite useful to understand how things are going. >>>> There is now a logging mechanism for qemu-char.c. Have you looked into >>>> making libvirt provide a QMP log based on it? >>>> >>>> The timestamping of patch 9 could be useful for character devices as well. >>> libvirt QEMU driver already has logging support for recording all the data >>> it both sends and receives over QMP, which should be sufficient for any >>> day to day troubleshooting of QMP issues. So I doubt duplicating that >>> info from QEMU side too is really beneficial for debugging issues when >>> libvirt is in use. >>> >>> In libvirtd set >>> >>> log_filters="1:qemu_monitor" >>> >>> and it'll capture everything on the QMP monitor in the default libvirtd >>> log file. >>> >>> The QMP data is also fed into the libvirt tracing backend, so you can >>> write systemtap scripts that hook on any QMP message, reply or event. >>> We ship a sample monitoring script examples/systemtap/qemu-monitor.stp >>> for this too. >>> >> you definitely sold this to me :) Thank you for pointing this out. >> >> There is the only differences in the approaches: >> - for example you have 20-50 VMs on the node >> - you have 1 problematic VM to be debugged by support (not development) >> >> In this case with my approach the load to the host IO subsystem will >> be less (logs from 1 VM will be written only). > Yep I can see your point but not sure how critical it is in practice. In > my experiance people often tend to just enable libvirt's QEMU debugging > permanently on the basis that by the time you notice a fault with a VM > it is too late to enable it. You often can't reproduce it, so can't just > turn it on for 1 VM once a probem occurs, you have to proactively collect > the data. In case where you do want to target a single VM though, there > is the systemtap approach to collect info which may be sufficient > > Regards, > Daniel Paolo, do you have any opinion on this? Den
On Mon, Mar 14, 2016 at 03:26:04PM +0000, Daniel P. Berrange wrote: > On Mon, Mar 14, 2016 at 06:05:07PM +0300, Denis V. Lunev wrote: > > On 03/14/2016 05:38 PM, Daniel P. Berrange wrote: > > >On Mon, Mar 14, 2016 at 03:33:53PM +0100, Paolo Bonzini wrote: > > >> > > >>On 14/03/2016 12:21, Denis V. Lunev wrote: > > >>>From: Pavel Butsykin <pbutsykin@virtuozzo.com> > > >>> > > >>>This log would be very welcome for long-term diagnostics of the system > > >>>in the production. This log is at least necessary to understand what > > >>>has been happened on the system and to identify issues at higher-level > > >>>subsystems (libvirt, etc). > > >>> > > >>>These messages will be quite useful to understand how things are going. > > >>There is now a logging mechanism for qemu-char.c. Have you looked into > > >>making libvirt provide a QMP log based on it? > > >> > > >>The timestamping of patch 9 could be useful for character devices as well. > > >libvirt QEMU driver already has logging support for recording all the data > > >it both sends and receives over QMP, which should be sufficient for any > > >day to day troubleshooting of QMP issues. So I doubt duplicating that > > >info from QEMU side too is really beneficial for debugging issues when > > >libvirt is in use. > > > > > >In libvirtd set > > > > > > log_filters="1:qemu_monitor" > > > > > >and it'll capture everything on the QMP monitor in the default libvirtd > > >log file. > > > > > >The QMP data is also fed into the libvirt tracing backend, so you can > > >write systemtap scripts that hook on any QMP message, reply or event. > > >We ship a sample monitoring script examples/systemtap/qemu-monitor.stp > > >for this too. > > > > > you definitely sold this to me :) Thank you for pointing this out. > > > > There is the only differences in the approaches: > > - for example you have 20-50 VMs on the node > > - you have 1 problematic VM to be debugged by support (not development) > > > > In this case with my approach the load to the host IO subsystem will > > be less (logs from 1 VM will be written only). > > Yep I can see your point but not sure how critical it is in practice. In > my experiance people often tend to just enable libvirt's QEMU debugging > permanently on the basis that by the time you notice a fault with a VM > it is too late to enable it. You often can't reproduce it, so can't just > turn it on for 1 VM once a probem occurs, you have to proactively collect > the data. In case where you do want to target a single VM though, there > is the systemtap approach to collect info which may be sufficient BTW, I'm not against adding this to QEMU in general - just pointing out that in the context of libvirt usage reference in the commit message, it is not really needed. I'm totally ambivalent wrt adding this to QEMU for benefit of non-libvirt usage. Regards, Daniel
On 03/14/2016 07:11 PM, Daniel P. Berrange wrote: > On Mon, Mar 14, 2016 at 03:26:04PM +0000, Daniel P. Berrange wrote: >> On Mon, Mar 14, 2016 at 06:05:07PM +0300, Denis V. Lunev wrote: >>> On 03/14/2016 05:38 PM, Daniel P. Berrange wrote: >>>> On Mon, Mar 14, 2016 at 03:33:53PM +0100, Paolo Bonzini wrote: >>>>> On 14/03/2016 12:21, Denis V. Lunev wrote: >>>>>> From: Pavel Butsykin <pbutsykin@virtuozzo.com> >>>>>> >>>>>> This log would be very welcome for long-term diagnostics of the system >>>>>> in the production. This log is at least necessary to understand what >>>>>> has been happened on the system and to identify issues at higher-level >>>>>> subsystems (libvirt, etc). >>>>>> >>>>>> These messages will be quite useful to understand how things are going. >>>>> There is now a logging mechanism for qemu-char.c. Have you looked into >>>>> making libvirt provide a QMP log based on it? >>>>> >>>>> The timestamping of patch 9 could be useful for character devices as well. >>>> libvirt QEMU driver already has logging support for recording all the data >>>> it both sends and receives over QMP, which should be sufficient for any >>>> day to day troubleshooting of QMP issues. So I doubt duplicating that >>>> info from QEMU side too is really beneficial for debugging issues when >>>> libvirt is in use. >>>> >>>> In libvirtd set >>>> >>>> log_filters="1:qemu_monitor" >>>> >>>> and it'll capture everything on the QMP monitor in the default libvirtd >>>> log file. >>>> >>>> The QMP data is also fed into the libvirt tracing backend, so you can >>>> write systemtap scripts that hook on any QMP message, reply or event. >>>> We ship a sample monitoring script examples/systemtap/qemu-monitor.stp >>>> for this too. >>>> >>> you definitely sold this to me :) Thank you for pointing this out. >>> >>> There is the only differences in the approaches: >>> - for example you have 20-50 VMs on the node >>> - you have 1 problematic VM to be debugged by support (not development) >>> >>> In this case with my approach the load to the host IO subsystem will >>> be less (logs from 1 VM will be written only). >> Yep I can see your point but not sure how critical it is in practice. In >> my experiance people often tend to just enable libvirt's QEMU debugging >> permanently on the basis that by the time you notice a fault with a VM >> it is too late to enable it. You often can't reproduce it, so can't just >> turn it on for 1 VM once a probem occurs, you have to proactively collect >> the data. In case where you do want to target a single VM though, there >> is the systemtap approach to collect info which may be sufficient > BTW, I'm not against adding this to QEMU in general - just pointing out > that in the context of libvirt usage reference in the commit message, > it is not really needed. I'm totally ambivalent wrt adding this to QEMU > for benefit of non-libvirt usage. > > Regards, > Daniel I see. This just requires very clear commit message from my side. Thank you for a discussion. Den
On 14/03/2016 17:10, Denis V. Lunev wrote: > On 03/14/2016 06:26 PM, Daniel P. Berrange wrote: >> On Mon, Mar 14, 2016 at 06:05:07PM +0300, Denis V. Lunev wrote: >>> On 03/14/2016 05:38 PM, Daniel P. Berrange wrote: >>>> On Mon, Mar 14, 2016 at 03:33:53PM +0100, Paolo Bonzini wrote: >>>>> On 14/03/2016 12:21, Denis V. Lunev wrote: >>>>>> From: Pavel Butsykin <pbutsykin@virtuozzo.com> >>>>>> >>>>>> This log would be very welcome for long-term diagnostics of the >>>>>> system >>>>>> in the production. This log is at least necessary to understand what >>>>>> has been happened on the system and to identify issues at >>>>>> higher-level >>>>>> subsystems (libvirt, etc). >>>>>> >>>>>> These messages will be quite useful to understand how things are >>>>>> going. >>>>> There is now a logging mechanism for qemu-char.c. Have you looked >>>>> into >>>>> making libvirt provide a QMP log based on it? >>>>> >>>>> The timestamping of patch 9 could be useful for character devices >>>>> as well. >>>> libvirt QEMU driver already has logging support for recording all >>>> the data >>>> it both sends and receives over QMP, which should be sufficient for any >>>> day to day troubleshooting of QMP issues. So I doubt duplicating that >>>> info from QEMU side too is really beneficial for debugging issues when >>>> libvirt is in use. >>>> >>>> In libvirtd set >>>> >>>> log_filters="1:qemu_monitor" >>>> >>>> and it'll capture everything on the QMP monitor in the default libvirtd >>>> log file. >>>> >>>> The QMP data is also fed into the libvirt tracing backend, so you can >>>> write systemtap scripts that hook on any QMP message, reply or event. >>>> We ship a sample monitoring script examples/systemtap/qemu-monitor.stp >>>> for this too. >>>> >>> you definitely sold this to me :) Thank you for pointing this out. >>> >>> There is the only differences in the approaches: >>> - for example you have 20-50 VMs on the node >>> - you have 1 problematic VM to be debugged by support (not development) >>> >>> In this case with my approach the load to the host IO subsystem will >>> be less (logs from 1 VM will be written only). >> Yep I can see your point but not sure how critical it is in practice. In >> my experiance people often tend to just enable libvirt's QEMU debugging >> permanently on the basis that by the time you notice a fault with a VM >> it is too late to enable it. You often can't reproduce it, so can't just >> turn it on for 1 VM once a probem occurs, you have to proactively collect >> the data. In case where you do want to target a single VM though, there >> is the systemtap approach to collect info which may be sufficient > > do you have any opinion on this? Daniel is usually very convincing to me as well. :) Paolo
On 14/03/2016 17:16, Denis V. Lunev wrote: >> BTW, I'm not against adding this to QEMU in general - just pointing out >> that in the context of libvirt usage reference in the commit message, >> it is not really needed. I'm totally ambivalent wrt adding this to QEMU >> for benefit of non-libvirt usage. > > I see. This just requires very clear commit message from my side. > Thank you for a discussion. I think this is not a compelling usage of the logging subsystem; QMP is always used through a character device, and character devices already have a logging mechanism. Adding a mechanism that looks for '\n' in the data written to a character device and emits a timestamp on the next character would be a useful addition. I'd be entirely happy with adding it now, it should be safe enough that we can do it during soft freeze. Paolo
On 03/14/2016 07:40 PM, Paolo Bonzini wrote: > > On 14/03/2016 17:16, Denis V. Lunev wrote: >>> BTW, I'm not against adding this to QEMU in general - just pointing out >>> that in the context of libvirt usage reference in the commit message, >>> it is not really needed. I'm totally ambivalent wrt adding this to QEMU >>> for benefit of non-libvirt usage. >> I see. This just requires very clear commit message from my side. >> Thank you for a discussion. > I think this is not a compelling usage of the logging subsystem; QMP is > always used through a character device, and character devices already > have a logging mechanism. > > Adding a mechanism that looks for '\n' in the data written to a > character device and emits a timestamp on the next character would be a > useful addition. I'd be entirely happy with adding it now, it should be > safe enough that we can do it during soft freeze. > > Paolo really interesting approach with a good place to get in. But we will need to modify this a infrastructure a bit. Af far as I can see only data from VM to outside world is logged. Data being 'read' should be logged too as far as I could understand. Den
On 16/03/2016 14:09, Denis V. Lunev wrote: > really interesting approach with a good place to get in. > But we will need to modify this a infrastructure a bit. > Af far as I can see only data from VM to outside world > is logged. Data being 'read' should be logged too as far > as I could understand. Hmm, you're right. As a start, let's document in the release notes that the format of the log file is subject to change. Paolo
On Wed, Mar 16, 2016 at 02:11:31PM +0100, Paolo Bonzini wrote: > > > On 16/03/2016 14:09, Denis V. Lunev wrote: > > really interesting approach with a good place to get in. > > But we will need to modify this a infrastructure a bit. > > Af far as I can see only data from VM to outside world > > is logged. Data being 'read' should be logged too as far > > as I could understand. > > Hmm, you're right. As a start, let's document in the release notes that > the format of the log file is subject to change. When logging terminal consoles (which motivated the feature) you don't really want to log input, since the terminal will echo text back already and you don't want to expose passwords sent in input either. None the less I can see the value in logging input too for other use cases. I could perhaps imagine a logdirection=in|out|both parameter being added to the -chardev to control this. Regards, Daniel
diff --git a/include/qemu/log.h b/include/qemu/log.h index a05c7dc..55bceae 100644 --- a/include/qemu/log.h +++ b/include/qemu/log.h @@ -42,6 +42,7 @@ static inline bool qemu_log_separate(void) #define CPU_LOG_TB_NOCHAIN (1 << 13) #define CPU_LOG_PAGE (1 << 14) #define LOG_TRACE (1 << 15) +#define LOG_QMP (1 << 16) /* Returns true if a bit is set in the current loglevel mask */ diff --git a/monitor.c b/monitor.c index e99ca8c..eec4e58 100644 --- a/monitor.c +++ b/monitor.c @@ -437,6 +437,12 @@ static void monitor_protocol_emitter(Monitor *mon, QObject *data, } monitor_json_emitter(mon, QOBJECT(qmp)); + if (qemu_loglevel_mask(LOG_QMP)) { + QString *output_json = qobject_to_json(QOBJECT(qmp)); + qemu_log_mask(LOG_QMP, "QMP reply: %s\n", output_json->string); + QDECREF(output_json); + } + QDECREF(qmp); } @@ -3867,6 +3873,11 @@ static void handle_qmp_command(JSONMessageParser *parser, GQueue *tokens) goto err_out; } + if (qemu_loglevel_mask(LOG_QMP)) { + QString *output_json = qobject_to_json(obj); + qemu_log_mask(LOG_QMP, "QMP command: %s\n", output_json->string); + QDECREF(output_json); + } input = qmp_check_input_obj(obj, &local_err); if (!input) { qobject_decref(obj); @@ -3988,12 +3999,14 @@ static void monitor_qmp_event(void *opaque, int event) monitor_json_emitter(mon, data); qobject_decref(data); mon_refcount++; + qemu_log_mask(LOG_QMP, "QMP: new connection established\n"); break; case CHR_EVENT_CLOSED: json_message_parser_destroy(&mon->qmp.parser); json_message_parser_init(&mon->qmp.parser, handle_qmp_command); mon_refcount--; monitor_fdsets_cleanup(); + qemu_log_mask(LOG_QMP, "QMP: connection closed\n"); break; } } diff --git a/util/log.c b/util/log.c index 65d46e2..5fc517b 100644 --- a/util/log.c +++ b/util/log.c @@ -131,6 +131,8 @@ const QEMULogItem qemu_log_items[] = { { CPU_LOG_TB_NOCHAIN, "nochain", "do not chain compiled TBs so that \"exec\" and \"cpu\" show\n" "complete traces" }, + { LOG_QMP, "qmp", + "log the QMP commands and events" }, { 0, NULL, NULL }, };