Bug#821778: autopkgtest: adt-run fails with QEMU - BrokenPipe

[Neil Williams]

Package: autopkgtest
Version: 3.20.4
Severity: normal

A QEMU VM which previously worked with autopkgtest is now failing
consistently with a testbed failure: cannot send to testbed, 
Broken Pipe.

adt-run /tmp/tmp.lXjW2N5fd3/lava-server_2016.4-1.dsc -U --- qemu adt-sid-2.raw
adt-run [09:21:08]: version 3.20.4
adt-run [09:21:08]: host sylvester; command line: /usr/bin/adt-run /tmp/tmp.lXjW2N5fd3/lava-server_2016.4-1.dsc -U --- qemu adt-sid-2.raw
warning: host doesn't support requested feature: CPUID.01H:ECX.vmx [bit 5]
qemu-system-x86_64: terminating on signal 15 from pid 20521
Unexpected error:
Traceback (most recent call last):
  File "/usr/share/autopkgtest/python/VirtSubproc.py", line 705, in mainloop
    command()
  File "/usr/share/autopkgtest/python/VirtSubproc.py", line 643, in command
    r = f(c, ce)
  File "/usr/share/autopkgtest/python/VirtSubproc.py", line 258, in cmd_open
    caller.hook_open()
  File "/usr/bin/adt-virt-qemu", line 567, in hook_open
    make_auxverb(shareddir)
  File "/usr/bin/adt-virt-qemu", line 413, in make_auxverb
    status = VirtSubproc.execute_timeout(None, 5, VirtSubproc.auxverb + ['true'])[0]
  File "/usr/share/autopkgtest/python/VirtSubproc.py", line 144, in execute_timeout
    (out, err) = sp.communicate(instr)
  File "/usr/lib/python3.5/subprocess.py", line 1057, in communicate
    self.wait()
  File "/usr/lib/python3.5/subprocess.py", line 1648, in wait
    (pid, sts) = self._try_wait(0)
  File "/usr/lib/python3.5/subprocess.py", line 1598, in _try_wait
    (pid, sts) = os.waitpid(self.pid, wait_flags)
  File "/usr/share/autopkgtest/python/VirtSubproc.py", line 64, in alarm_handler
    raise Timeout()
VirtSubproc.Timeout
adt-run [09:21:28]: ERROR: testbed failure: cannot send to testbed: ['BrokenPipeError: [Errno 32] Broken pipe\n']

I get the same traceback when using a freshly built QEMU qcow2 image:

sudo vmdebootstrap --verbose --serial-console --distribution=sid --convert-qcow2 --customize=/usr/share/autopkgtest/setup-commands/setup-testbed --user=adt/adt --size=10000000000 --grub --image=adt-sid-2.raw

Both images load fine with QEMU:

sudo qemu-system-x86_64 -enable-kvm -nographic -drive file=/home/neil/code/lava/packaging/alioth/adt-run-qemu/adt-sid.img,index=1

I've tried downgrading autopkgtest - down as far as the current package
in jessie - without success, so this may well be a change in one of the
dependencies causing autopkgtest to fail.

log file using -d option attached.

I was hoping to find the actual command line sent to qemu-system_x86_64
but I couldn't see that in the logs.

-- System Information:
Debian Release: stretch/sid
  APT prefers unstable
  APT policy: (500, 'unstable'), (500, 'testing'), (500, 'stable'), (1, 'experimental')
Architecture: amd64 (x86_64)
Foreign Architectures: i386, armhf, arm64

Kernel: Linux 4.4.0-1-amd64 (SMP w/4 CPU cores)
Locale: LANG=en_GB.utf8, LC_CTYPE=en_GB.utf8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages autopkgtest depends on:
ii  apt-utils       1.2.10
ii  libdpkg-perl    1.18.4
ii  procps          2:3.3.11-3
ii  python3         3.5.1-3
ii  python3-debian  0.1.27

Versions of packages autopkgtest recommends:
pn  autodep8  <none>

Versions of packages autopkgtest suggests:
ii  lxc          1:2.0.0-2
pn  lxd-client   <none>
pn  qemu-system  <none>
ii  qemu-utils   1:2.5+dfsg-5+b1
ii  schroot      1.6.10-2

-- no debconf information
-------------- next part --------------
adt-run: DBG: testbed init
adt-run [09:30:12]: version 3.20.4
adt-run [09:30:12]: host sylvester; command line: /usr/bin/adt-run -o logs -l adt.log -d /tmp/tmp.lXjW2N5fd3/lava-server_2016.4-1.dsc -U --- qemu adt-sid-2.raw
adt-run: DBG: got reply from testbed: ok
adt-run: DBG: testbed open, scratch=None
adt-run: DBG: sending command to testbed: open
warning: host doesn't support requested feature: CPUID.01H:ECX.vmx [bit 5]
qemu-system-x86_64: terminating on signal 15 from pid 21491
Unexpected error:
Traceback (most recent call last):
  File "/usr/share/autopkgtest/python/VirtSubproc.py", line 705, in mainloop
    command()
  File "/usr/share/autopkgtest/python/VirtSubproc.py", line 643, in command
    r = f(c, ce)
  File "/usr/share/autopkgtest/python/VirtSubproc.py", line 258, in cmd_open
    caller.hook_open()
  File "/usr/bin/adt-virt-qemu", line 567, in hook_open
    make_auxverb(shareddir)
  File "/usr/bin/adt-virt-qemu", line 413, in make_auxverb
    status = VirtSubproc.execute_timeout(None, 5, VirtSubproc.auxverb + ['true'])[0]
  File "/usr/share/autopkgtest/python/VirtSubproc.py", line 144, in execute_timeout
    (out, err) = sp.communicate(instr)
  File "/usr/lib/python3.5/subprocess.py", line 1057, in communicate
    self.wait()
  File "/usr/lib/python3.5/subprocess.py", line 1648, in wait
    (pid, sts) = self._try_wait(0)
  File "/usr/lib/python3.5/subprocess.py", line 1598, in _try_wait
    (pid, sts) = os.waitpid(self.pid, wait_flags)
  File "/usr/share/autopkgtest/python/VirtSubproc.py", line 64, in alarm_handler
    raise Timeout()
VirtSubproc.Timeout
adt-run: DBG: TestbedFailure unexpected eof from the testbed
adt-run: DBG: testbed stop
adt-run: DBG: testbed close, scratch=None
adt-run: DBG: sending command to testbed: quit
adt-run: DBG: TestbedFailure cannot send to testbed: ['BrokenPipeError: [Errno 32] Broken pipe\n']
adt-run: DBG: testbed stop
adt-run [09:30:31]: ERROR: testbed failure: cannot send to testbed: ['BrokenPipeError: [Errno 32] Broken pipe\n']
adt-run: DBG: testbed stop
-------------- next part --------------
{
  "virt_server": "adt-virt-qemu adt-sid-2.raw"
}