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
andstderr=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 needsubprocess.PIPE
back in the time, as they obviously wanted to printstderr
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 stopPIPE
ing stderr, albeit this would break some nice error printing like for thesudo
case.
- That would just mean removing the
- Do we want to also handle the virt subprocess
stdout
in the same way, with abuf_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 ofadtlog.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 already changed to use
- 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:
- Add the following at the top of the
open()
function inssh-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
- 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