[libvirt] [PATCH 0/3]: Better debug output from virExec/virRun

The following three patches add improved debug output for the virExec and virRun commands. The full argv is now logged, and virRun reads the command stdout and stderr for use in error reporting. Thanks, Cole

The attached patch moves the argvToString function from iptables.c to util.c for use in later patches. Thanks, Cole

On Thu, Oct 30, 2008 at 02:06:06PM -0400, Cole Robinson wrote:
The attached patch moves the argvToString function from iptables.c to util.c for use in later patches.
ACK 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 :|

The attached patch logs the the argv's passed to the virExec and virRun functions. There's a bit of trickery here: since virRun is just a wrapper for virExec, we don't want the argv string to be logged twice. I addressed this by renaming virExec to __virExec, and keeping the original function name to simply debug the argv and then hand off control. This means anytime virExec is explictly called, the argv will be logged, but if functions wish to by pass that they can just call __virExec (which is what virRun does.) Please let me know if there are any problems with that approach. Thanks, Cole

On Thu, Oct 30, 2008 at 02:06:20PM -0400, Cole Robinson wrote:
The attached patch logs the the argv's passed to the virExec and virRun functions. There's a bit of trickery here: since virRun is just a wrapper for virExec, we don't want the argv string to be logged twice.
I addressed this by renaming virExec to __virExec, and keeping the original function name to simply debug the argv and then hand off control. This means anytime virExec is explictly called, the argv will be logged, but if functions wish to by pass that they can just call __virExec (which is what virRun does.)
I'm a little confused about why we can't just put the logging calling directly in the existing virExec() function. Since the first thing virRun() does is to call virExec() this would seem to be sufficient without need of a wrapper. 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 :|

Daniel P. Berrange wrote:
On Thu, Oct 30, 2008 at 02:06:20PM -0400, Cole Robinson wrote:
The attached patch logs the the argv's passed to the virExec and virRun functions. There's a bit of trickery here: since virRun is just a wrapper for virExec, we don't want the argv string to be logged twice.
I addressed this by renaming virExec to __virExec, and keeping the original function name to simply debug the argv and then hand off control. This means anytime virExec is explictly called, the argv will be logged, but if functions wish to by pass that they can just call __virExec (which is what virRun does.)
I'm a little confused about why we can't just put the logging calling directly in the existing virExec() function. Since the first thing virRun() does is to call virExec() this would seem to be sufficient without need of a wrapper.
Daniel
Two small benefits of the way this patch does it: - We can tell by the debug output whether the argv is coming from virRun or from virExec called explicitly. - We want the argv string available in virRun for error reporting. The patch allows us to avoid converting the argv to string twice. I can rework the patch if you'd like, the above points aren't deal breakers. Thanks, Cole

On Mon, Nov 03, 2008 at 11:21:26AM -0500, Cole Robinson wrote:
Daniel P. Berrange wrote:
On Thu, Oct 30, 2008 at 02:06:20PM -0400, Cole Robinson wrote:
The attached patch logs the the argv's passed to the virExec and virRun functions. There's a bit of trickery here: since virRun is just a wrapper for virExec, we don't want the argv string to be logged twice.
I addressed this by renaming virExec to __virExec, and keeping the original function name to simply debug the argv and then hand off control. This means anytime virExec is explictly called, the argv will be logged, but if functions wish to by pass that they can just call __virExec (which is what virRun does.)
I'm a little confused about why we can't just put the logging calling directly in the existing virExec() function. Since the first thing virRun() does is to call virExec() this would seem to be sufficient without need of a wrapper.
Daniel
Two small benefits of the way this patch does it:
- We can tell by the debug output whether the argv is coming from virRun or from virExec called explicitly.
- We want the argv string available in virRun for error reporting. The patch allows us to avoid converting the argv to string twice.
I can rework the patch if you'd like, the above points aren't deal breakers.
Nah, I understand the purpose of your original approach now - ACK to the patch. 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 :|

