Skip to content

Draft: show VirtSubproc output in real-time

Currently, the virt subprocess output is only shown at the end, either after it times out, or it succeeds. This is both very inconvenient for developing and debugging those subprocesses, but also very confusing for users of the autopkgtest logs that usually end up with:

  • those logs at the very end
  • without even a prefix
  • scrambling the useful summary output
  • having the wrong timestamp

See an example (look at the bottom, the nova logs).

This MR proposes one approach to fix the issue, but opens a few questions:

  • Why not avoid redirecting the stream in the first place?
    • That would just mean removing the stdout=subprocess.PIPE and stderr=subprocess.PIPE lines.
    • I couldn't find a satisfying explanation as to why redirect the stdout stream. The redirection was introduced in 76c7eab4 and 759c998e for virt-ssh. Didn't check the others.
    • The redirection of stderr was introduced in a93602a9, for LP #1630578, along with a few other changes. I'm not sure why they would need subprocess.PIPE back in the time, as they obviously wanted to print stderr anyway directly after the return of the command. In short, this commit just introduced the issue we currently have, which is making the output of the virt server not synchronous with autopkgtest.
    • I guess one intent was to be able to react to some particular messages from the virt server, but that doesn't seem to be really done in autopkgtest, apart from the nicer printing of sudo failed with stderr: case.
    • One advantage of capturing the buffers is to print them with some prefix, to clarify where these lines are coming from. Also, keeping the possibility of printing them in a bomb() seems nice to ease the debugging of some cases where autopkgtest is aware of a particular issue of the virt server.
    • In the end, I'm not particularly in favor of any solution. Capturing with PIPE and printing in the loop as this MR does seems fine, but I don't mind removing that mechanism and just stop PIPEing stderr, albeit this would break some nice error printing like for the sudo case.
  • Do we want to also handle the virt subprocess stdout in the same way, with a buf_stdout variable?
    • Likely not, as according to @paride it might be used as a mean of communication with the virt server.
  • I've seen no other occurrence of adtlog.log called directly, but I still feel this would be the most appropriate. Any opinions on this?
    • I've already changed to use sys.stderr.write() directly and avoid the \n mess. It's easy to roll back if needed.
  • I've only tested that with -- ssh -s nova, a bit like on Ubuntu's infrastructure. I bet a few other changes would be required in some other virt servers to avoid duplicating their output. Still, I want to validate the approach before spending more time on this.

To test that easily, here is what I do:

  1. Add the following at the top of the open() function in ssh-setup/nova (already done in a "REMOVE ME" commit in this MR):
    for i in $(seq 0 5); do
        warning "Hello there #$i"
        error "General Kenobi! #$i"
        sleep 2
    done
    exit 1
  1. Run autopkgtest with the following: ./runner/autopkgtest gzip -- ssh -s ./ssh-setup/nova -- --flavor dumb_flavor --security-groups dumb_sec_group --name dumb_server_name --image dumb_image --keyname dumb_keyname --net-id=dumb_net
Edited by Florent 'Skia' Jacquet

Merge request reports

Loading