[PATCH v2] Add VM info to improve error log message for qemu monitor

Rohit Kumar posted 1 patch 2 years, 3 months ago
Test syntax-check failed
Patches applied successfully (tree, apply log)
git fetch https://github.com/patchew-project/libvirt tags/patchew/20211223063921.550303-1-rohit.kumar3@nutanix.com
There is a newer version of this series
src/qemu/qemu_monitor.c | 47 +++++++++++++++++++++++++----------------
1 file changed, 29 insertions(+), 18 deletions(-)
[PATCH v2] Add VM info to improve error log message for qemu monitor
Posted by Rohit Kumar 2 years, 3 months ago
This patch is to determine the VM which had IO or socket hangup error.
Accessing directly vm->def->name inside qemuMonitorIO() or qemuMonitorSend()
might leads to illegal access as we are out of 'vm' context and vm->def might
not exist. Adding a field "domainName" inside mon object to access vm name
and initialising it when creating mon object.

Signed-off-by: Rohit Kumar <rohit.kumar3@nutanix.com>
---
 diff to v1:
  - Adding a field domainName inside _qemuMonitor struct for accessing vm name
    instead of directly accessing mon->vm->def->name.
  - Link to v1: https://listman.redhat.com/archives/libvir-list/2021-December/msg00217.html
  - Talked with peter on RFC and he suggested me to add a field inside 
    monitor struct to get VM name.
 
 src/qemu/qemu_monitor.c | 47 +++++++++++++++++++++++++----------------
 1 file changed, 29 insertions(+), 18 deletions(-)

diff --git a/src/qemu/qemu_monitor.c b/src/qemu/qemu_monitor.c
index dda6ae9796..c3a0227795 100644
--- a/src/qemu/qemu_monitor.c
+++ b/src/qemu/qemu_monitor.c
@@ -80,6 +80,7 @@ struct _qemuMonitor {
     GSource *watch;
 
     virDomainObj *vm;
+    char *domainName;
 
     qemuMonitorCallbacks *cb;
     void *callbackOpaque;
@@ -243,6 +244,7 @@ qemuMonitorDispose(void *obj)
     virCondDestroy(&mon->notify);
     g_free(mon->buffer);
     g_free(mon->balloonpath);
+    g_free(mon->domainName);
 }
 
 
@@ -530,13 +532,18 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
     qemuMonitor *mon = opaque;
     bool error = false;
     bool hangup = false;
+    virDomainObj *vm = NULL;
+    char *vmName = NULL;
 
     virObjectRef(mon);
 
+    vm = mon->vm;
+    vmName = mon->domainName;
+
     /* lock access to the monitor and protect fd */
     virObjectLock(mon);
 #if DEBUG_IO
-    VIR_DEBUG("Monitor %p I/O on socket %p cond %d", mon, socket, cond);
+    VIR_DEBUG("Monitor %p I/O on socket %p cond %d vm=%p name=%s", mon, socket, cond, vm, NULLSTR(vmName));
 #endif
     if (mon->fd == -1 || !mon->watch) {
         virObjectUnlock(mon);
@@ -583,8 +590,8 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
 
         if (!error && !mon->goteof &&
             cond & G_IO_ERR) {
-            virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
-                           _("Invalid file descriptor while waiting for monitor"));
+            virReportError(VIR_ERR_INTERNAL_ERROR,
+                           _("%s: Invalid file descriptor while waiting for monitor"), NULLSTR(vmName));
             mon->goteof = true;
         }
     }
@@ -609,13 +616,14 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
             virResetLastError();
         } else {
             if (virGetLastErrorCode() == VIR_ERR_OK && !mon->goteof)
-                virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
-                               _("Error while processing monitor IO"));
+                virReportError(VIR_ERR_INTERNAL_ERROR,
+                               _("%s: Error while processing monitor IO"), NULLSTR(vmName));
             virCopyLastError(&mon->lastError);
             virResetLastError();
         }
 
