[libvirt] [PATCH 0/9] stream error reporting fixes
This series attempts to address various stream finish/abort error reporting issues: * Unclear error messages * virStreamAbort always returns an error * Spurious errors logged on the daemon side * Various issues in stream error cleanup (found through code inspection) Cole Robinson (9): fdstream: separate out virCommandPtr cleanup fdstream: Report error with virProcessTranslateStatus fdstream: Raise explicit error when iohelper gets SIGPIPE daemon: stream: Close stream on send failure daemon: stream: don't update events if stream->closed daemon: stream: set stream->closed on removal rpc: protocol: Clarify VIR_NET_ERROR usage with streams daemon: stream: Don't force error when client aborts fdstream: don't raise error on SIGPIPE if abort requested daemon/stream.c | 42 +++++++++++++++++------- src/fdstream.c | 84 ++++++++++++++++++++++++++++++------------------ src/rpc/virnetprotocol.x | 7 ++-- 3 files changed, 88 insertions(+), 45 deletions(-) -- 2.7.3
Let's us de-nest some of the logic, and will simplify upcoming patches --- src/fdstream.c | 73 +++++++++++++++++++++++++++++++++------------------------- 1 file changed, 42 insertions(+), 31 deletions(-) diff --git a/src/fdstream.c b/src/fdstream.c index a6a0fbe..681b90e 100644 --- a/src/fdstream.c +++ b/src/fdstream.c @@ -240,6 +240,46 @@ virFDStreamAddCallback(virStreamPtr st, return ret; } +static int +virFDStreamCloseCommand(struct virFDStreamData *fdst) +{ + char buf[1024]; + ssize_t len; + int status; + int ret = -1; + + if (!fdst->cmd) + return 0; + + if ((len = saferead(fdst->errfd, buf, sizeof(buf)-1)) < 0) + buf[0] = '\0'; + else + buf[len] = '\0'; + + virCommandRawStatus(fdst->cmd); + if (virCommandWait(fdst->cmd, &status) < 0) + goto error; + + if (status != 0) { + if (buf[0] != '\0') { + virReportError(VIR_ERR_INTERNAL_ERROR, "%s", buf); + } else if (WIFEXITED(status)) { + virReportError(VIR_ERR_INTERNAL_ERROR, + _("I/O helper exited with status %d"), + WEXITSTATUS(status)); + } else { + virReportError(VIR_ERR_INTERNAL_ERROR, "%s", + _("I/O helper exited abnormally")); + } + goto error; + } + + ret = 0; + error: + virCommandFree(fdst->cmd); + fdst->cmd = NULL; + return ret; +} static int virFDStreamCloseInt(virStreamPtr st, bool streamAbort) @@ -285,37 +325,8 @@ virFDStreamCloseInt(virStreamPtr st, bool streamAbort) /* mutex locked */ ret = VIR_CLOSE(fdst->fd); - if (fdst->cmd) { - char buf[1024]; - ssize_t len; - int status; - if ((len = saferead(fdst->errfd, buf, sizeof(buf)-1)) < 0) - buf[0] = '\0'; - else - buf[len] = '\0'; - - virCommandRawStatus(fdst->cmd); - if (virCommandWait(fdst->cmd, &status) < 0) { - ret = -1; - } else if (status != 0) { - if (buf[0] == '\0') { - if (WIFEXITED(status)) { - virReportError(VIR_ERR_INTERNAL_ERROR, - _("I/O helper exited with status %d"), - WEXITSTATUS(status)); - } else { - virReportError(VIR_ERR_INTERNAL_ERROR, "%s", - _("I/O helper exited abnormally")); - } - } else { - virReportError(VIR_ERR_INTERNAL_ERROR, "%s", - buf); - } - ret = -1; - } - virCommandFree(fdst->cmd); - fdst->cmd = NULL; - } + if (virFDStreamCloseCommand(fdst) < 0) + ret = -1; if (VIR_CLOSE(fdst->errfd) < 0) VIR_DEBUG("ignoring failed close on fd %d", fdst->errfd); -- 2.7.3
On 25.04.2016 20:46, Cole Robinson wrote:
Let's us de-nest some of the logic, and will simplify upcoming patches --- src/fdstream.c | 73 +++++++++++++++++++++++++++++++++------------------------- 1 file changed, 42 insertions(+), 31 deletions(-)
diff --git a/src/fdstream.c b/src/fdstream.c index a6a0fbe..681b90e 100644 --- a/src/fdstream.c +++ b/src/fdstream.c @@ -240,6 +240,46 @@ virFDStreamAddCallback(virStreamPtr st, return ret; }
+static int +virFDStreamCloseCommand(struct virFDStreamData *fdst) +{ + char buf[1024]; + ssize_t len; + int status; + int ret = -1; + + if (!fdst->cmd) + return 0; + + if ((len = saferead(fdst->errfd, buf, sizeof(buf)-1)) < 0) + buf[0] = '\0'; + else + buf[len] = '\0'; + + virCommandRawStatus(fdst->cmd); + if (virCommandWait(fdst->cmd, &status) < 0) + goto error; + + if (status != 0) { + if (buf[0] != '\0') { + virReportError(VIR_ERR_INTERNAL_ERROR, "%s", buf); + } else if (WIFEXITED(status)) { + virReportError(VIR_ERR_INTERNAL_ERROR, + _("I/O helper exited with status %d"), + WEXITSTATUS(status)); + } else { + virReportError(VIR_ERR_INTERNAL_ERROR, "%s", + _("I/O helper exited abnormally")); + } + goto error; + } + + ret = 0; + error:
Just a small nit, we tend to name 'cleanup' labels that are used in both successful and unsuccessful return paths. So this should be 'cleanup' to follow our style.
+ virCommandFree(fdst->cmd); + fdst->cmd = NULL; + return ret; +}
Michal
On 05/02/2016 04:48 AM, Michal Privoznik wrote:
On 25.04.2016 20:46, Cole Robinson wrote:
Let's us de-nest some of the logic, and will simplify upcoming patches --- src/fdstream.c | 73 +++++++++++++++++++++++++++++++++------------------------- 1 file changed, 42 insertions(+), 31 deletions(-)
diff --git a/src/fdstream.c b/src/fdstream.c index a6a0fbe..681b90e 100644 --- a/src/fdstream.c +++ b/src/fdstream.c @@ -240,6 +240,46 @@ virFDStreamAddCallback(virStreamPtr st, return ret; }
+static int +virFDStreamCloseCommand(struct virFDStreamData *fdst) +{ + char buf[1024]; + ssize_t len; + int status; + int ret = -1; + + if (!fdst->cmd) + return 0; + + if ((len = saferead(fdst->errfd, buf, sizeof(buf)-1)) < 0) + buf[0] = '\0'; + else + buf[len] = '\0'; + + virCommandRawStatus(fdst->cmd); + if (virCommandWait(fdst->cmd, &status) < 0) + goto error; + + if (status != 0) { + if (buf[0] != '\0') { + virReportError(VIR_ERR_INTERNAL_ERROR, "%s", buf); + } else if (WIFEXITED(status)) { + virReportError(VIR_ERR_INTERNAL_ERROR, + _("I/O helper exited with status %d"), + WEXITSTATUS(status)); + } else { + virReportError(VIR_ERR_INTERNAL_ERROR, "%s", + _("I/O helper exited abnormally")); + } + goto error; + } + + ret = 0; + error:
Just a small nit, we tend to name 'cleanup' labels that are used in both successful and unsuccessful return paths. So this should be 'cleanup' to follow our style.
Thanks for the review. I fixed this and pushed the series now - Cole
Rather than poorly duplicate it --- src/fdstream.c | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/src/fdstream.c b/src/fdstream.c index 681b90e..b0a46e9 100644 --- a/src/fdstream.c +++ b/src/fdstream.c @@ -43,6 +43,7 @@ #include "configmake.h" #include "virstring.h" #include "virtime.h" +#include "virprocess.h" #define VIR_FROM_THIS VIR_FROM_STREAMS @@ -263,13 +264,12 @@ virFDStreamCloseCommand(struct virFDStreamData *fdst) if (status != 0) { if (buf[0] != '\0') { virReportError(VIR_ERR_INTERNAL_ERROR, "%s", buf); - } else if (WIFEXITED(status)) { - virReportError(VIR_ERR_INTERNAL_ERROR, - _("I/O helper exited with status %d"), - WEXITSTATUS(status)); } else { - virReportError(VIR_ERR_INTERNAL_ERROR, "%s", - _("I/O helper exited abnormally")); + char *str = virProcessTranslateStatus(status); + virReportError(VIR_ERR_INTERNAL_ERROR, + _("I/O helper exited with %s"), + NULLSTR(str)); + VIR_FREE(str); } goto error; } -- 2.7.3
This happens when virStreamFinish/Abort are called, but iohelper still has data to process. --- src/fdstream.c | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/fdstream.c b/src/fdstream.c index b0a46e9..155311a 100644 --- a/src/fdstream.c +++ b/src/fdstream.c @@ -264,6 +264,10 @@ virFDStreamCloseCommand(struct virFDStreamData *fdst) if (status != 0) { if (buf[0] != '\0') { virReportError(VIR_ERR_INTERNAL_ERROR, "%s", buf); + } else if (WIFSIGNALED(status) && WTERMSIG(status) == SIGPIPE) { + virReportError(VIR_ERR_INTERNAL_ERROR, "%s", + _("I/O helper exited " + "before all data was processed")); } else { char *str = virProcessTranslateStatus(status); virReportError(VIR_ERR_INTERNAL_ERROR, -- 2.7.3
This is the only place in daemon/stream.c that sets 'stream->closed = true' but neglects to actually abort the stream and remove the callback, which seems wrong. --- daemon/stream.c | 3 +++ 1 file changed, 3 insertions(+) diff --git a/daemon/stream.c b/daemon/stream.c index c892dcb..f072a17 100644 --- a/daemon/stream.c +++ b/daemon/stream.c @@ -539,6 +539,9 @@ daemonStreamHandleWriteData(virNetServerClientPtr client, VIR_INFO("Stream send failed"); stream->closed = true; + virStreamEventRemoveCallback(stream->st); + virStreamAbort(stream->st); + return virNetServerProgramSendReplyError(stream->prog, client, msg, -- 2.7.3
On 25.04.2016 20:46, Cole Robinson wrote:
This is the only place in daemon/stream.c that sets 'stream->closed = true' but neglects to actually abort the stream and remove the callback, which seems wrong. --- daemon/stream.c | 3 +++ 1 file changed, 3 insertions(+)
diff --git a/daemon/stream.c b/daemon/stream.c index c892dcb..f072a17 100644 --- a/daemon/stream.c +++ b/daemon/stream.c @@ -539,6 +539,9 @@ daemonStreamHandleWriteData(virNetServerClientPtr client,
VIR_INFO("Stream send failed"); stream->closed = true; + virStreamEventRemoveCallback(stream->st); + virStreamAbort(stream->st); + return virNetServerProgramSendReplyError(stream->prog, client, msg,
Correct. Once we set stream->closed, pretty much no other callback are called. Michal
Calling virStreamFinish prematurely seems to trigger this code path even after the stream is closed, which ends up hitting this error message later: error : virFDStreamUpdateCallback:127 : internal error: stream is not open Skip this function if stream->closed, which is used in many other places like read/write handlers --- daemon/stream.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/daemon/stream.c b/daemon/stream.c index f072a17..8a97260 100644 --- a/daemon/stream.c +++ b/daemon/stream.c @@ -76,6 +76,8 @@ static void daemonStreamUpdateEvents(daemonClientStream *stream) { int newEvents = 0; + if (stream->closed) + return; if (stream->rx) newEvents |= VIR_STREAM_EVENT_WRITABLE; if (stream->tx && !stream->recvEOF) -- 2.7.3
These are the only places where we don't set stream->closed when aborting the stream. This leads to spurious errors when the client hangs up unexpectedly: error : virFDStreamUpdateCallback:127 : internal error: stream is not open --- daemon/stream.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/daemon/stream.c b/daemon/stream.c index 8a97260..fcec3d0 100644 --- a/daemon/stream.c +++ b/daemon/stream.c @@ -463,6 +463,7 @@ daemonRemoveClientStream(virNetServerClientPtr client, } if (!stream->closed) { + stream->closed = true; virStreamEventRemoveCallback(stream->st); virStreamAbort(stream->st); } @@ -493,6 +494,7 @@ daemonRemoveAllClientStreams(daemonClientStream *stream) tmp = stream->next; if (!stream->closed) { + stream->closed = true; virStreamEventRemoveCallback(stream->st); virStreamAbort(stream->st); } -- 2.7.3
The described protocol semantics really only apply to server initiated stream messages. Document the semantics for client messages. --- src/rpc/virnetprotocol.x | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/src/rpc/virnetprotocol.x b/src/rpc/virnetprotocol.x index 327a334..9ce33b0 100644 --- a/src/rpc/virnetprotocol.x +++ b/src/rpc/virnetprotocol.x @@ -104,7 +104,9 @@ const VIR_NET_MESSAGE_NUM_FDS_MAX = 32; * - type == VIR_NET_STREAM * * VIR_NET_CONTINUE if more data is following * * VIR_NET_OK if stream is complete - * * VIR_NET_ERROR if stream had an error + * * VIR_NET_ERROR + * server message: stream had an error + * client message: client aborted the stream * * Payload varies according to type and status: * @@ -125,7 +127,8 @@ const VIR_NET_MESSAGE_NUM_FDS_MAX = 32; * * status == VIR_NET_CONTINUE * byte[] raw stream data * * status == VIR_NET_ERROR - * remote_error error information + * server message: remote_error error information + * client message: <empty> * * status == VIR_NET_OK * <empty> * -- 2.7.3
Every time a client aborts a stream via the virStreamAbort API, the daemon always logs an error like: error : daemonStreamHandleAbort:617 : stream aborted at client request and that same error is returned to the client. Meaning virStreamAbort always returns -1, which seems strange. This reworks the error handling to only raise an error on virStreamAbort if the actual server side abort call raises an error. This is similar to how virStreamFinish works. If the abort code path is triggered by an unexpected message type then we continue to raise an unconditional error. Also drop a redundant VIR_WARN call there, since virReportError will raise a VIR_ERROR anyways --- daemon/stream.c | 35 +++++++++++++++++++++++------------ 1 file changed, 23 insertions(+), 12 deletions(-) diff --git a/daemon/stream.c b/daemon/stream.c index fcec3d0..bd0b5d2 100644 --- a/daemon/stream.c +++ b/daemon/stream.c @@ -611,29 +611,40 @@ daemonStreamHandleAbort(virNetServerClientPtr client, { VIR_DEBUG("client=%p, stream=%p, proc=%d, serial=%u", client, stream, msg->header.proc, msg->header.serial); - virNetMessageError rerr; - - memset(&rerr, 0, sizeof(rerr)); + int ret; + bool raise_error = false; stream->closed = true; virStreamEventRemoveCallback(stream->st); - virStreamAbort(stream->st); + ret = virStreamAbort(stream->st); if (msg->header.status == VIR_NET_ERROR) { - virReportError(VIR_ERR_RPC, - "%s", _("stream aborted at client request")); + VIR_INFO("stream aborted at client request"); + raise_error = (ret < 0); } else { - VIR_WARN("unexpected stream status %d", msg->header.status); virReportError(VIR_ERR_RPC, _("stream aborted with unexpected status %d"), msg->header.status); + raise_error = true; } - return virNetServerProgramSendReplyError(remoteProgram, - client, - msg, - &rerr, - &msg->header); + if (raise_error) { + virNetMessageError rerr; + memset(&rerr, 0, sizeof(rerr)); + return virNetServerProgramSendReplyError(remoteProgram, + client, + msg, + &rerr, + &msg->header); + } else { + /* Send zero-length confirm */ + return virNetServerProgramSendStreamData(stream->prog, + client, + msg, + stream->procedure, + stream->serial, + NULL, 0); + } } -- 2.7.3
The iohelper dies on SIGPIPE if the stream is closed before all data is processed. IMO this should be an error condition for virStreamFinish according to docs like: * This method is a synchronization point for all asynchronous * errors, so if this returns a success code the application can * be sure that all data has been successfully processed. However for virStreamAbort, not so much: * Request that the in progress data transfer be cancelled * abnormally before the end of the stream has been reached. * For output streams this can be used to inform the driver * that the stream is being terminated early. For input * streams this can be used to inform the driver that it * should stop sending data. Without this, virStreamAbort will realistically always error for active streams like domain console. So, treat the SIGPIPE case as non-fatal if abort is requested. Note, this will only affect an explicit user requested abort. An abnormal abort, like from a server error, always raises an error in the daemon. --- src/fdstream.c | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/src/fdstream.c b/src/fdstream.c index 155311a..f22107c 100644 --- a/src/fdstream.c +++ b/src/fdstream.c @@ -242,7 +242,7 @@ virFDStreamAddCallback(virStreamPtr st, } static int -virFDStreamCloseCommand(struct virFDStreamData *fdst) +virFDStreamCloseCommand(struct virFDStreamData *fdst, bool streamAbort) { char buf[1024]; ssize_t len; @@ -265,6 +265,12 @@ virFDStreamCloseCommand(struct virFDStreamData *fdst) if (buf[0] != '\0') { virReportError(VIR_ERR_INTERNAL_ERROR, "%s", buf); } else if (WIFSIGNALED(status) && WTERMSIG(status) == SIGPIPE) { + if (streamAbort) { + /* Explicit abort request means the caller doesn't care + if there's data left over, so skip the error */ + goto out; + } + virReportError(VIR_ERR_INTERNAL_ERROR, "%s", _("I/O helper exited " "before all data was processed")); @@ -278,6 +284,7 @@ virFDStreamCloseCommand(struct virFDStreamData *fdst) goto error; } + out: ret = 0; error: virCommandFree(fdst->cmd); @@ -329,7 +336,7 @@ virFDStreamCloseInt(virStreamPtr st, bool streamAbort) /* mutex locked */ ret = VIR_CLOSE(fdst->fd); - if (virFDStreamCloseCommand(fdst) < 0) + if (virFDStreamCloseCommand(fdst, streamAbort) < 0) ret = -1; if (VIR_CLOSE(fdst->errfd) < 0) -- 2.7.3
On 25.04.2016 20:46, Cole Robinson wrote:
This series attempts to address various stream finish/abort error reporting issues:
* Unclear error messages * virStreamAbort always returns an error * Spurious errors logged on the daemon side * Various issues in stream error cleanup (found through code inspection)
Cole Robinson (9): fdstream: separate out virCommandPtr cleanup fdstream: Report error with virProcessTranslateStatus fdstream: Raise explicit error when iohelper gets SIGPIPE daemon: stream: Close stream on send failure daemon: stream: don't update events if stream->closed daemon: stream: set stream->closed on removal rpc: protocol: Clarify VIR_NET_ERROR usage with streams daemon: stream: Don't force error when client aborts fdstream: don't raise error on SIGPIPE if abort requested
daemon/stream.c | 42 +++++++++++++++++------- src/fdstream.c | 84 ++++++++++++++++++++++++++++++------------------ src/rpc/virnetprotocol.x | 7 ++-- 3 files changed, 88 insertions(+), 45 deletions(-)
ACK series Michal
participants (2)
-
Cole Robinson -
Michal Privoznik