logging: ensure pending I/O is drained before reading position

[libvirt] [PATCH] logging: ensure pending I/O is drained before reading position

Posted by Daniel P. Berrangé 5 years, 4 months ago

The virtualization driver has two connections to the virtlogd daemon,
one pipe fd for writing to the log file, and one socket fd for making
RPC calls. The typical sequence is to write some data to the pipe fd and
then make an RPC call to determine the current log file offset.

Unfortunately these two operations are not guaranteed to be handling in
order by virtlogd. The event loop for virtlogd may identify an incoming
event on both the pipe fd and socket fd in the same iteration of the
event loop. It is then entirely possible that it will process the socket
fd RPC call before reading the pending log data from the pipe fd.

As a result the virtualization driver will get an outdated log file
offset reported back.

This can be seen with the QEMU driver where, when a guest fails to
start, it will randomly include too much data in the error message it
has fetched from the log file.

The solution is to ensure we have drained all pending data from the pipe
fd before reporting the log file offset. The pipe fd is always in
blocking mode, so cares needs to be taken to avoid blocking. When
draining this is taken care of by using poll(). The extra complication
is that they might already be an event loop dispatch pending on the pipe
fd. If we have just drained the pipe this pending event will be invalid
so must be discarded.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 src/logging/log_handler.c | 48 +++++++++++++++++++++++++++++++++++++++
 1 file changed, 48 insertions(+)

diff --git a/src/logging/log_handler.c b/src/logging/log_handler.c
index 9e1f1f1577..272bb719ca 100644
--- a/src/logging/log_handler.c
+++ b/src/logging/log_handler.c
@@ -32,6 +32,7 @@
 
 #include <unistd.h>
 #include <fcntl.h>
+#include <poll.h>
 
 #include "configmake.h"
 
@@ -48,6 +49,7 @@ struct _virLogHandlerLogFile {
     virRotatingFileWriterPtr file;
     int watch;
     int pipefd; /* Read from QEMU via this */
+    bool drained;
 
     char *driver;
     unsigned char domuuid[VIR_UUID_BUFLEN];
@@ -151,6 +153,11 @@ virLogHandlerDomainLogFileEvent(int watch,
         return;
     }
 
+    if (logfile->drained) {
+        logfile->drained = false;
+        goto cleanup;
+    }
+
  reread:
     len = read(fd, buf, sizeof(buf));
     if (len < 0) {
@@ -168,6 +175,7 @@ virLogHandlerDomainLogFileEvent(int watch,
     if (events & VIR_EVENT_HANDLE_HANGUP)
         goto error;
 
+ cleanup:
     virObjectUnlock(handler);
     return;
 
@@ -433,6 +441,44 @@ virLogHandlerDomainOpenLogFile(virLogHandlerPtr handler,
 }
 
 
+static void
+virLogHandlerDomainLogFileDrain(virLogHandlerLogFilePtr file)
+{
+    char buf[1024];
+    ssize_t len;
+    struct pollfd pfd;
+    int ret;
+
+    for (;;) {
+        pfd.fd = file->pipefd;
+        pfd.events = POLLIN;
+        pfd.revents = 0;
+
+        ret = poll(&pfd, 1, 0);
+        if (ret < 0) {
+            if (errno == EINTR)
+                continue;
+
+            return;
+        }
+
+        if (ret == 0)
+            return;
+
+        len = read(file->pipefd, buf, sizeof(buf));
+        file->drained = true;
+        if (len < 0) {
+            if (errno == EINTR)
+                continue;
+            return;
+        }
+
+        if (virRotatingFileWriterAppend(file->file, buf, len) != len)
+            return;
+    }
+}
+
+
 int
 virLogHandlerDomainGetLogFilePosition(virLogHandlerPtr handler,
                                       const char *path,
@@ -463,6 +509,8 @@ virLogHandlerDomainGetLogFilePosition(virLogHandlerPtr handler,
         goto cleanup;
     }
 
+    virLogHandlerDomainLogFileDrain(file);
+
     *inode = virRotatingFileWriterGetINode(file->file);
     *offset = virRotatingFileWriterGetOffset(file->file);
 
-- 
2.19.2

--
libvir-list mailing list
libvir-list@redhat.com
https://www.redhat.com/mailman/listinfo/libvir-list

Re: [libvirt] [PATCH] logging: ensure pending I/O is drained before reading position

Posted by Andrea Bolognani 5 years, 4 months ago

On Fri, 2018-12-14 at 13:04 +0000, Daniel P. Berrangé wrote:
> The virtualization driver has two connections to the virtlogd daemon,
> one pipe fd for writing to the log file, and one socket fd for making
> RPC calls. The typical sequence is to write some data to the pipe fd and
> then make an RPC call to determine the current log file offset.
> 
> Unfortunately these two operations are not guaranteed to be handling in
> order by virtlogd. The event loop for virtlogd may identify an incoming
> event on both the pipe fd and socket fd in the same iteration of the
> event loop. It is then entirely possible that it will process the socket
> fd RPC call before reading the pending log data from the pipe fd.
> 
> As a result the virtualization driver will get an outdated log file
> offset reported back.
> 
> This can be seen with the QEMU driver where, when a guest fails to
> start, it will randomly include too much data in the error message it
> has fetched from the log file.

It looks like this patch will address

  https://bugzilla.redhat.com/show_bug.cgi?id=1356108

If that's indeed the case, you can consider adding the link to the
commit message before pushing.

-- 
Andrea Bolognani / Red Hat / Virtualization

--
libvir-list mailing list
libvir-list@redhat.com
https://www.redhat.com/mailman/listinfo/libvir-list

Re: [libvirt] [PATCH] logging: ensure pending I/O is drained before reading position

Posted by Michal Privoznik 5 years, 4 months ago

On 12/14/18 2:04 PM, Daniel P. Berrangé wrote:
> The virtualization driver has two connections to the virtlogd daemon,
> one pipe fd for writing to the log file, and one socket fd for making
> RPC calls. The typical sequence is to write some data to the pipe fd and
> then make an RPC call to determine the current log file offset.
> 
> Unfortunately these two operations are not guaranteed to be handling in
> order by virtlogd. The event loop for virtlogd may identify an incoming
> event on both the pipe fd and socket fd in the same iteration of the
> event loop. It is then entirely possible that it will process the socket
> fd RPC call before reading the pending log data from the pipe fd.
> 
> As a result the virtualization driver will get an outdated log file
> offset reported back.
> 
> This can be seen with the QEMU driver where, when a guest fails to
> start, it will randomly include too much data in the error message it
> has fetched from the log file.
> 
> The solution is to ensure we have drained all pending data from the pipe
> fd before reporting the log file offset. The pipe fd is always in
> blocking mode, so cares needs to be taken to avoid blocking. When
> draining this is taken care of by using poll(). The extra complication
> is that they might already be an event loop dispatch pending on the pipe
> fd. If we have just drained the pipe this pending event will be invalid
> so must be discarded.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>  src/logging/log_handler.c | 48 +++++++++++++++++++++++++++++++++++++++
>  1 file changed, 48 insertions(+)

ACK

Michal

--
libvir-list mailing list
libvir-list@redhat.com
https://www.redhat.com/mailman/listinfo/libvir-list