The attached patch is my second cut at reading stdout and stderr of the command virRun kicks off. There is no hard limit to the amount of data we read now, and we use a poll loop to avoid any possible full buffer issues. If stdout or stderr had any content, we DEBUG it, and if the command appears to fail we return stderr in the error message. So now, trying to stop a logical pool with active volumes will return: $ sudo virsh pool-destroy vgdata libvir: error : internal error '/sbin/vgchange -an vgdata' exited with non-zero status 5 and signal 0: Can't deactivate volume group "vgdata" with 2 open logical volume(s) error: Failed to destroy pool vgdata Thanks, Cole

Cole Robinson <crobinso@redhat.com> wrote:
The attached patch is my second cut at reading stdout and stderr of the command virRun kicks off. There is no hard limit to the amount of data we read now, and we use a poll loop to avoid any possible full buffer issues.
If stdout or stderr had any content, we DEBUG it, and if the command appears to fail we return stderr in the error message. So now, trying to stop a logical pool with active volumes will return:
$ sudo virsh pool-destroy vgdata libvir: error : internal error '/sbin/vgchange -an vgdata' exited with non-zero status 5 and signal 0: Can't deactivate volume group "vgdata" with 2 open logical volume(s) error: Failed to destroy pool vgdata
Thanks, Cole
commit af7d94392bc89fd0645514cd13a2186ca5224dfc Author: Cole Robinson <crobinso@redhat.com> Date: Thu Oct 30 13:46:06 2008 -0400
Capture command stdout and stderr in virRun
diff --git a/src/util.c b/src/util.c index e59e25c..8d624b2 100644 --- a/src/util.c +++ b/src/util.c @@ -33,6 +33,9 @@ #include <errno.h> #include <sys/types.h> #include <sys/stat.h> +#if HAVE_SYS_POLL_H +#include <sys/poll.h> +#endif
Hi Cole, This looks fine to me. One minor suggestion: You can replace the above 3 lines with just #include <poll.h> <poll.h> is POSIX-specified, and guaranteed to be usable, since we're now using gnulib's "poll" module.

