8:24 a.m.
The code fixed in the first actual patch is quite venerable so I made up
a synthetic test to show issue/test it is fixed. Test covers both issues.
Initially I got /tmp/virtlogd-test size of only 2048 and after the first
fix I saw actual endless loop.
Nikolay Shirokovskiy (3):
DO NOT APPLY: code to show logging issues
logging: read all bytes on EOF in event handler
logging: fix endless loop on EOF
src/logging/log_handler.c | 10 ++++++----
src/qemu/qemu_process.c | 35 +++++++++++++++++++++++++++++++++++
2 files changed, 41 insertions(+), 4 deletions(-)
--
1.8.3.1
8:24 a.m.
New subject: [PATCH 1/3] DO NOT APPLY: code to show logging issues
---
src/logging/log_handler.c | 1 +
src/qemu/qemu_process.c | 35 +++++++++++++++++++++++++++++++++++
2 files changed, 36 insertions(+)
diff --git a/src/logging/log_handler.c b/src/logging/log_handler.c
index 87748d9..cfadc69 100644
--- a/src/logging/log_handler.c
+++ b/src/logging/log_handler.c
@@ -160,6 +160,7 @@ virLogHandlerDomainLogFileEvent(int watch,
}
reread:
+ g_usleep(200 * 1000);
len = read(fd, buf, sizeof(buf));
if (len < 0) {
if (errno == EINTR)
diff --git a/src/qemu/qemu_process.c b/src/qemu/qemu_process.c
index f21b8f1..22219f8 100644
--- a/src/qemu/qemu_process.c
+++ b/src/qemu/qemu_process.c
@@ -93,6 +93,8 @@
#include "viridentity.h"
#include "virthreadjob.h"
#include "virutil.h"
+#include "logging/log_manager.h"
+#include "logging/log_protocol.h"
#define VIR_FROM_THIS VIR_FROM_QEMU
@@ -6829,6 +6831,39 @@ qemuProcessLaunch(virConnectPtr conn,
incoming != NULL) < 0)
goto cleanup;
+ if (qemuDomainLogContextGetManager(logCtxt)) {
+ int fd = -1;
+ char *buf;
+ int rc;
+ ino_t inode;
+ off_t offset;
+
+ if ((fd = virLogManagerDomainOpenLogFile(
+ qemuDomainLogContextGetManager(logCtxt),
+ "qemu",
+ vm->def->uuid,
+ vm->def->name,
+ "/tmp/virtlogd-test",
+ VIR_LOG_MANAGER_PROTOCOL_DOMAIN_OPEN_LOG_FILE_TRUNCATE,
+ NULL, NULL)) < 0)
+ goto cleanup;
+
+ buf = g_new0(char, 10000);
+ rc = safewrite(fd, buf, 10000);
+ VIR_FORCE_CLOSE(fd);
+
+ if (rc < 10000) {
+ virReportError(VIR_ERR_INTERNAL_ERROR,
+ "can't write all bytes to test file");
+ goto cleanup;
+ }
+
+ if (virLogManagerDomainGetLogFilePosition(
+ qemuDomainLogContextGetManager(logCtxt),
+ "/tmp/virtlogd-test", 0, &inode, &offset) <
0)
+ goto cleanup;
+ }
+
VIR_DEBUG("Building emulator command line");
if (!(cmd = qemuBuildCommandLine(driver,
qemuDomainLogContextGetManager(logCtxt),
--
1.8.3.1
8:24 a.m.
New subject: [PATCH 2/3] logging: read all bytes on EOF in event handler
If writing side writes enough bytes to the pipe and closes writing
end then we got both VIR_EVENT_HANDLE_HANGUP and VIR_EVENT_HANDLE_READ
in handler. Currently in this situation handler reads 1024 bytes
and finish reading leaving unread data in pipe.
Signed-off-by: Nikolay Shirokovskiy <nshirokovskiy(a)virtuozzo.com>
---
src/logging/log_handler.c | 7 +++----
1 file changed, 3 insertions(+), 4 deletions(-)
diff --git a/src/logging/log_handler.c b/src/logging/log_handler.c
index cfadc69..c04f341 100644
--- a/src/logging/log_handler.c
+++ b/src/logging/log_handler.c
@@ -138,7 +138,7 @@ virLogHandlerGetLogFileFromWatch(virLogHandlerPtr handler,
static void
virLogHandlerDomainLogFileEvent(int watch,
int fd,
- int events,
+ int events G_GNUC_UNUSED,
void *opaque)
{
virLogHandlerPtr handler = opaque;
@@ -169,14 +169,13 @@ virLogHandlerDomainLogFileEvent(int watch,
virReportSystemError(errno, "%s",
_("Unable to read from log pipe"));
goto error;
+ } else if (len == 0) {
+ goto error;
}
if (virRotatingFileWriterAppend(logfile->file, buf, len) != len)
goto error;
- if (events & VIR_EVENT_HANDLE_HANGUP)
- goto error;
-
cleanup:
virObjectUnlock(handler);
return;
--
1.8.3.1
8:24 a.m.
New subject: [PATCH 3/3] logging: fix endless loop on EOF
On EOF condition we always have POLLHUP event and read returns
0 thus we never break loop in virLogHandlerDomainLogFileDrain.
Signed-off-by: Nikolay Shirokovskiy <nshirokovskiy(a)virtuozzo.com>
---
src/logging/log_handler.c | 2 ++
1 file changed, 2 insertions(+)
diff --git a/src/logging/log_handler.c b/src/logging/log_handler.c
index c04f341..152ca24 100644
--- a/src/logging/log_handler.c
+++ b/src/logging/log_handler.c
@@ -464,6 +464,8 @@ virLogHandlerDomainLogFileDrain(virLogHandlerLogFilePtr file)
if (errno == EINTR)
continue;
return;
+ } else if (len == 0) {
+ return;
}
if (virRotatingFileWriterAppend(file->file, buf, len) != len)
--
1.8.3.1
9:38 a.m.
New subject: [PATCH 3/3] logging: fix endless loop on EOF
On 9/24/20 3:24 PM, Nikolay Shirokovskiy wrote:
On EOF condition we always have POLLHUP event and read returns
0 thus we never break loop in virLogHandlerDomainLogFileDrain.
Signed-off-by: Nikolay Shirokovskiy <nshirokovskiy(a)virtuozzo.com>
---
src/logging/log_handler.c | 2 ++
1 file changed, 2 insertions(+)
diff --git a/src/logging/log_handler.c b/src/logging/log_handler.c
index c04f341..152ca24 100644
--- a/src/logging/log_handler.c
+++ b/src/logging/log_handler.c
@@ -464,6 +464,8 @@ virLogHandlerDomainLogFileDrain(virLogHandlerLogFilePtr file)
if (errno == EINTR)
continue;
return;
+ } else if (len == 0) {
Shouldn't we move "file->drained = true;" from above (not seen in the
context though) into this branch and possibly the "if (len < 0)" branch?
I mean, if we haven't read all the data the pipe is not drained, is it?
But let's do that in a separate patch anyway.
For 2/3 and 3/3:
Reviewed-by: Michal Privoznik <mprivozn(a)redhat.com>
Michal
10:17 a.m.
New subject: [PATCH 3/3] logging: fix endless loop on EOF
On 01.10.2020 17:38, Michal Prívozník wrote:
On 9/24/20 3:24 PM, Nikolay Shirokovskiy wrote:
> On EOF condition we always have POLLHUP event and read returns
> 0 thus we never break loop in virLogHandlerDomainLogFileDrain.
>
> Signed-off-by: Nikolay Shirokovskiy <nshirokovskiy(a)virtuozzo.com>
> ---
> src/logging/log_handler.c | 2 ++
> 1 file changed, 2 insertions(+)
>
> diff --git a/src/logging/log_handler.c b/src/logging/log_handler.c
> index c04f341..152ca24 100644
> --- a/src/logging/log_handler.c
> +++ b/src/logging/log_handler.c
> @@ -464,6 +464,8 @@ virLogHandlerDomainLogFileDrain(virLogHandlerLogFilePtr file)
> if (errno == EINTR)
> continue;
> return;
> + } else if (len == 0) {
Shouldn't we move "file->drained = true;" from above (not seen in the
context though) into this branch and possibly the "if (len < 0)" branch? I
mean, if we haven't read all the data the pipe is not drained, is it?
I guess current code is ok. May be we should name this flag another way. It is used to
handle race with event loop
thread polling pipe too [1]:
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.
So if we saw read poll event on pipe we need to set this flag. May we should name
it discardEvent or something.
[1]
commit cc9e80c59368478d179ee3eb7bf8106664c56870
Author: Daniel P. Berrangé <berrange(a)redhat.com>
Date: Fri Dec 14 12:57:37 2018 +0000
logging: ensure pending I/O is drained before reading position
Nikolay
1512
days inactive
1519
days old
5 comments
2 participants
participants (2)
-
Michal Prívozník -
Nikolay Shirokovskiy