[RFC PATCH] qemu: Do not report eof when processing monitor IO

Jim Fehlig posted 1 patch 1 week, 6 days ago
Patches applied successfully (tree, apply log)
git fetch https://github.com/patchew-project/libvirt tags/patchew/20211008213749.26414-1-jfehlig@suse.com
src/qemu/qemu_monitor.c | 29 ++++++++++++++++-------------
1 file changed, 16 insertions(+), 13 deletions(-)

[RFC PATCH] qemu: Do not report eof when processing monitor IO

Posted by Jim Fehlig 1 week, 6 days ago
There have been countless reports from users concerned about the following
error reported by libvirtd when qemu domains are shutdown

internal error: End of file from qemu monitor

While the error is harmless, users often mistaken it for real problem with
their deployments. EOF from the monitor can't be entirely ignored since
other threads may be using the monitor and must be able to detect the EOF
condition.

One potential fix is to delay reporting EOF until the monitor is used
after EOF is detected. This patch adds a 'goteof' member to the
qemuMonitor structure, which is set when EOF is detected on the monitor
socket. If another thread later tries to send data on the monitor, the
EOF error is reported.

Signed-off-by: Jim Fehlig <jfehlig@suse.com>
---

An RFC patch to squelch qemu monitor EOF error messages on VM shutdown.
Previous discussions and information on testing of the patch can be
found in this thread

https://listman.redhat.com/archives/libvir-list/2021-September/msg00949.html

 src/qemu/qemu_monitor.c | 29 ++++++++++++++++-------------
 1 file changed, 16 insertions(+), 13 deletions(-)

diff --git a/src/qemu/qemu_monitor.c b/src/qemu/qemu_monitor.c
index 5fc23f13d3..751ec8ba6c 100644
--- a/src/qemu/qemu_monitor.c
+++ b/src/qemu/qemu_monitor.c
@@ -113,6 +113,7 @@ struct _qemuMonitor {
 
     /* true if qemu no longer wants 'props' sub-object of object-add */
     bool objectAddNoWrap;
+    bool goteof;
 };
 
 /**
@@ -526,10 +527,10 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
 {
     qemuMonitor *mon = opaque;
     bool error = false;
-    bool eof = false;
     bool hangup = false;
 
     virObjectRef(mon);
+    mon->goteof = false;
 
     /* lock access to the monitor and protect fd */
     virObjectLock(mon);
@@ -544,7 +545,7 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
 
     if (mon->lastError.code != VIR_ERR_OK) {
         if (cond & (G_IO_HUP | G_IO_ERR))
-            eof = true;
+            mon->goteof = true;
         error = true;
     } else {
         if (cond & G_IO_OUT) {
@@ -562,7 +563,7 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
                 if (errno == ECONNRESET)
                     hangup = true;
             } else if (got == 0) {
-                eof = true;
+                mon->goteof = true;
             } else {
                 /* Ignore hangup/error cond if we read some data, to
                  * give time for that data to be consumed */
@@ -575,22 +576,19 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
 
         if (cond & G_IO_HUP) {
             hangup = true;
-            if (!error) {
-                virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
-                               _("End of file from qemu monitor"));
-                eof = true;
-            }
+            if (!error)
+                mon->goteof = true;
         }
 
-        if (!error && !eof &&
+        if (!error && !mon->goteof &&
             cond & G_IO_ERR) {
             virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
                            _("Invalid file descriptor while waiting for monitor"));
-            eof = true;
+            mon->goteof = true;
         }
     }
 