On Thu, Oct 30, 2008 at 02:06:35PM -0400, Cole Robinson wrote:
The attached patch is my second cut at reading stdout and stderr of the command virRun kicks off. There is no hard limit to the amount of data we read now, and we use a poll loop to avoid any possible full buffer issues.
If stdout or stderr had any content, we DEBUG it, and if the command appears to fail we return stderr in the error message. So now, trying to stop a logical pool with active volumes will return:
$ sudo virsh pool-destroy vgdata libvir: error : internal error '/sbin/vgchange -an vgdata' exited with non-zero status 5 and signal 0: Can't deactivate volume group "vgdata" with 2 open logical volume(s) error: Failed to destroy pool vgdata
+ fds[0].fd = outfd; + fds[0].events = POLLIN; + finished[0] = 0; + fds[1].fd = errfd; + fds[1].events = POLLIN; + finished[1] = 0; + + while(!(finished[0] && finished[1])) { + + if (poll(fds, ARRAY_CARDINALITY(fds), -1) < 0) { + if (errno == EAGAIN) + continue; + goto pollerr; + } + + for (i = 0; i < ARRAY_CARDINALITY(fds); ++i) { + char data[1024], **buf; + int got, size; + + if (!(fds[i].revents)) + continue; + else if (fds[i].revents & POLLHUP) + finished[i] = 1; + + if (!(fds[i].revents & POLLIN)) { + if (fds[i].revents & POLLHUP) + continue; + + ReportError(conn, VIR_ERR_INTERNAL_ERROR, + "%s", _("Unknown poll response.")); + goto error; + } + + got = read(fds[i].fd, data, sizeof(data)); + + if (got == 0) { + finished[i] = 1; + continue; + } + if (got < 0) { + if (errno == EINTR) + continue; + if (errno == EAGAIN) + break; + goto pollerr; + }
- while ((ret = waitpid(childpid, &exitstatus, 0) == -1) && errno == EINTR); - if (ret == -1) { + buf = ((fds[i].fd == outfd) ? &outbuf : &errbuf); + size = (*buf ? strlen(*buf) : 0); + if (VIR_REALLOC_N(*buf, size+got+1) < 0) { + ReportError(conn, VIR_ERR_NO_MEMORY, "%s", "realloc buf"); + goto error; + } + memmove(*buf+size, data, got); + (*buf)[size+got] = '\0'; + } + continue; + + pollerr: + ReportError(conn, VIR_ERR_INTERNAL_ERROR, + _("poll error: %s"), strerror(errno)); + goto error; + }
I think it'd be nice to move the I/O processing loop out of the virRun() function and into a separate helper functiion along the lines of virPipeReadUntilEOF(int outfd, int errfd, char **outbuf, char **errbuf) 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 :|

Daniel P. Berrange wrote:
On Thu, Oct 30, 2008 at 02:06:35PM -0400, Cole Robinson wrote:
The attached patch is my second cut at reading stdout and stderr of the command virRun kicks off. There is no hard limit to the amount of data we read now, and we use a poll loop to avoid any possible full buffer issues.
If stdout or stderr had any content, we DEBUG it, and if the command appears to fail we return stderr in the error message. So now, trying to stop a logical pool with active volumes will return:
$ sudo virsh pool-destroy vgdata libvir: error : internal error '/sbin/vgchange -an vgdata' exited with non-zero status 5 and signal 0: Can't deactivate volume group "vgdata" with 2 open logical volume(s) error: Failed to destroy pool vgdata
<snip>
I think it'd be nice to move the I/O processing loop out of the virRun() function and into a separate helper functiion along the lines of
virPipeReadUntilEOF(int outfd, int errfd, char **outbuf, char **errbuf)
Daniel
Okay, updated patch attached. Also addresses the point Jim raised about poll.h Thanks, Cole

On Mon, Nov 03, 2008 at 02:54:23PM -0500, Cole Robinson wrote:
Daniel P. Berrange wrote:
On Thu, Oct 30, 2008 at 02:06:35PM -0400, Cole Robinson wrote:
The attached patch is my second cut at reading stdout and stderr of the command virRun kicks off. There is no hard limit to the amount of data we read now, and we use a poll loop to avoid any possible full buffer issues.
If stdout or stderr had any content, we DEBUG it, and if the command appears to fail we return stderr in the error message. So now, trying to stop a logical pool with active volumes will return:
$ sudo virsh pool-destroy vgdata libvir: error : internal error '/sbin/vgchange -an vgdata' exited with non-zero status 5 and signal 0: Can't deactivate volume group "vgdata" with 2 open logical volume(s) error: Failed to destroy pool vgdata
<snip>
I think it'd be nice to move the I/O processing loop out of the virRun() function and into a separate helper functiion along the lines of
virPipeReadUntilEOF(int outfd, int errfd, char **outbuf, char **errbuf)
Daniel
Okay, updated patch attached. Also addresses the point Jim raised about poll.h
ACK, this version looks good to me. 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 :|

Daniel P. Berrange wrote:
On Mon, Nov 03, 2008 at 02:54:23PM -0500, Cole Robinson wrote:
Daniel P. Berrange wrote:
On Thu, Oct 30, 2008 at 02:06:35PM -0400, Cole Robinson wrote:
The attached patch is my second cut at reading stdout and stderr of the command virRun kicks off. There is no hard limit to the amount of data we read now, and we use a poll loop to avoid any possible full buffer issues.
If stdout or stderr had any content, we DEBUG it, and if the command appears to fail we return stderr in the error message. So now, trying to stop a logical pool with active volumes will return:
$ sudo virsh pool-destroy vgdata libvir: error : internal error '/sbin/vgchange -an vgdata' exited with non-zero status 5 and signal 0: Can't deactivate volume group "vgdata" with 2 open logical volume(s) error: Failed to destroy pool vgdata
<snip>
I think it'd be nice to move the I/O processing loop out of the virRun() function and into a separate helper functiion along the lines of
virPipeReadUntilEOF(int outfd, int errfd, char **outbuf, char **errbuf)
Daniel
Okay, updated patch attached. Also addresses the point Jim raised about poll.h
ACK, this version looks good to me.
Daniel
Thanks, I've committed the series. - Cole
participants (3)
-
Cole Robinson
-
Daniel P. Berrange
-
Jim Meyering