[PATCH 0/3] logging: fix a couple of issues
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
--- 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
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@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
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@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
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@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@redhat.com> Michal
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@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@redhat.com> Date: Fri Dec 14 12:57:37 2018 +0000 logging: ensure pending I/O is drained before reading position Nikolay
participants (2)
-
Michal Prívozník -
Nikolay Shirokovskiy