-        VIR_DEBUG("Error on monitor %s", NULLSTR(mon->lastError.message));
+        VIR_DEBUG("Error on monitor %s mon=%p vm=%p name=%s",
+                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
         /* If IO process resulted in an error & we have a message,
          * then wakeup that waiter */
         if (mon->msg && !mon->msg->finished) {
@@ -631,22 +639,22 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
      * will try to acquire the virDomainObj *mutex next */
     if (mon->goteof) {
         qemuMonitorEofNotifyCallback eofNotify = mon->cb->eofNotify;
-        virDomainObj *vm = mon->vm;
 
         /* Make sure anyone waiting wakes up now */
         virCondSignal(&mon->notify);
         virObjectUnlock(mon);
-        VIR_DEBUG("Triggering EOF callback");
+        VIR_DEBUG("Triggering EOF callback mon=%p vm=%p name=%s",
+                  mon, vm, NULLSTR(vmName));
         (eofNotify)(mon, vm, mon->callbackOpaque);
         virObjectUnref(mon);
     } else if (error) {
         qemuMonitorErrorNotifyCallback errorNotify = mon->cb->errorNotify;
-        virDomainObj *vm = mon->vm;
 
         /* Make sure anyone waiting wakes up now */
         virCondSignal(&mon->notify);
         virObjectUnlock(mon);
-        VIR_DEBUG("Triggering error callback");
+        VIR_DEBUG("Triggering error callback mon=%p vm=%p name=%s",
+                  mon, vm, NULLSTR(vmName));
         (errorNotify)(mon, vm, mon->callbackOpaque);
         virObjectUnref(mon);
     } else {
@@ -694,6 +702,7 @@ qemuMonitorOpenInternal(virDomainObj *vm,
     mon->fd = fd;
     mon->context = g_main_context_ref(context);
     mon->vm = virObjectRef(vm);
+    mon->domainName = g_strdup(vm->def->name);
     mon->waitGreeting = true;
     mon->cb = cb;
     mon->callbackOpaque = opaque;
@@ -932,17 +941,19 @@ qemuMonitorSend(qemuMonitor *mon,
                 qemuMonitorMessage *msg)
 {
     int ret = -1;
+    virDomainObj *vm = mon->vm;
+    char *vmName = mon->domainName;
 
     /* Check whether qemu quit unexpectedly */
     if (mon->lastError.code != VIR_ERR_OK) {
-        VIR_DEBUG("Attempt to send command while error is set %s",
-                  NULLSTR(mon->lastError.message));
+        VIR_DEBUG("Attempt to send command while error is set %s mon=%p vm=%p name=%s",
+                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
         virSetError(&mon->lastError);
         return -1;
     }
     if (mon->goteof) {
-        virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
-                       _("End of file from qemu monitor"));
+        virReportError(VIR_ERR_INTERNAL_ERROR,
+                       _("%s: End of file from qemu monitor"), NULLSTR(vmName));
         return -1;
     }
 
@@ -955,15 +966,15 @@ qemuMonitorSend(qemuMonitor *mon,
 
     while (!mon->msg->finished) {
         if (virCondWait(&mon->notify, &mon->parent.lock) < 0) {
-            virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
-                           _("Unable to wait on monitor condition"));
+            virReportError(VIR_ERR_INTERNAL_ERROR,
+                           _("%s: Unable to wait on monitor condition"), NULLSTR(vmName));
             goto cleanup;
         }
     }
 
     if (mon->lastError.code != VIR_ERR_OK) {
-        VIR_DEBUG("Send command resulted in error %s",
-                  NULLSTR(mon->lastError.message));
+        VIR_DEBUG("Send command resulted in error %s mon=%p vm=%p name=%s",
+                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
         virSetError(&mon->lastError);
         goto cleanup;
     }
-- 
2.25.1

Re: [PATCH v2] Add VM info to improve error log message for qemu monitor
Posted by Rohit Kumar 2 years, 3 months ago
Ping. Please look at this patch.
Link: 
https://listman.redhat.com/archives/libvir-list/2021-December/msg00891.html

On 23/12/21 12:09 pm, Rohit Kumar wrote:
> This patch is to determine the VM which had IO or socket hangup error.
> Accessing directly vm->def->name inside qemuMonitorIO() or qemuMonitorSend()
> might leads to illegal access as we are out of 'vm' context and vm->def might
> not exist. Adding a field "domainName" inside mon object to access vm name
> and initialising it when creating mon object.
>
> Signed-off-by: Rohit Kumar <rohit.kumar3@nutanix.com>
> ---
>   diff to v1:
>    - Adding a field domainName inside _qemuMonitor struct for accessing vm name
>      instead of directly accessing mon->vm->def->name.
>    - Link to v1: https://listman.redhat.com/archives/libvir-list/2021-December/msg00217.html
>    - Talked with peter on RFC and he suggested me to add a field inside
>      monitor struct to get VM name.
>   
>   src/qemu/qemu_monitor.c | 47 +++++++++++++++++++++++++----------------
>   1 file changed, 29 insertions(+), 18 deletions(-)
>
> diff --git a/src/qemu/qemu_monitor.c b/src/qemu/qemu_monitor.c
> index dda6ae9796..c3a0227795 100644
> --- a/src/qemu/qemu_monitor.c
> +++ b/src/qemu/qemu_monitor.c
> @@ -80,6 +80,7 @@ struct _qemuMonitor {
>       GSource *watch;
>   
>       virDomainObj *vm;
> +    char *domainName;
>   
>       qemuMonitorCallbacks *cb;
>       void *callbackOpaque;
> @@ -243,6 +244,7 @@ qemuMonitorDispose(void *obj)
>       virCondDestroy(&mon->notify);
>       g_free(mon->buffer);
>       g_free(mon->balloonpath);
> +    g_free(mon->domainName);
>   }
>   
>   
> @@ -530,13 +532,18 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>       qemuMonitor *mon = opaque;
>       bool error = false;
>       bool hangup = false;
> +    virDomainObj *vm = NULL;
> +    char *vmName = NULL;
>   
>       virObjectRef(mon);
>   
> +    vm = mon->vm;
> +    vmName = mon->domainName;
> +
>       /* lock access to the monitor and protect fd */
>       virObjectLock(mon);
>   #if DEBUG_IO
> -    VIR_DEBUG("Monitor %p I/O on socket %p cond %d", mon, socket, cond);
> +    VIR_DEBUG("Monitor %p I/O on socket %p cond %d vm=%p name=%s", mon, socket, cond, vm, NULLSTR(vmName));
>   #endif
>       if (mon->fd == -1 || !mon->watch) {
>           virObjectUnlock(mon);
> @@ -583,8 +590,8 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>   
>           if (!error && !mon->goteof &&
>               cond & G_IO_ERR) {
> -            virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> -                           _("Invalid file descriptor while waiting for monitor"));
> +            virReportError(VIR_ERR_INTERNAL_ERROR,
> +                           _("%s: Invalid file descriptor while waiting for monitor"), NULLSTR(vmName));
>               mon->goteof = true;
>           }
>       }
> @@ -609,13 +616,14 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>               virResetLastError();
>           } else {
>               if (virGetLastErrorCode() == VIR_ERR_OK && !mon->goteof)
> -                virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> -                               _("Error while processing monitor IO"));
> +                virReportError(VIR_ERR_INTERNAL_ERROR,
> +                               _("%s: Error while processing monitor IO"), NULLSTR(vmName));
>               virCopyLastError(&mon->lastError);
>               virResetLastError();
>           }
>   
> -        VIR_DEBUG("Error on monitor %s", NULLSTR(mon->lastError.message));
> +        VIR_DEBUG("Error on monitor %s mon=%p vm=%p name=%s",
> +                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
>           /* If IO process resulted in an error & we have a message,
>            * then wakeup that waiter */
>           if (mon->msg && !mon->msg->finished) {
> @@ -631,22 +639,22 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>        * will try to acquire the virDomainObj *mutex next */
>       if (mon->goteof) {
>           qemuMonitorEofNotifyCallback eofNotify = mon->cb->eofNotify;
> -        virDomainObj *vm = mon->vm;
>   
>           /* Make sure anyone waiting wakes up now */
>           virCondSignal(&mon->notify);
>           virObjectUnlock(mon);
> -        VIR_DEBUG("Triggering EOF callback");
> +        VIR_DEBUG("Triggering EOF callback mon=%p vm=%p name=%s",
> +                  mon, vm, NULLSTR(vmName));
>           (eofNotify)(mon, vm, mon->callbackOpaque);
>           virObjectUnref(mon);
>       } else if (error) {
>           qemuMonitorErrorNotifyCallback errorNotify = mon->cb->errorNotify;
> -        virDomainObj *vm = mon->vm;
>   
>           /* Make sure anyone waiting wakes up now */
>           virCondSignal(&mon->notify);
>           virObjectUnlock(mon);
> -        VIR_DEBUG("Triggering error callback");
> +        VIR_DEBUG("Triggering error callback mon=%p vm=%p name=%s",
> +                  mon, vm, NULLSTR(vmName));
>           (errorNotify)(mon, vm, mon->callbackOpaque);
>           virObjectUnref(mon);
>       } else {
> @@ -694,6 +702,7 @@ qemuMonitorOpenInternal(virDomainObj *vm,
>       mon->fd = fd;
>       mon->context = g_main_context_ref(context);
>       mon->vm = virObjectRef(vm);
> +    mon->domainName = g_strdup(vm->def->name);
>       mon->waitGreeting = true;
>       mon->cb = cb;
>       mon->callbackOpaque = opaque;
> @@ -932,17 +941,19 @@ qemuMonitorSend(qemuMonitor *mon,
>                   qemuMonitorMessage *msg)
>   {
>       int ret = -1;
> +    virDomainObj *vm = mon->vm;
> +    char *vmName = mon->domainName;
>   
>       /* Check whether qemu quit unexpectedly */
>       if (mon->lastError.code != VIR_ERR_OK) {
> -        VIR_DEBUG("Attempt to send command while error is set %s",
> -                  NULLSTR(mon->lastError.message));
> +        VIR_DEBUG("Attempt to send command while error is set %s mon=%p vm=%p name=%s",
> +                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
>           virSetError(&mon->lastError);
>           return -1;
>       }
>       if (mon->goteof) {
> -        virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> -                       _("End of file from qemu monitor"));
> +        virReportError(VIR_ERR_INTERNAL_ERROR,
> +                       _("%s: End of file from qemu monitor"), NULLSTR(vmName));
>           return -1;
>       }
>   
> @@ -955,15 +966,15 @@ qemuMonitorSend(qemuMonitor *mon,
>   
>       while (!mon->msg->finished) {
>           if (virCondWait(&mon->notify, &mon->parent.lock) < 0) {
> -            virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> -                           _("Unable to wait on monitor condition"));
> +            virReportError(VIR_ERR_INTERNAL_ERROR,
> +                           _("%s: Unable to wait on monitor condition"), NULLSTR(vmName));
>               goto cleanup;
>           }
>       }
>   
>       if (mon->lastError.code != VIR_ERR_OK) {
> -        VIR_DEBUG("Send command resulted in error %s",
> -                  NULLSTR(mon->lastError.message));
> +        VIR_DEBUG("Send command resulted in error %s mon=%p vm=%p name=%s",
> +                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
>           virSetError(&mon->lastError);
>           goto cleanup;
>       }

Re: [PATCH v2] Add VM info to improve error log message for qemu monitor
Posted by Ani Sinha 2 years, 3 months ago

On Wed, 22 Dec 2021, Rohit Kumar wrote:

> This patch is to determine the VM which had IO or socket hangup error.
> Accessing directly vm->def->name inside qemuMonitorIO() or qemuMonitorSend()
> might leads to illegal access as we are out of 'vm' context and vm->def might
> not exist. Adding a field "domainName" inside mon object to access vm name
> and initialising it when creating mon object.

The commit message should desribe the purpose of the change, not how it is
done. That can be easily understood reading the code. As for why the
implementation follows a particular way, we can explain it in the code
comments.

This change adds the domain name in the error and debug logs during
monitor IO processing so that we may infer which VM experienced those
errors etc. This may help in debugging monitor IO errors. IMHO this
decription is enough.

>
> Signed-off-by: Rohit Kumar <rohit.kumar3@nutanix.com>
> ---
>  diff to v1:
>   - Adding a field domainName inside _qemuMonitor struct for accessing vm name
>     instead of directly accessing mon->vm->def->name.
>   - Link to v1: https://listman.redhat.com/archives/libvir-list/2021-December/msg00217.html
>   - Talked with peter on RFC and he suggested me to add a field inside
>     monitor struct to get VM name.
>
>  src/qemu/qemu_monitor.c | 47 +++++++++++++++++++++++++----------------
>  1 file changed, 29 insertions(+), 18 deletions(-)
>
> diff --git a/src/qemu/qemu_monitor.c b/src/qemu/qemu_monitor.c
> index dda6ae9796..c3a0227795 100644
> --- a/src/qemu/qemu_monitor.c
> +++ b/src/qemu/qemu_monitor.c
> @@ -80,6 +80,7 @@ struct _qemuMonitor {
>      GSource *watch;
>
>      virDomainObj *vm;
> +    char *domainName;
>

Here we can explain why we are adding an extra member as opposed to
referencing it directly.

>      qemuMonitorCallbacks *cb;
>      void *callbackOpaque;
> @@ -243,6 +244,7 @@ qemuMonitorDispose(void *obj)
>      virCondDestroy(&mon->notify);
>      g_free(mon->buffer);
>      g_free(mon->balloonpath);
> +    g_free(mon->domainName);
>  }
>
>
> @@ -530,13 +532,18 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>      qemuMonitor *mon = opaque;
>      bool error = false;
>      bool hangup = false;
> +    virDomainObj *vm = NULL;
> +    char *vmName = NULL;
>

These initializations are redundant since ...

>      virObjectRef(mon);
>
> +    vm = mon->vm;
> +    vmName = mon->domainName;

you initialize them here anyway.

> +
>      /* lock access to the monitor and protect fd */
>      virObjectLock(mon);
>  #if DEBUG_IO
> -    VIR_DEBUG("Monitor %p I/O on socket %p cond %d", mon, socket, cond);
> +    VIR_DEBUG("Monitor %p I/O on socket %p cond %d vm=%p name=%s", mon, socket, cond, vm, NULLSTR(vmName));
>  #endif
>      if (mon->fd == -1 || !mon->watch) {
>          virObjectUnlock(mon);
> @@ -583,8 +590,8 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>
>          if (!error && !mon->goteof &&
>              cond & G_IO_ERR) {
> -            virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> -                           _("Invalid file descriptor while waiting for monitor"));
> +            virReportError(VIR_ERR_INTERNAL_ERROR,
> +                           _("%s: Invalid file descriptor while waiting for monitor"), NULLSTR(vmName));

As per https://libvirt.org/coding-style.html#error-message-format, please
enclose %s within quotes:
_("'%s': Invalid file descriptor while waiting for monitor")

>              mon->goteof = true;
>          }
>      }
> @@ -609,13 +616,14 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>              virResetLastError();
>          } else {
>              if (virGetLastErrorCode() == VIR_ERR_OK && !mon->goteof)
> -                virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> -                               _("Error while processing monitor IO"));
> +                virReportError(VIR_ERR_INTERNAL_ERROR,
> +                               _("%s: Error while processing monitor IO"), NULLSTR(vmName));

Ditto.

>              virCopyLastError(&mon->lastError);
>              virResetLastError();
>          }
>
> -        VIR_DEBUG("Error on monitor %s", NULLSTR(mon->lastError.message));
> +        VIR_DEBUG("Error on monitor %s mon=%p vm=%p name=%s",
> +                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
>          /* If IO process resulted in an error & we have a message,
>           * then wakeup that waiter */
>          if (mon->msg && !mon->msg->finished) {
> @@ -631,22 +639,22 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>       * will try to acquire the virDomainObj *mutex next */
>      if (mon->goteof) {
>          qemuMonitorEofNotifyCallback eofNotify = mon->cb->eofNotify;
> -        virDomainObj *vm = mon->vm;
>
>          /* Make sure anyone waiting wakes up now */
>          virCondSignal(&mon->notify);
>          virObjectUnlock(mon);
> -        VIR_DEBUG("Triggering EOF callback");
> +        VIR_DEBUG("Triggering EOF callback mon=%p vm=%p name=%s",
> +                  mon, vm, NULLSTR(vmName));
>          (eofNotify)(mon, vm, mon->callbackOpaque);
>          virObjectUnref(mon);
>      } else if (error) {
>          qemuMonitorErrorNotifyCallback errorNotify = mon->cb->errorNotify;
> -        virDomainObj *vm = mon->vm;
>
>          /* Make sure anyone waiting wakes up now */
>          virCondSignal(&mon->notify);
>          virObjectUnlock(mon);
> -        VIR_DEBUG("Triggering error callback");
> +        VIR_DEBUG("Triggering error callback mon=%p vm=%p name=%s",
> +                  mon, vm, NULLSTR(vmName));
>          (errorNotify)(mon, vm, mon->callbackOpaque);
>          virObjectUnref(mon);
>      } else {
> @@ -694,6 +702,7 @@ qemuMonitorOpenInternal(virDomainObj *vm,
>      mon->fd = fd;
>      mon->context = g_main_context_ref(context);
>      mon->vm = virObjectRef(vm);
> +    mon->domainName = g_strdup(vm->def->name);

do not forget to g_free() this during cleanup in the same function.

>      mon->waitGreeting = true;
>      mon->cb = cb;
>      mon->callbackOpaque = opaque;
> @@ -932,17 +941,19 @@ qemuMonitorSend(qemuMonitor *mon,
>                  qemuMonitorMessage *msg)
>  {
>      int ret = -1;
> +    virDomainObj *vm = mon->vm;
> +    char *vmName = mon->domainName;
>
>      /* Check whether qemu quit unexpectedly */
>      if (mon->lastError.code != VIR_ERR_OK) {
> -        VIR_DEBUG("Attempt to send command while error is set %s",
> -                  NULLSTR(mon->lastError.message));
> +        VIR_DEBUG("Attempt to send command while error is set %s mon=%p vm=%p name=%s",
> +                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
>          virSetError(&mon->lastError);
>          return -1;
>      }
>      if (mon->goteof) {
> -        virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> -                       _("End of file from qemu monitor"));
> +        virReportError(VIR_ERR_INTERNAL_ERROR,
> +                       _("%s: End of file from qemu monitor"), NULLSTR(vmName));

ditto re error string format.

>          return -1;
>      }
>
> @@ -955,15 +966,15 @@ qemuMonitorSend(qemuMonitor *mon,
>
>      while (!mon->msg->finished) {
>          if (virCondWait(&mon->notify, &mon->parent.lock) < 0) {
> -            virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> -                           _("Unable to wait on monitor condition"));
> +            virReportError(VIR_ERR_INTERNAL_ERROR,
> +                           _("%s: Unable to wait on monitor condition"), NULLSTR(vmName));

ditto as above.

>              goto cleanup;
>          }
>      }
>
>      if (mon->lastError.code != VIR_ERR_OK) {
> -        VIR_DEBUG("Send command resulted in error %s",
> -                  NULLSTR(mon->lastError.message));
> +        VIR_DEBUG("Send command resulted in error %s mon=%p vm=%p name=%s",
> +                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
>          virSetError(&mon->lastError);
>          goto cleanup;
>      }
> --
> 2.25.1
>
>

Re: [PATCH v2] Add VM info to improve error log message for qemu monitor
Posted by Rohit Kumar 2 years, 3 months ago
On 03/01/22 7:12 pm, Ani Sinha wrote:
>
> On Wed, 22 Dec 2021, Rohit Kumar wrote:
>
>> This patch is to determine the VM which had IO or socket hangup error.
>> Accessing directly vm->def->name inside qemuMonitorIO() or qemuMonitorSend()
>> might leads to illegal access as we are out of 'vm' context and vm->def might
>> not exist. Adding a field "domainName" inside mon object to access vm name
>> and initialising it when creating mon object.
> The commit message should desribe the purpose of the change, not how it is
> done. That can be easily understood reading the code. As for why the
> implementation follows a particular way, we can explain it in the code
> comments.
>
> This change adds the domain name in the error and debug logs during
> monitor IO processing so that we may infer which VM experienced those
> errors etc. This may help in debugging monitor IO errors. IMHO this
> decription is enough.
Thanks Ani, I will update the commit message in the next patch.
>
>> Signed-off-by: Rohit Kumar <rohit.kumar3@nutanix.com>
>> ---
>>   diff to v1:
>>    - Adding a field domainName inside _qemuMonitor struct for accessing vm name
>>      instead of directly accessing mon->vm->def->name.
>>    - Link to v1: https://urldefense.proofpoint.com/v2/url?u=https-3A__listman.redhat.com_archives_libvir-2Dlist_2021-2DDecember_msg00217.html&d=DwIBAg&c=s883GpUCOChKOHiocYtGcg&r=ABSkr7gy7ZTfApFfI-Xxt1gZNtsDDiXoXOXc0OrkyFs&m=W2jEgk2s_xjLOLC-j8lPBnwVgteHS0-yYEGMqin16nmfzndzNgBE9mEvtbvyVzQo&s=Sa2q9edb4cvXo-EUriIPwlJxNo-itpp6--ZxY7rla2U&e=
>>    - Talked with peter on RFC and he suggested me to add a field inside
>>      monitor struct to get VM name.
>>
>>   src/qemu/qemu_monitor.c | 47 +++++++++++++++++++++++++----------------
>>   1 file changed, 29 insertions(+), 18 deletions(-)
>>
>> diff --git a/src/qemu/qemu_monitor.c b/src/qemu/qemu_monitor.c
>> index dda6ae9796..c3a0227795 100644
>> --- a/src/qemu/qemu_monitor.c
>> +++ b/src/qemu/qemu_monitor.c
>> @@ -80,6 +80,7 @@ struct _qemuMonitor {
>>       GSource *watch;
>>
>>       virDomainObj *vm;
>> +    char *domainName;
>>
> Here we can explain why we are adding an extra member as opposed to
> referencing it directly.
Right, we can access it directly.
>
>>       qemuMonitorCallbacks *cb;
>>       void *callbackOpaque;
>> @@ -243,6 +244,7 @@ qemuMonitorDispose(void *obj)
>>       virCondDestroy(&mon->notify);
>>       g_free(mon->buffer);
>>       g_free(mon->balloonpath);
>> +    g_free(mon->domainName);
>>   }
>>
>>
>> @@ -530,13 +532,18 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>>       qemuMonitor *mon = opaque;
>>       bool error = false;
>>       bool hangup = false;
>> +    virDomainObj *vm = NULL;
>> +    char *vmName = NULL;
>>
> These initializations are redundant since ...
Acknowledged.
>>       virObjectRef(mon);
>>
>> +    vm = mon->vm;
>> +    vmName = mon->domainName;
> you initialize them here anyway.
I will remove these in next patch.
>
>> +
>>       /* lock access to the monitor and protect fd */
>>       virObjectLock(mon);
>>   #if DEBUG_IO
>> -    VIR_DEBUG("Monitor %p I/O on socket %p cond %d", mon, socket, cond);
>> +    VIR_DEBUG("Monitor %p I/O on socket %p cond %d vm=%p name=%s", mon, socket, cond, vm, NULLSTR(vmName));
>>   #endif
>>       if (mon->fd == -1 || !mon->watch) {
>>           virObjectUnlock(mon);
>> @@ -583,8 +590,8 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>>
>>           if (!error && !mon->goteof &&
>>               cond & G_IO_ERR) {
>> -            virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
>> -                           _("Invalid file descriptor while waiting for monitor"));
>> +            virReportError(VIR_ERR_INTERNAL_ERROR,
>> +                           _("%s: Invalid file descriptor while waiting for monitor"), NULLSTR(vmName));
> As per https://urldefense.proofpoint.com/v2/url?u=https-3A__libvirt.org_coding-2Dstyle.html-23error-2Dmessage-2Dformat&d=DwIBAg&c=s883GpUCOChKOHiocYtGcg&r=ABSkr7gy7ZTfApFfI-Xxt1gZNtsDDiXoXOXc0OrkyFs&m=W2jEgk2s_xjLOLC-j8lPBnwVgteHS0-yYEGMqin16nmfzndzNgBE9mEvtbvyVzQo&s=zU-TBR-xTsKRXEW5gdgL0WRRYBg7B7cbLluu65_PfkI&e= , please
> enclose %s within quotes:
> _("'%s': Invalid file descriptor while waiting for monitor")
Ack. Thanks.
>>               mon->goteof = true;
>>           }
>>       }
>> @@ -609,13 +616,14 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>>               virResetLastError();
>>           } else {
>>               if (virGetLastErrorCode() == VIR_ERR_OK && !mon->goteof)
>> -                virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
>> -                               _("Error while processing monitor IO"));
>> +                virReportError(VIR_ERR_INTERNAL_ERROR,
>> +                               _("%s: Error while processing monitor IO"), NULLSTR(vmName));
> Ditto.
Ack.
>>               virCopyLastError(&mon->lastError);
>>               virResetLastError();
>>           }
>>
>> -        VIR_DEBUG("Error on monitor %s", NULLSTR(mon->lastError.message));
>> +        VIR_DEBUG("Error on monitor %s mon=%p vm=%p name=%s",
>> +                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
>>           /* If IO process resulted in an error & we have a message,
>>            * then wakeup that waiter */
>>           if (mon->msg && !mon->msg->finished) {
>> @@ -631,22 +639,22 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>>        * will try to acquire the virDomainObj *mutex next */
>>       if (mon->goteof) {
>>           qemuMonitorEofNotifyCallback eofNotify = mon->cb->eofNotify;
>> -        virDomainObj *vm = mon->vm;
>>
>>           /* Make sure anyone waiting wakes up now */
>>           virCondSignal(&mon->notify);
>>           virObjectUnlock(mon);
>> -        VIR_DEBUG("Triggering EOF callback");
>> +        VIR_DEBUG("Triggering EOF callback mon=%p vm=%p name=%s",
>> +                  mon, vm, NULLSTR(vmName));
>>           (eofNotify)(mon, vm, mon->callbackOpaque);
>>           virObjectUnref(mon);
>>       } else if (error) {
>>           qemuMonitorErrorNotifyCallback errorNotify = mon->cb->errorNotify;
>> -        virDomainObj *vm = mon->vm;
>>
>>           /* Make sure anyone waiting wakes up now */
>>           virCondSignal(&mon->notify);
>>           virObjectUnlock(mon);
>> -        VIR_DEBUG("Triggering error callback");
>> +        VIR_DEBUG("Triggering error callback mon=%p vm=%p name=%s",
>> +                  mon, vm, NULLSTR(vmName));
>>           (errorNotify)(mon, vm, mon->callbackOpaque);
>>           virObjectUnref(mon);
>>       } else {
>> @@ -694,6 +702,7 @@ qemuMonitorOpenInternal(virDomainObj *vm,
>>       mon->fd = fd;
>>       mon->context = g_main_context_ref(context);
>>       mon->vm = virObjectRef(vm);
>> +    mon->domainName = g_strdup(vm->def->name);
> do not forget to g_free() this during cleanup in the same function.
So, in cleanup: qemuMonitorDispose is called. And there I have added 
g_free() to clean mon->domainName.
>
>>       mon->waitGreeting = true;
>>       mon->cb = cb;
>>       mon->callbackOpaque = opaque;
>> @@ -932,17 +941,19 @@ qemuMonitorSend(qemuMonitor *mon,
>>                   qemuMonitorMessage *msg)
>>   {
>>       int ret = -1;
>> +    virDomainObj *vm = mon->vm;
>> +    char *vmName = mon->domainName;
>>
>>       /* Check whether qemu quit unexpectedly */
>>       if (mon->lastError.code != VIR_ERR_OK) {
>> -        VIR_DEBUG("Attempt to send command while error is set %s",
>> -                  NULLSTR(mon->lastError.message));
>> +        VIR_DEBUG("Attempt to send command while error is set %s mon=%p vm=%p name=%s",
>> +                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
>>           virSetError(&mon->lastError);
>>           return -1;
>>       }
>>       if (mon->goteof) {
>> -        virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
>> -                       _("End of file from qemu monitor"));
>> +        virReportError(VIR_ERR_INTERNAL_ERROR,
>> +                       _("%s: End of file from qemu monitor"), NULLSTR(vmName));
> ditto re error string format.
Ack.
>
>>           return -1;
>>       }
>>
>> @@ -955,15 +966,15 @@ qemuMonitorSend(qemuMonitor *mon,
>>
>>       while (!mon->msg->finished) {
>>           if (virCondWait(&mon->notify, &mon->parent.lock) < 0) {
>> -            virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
>> -                           _("Unable to wait on monitor condition"));
>> +            virReportError(VIR_ERR_INTERNAL_ERROR,
>> +                           _("%s: Unable to wait on monitor condition"), NULLSTR(vmName));
> ditto as above.
Ack.
>>               goto cleanup;
>>           }
>>       }
>>
>>       if (mon->lastError.code != VIR_ERR_OK) {
>> -        VIR_DEBUG("Send command resulted in error %s",
>> -                  NULLSTR(mon->lastError.message));
>> +        VIR_DEBUG("Send command resulted in error %s mon=%p vm=%p name=%s",
>> +                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
>>           virSetError(&mon->lastError);
>>           goto cleanup;
>>       }
>> --
>> 2.25.1
>>
>>

Re: [PATCH v2] Add VM info to improve error log message for qemu monitor
Posted by Ani Sinha 2 years, 3 months ago

On Tue, 4 Jan 2022, Rohit Kumar wrote:

>
> On 03/01/22 7:12 pm, Ani Sinha wrote:
> >
> > On Wed, 22 Dec 2021, Rohit Kumar wrote:
> >
> > > This patch is to determine the VM which had IO or socket hangup error.
> > > Accessing directly vm->def->name inside qemuMonitorIO() or
> > > qemuMonitorSend()
> > > might leads to illegal access as we are out of 'vm' context and vm->def
> > > might
> > > not exist. Adding a field "domainName" inside mon object to access vm name
> > > and initialising it when creating mon object.
> > The commit message should desribe the purpose of the change, not how it is
> > done. That can be easily understood reading the code. As for why the
> > implementation follows a particular way, we can explain it in the code
> > comments.
> >
> > This change adds the domain name in the error and debug logs during
> > monitor IO processing so that we may infer which VM experienced those
> > errors etc. This may help in debugging monitor IO errors. IMHO this
> > decription is enough.
> Thanks Ani, I will update the commit message in the next patch.
> >
> > > Signed-off-by: Rohit Kumar <rohit.kumar3@nutanix.com>
> > > ---
> > >   diff to v1:
> > >    - Adding a field domainName inside _qemuMonitor struct for accessing vm
> > > name
> > >      instead of directly accessing mon->vm->def->name.
> > >    - Link to v1:
> > > https://urldefense.proofpoint.com/v2/url?u=https-3A__listman.redhat.com_archives_libvir-2Dlist_2021-2DDecember_msg00217.html&d=DwIBAg&c=s883GpUCOChKOHiocYtGcg&r=ABSkr7gy7ZTfApFfI-Xxt1gZNtsDDiXoXOXc0OrkyFs&m=W2jEgk2s_xjLOLC-j8lPBnwVgteHS0-yYEGMqin16nmfzndzNgBE9mEvtbvyVzQo&s=Sa2q9edb4cvXo-EUriIPwlJxNo-itpp6--ZxY7rla2U&e=
> > >    - Talked with peter on RFC and he suggested me to add a field inside
> > >      monitor struct to get VM name.
> > >
> > >   src/qemu/qemu_monitor.c | 47 +++++++++++++++++++++++++----------------
> > >   1 file changed, 29 insertions(+), 18 deletions(-)
> > >
> > > diff --git a/src/qemu/qemu_monitor.c b/src/qemu/qemu_monitor.c
> > > index dda6ae9796..c3a0227795 100644
> > > --- a/src/qemu/qemu_monitor.c
> > > +++ b/src/qemu/qemu_monitor.c
> > > @@ -80,6 +80,7 @@ struct _qemuMonitor {
> > >       GSource *watch;
> > >
> > >       virDomainObj *vm;
> > > +    char *domainName;
> > >
> > Here we can explain why we are adding an extra member as opposed to
> > referencing it directly.
> Right, we can access it directly.
> >
> > >       qemuMonitorCallbacks *cb;
> > >       void *callbackOpaque;
> > > @@ -243,6 +244,7 @@ qemuMonitorDispose(void *obj)
> > >       virCondDestroy(&mon->notify);
> > >       g_free(mon->buffer);
> > >       g_free(mon->balloonpath);
> > > +    g_free(mon->domainName);
> > >   }
> > >
> > >
> > > @@ -530,13 +532,18 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
> > >       qemuMonitor *mon = opaque;
> > >       bool error = false;
> > >       bool hangup = false;
> > > +    virDomainObj *vm = NULL;
> > > +    char *vmName = NULL;
> > >
> > These initializations are redundant since ...
> Acknowledged.
> > >       virObjectRef(mon);
> > >
> > > +    vm = mon->vm;
> > > +    vmName = mon->domainName;
> > you initialize them here anyway.
> I will remove these in next patch.
> >
> > > +
> > >       /* lock access to the monitor and protect fd */
> > >       virObjectLock(mon);
> > >   #if DEBUG_IO
> > > -    VIR_DEBUG("Monitor %p I/O on socket %p cond %d", mon, socket, cond);
> > > +    VIR_DEBUG("Monitor %p I/O on socket %p cond %d vm=%p name=%s", mon,
> > > socket, cond, vm, NULLSTR(vmName));
> > >   #endif
> > >       if (mon->fd == -1 || !mon->watch) {
> > >           virObjectUnlock(mon);
> > > @@ -583,8 +590,8 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
> > >
> > >           if (!error && !mon->goteof &&
> > >               cond & G_IO_ERR) {
> > > -            virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> > > -                           _("Invalid file descriptor while waiting for
> > > monitor"));
> > > +            virReportError(VIR_ERR_INTERNAL_ERROR,
> > > +                           _("%s: Invalid file descriptor while waiting
> > > for monitor"), NULLSTR(vmName));
> > As per
> > https://urldefense.proofpoint.com/v2/url?u=https-3A__libvirt.org_coding-2Dstyle.html-23error-2Dmessage-2Dformat&d=DwIBAg&c=s883GpUCOChKOHiocYtGcg&r=ABSkr7gy7ZTfApFfI-Xxt1gZNtsDDiXoXOXc0OrkyFs&m=W2jEgk2s_xjLOLC-j8lPBnwVgteHS0-yYEGMqin16nmfzndzNgBE9mEvtbvyVzQo&s=zU-TBR-xTsKRXEW5gdgL0WRRYBg7B7cbLluu65_PfkI&e=
> > , please
> > enclose %s within quotes:
> > _("'%s': Invalid file descriptor while waiting for monitor")
> Ack. Thanks.
> > >               mon->goteof = true;
> > >           }
> > >       }
> > > @@ -609,13 +616,14 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
> > >               virResetLastError();
> > >           } else {
> > >               if (virGetLastErrorCode() == VIR_ERR_OK && !mon->goteof)
> > > -                virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> > > -                               _("Error while processing monitor IO"));
> > > +                virReportError(VIR_ERR_INTERNAL_ERROR,
> > > +                               _("%s: Error while processing monitor
> > > IO"), NULLSTR(vmName));
> > Ditto.
> Ack.
> > >               virCopyLastError(&mon->lastError);
> > >               virResetLastError();
> > >           }
> > >
> > > -        VIR_DEBUG("Error on monitor %s",
> > > NULLSTR(mon->lastError.message));
> > > +        VIR_DEBUG("Error on monitor %s mon=%p vm=%p name=%s",
> > > +                  NULLSTR(mon->lastError.message), mon, vm,
> > > NULLSTR(vmName));
> > >           /* If IO process resulted in an error & we have a message,
> > >            * then wakeup that waiter */
> > >           if (mon->msg && !mon->msg->finished) {
> > > @@ -631,22 +639,22 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
> > >        * will try to acquire the virDomainObj *mutex next */
> > >       if (mon->goteof) {
> > >           qemuMonitorEofNotifyCallback eofNotify = mon->cb->eofNotify;
> > > -        virDomainObj *vm = mon->vm;
> > >
> > >           /* Make sure anyone waiting wakes up now */
> > >           virCondSignal(&mon->notify);
> > >           virObjectUnlock(mon);
> > > -        VIR_DEBUG("Triggering EOF callback");
> > > +        VIR_DEBUG("Triggering EOF callback mon=%p vm=%p name=%s",
> > > +                  mon, vm, NULLSTR(vmName));
> > >           (eofNotify)(mon, vm, mon->callbackOpaque);
> > >           virObjectUnref(mon);
> > >       } else if (error) {
> > >           qemuMonitorErrorNotifyCallback errorNotify =
> > > mon->cb->errorNotify;
> > > -        virDomainObj *vm = mon->vm;
> > >
> > >           /* Make sure anyone waiting wakes up now */
> > >           virCondSignal(&mon->notify);
> > >           virObjectUnlock(mon);
> > > -        VIR_DEBUG("Triggering error callback");
> > > +        VIR_DEBUG("Triggering error callback mon=%p vm=%p name=%s",
> > > +                  mon, vm, NULLSTR(vmName));
> > >           (errorNotify)(mon, vm, mon->callbackOpaque);
> > >           virObjectUnref(mon);
> > >       } else {
> > > @@ -694,6 +702,7 @@ qemuMonitorOpenInternal(virDomainObj *vm,
> > >       mon->fd = fd;
> > >       mon->context = g_main_context_ref(context);
> > >       mon->vm = virObjectRef(vm);
> > > +    mon->domainName = g_strdup(vm->def->name);
> > do not forget to g_free() this during cleanup in the same function.
> So, in cleanup: qemuMonitorDispose is called. And there I have added g_free()
> to clean mon->domainName.

No, in cleanup, I see qemuMonitorClose() is called where do you do not add
any additional code to free the allocation.

This is what I see in cleanup code:

```
cleanup:
    /* We don't want the 'destroy' callback invoked during
     * cleanup from construction failure, because that can
     * give a double-unref on virDomainObj *in the caller,
     * so kill the callbacks now.
     */
    mon->cb = NULL;
    /* The caller owns 'fd' on failure */
    mon->fd = -1;
    qemuMonitorClose(mon);
    return NULL;
```

> >
> > >       mon->waitGreeting = true;
> > >       mon->cb = cb;
> > >       mon->callbackOpaque = opaque;
> > > @@ -932,17 +941,19 @@ qemuMonitorSend(qemuMonitor *mon,
> > >                   qemuMonitorMessage *msg)
> > >   {
> > >       int ret = -1;
> > > +    virDomainObj *vm = mon->vm;
> > > +    char *vmName = mon->domainName;
> > >
> > >       /* Check whether qemu quit unexpectedly */
> > >       if (mon->lastError.code != VIR_ERR_OK) {
> > > -        VIR_DEBUG("Attempt to send command while error is set %s",
> > > -                  NULLSTR(mon->lastError.message));
> > > +        VIR_DEBUG("Attempt to send command while error is set %s mon=%p
> > > vm=%p name=%s",
> > > +                  NULLSTR(mon->lastError.message), mon, vm,
> > > NULLSTR(vmName));
> > >           virSetError(&mon->lastError);
> > >           return -1;
> > >       }
> > >       if (mon->goteof) {
> > > -        virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> > > -                       _("End of file from qemu monitor"));
> > > +        virReportError(VIR_ERR_INTERNAL_ERROR,
> > > +                       _("%s: End of file from qemu monitor"),
> > > NULLSTR(vmName));
> > ditto re error string format.
> Ack.
> >
> > >           return -1;
> > >       }
> > >
> > > @@ -955,15 +966,15 @@ qemuMonitorSend(qemuMonitor *mon,
> > >
> > >       while (!mon->msg->finished) {
> > >           if (virCondWait(&mon->notify, &mon->parent.lock) < 0) {
> > > -            virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> > > -                           _("Unable to wait on monitor condition"));
> > > +            virReportError(VIR_ERR_INTERNAL_ERROR,
> > > +                           _("%s: Unable to wait on monitor condition"),
> > > NULLSTR(vmName));
> > ditto as above.
> Ack.
> > >               goto cleanup;
> > >           }
> > >       }
> > >
> > >       if (mon->lastError.code != VIR_ERR_OK) {
> > > -        VIR_DEBUG("Send command resulted in error %s",
> > > -                  NULLSTR(mon->lastError.message));
> > > +        VIR_DEBUG("Send command resulted in error %s mon=%p vm=%p
> > > name=%s",
> > > +                  NULLSTR(mon->lastError.message), mon, vm,
> > > NULLSTR(vmName));
> > >           virSetError(&mon->lastError);
> > >           goto cleanup;
> > >       }
> > > --
> > > 2.25.1
> > >
> > >
>

Re: [PATCH v2] Add VM info to improve error log message for qemu monitor
Posted by Peter Krempa 2 years, 3 months ago
On Tue, Jan 04, 2022 at 15:30:00 +0530, Ani Sinha wrote:
> On Tue, 4 Jan 2022, Rohit Kumar wrote:
> > On 03/01/22 7:12 pm, Ani Sinha wrote:
> > > On Wed, 22 Dec 2021, Rohit Kumar wrote:

[...]

> > > > @@ -694,6 +702,7 @@ qemuMonitorOpenInternal(virDomainObj *vm,
> > > >       mon->fd = fd;
> > > >       mon->context = g_main_context_ref(context);
> > > >       mon->vm = virObjectRef(vm);
> > > > +    mon->domainName = g_strdup(vm->def->name);
> > > do not forget to g_free() this during cleanup in the same function.
> > So, in cleanup: qemuMonitorDispose is called. And there I have added g_free()
> > to clean mon->domainName.
> 
> No, in cleanup, I see qemuMonitorClose() is called where do you do not add
> any additional code to free the allocation.
> 
> This is what I see in cleanup code:
> 
> ```
> cleanup:
>     /* We don't want the 'destroy' callback invoked during
>      * cleanup from construction failure, because that can
>      * give a double-unref on virDomainObj *in the caller,
>      * so kill the callbacks now.
>      */
>     mon->cb = NULL;
>     /* The caller owns 'fd' on failure */
>     mon->fd = -1;
>     qemuMonitorClose(mon);

qemuMonitorClose() eventually calls virObjectUnref(mon). Once the last
reference on the monitor object is removed the object is freed via
qemuMonitorDispose().

This patch has:

@@ -243,6 +244,7 @@ qemuMonitorDispose(void *obj)
     virCondDestroy(&mon->notify);
     g_free(mon->buffer);
     g_free(mon->balloonpath);
+    g_free(mon->domainName);
 }

Re: [PATCH v2] Add VM info to improve error log message for qemu monitor
Posted by Ani Sinha 2 years, 3 months ago

On Tue, 4 Jan 2022, Peter Krempa wrote:

> On Tue, Jan 04, 2022 at 15:30:00 +0530, Ani Sinha wrote:
> > On Tue, 4 Jan 2022, Rohit Kumar wrote:
> > > On 03/01/22 7:12 pm, Ani Sinha wrote:
> > > > On Wed, 22 Dec 2021, Rohit Kumar wrote:
>
> [...]
>
> > > > > @@ -694,6 +702,7 @@ qemuMonitorOpenInternal(virDomainObj *vm,
> > > > >       mon->fd = fd;
> > > > >       mon->context = g_main_context_ref(context);
> > > > >       mon->vm = virObjectRef(vm);
> > > > > +    mon->domainName = g_strdup(vm->def->name);
> > > > do not forget to g_free() this during cleanup in the same function.
> > > So, in cleanup: qemuMonitorDispose is called. And there I have added g_free()
> > > to clean mon->domainName.
> >
> > No, in cleanup, I see qemuMonitorClose() is called where do you do not add
> > any additional code to free the allocation.
> >
> > This is what I see in cleanup code:
> >
> > ```
> > cleanup:
> >     /* We don't want the 'destroy' callback invoked during
> >      * cleanup from construction failure, because that can
> >      * give a double-unref on virDomainObj *in the caller,
> >      * so kill the callbacks now.
> >      */
> >     mon->cb = NULL;
> >     /* The caller owns 'fd' on failure */
> >     mon->fd = -1;
> >     qemuMonitorClose(mon);
>
> qemuMonitorClose() eventually calls virObjectUnref(mon). Once the last
> reference on the monitor object is removed the object is freed via
> qemuMonitorDispose().
>
> This patch has:
>
> @@ -243,6 +244,7 @@ qemuMonitorDispose(void *obj)
>      virCondDestroy(&mon->notify);
>      g_free(mon->buffer);
>      g_free(mon->balloonpath);
> +    g_free(mon->domainName);
>  }

Oh ok. I assumed that there was two cleanup paths :
one is the natural tear down where qemuMonitorDispose() would be called.
Other was failure during contruction itself which I thought needed
additional handling.
Its ok then, no need to add additional g_free in monitorOpen()


Re: [PATCH v2] Add VM info to improve error log message for qemu monitor
Posted by Rohit Kumar 2 years, 3 months ago
On 04/01/22 3:56 pm, Ani Sinha wrote:
>
> On Tue, 4 Jan 2022, Peter Krempa wrote:
>
>> On Tue, Jan 04, 2022 at 15:30:00 +0530, Ani Sinha wrote:
>>> On Tue, 4 Jan 2022, Rohit Kumar wrote:
>>>> On 03/01/22 7:12 pm, Ani Sinha wrote:
>>>>> On Wed, 22 Dec 2021, Rohit Kumar wrote:
>> [...]
>>
>>>>>> @@ -694,6 +702,7 @@ qemuMonitorOpenInternal(virDomainObj *vm,
>>>>>>        mon->fd = fd;
>>>>>>        mon->context = g_main_context_ref(context);
>>>>>>        mon->vm = virObjectRef(vm);
>>>>>> +    mon->domainName = g_strdup(vm->def->name);
>>>>> do not forget to g_free() this during cleanup in the same function.
>>>> So, in cleanup: qemuMonitorDispose is called. And there I have added g_free()
>>>> to clean mon->domainName.
>>> No, in cleanup, I see qemuMonitorClose() is called where do you do not add
>>> any additional code to free the allocation.
>>>
>>> This is what I see in cleanup code:
>>>
>>> ```
>>> cleanup:
>>>      /* We don't want the 'destroy' callback invoked during
>>>       * cleanup from construction failure, because that can
>>>       * give a double-unref on virDomainObj *in the caller,
>>>       * so kill the callbacks now.
>>>       */
>>>      mon->cb = NULL;
>>>      /* The caller owns 'fd' on failure */
>>>      mon->fd = -1;
>>>      qemuMonitorClose(mon);
>> qemuMonitorClose() eventually calls virObjectUnref(mon). Once the last
>> reference on the monitor object is removed the object is freed via
>> qemuMonitorDispose().
>>
>> This patch has:
>>
>> @@ -243,6 +244,7 @@ qemuMonitorDispose(void *obj)
>>       virCondDestroy(&mon->notify);
>>       g_free(mon->buffer);
>>       g_free(mon->balloonpath);
>> +    g_free(mon->domainName);
>>   }
> Oh ok. I assumed that there was two cleanup paths :
> one is the natural tear down where qemuMonitorDispose() would be called.
> Other was failure during contruction itself which I thought needed
> additional handling.
> Its ok then, no need to add additional g_free in monitorOpen()
>
Ack. Thanks for the review Ani.

Re: [PATCH v2] Add VM info to improve error log message for qemu monitor
Posted by Peter Krempa 2 years, 3 months ago
On Wed, Dec 22, 2021 at 22:39:21 -0800, Rohit Kumar wrote:
> This patch is to determine the VM which had IO or socket hangup error.
> Accessing directly vm->def->name inside qemuMonitorIO() or qemuMonitorSend()
> might leads to illegal access as we are out of 'vm' context and vm->def might
> not exist. Adding a field "domainName" inside mon object to access vm name
> and initialising it when creating mon object.
> 
> Signed-off-by: Rohit Kumar <rohit.kumar3@nutanix.com>
> ---
>  diff to v1:
>   - Adding a field domainName inside _qemuMonitor struct for accessing vm name
>     instead of directly accessing mon->vm->def->name.
>   - Link to v1: https://listman.redhat.com/archives/libvir-list/2021-December/msg00217.html
>   - Talked with peter on RFC and he suggested me to add a field inside 
>     monitor struct to get VM name.
>  
>  src/qemu/qemu_monitor.c | 47 +++++++++++++++++++++++++----------------
>  1 file changed, 29 insertions(+), 18 deletions(-)
> 
> diff --git a/src/qemu/qemu_monitor.c b/src/qemu/qemu_monitor.c
> index dda6ae9796..c3a0227795 100644
> --- a/src/qemu/qemu_monitor.c
> +++ b/src/qemu/qemu_monitor.c

[...]

> @@ -530,13 +532,18 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>      qemuMonitor *mon = opaque;
>      bool error = false;
>      bool hangup = false;
> +    virDomainObj *vm = NULL;
> +    char *vmName = NULL;

These local variables are not very useful, you can access 'mon' directly
without the need for this alias ...

>  
>      virObjectRef(mon);
>  
> +    vm = mon->vm;
> +    vmName = mon->domainName;
> +
>      /* lock access to the monitor and protect fd */
>      virObjectLock(mon);
>  #if DEBUG_IO
> -    VIR_DEBUG("Monitor %p I/O on socket %p cond %d", mon, socket, cond);
> +    VIR_DEBUG("Monitor %p I/O on socket %p cond %d vm=%p name=%s", mon, socket, cond, vm, NULLSTR(vmName));
>  #endif

There's no much point in adding to thhese debug statements (inside
DEBUG_IO) as they are not compiled by default. In fact I'll propose a
removal of those.

>      if (mon->fd == -1 || !mon->watch) {
>          virObjectUnlock(mon);
> @@ -583,8 +590,8 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>  
>          if (!error && !mon->goteof &&
>              cond & G_IO_ERR) {
> -            virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> -                           _("Invalid file descriptor while waiting for monitor"));
> +            virReportError(VIR_ERR_INTERNAL_ERROR,
> +                           _("%s: Invalid file descriptor while waiting for monitor"), NULLSTR(vmName));

Do not prefix the error message by the VM name, but rather put it at the
end or inside:

 Invalid file descriptor while waiting for monitor (vm='%s')

or smilar.

>              mon->goteof = true;
>          }
>      }
> @@ -609,13 +616,14 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>              virResetLastError();
>          } else {
>              if (virGetLastErrorCode() == VIR_ERR_OK && !mon->goteof)
> -                virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> -                               _("Error while processing monitor IO"));
> +                virReportError(VIR_ERR_INTERNAL_ERROR,
> +                               _("%s: Error while processing monitor IO"), NULLSTR(vmName));

Same here. Additionally did you ever get to a situation where vmName
would be NULL?

>              virCopyLastError(&mon->lastError);
>              virResetLastError();
>          }
>  
> -        VIR_DEBUG("Error on monitor %s", NULLSTR(mon->lastError.message));
> +        VIR_DEBUG("Error on monitor %s mon=%p vm=%p name=%s",
> +                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));

This is a good example.

>          /* If IO process resulted in an error & we have a message,
>           * then wakeup that waiter */
>          if (mon->msg && !mon->msg->finished) {
> @@ -631,22 +639,22 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>       * will try to acquire the virDomainObj *mutex next */
>      if (mon->goteof) {
>          qemuMonitorEofNotifyCallback eofNotify = mon->cb->eofNotify;
> -        virDomainObj *vm = mon->vm;

You can remove this local when you are accessing it directly.

>  
>          /* Make sure anyone waiting wakes up now */
>          virCondSignal(&mon->notify);
>          virObjectUnlock(mon);
> -        VIR_DEBUG("Triggering EOF callback");
> +        VIR_DEBUG("Triggering EOF callback mon=%p vm=%p name=%s",
> +                  mon, vm, NULLSTR(vmName));
>          (eofNotify)(mon, vm, mon->callbackOpaque);
>          virObjectUnref(mon);
>      } else if (error) {
>          qemuMonitorErrorNotifyCallback errorNotify = mon->cb->errorNotify;
> -        virDomainObj *vm = mon->vm;
>  
>          /* Make sure anyone waiting wakes up now */
>          virCondSignal(&mon->notify);
>          virObjectUnlock(mon);
> -        VIR_DEBUG("Triggering error callback");
> +        VIR_DEBUG("Triggering error callback mon=%p vm=%p name=%s",
> +                  mon, vm, NULLSTR(vmName));
>          (errorNotify)(mon, vm, mon->callbackOpaque);
>          virObjectUnref(mon);
>      } else {
> @@ -694,6 +702,7 @@ qemuMonitorOpenInternal(virDomainObj *vm,
>      mon->fd = fd;
>      mon->context = g_main_context_ref(context);
>      mon->vm = virObjectRef(vm);
> +    mon->domainName = g_strdup(vm->def->name);

As noted above, did you ever run into a situation where this would be
NULL? That would seem weird.

>      mon->waitGreeting = true;
>      mon->cb = cb;
>      mon->callbackOpaque = opaque;
> @@ -932,17 +941,19 @@ qemuMonitorSend(qemuMonitor *mon,
>                  qemuMonitorMessage *msg)
>  {
>      int ret = -1;
> +    virDomainObj *vm = mon->vm;
> +    char *vmName = mon->domainName;

Avoid these.

>  
>      /* Check whether qemu quit unexpectedly */
>      if (mon->lastError.code != VIR_ERR_OK) {
> -        VIR_DEBUG("Attempt to send command while error is set %s",
> -                  NULLSTR(mon->lastError.message));
> +        VIR_DEBUG("Attempt to send command while error is set %s mon=%p vm=%p name=%s",
> +                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
>          virSetError(&mon->lastError);
>          return -1;
>      }
>      if (mon->goteof) {
> -        virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> -                       _("End of file from qemu monitor"));
> +        virReportError(VIR_ERR_INTERNAL_ERROR,
> +                       _("%s: End of file from qemu monitor"), NULLSTR(vmName));

No prefixing.

>          return -1;
>      }
>  
> @@ -955,15 +966,15 @@ qemuMonitorSend(qemuMonitor *mon,
>  
>      while (!mon->msg->finished) {
>          if (virCondWait(&mon->notify, &mon->parent.lock) < 0) {
> -            virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> -                           _("Unable to wait on monitor condition"));
> +            virReportError(VIR_ERR_INTERNAL_ERROR,
> +                           _("%s: Unable to wait on monitor condition"), NULLSTR(vmName));

Same here.

>              goto cleanup;
>          }
>      }
>  
>      if (mon->lastError.code != VIR_ERR_OK) {
> -        VIR_DEBUG("Send command resulted in error %s",
> -                  NULLSTR(mon->lastError.message));
> +        VIR_DEBUG("Send command resulted in error %s mon=%p vm=%p name=%s",
> +                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
>          virSetError(&mon->lastError);
>          goto cleanup;
>      }
> -- 
> 2.25.1
> 

Re: [PATCH v2] Add VM info to improve error log message for qemu monitor
Posted by Rohit Kumar 2 years, 3 months ago
On 03/01/22 10:12 pm, Peter Krempa wrote:
> On Wed, Dec 22, 2021 at 22:39:21 -0800, Rohit Kumar wrote:
>> This patch is to determine the VM which had IO or socket hangup error.
>> Accessing directly vm->def->name inside qemuMonitorIO() or qemuMonitorSend()
>> might leads to illegal access as we are out of 'vm' context and vm->def might
>> not exist. Adding a field "domainName" inside mon object to access vm name
>> and initialising it when creating mon object.
>>
>> Signed-off-by: Rohit Kumar <rohit.kumar3@nutanix.com>
>> ---
>>   diff to v1:
>>    - Adding a field domainName inside _qemuMonitor struct for accessing vm name
>>      instead of directly accessing mon->vm->def->name.
>>    - Link to v1: https://urldefense.proofpoint.com/v2/url?u=https-3A__listman.redhat.com_archives_libvir-2Dlist_2021-2DDecember_msg00217.html&d=DwIBAg&c=s883GpUCOChKOHiocYtGcg&r=ABSkr7gy7ZTfApFfI-Xxt1gZNtsDDiXoXOXc0OrkyFs&m=Zx9EFUnjB-Vnos3Ycje0GLa92yVGi-GQA7I5kFT9ll8jJUujvx-k2cEpTTb40KZW&s=KjRU2euJOCStdmi2A-a_axYFby40T-oNyr6kApd0nYI&e=
>>    - Talked with peter on RFC and he suggested me to add a field inside
>>      monitor struct to get VM name.
>>   
>>   src/qemu/qemu_monitor.c | 47 +++++++++++++++++++++++++----------------
>>   1 file changed, 29 insertions(+), 18 deletions(-)
>>
>> diff --git a/src/qemu/qemu_monitor.c b/src/qemu/qemu_monitor.c
>> index dda6ae9796..c3a0227795 100644
>> --- a/src/qemu/qemu_monitor.c
>> +++ b/src/qemu/qemu_monitor.c
> [...]
>
>> @@ -530,13 +532,18 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>>       qemuMonitor *mon = opaque;
>>       bool error = false;
>>       bool hangup = false;
>> +    virDomainObj *vm = NULL;
>> +    char *vmName = NULL;
> These local variables are not very useful, you can access 'mon' directly
> without the need for this alias ...
Thanks for the review Peter. I will update it in the next patch.
>
>>   
>>       virObjectRef(mon);
>>   
>> +    vm = mon->vm;
>> +    vmName = mon->domainName;
>> +
>>       /* lock access to the monitor and protect fd */
>>       virObjectLock(mon);
>>   #if DEBUG_IO
>> -    VIR_DEBUG("Monitor %p I/O on socket %p cond %d", mon, socket, cond);
>> +    VIR_DEBUG("Monitor %p I/O on socket %p cond %d vm=%p name=%s", mon, socket, cond, vm, NULLSTR(vmName));
>>   #endif
> There's no much point in adding to thhese debug statements (inside
> DEBUG_IO) as they are not compiled by default. In fact I'll propose a
> removal of those.
Okay. I will remove these from here.
>
>>       if (mon->fd == -1 || !mon->watch) {
>>           virObjectUnlock(mon);
>> @@ -583,8 +590,8 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>>   
>>           if (!error && !mon->goteof &&
>>               cond & G_IO_ERR) {
>> -            virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
>> -                           _("Invalid file descriptor while waiting for monitor"));
>> +            virReportError(VIR_ERR_INTERNAL_ERROR,
>> +                           _("%s: Invalid file descriptor while waiting for monitor"), NULLSTR(vmName));
> Do not prefix the error message by the VM name, but rather put it at the
> end or inside:
>
>   Invalid file descriptor while waiting for monitor (vm='%s')
>
> or smilar.
Acknowledge. Will update in next patch. Thanks.
>
>>               mon->goteof = true;
>>           }
>>       }
>> @@ -609,13 +616,14 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>>               virResetLastError();
>>           } else {
>>               if (virGetLastErrorCode() == VIR_ERR_OK && !mon->goteof)
>> -                virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
>> -                               _("Error while processing monitor IO"));
>> +                virReportError(VIR_ERR_INTERNAL_ERROR,
>> +                               _("%s: Error while processing monitor IO"), NULLSTR(vmName));
> Same here. Additionally did you ever get to a situation where vmName
> would be NULL?
There might be a situation when g_strdup() fails to allocate vm name, 
for e.g. if host ran out of memory ?
Let me know your thoughts on this, I would be happy to remove NULLSTR if 
it's not the case.
>
>>               virCopyLastError(&mon->lastError);
>>               virResetLastError();
>>           }
>>   
>> -        VIR_DEBUG("Error on monitor %s", NULLSTR(mon->lastError.message));
>> +        VIR_DEBUG("Error on monitor %s mon=%p vm=%p name=%s",
>> +                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
> This is a good example.
Okay.
>
>>           /* If IO process resulted in an error & we have a message,
>>            * then wakeup that waiter */
>>           if (mon->msg && !mon->msg->finished) {
>> @@ -631,22 +639,22 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>>        * will try to acquire the virDomainObj *mutex next */
>>       if (mon->goteof) {
>>           qemuMonitorEofNotifyCallback eofNotify = mon->cb->eofNotify;
>> -        virDomainObj *vm = mon->vm;
> You can remove this local when you are accessing it directly.
Sure. Ack.
>
>>   
>>           /* Make sure anyone waiting wakes up now */
>>           virCondSignal(&mon->notify);
>>           virObjectUnlock(mon);
>> -        VIR_DEBUG("Triggering EOF callback");
>> +        VIR_DEBUG("Triggering EOF callback mon=%p vm=%p name=%s",
>> +                  mon, vm, NULLSTR(vmName));
>>           (eofNotify)(mon, vm, mon->callbackOpaque);
>>           virObjectUnref(mon);
>>       } else if (error) {
>>           qemuMonitorErrorNotifyCallback errorNotify = mon->cb->errorNotify;
>> -        virDomainObj *vm = mon->vm;
>>   
>>           /* Make sure anyone waiting wakes up now */
>>           virCondSignal(&mon->notify);
>>           virObjectUnlock(mon);
>> -        VIR_DEBUG("Triggering error callback");
>> +        VIR_DEBUG("Triggering error callback mon=%p vm=%p name=%s",
>> +                  mon, vm, NULLSTR(vmName));
>>           (errorNotify)(mon, vm, mon->callbackOpaque);
>>           virObjectUnref(mon);
>>       } else {
>> @@ -694,6 +702,7 @@ qemuMonitorOpenInternal(virDomainObj *vm,
>>       mon->fd = fd;
>>       mon->context = g_main_context_ref(context);
>>       mon->vm = virObjectRef(vm);
>> +    mon->domainName = g_strdup(vm->def->name);
> As noted above, did you ever run into a situation where this would be
> NULL? That would seem weird.
My concern was with g_strdup() allocation failing. Let me know if that 
isn't the case.
>
>>       mon->waitGreeting = true;
>>       mon->cb = cb;
>>       mon->callbackOpaque = opaque;
>> @@ -932,17 +941,19 @@ qemuMonitorSend(qemuMonitor *mon,
>>                   qemuMonitorMessage *msg)
>>   {
>>       int ret = -1;
>> +    virDomainObj *vm = mon->vm;
>> +    char *vmName = mon->domainName;
> Avoid these.
Ack.
>
>>   
>>       /* Check whether qemu quit unexpectedly */
>>       if (mon->lastError.code != VIR_ERR_OK) {
>> -        VIR_DEBUG("Attempt to send command while error is set %s",
>> -                  NULLSTR(mon->lastError.message));
>> +        VIR_DEBUG("Attempt to send command while error is set %s mon=%p vm=%p name=%s",
>> +                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
>>           virSetError(&mon->lastError);
>>           return -1;
>>       }
>>       if (mon->goteof) {
>> -        virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
>> -                       _("End of file from qemu monitor"));
>> +        virReportError(VIR_ERR_INTERNAL_ERROR,
>> +                       _("%s: End of file from qemu monitor"), NULLSTR(vmName));
> No prefixing.
Ack.
>
>>           return -1;
>>       }
>>   
>> @@ -955,15 +966,15 @@ qemuMonitorSend(qemuMonitor *mon,
>>   
>>       while (!mon->msg->finished) {
>>           if (virCondWait(&mon->notify, &mon->parent.lock) < 0) {
>> -            virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
>> -                           _("Unable to wait on monitor condition"));
>> +            virReportError(VIR_ERR_INTERNAL_ERROR,
>> +                           _("%s: Unable to wait on monitor condition"), NULLSTR(vmName));
> Same here.
Ack.
Thanks, I will update these in the next patch.
>
>>               goto cleanup;
>>           }
>>       }
>>   
>>       if (mon->lastError.code != VIR_ERR_OK) {
>> -        VIR_DEBUG("Send command resulted in error %s",
>> -                  NULLSTR(mon->lastError.message));
>> +        VIR_DEBUG("Send command resulted in error %s mon=%p vm=%p name=%s",
>> +                  NULLSTR(mon->lastError.message), mon, vm, NULLSTR(vmName));
>>           virSetError(&mon->lastError);
>>           goto cleanup;
>>       }
>> -- 
>> 2.25.1
>>

Re: [PATCH v2] Add VM info to improve error log message for qemu monitor
Posted by Peter Krempa 2 years, 3 months ago
On Tue, Jan 04, 2022 at 14:10:49 +0530, Rohit Kumar wrote:
> 
> On 03/01/22 10:12 pm, Peter Krempa wrote:
> > On Wed, Dec 22, 2021 at 22:39:21 -0800, Rohit Kumar wrote:
> > > This patch is to determine the VM which had IO or socket hangup error.
> > > Accessing directly vm->def->name inside qemuMonitorIO() or qemuMonitorSend()
> > > might leads to illegal access as we are out of 'vm' context and vm->def might
> > > not exist. Adding a field "domainName" inside mon object to access vm name
> > > and initialising it when creating mon object.
> > > 
> > > Signed-off-by: Rohit Kumar <rohit.kumar3@nutanix.com>
> > > ---

[...]

> > > @@ -609,13 +616,14 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
> > >               virResetLastError();
> > >           } else {
> > >               if (virGetLastErrorCode() == VIR_ERR_OK && !mon->goteof)
> > > -                virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> > > -                               _("Error while processing monitor IO"));
> > > +                virReportError(VIR_ERR_INTERNAL_ERROR,
> > > +                               _("%s: Error while processing monitor IO"), NULLSTR(vmName));
> > Same here. Additionally did you ever get to a situation where vmName
> > would be NULL?
> There might be a situation when g_strdup() fails to allocate vm name, for
> e.g. if host ran out of memory ?

No, g_strdup on out of memory condition abort()s the program completely.

The only time when g_strdup returns NULL is if the argument is NULL.

> Let me know your thoughts on this, I would be happy to remove NULLSTR if
> it's not the case.

That depends if you happened to see whether all callers avoid passing
NULL name for the VM which is very likely.

Re: [PATCH v2] Add VM info to improve error log message for qemu monitor
Posted by Peter Krempa 2 years, 3 months ago
On Tue, Jan 04, 2022 at 09:45:30 +0100, Peter Krempa wrote:
> On Tue, Jan 04, 2022 at 14:10:49 +0530, Rohit Kumar wrote:
> > 
> > On 03/01/22 10:12 pm, Peter Krempa wrote:
> > > On Wed, Dec 22, 2021 at 22:39:21 -0800, Rohit Kumar wrote:
> > > > This patch is to determine the VM which had IO or socket hangup error.
> > > > Accessing directly vm->def->name inside qemuMonitorIO() or qemuMonitorSend()
> > > > might leads to illegal access as we are out of 'vm' context and vm->def might
> > > > not exist. Adding a field "domainName" inside mon object to access vm name
> > > > and initialising it when creating mon object.
> > > > 
> > > > Signed-off-by: Rohit Kumar <rohit.kumar3@nutanix.com>
> > > > ---
> 
> [...]
> 
> > > > @@ -609,13 +616,14 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
> > > >               virResetLastError();
> > > >           } else {
> > > >               if (virGetLastErrorCode() == VIR_ERR_OK && !mon->goteof)
> > > > -                virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> > > > -                               _("Error while processing monitor IO"));
> > > > +                virReportError(VIR_ERR_INTERNAL_ERROR,
> > > > +                               _("%s: Error while processing monitor IO"), NULLSTR(vmName));
> > > Same here. Additionally did you ever get to a situation where vmName
> > > would be NULL?
> > There might be a situation when g_strdup() fails to allocate vm name, for
> > e.g. if host ran out of memory ?
> 
> No, g_strdup on out of memory condition abort()s the program completely.
> 
> The only time when g_strdup returns NULL is if the argument is NULL.
> 
> > Let me know your thoughts on this, I would be happy to remove NULLSTR if
> > it's not the case.
> 
> That depends if you happened to see whether all callers avoid passing
> NULL name for the VM which is very likely.

Alternatively you can do g_strdup(NULLSTR(vm->def->name)). Thus the
domain name variable will hold a copy of "<null>" as the name. Since
it's for error messages only this is tolerable and allows you to avoid
all the other NULLSTR usage.

Re: [PATCH v2] Add VM info to improve error log message for qemu monitor
Posted by Rohit Kumar 2 years, 3 months ago
On 04/01/22 2:17 pm, Peter Krempa wrote:
> On Tue, Jan 04, 2022 at 09:45:30 +0100, Peter Krempa wrote:
>> On Tue, Jan 04, 2022 at 14:10:49 +0530, Rohit Kumar wrote:
>>> On 03/01/22 10:12 pm, Peter Krempa wrote:
>>>> On Wed, Dec 22, 2021 at 22:39:21 -0800, Rohit Kumar wrote:
>>>>> This patch is to determine the VM which had IO or socket hangup error.
>>>>> Accessing directly vm->def->name inside qemuMonitorIO() or qemuMonitorSend()
>>>>> might leads to illegal access as we are out of 'vm' context and vm->def might
>>>>> not exist. Adding a field "domainName" inside mon object to access vm name
>>>>> and initialising it when creating mon object.
>>>>>
>>>>> Signed-off-by: Rohit Kumar <rohit.kumar3@nutanix.com>
>>>>> ---
>> [...]
>>
>>>>> @@ -609,13 +616,14 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>>>>>                virResetLastError();
>>>>>            } else {
>>>>>                if (virGetLastErrorCode() == VIR_ERR_OK && !mon->goteof)
>>>>> -                virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
>>>>> -                               _("Error while processing monitor IO"));
>>>>> +                virReportError(VIR_ERR_INTERNAL_ERROR,
>>>>> +                               _("%s: Error while processing monitor IO"), NULLSTR(vmName));
>>>> Same here. Additionally did you ever get to a situation where vmName
>>>> would be NULL?
>>> There might be a situation when g_strdup() fails to allocate vm name, for
>>> e.g. if host ran out of memory ?
>> No, g_strdup on out of memory condition abort()s the program completely.
>>
>> The only time when g_strdup returns NULL is if the argument is NULL.
>>
>>> Let me know your thoughts on this, I would be happy to remove NULLSTR if
>>> it's not the case.
>> That depends if you happened to see whether all callers avoid passing
>> NULL name for the VM which is very likely.
> Alternatively you can do g_strdup(NULLSTR(vm->def->name)). Thus the
> domain name variable will hold a copy of "<null>" as the name. Since
> it's for error messages only this is tolerable and allows you to avoid
> all the other NULLSTR usage.
Sure, this would be much better, I will update this. Thanks for the 
suggestion.
>