[libvirt] [PATCH] Log virRun command output, return with error

The attached patch adds some extra logging to the virRun command. The full argv is now logged with DEBUG, as well as the commands stdout and stderr (if anything is found). Also, if the command returns an error, we raise the stderr content with the reported error msg. This will significantly help with debugging certain issues, particularly with the storage driver which makes heavy use of virRun. Thanks, Cole

Cole Robinson wrote:
The attached patch adds some extra logging to the virRun command. The full argv is now logged with DEBUG, as well as the commands stdout and stderr (if anything is found).
Also, if the command returns an error, we raise the stderr content with the reported error msg. This will significantly help with debugging certain issues, particularly with the storage driver which makes heavy use of virRun.
I think the idea is great. I'm a little worried about the implementation, though.
--- a/src/util.c +++ b/src/util.c @@ -54,6 +54,9 @@ #include "memory.h" #include "util-lib.c"
+#define DEBUG(fmt,...) VIR_DEBUG(__FILE__, fmt, __VA_ARGS__) +#define DEBUG0(msg) VIR_DEBUG(__FILE__, "%s", msg)
Leftover cruft, it looks like. It's not used anywhere, and you can just use DEBUG() for the same thing.
+ #ifndef NSIG # define NSIG 32 #endif @@ -404,10 +407,19 @@ int virRun(virConnectPtr conn, const char *const*argv, int *status) { - int childpid, exitstatus, ret; + int childpid, exitstatus, ret, i; + int errfd = -1, outfd = -1; + char out[256] = "\0", err[256] = "\0", cmd[512] = "\0";; + + /* Log argv */ + for (i = 0; argv[i] != NULL; ++i) { + strncat(cmd, " ", sizeof(cmd) - strlen(cmd) - 1); + strncat(cmd, argv[i], sizeof(cmd) - strlen(cmd) - 1); + }
What happens if you have enough arguments that you overrun 512 bytes in the cmd array? I guess the sizeof(cmd) - strlen(cmd) - 1 will protect you from running off the end of the buffer, but you'll truncate the output. There are some examples elsewhere in the code (src/qemu_conf.c, I think) that properly build up the whole thing; it's probably worthwhile to look there.
+ DEBUG("Running command '%s'", cmd);
if ((ret = virExec(conn, argv, NULL, NULL, - &childpid, -1, NULL, NULL, VIR_EXEC_NONE)) < 0) + &childpid, -1, &outfd, &errfd, VIR_EXEC_NONE)) < 0) return ret;
while ((ret = waitpid(childpid, &exitstatus, 0) == -1) && errno == EINTR); @@ -418,16 +430,31 @@ virRun(virConnectPtr conn, return -1; }
+ /* Log command output */ + if (outfd) { + ret = saferead(outfd, out, sizeof(out)-1); + err[ret < 0 ? 0 : ret] = '\0'; + if (*out) + DEBUG("Command stdout: %s", out);
Don't you also want to close(outfd) here?
+ } + if (errfd) { + ret = saferead(errfd, err, sizeof(err)-1); + err[ret < 0 ? 0 : ret] = '\0'; + if (*err) + DEBUG("Command stderr: %s", err);
Ditto for errfd. Chris Lalancette

On Tue, Sep 23, 2008 at 04:56:45PM -0400, Cole Robinson wrote:
if ((ret = virExec(conn, argv, NULL, NULL, - &childpid, -1, NULL, NULL, VIR_EXEC_NONE)) < 0) + &childpid, -1, &outfd, &errfd, VIR_EXEC_NONE)) < 0) return ret;
while ((ret = waitpid(childpid, &exitstatus, 0) == -1) && errno == EINTR); @@ -418,16 +430,31 @@ virRun(virConnectPtr conn, return -1; }
+ /* Log command output */ + if (outfd) { + ret = saferead(outfd, out, sizeof(out)-1); + err[ret < 0 ? 0 : ret] = '\0'; + if (*out) + DEBUG("Command stdout: %s", out); + } + if (errfd) { + ret = saferead(errfd, err, sizeof(err)-1); + err[ret < 0 ? 0 : ret] = '\0'; + if (*err) + DEBUG("Command stderr: %s", err); + } +
I'm sure this works in tests, but I don't think it'll work reliably all the time. What happens if the command pauses for some time before sending output to stdout/stderr? You need to integrate these in the event loop, which is going to make everything a lot more complicated. Rich. -- Richard Jones, Emerging Technologies, Red Hat http://et.redhat.com/~rjones virt-top is 'top' for virtual machines. Tiny program with many powerful monitoring features, net stats, disk stats, logging, etc. http://et.redhat.com/~rjones/virt-top

On Wed, Sep 24, 2008 at 12:24:18PM +0100, Richard W.M. Jones wrote:
On Tue, Sep 23, 2008 at 04:56:45PM -0400, Cole Robinson wrote:
if ((ret = virExec(conn, argv, NULL, NULL, - &childpid, -1, NULL, NULL, VIR_EXEC_NONE)) < 0) + &childpid, -1, &outfd, &errfd, VIR_EXEC_NONE)) < 0) return ret;
while ((ret = waitpid(childpid, &exitstatus, 0) == -1) && errno == EINTR); @@ -418,16 +430,31 @@ virRun(virConnectPtr conn, return -1; }
+ /* Log command output */ + if (outfd) { + ret = saferead(outfd, out, sizeof(out)-1); + err[ret < 0 ? 0 : ret] = '\0'; + if (*out) + DEBUG("Command stdout: %s", out); + } + if (errfd) { + ret = saferead(errfd, err, sizeof(err)-1); + err[ret < 0 ? 0 : ret] = '\0'; + if (*err) + DEBUG("Command stderr: %s", err); + } +
I'm sure this works in tests, but I don't think it'll work reliably all the time.
What happens if the command pauses for some time before sending output to stdout/stderr? You need to integrate these in the event loop, which is going to make everything a lot more complicated.
The virRun command is synchronous so its blocking the caller no matter what. We do however need to process more than justa fixed size buffer, and in doing so you can't rely on reading all of stdout, followed by all or stderr. You need to read which has data sent to it as it happens otherwise the process could block on a full pipe for stderr(), while you're waiting for end-of-file on stdout. So we do need to call poll() here to determine which FD has more data available. Don't need a full event loop though. Daniel -- |: Red Hat, Engineering, London -o- http://people.redhat.com/berrange/ :| |: http://libvirt.org -o- http://virt-manager.org -o- http://ovirt.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: GnuPG: 7D3B9505 -o- F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 :|
participants (4)
-
Chris Lalancette
-
Cole Robinson
-
Daniel P. Berrange
-
Richard W.M. Jones