-    if (error || eof) {
+    if (error || mon->goteof) {
         if (hangup && mon->logFunc != NULL) {
             /* Check if an error message from qemu is available and if so, use
              * it to overwrite the actual message. It's done only in early
@@ -609,7 +607,7 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
             /* Already have an error, so clear any new error */
             virResetLastError();
         } else {
-            if (virGetLastErrorCode() == VIR_ERR_OK)
+            if (virGetLastErrorCode() == VIR_ERR_OK && !mon->goteof)
                 virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
                                _("Error while processing monitor IO"));
             virCopyLastError(&mon->lastError);
@@ -630,7 +628,7 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
     /* We have to unlock to avoid deadlock against command thread,
      * but is this safe ?  I think it is, because the callback
      * will try to acquire the virDomainObj *mutex next */
-    if (eof) {
+    if (mon->goteof) {
         qemuMonitorEofNotifyCallback eofNotify = mon->cb->eofNotify;
         virDomainObj *vm = mon->vm;
 
@@ -949,6 +947,11 @@ qemuMonitorSend(qemuMonitor *mon,
         virSetError(&mon->lastError);
         return -1;
     }
+    if (mon->goteof) {
+        virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
+                       _("End of file from qemu monitor"));
+        return -1;
+    }
 
     mon->msg = msg;
     qemuMonitorUpdateWatch(mon);
-- 
2.33.0


Re: [RFC PATCH] qemu: Do not report eof when processing monitor IO

Posted by Michal Prívozník 1 week, 2 days ago
On 10/8/21 11:37 PM, Jim Fehlig wrote:
> There have been countless reports from users concerned about the following
> error reported by libvirtd when qemu domains are shutdown
> 
> internal error: End of file from qemu monitor
> 
> While the error is harmless, users often mistaken it for real problem with
> their deployments. EOF from the monitor can't be entirely ignored since
> other threads may be using the monitor and must be able to detect the EOF
> condition.
> 
> One potential fix is to delay reporting EOF until the monitor is used
> after EOF is detected. This patch adds a 'goteof' member to the
> qemuMonitor structure, which is set when EOF is detected on the monitor
> socket. If another thread later tries to send data on the monitor, the
> EOF error is reported.
> 
> Signed-off-by: Jim Fehlig <jfehlig@suse.com>
> ---
> 
> An RFC patch to squelch qemu monitor EOF error messages on VM shutdown.
> Previous discussions and information on testing of the patch can be
> found in this thread
> 
> https://listman.redhat.com/archives/libvir-list/2021-September/msg00949.html
> 
>  src/qemu/qemu_monitor.c | 29 ++++++++++++++++-------------
>  1 file changed, 16 insertions(+), 13 deletions(-)
> 
> diff --git a/src/qemu/qemu_monitor.c b/src/qemu/qemu_monitor.c
> index 5fc23f13d3..751ec8ba6c 100644
> --- a/src/qemu/qemu_monitor.c
> +++ b/src/qemu/qemu_monitor.c
> @@ -113,6 +113,7 @@ struct _qemuMonitor {
>  
>      /* true if qemu no longer wants 'props' sub-object of object-add */
>      bool objectAddNoWrap;
> +    bool goteof;
>  };
>  
>  /**
> @@ -526,10 +527,10 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>  {
>      qemuMonitor *mon = opaque;
>      bool error = false;
> -    bool eof = false;
>      bool hangup = false;
>  
>      virObjectRef(mon);
> +    mon->goteof = false;
>  

At this point, the monitor object is unlocked (see the line below). So
setting this flag outside is potentially dangerous. But, I don't think
we need to set ->goteof here at all, do we? I mean, the moment we see
EOF the monitor object will be disposed and not ever used again.

>      /* lock access to the monitor and protect fd */
>      virObjectLock(mon);

Otherwise looking good and also passes my testing.

Michal

Re: [RFC PATCH] qemu: Do not report eof when processing monitor IO

Posted by Jim Fehlig 1 week ago
On 10/13/21 05:02, Michal Prívozník wrote:
> On 10/8/21 11:37 PM, Jim Fehlig wrote:
>> There have been countless reports from users concerned about the following
>> error reported by libvirtd when qemu domains are shutdown
>>
>> internal error: End of file from qemu monitor
>>
>> While the error is harmless, users often mistaken it for real problem with
>> their deployments. EOF from the monitor can't be entirely ignored since
>> other threads may be using the monitor and must be able to detect the EOF
>> condition.
>>
>> One potential fix is to delay reporting EOF until the monitor is used
>> after EOF is detected. This patch adds a 'goteof' member to the
>> qemuMonitor structure, which is set when EOF is detected on the monitor
>> socket. If another thread later tries to send data on the monitor, the
>> EOF error is reported.
>>
>> Signed-off-by: Jim Fehlig <jfehlig@suse.com>
>> ---
>>
>> An RFC patch to squelch qemu monitor EOF error messages on VM shutdown.
>> Previous discussions and information on testing of the patch can be
>> found in this thread
>>
>> https://listman.redhat.com/archives/libvir-list/2021-September/msg00949.html
>>
>>   src/qemu/qemu_monitor.c | 29 ++++++++++++++++-------------
>>   1 file changed, 16 insertions(+), 13 deletions(-)
>>
>> diff --git a/src/qemu/qemu_monitor.c b/src/qemu/qemu_monitor.c
>> index 5fc23f13d3..751ec8ba6c 100644
>> --- a/src/qemu/qemu_monitor.c
>> +++ b/src/qemu/qemu_monitor.c
>> @@ -113,6 +113,7 @@ struct _qemuMonitor {
>>   
>>       /* true if qemu no longer wants 'props' sub-object of object-add */
>>       bool objectAddNoWrap;
>> +    bool goteof;
>>   };
>>   
>>   /**
>> @@ -526,10 +527,10 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>>   {
>>       qemuMonitor *mon = opaque;
>>       bool error = false;
>> -    bool eof = false;
>>       bool hangup = false;
>>   
>>       virObjectRef(mon);
>> +    mon->goteof = false;
>>   
> 
> At this point, the monitor object is unlocked (see the line below). So
> setting this flag outside is potentially dangerous. But, I don't think
> we need to set ->goteof here at all, do we? I mean, the moment we see
> EOF the monitor object will be disposed and not ever used again.

Agreed. I've removed it and sent a non-RFC version of the patch

https://listman.redhat.com/archives/libvir-list/2021-October/msg00664.html

As an update to the commentary in that patch, my tests have now survived 220 
iterations.

Regards,
Jim


Re: [RFC PATCH] qemu: Do not report eof when processing monitor IO

Posted by Jim Fehlig 1 week, 2 days ago
On 10/8/21 15:37, Jim Fehlig wrote:
> There have been countless reports from users concerned about the following
> error reported by libvirtd when qemu domains are shutdown
> 
> internal error: End of file from qemu monitor
> 
> While the error is harmless, users often mistaken it for real problem with
> their deployments. EOF from the monitor can't be entirely ignored since
> other threads may be using the monitor and must be able to detect the EOF
> condition.
> 
> One potential fix is to delay reporting EOF until the monitor is used
> after EOF is detected. This patch adds a 'goteof' member to the
> qemuMonitor structure, which is set when EOF is detected on the monitor
> socket. If another thread later tries to send data on the monitor, the
> EOF error is reported.
> 
> Signed-off-by: Jim Fehlig <jfehlig@suse.com>
> ---
> 
> An RFC patch to squelch qemu monitor EOF error messages on VM shutdown.
> Previous discussions and information on testing of the patch can be
> found in this thread
> 
> https://listman.redhat.com/archives/libvir-list/2021-September/msg00949.html

FYI, the tests mentioned in that thread ran for 2376 iterations with this patch 
before I had to use the machine for other purposes.

Any comments on this approach to squelching the error message? Or other ideas 
for achieving the same?

Regards,
Jim

>   src/qemu/qemu_monitor.c | 29 ++++++++++++++++-------------
>   1 file changed, 16 insertions(+), 13 deletions(-)
> 
> diff --git a/src/qemu/qemu_monitor.c b/src/qemu/qemu_monitor.c
> index 5fc23f13d3..751ec8ba6c 100644
> --- a/src/qemu/qemu_monitor.c
> +++ b/src/qemu/qemu_monitor.c
> @@ -113,6 +113,7 @@ struct _qemuMonitor {
>   
>       /* true if qemu no longer wants 'props' sub-object of object-add */
>       bool objectAddNoWrap;
> +    bool goteof;
>   };
>   
>   /**
> @@ -526,10 +527,10 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>   {
>       qemuMonitor *mon = opaque;
>       bool error = false;
> -    bool eof = false;
>       bool hangup = false;
>   
>       virObjectRef(mon);
> +    mon->goteof = false;
>   
>       /* lock access to the monitor and protect fd */
>       virObjectLock(mon);
> @@ -544,7 +545,7 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>   
>       if (mon->lastError.code != VIR_ERR_OK) {
>           if (cond & (G_IO_HUP | G_IO_ERR))
> -            eof = true;
> +            mon->goteof = true;
>           error = true;
>       } else {
>           if (cond & G_IO_OUT) {
> @@ -562,7 +563,7 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>                   if (errno == ECONNRESET)
>                       hangup = true;
>               } else if (got == 0) {
> -                eof = true;
> +                mon->goteof = true;
>               } else {
>                   /* Ignore hangup/error cond if we read some data, to
>                    * give time for that data to be consumed */
> @@ -575,22 +576,19 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>   
>           if (cond & G_IO_HUP) {
>               hangup = true;
> -            if (!error) {
> -                virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> -                               _("End of file from qemu monitor"));
> -                eof = true;
> -            }
> +            if (!error)
> +                mon->goteof = true;
>           }
>   
> -        if (!error && !eof &&
> +        if (!error && !mon->goteof &&
>               cond & G_IO_ERR) {
>               virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
>                              _("Invalid file descriptor while waiting for monitor"));
> -            eof = true;
> +            mon->goteof = true;
>           }
>       }
>   
> -    if (error || eof) {
> +    if (error || mon->goteof) {
>           if (hangup && mon->logFunc != NULL) {
>               /* Check if an error message from qemu is available and if so, use
>                * it to overwrite the actual message. It's done only in early
> @@ -609,7 +607,7 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>               /* Already have an error, so clear any new error */
>               virResetLastError();
>           } else {
> -            if (virGetLastErrorCode() == VIR_ERR_OK)
> +            if (virGetLastErrorCode() == VIR_ERR_OK && !mon->goteof)
>                   virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
>                                  _("Error while processing monitor IO"));
>               virCopyLastError(&mon->lastError);
> @@ -630,7 +628,7 @@ qemuMonitorIO(GSocket *socket G_GNUC_UNUSED,
>       /* We have to unlock to avoid deadlock against command thread,
>        * but is this safe ?  I think it is, because the callback
>        * will try to acquire the virDomainObj *mutex next */
> -    if (eof) {
> +    if (mon->goteof) {
>           qemuMonitorEofNotifyCallback eofNotify = mon->cb->eofNotify;
>           virDomainObj *vm = mon->vm;
>   
> @@ -949,6 +947,11 @@ qemuMonitorSend(qemuMonitor *mon,
>           virSetError(&mon->lastError);
>           return -1;
>       }
> +    if (mon->goteof) {
> +        virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> +                       _("End of file from qemu monitor"));
> +        return -1;
> +    }
>   
>       mon->msg = msg;
>       qemuMonitorUpdateWatch(mon);
>