Re: [PATCH 1/4] tests/vm: write raw console log

["Alex Bennée" <alex.bennee@linaro.org>]

Cleber Rosa <crosa@redhat.com> writes:

> On Mon, Mar 16, 2020 at 03:22:07PM +0100, Philippe Mathieu-Daudé wrote:
>> On 3/16/20 3:16 PM, Alex Bennée wrote:
>> > 
>> > Gerd Hoffmann <kraxel@redhat.com> writes:
>> > 
>> > > Run "tail -f /var/tmp/*/qemu*console.raw" in another terminal
>> > > to watch the install console.
>> > > 
>> > > Signed-off-by: Gerd Hoffmann <kraxel@redhat.com>
>> > 
>> > I suspect this is what's breaking "make check-acceptance" so I've
>> > dropped the series from testing/next for now.
>> >
>> >    2020-03-11 12:12:30,546 stacktrace       L0039 ERROR|
>> >    2020-03-11 12:12:30,546 stacktrace       L0042 ERROR| Reproduced traceback from: /home/alex.bennee/lsrc/qemu.git/builds/all/tests/venv/lib/python3.6/site-packages/avocado/c\
>> >    ore/test.py:860
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR| Traceback (most recent call last):
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|   File "/home/alex.bennee/lsrc/qemu.git/builds/all/tests/venv/lib/python3.6/site-packages/avocado/core/test.py", line \
>> >    1456, in test
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|     self.error(self.exception)
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|   File "/home/alex.bennee/lsrc/qemu.git/builds/all/tests/venv/lib/python3.6/site-packages/avocado/core/test.py", line \
>> >    1064, in error
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|     raise exceptions.TestError(message)
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR| avocado.core.exceptions.TestError: Traceback (most recent call last):
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|   File "/usr/lib/python3.6/imp.py", line 235, in load_module
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|     return load_source(name, filename, file)
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|   File "/usr/lib/python3.6/imp.py", line 172, in load_source
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|     module = _load(spec)
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|   File "<frozen importlib._bootstrap>", line 684, in _load
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|   File "<frozen importlib._bootstrap>", line 665, in _load_unlocked
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|   File "<frozen importlib._bootstrap_external>", line 678, in exec_module
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|   File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|   File "/home/alex.bennee/lsrc/qemu.git/builds/all/tests/acceptance/machine_mips_malta.py", line 15, in <module>
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|     from avocado_qemu import Test
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|   File "/home/alex.bennee/lsrc/qemu.git/builds/all/tests/acceptance/avocado_qemu/__init__.py", line 22, in <module>
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|     from qemu.machine import QEMUMachine
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|   File "/home/alex.bennee/lsrc/qemu.git/builds/all/tests/acceptance/avocado_qemu/../../../python/qemu/machine.py", lin\
>> >    e 27, in <module>
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|     from qemu.console_socket import ConsoleSocket
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR| ModuleNotFoundError: No module named 'qemu.console_socket'
>> 
>> Cc'ing Wainer/Cleber in case...
>>
>
> I've applied the "[PATCH v4 00/10] tests/vm: Add support for aarch64
> VMs" series and this patch (on top of d649689a8) and could not
> replicate this issue with "make check-acceptance".
>
> Maybe I'm missing some other patch?
>
> - Cleber.
>
>> >    2020-03-11 12:12:30,547 stacktrace       L0045 ERROR|
>> >    2020-03-11 12:12:30,547 stacktrace       L0046 ERROR|
>> >    2020-03-11 12:12:30,548 test             L0865 DEBUG| Local variables:
>> >    2020-03-11 12:12:30,561 test             L0868 DEBUG|  -> self <class 'avocado.core.test.TestError'>: 1-./tests/acceptance/machine_mips_malta.py:MaltaMachineFramebuffer.tes\
>> >    t_mips_malta_i6400_framebuffer_logo_1core
>> > 
>> > 
>> > > ---
>> > >   tests/vm/basevm.py | 6 ++++++
>> > >   1 file changed, 6 insertions(+)
>> > > 
>> > > diff --git a/tests/vm/basevm.py b/tests/vm/basevm.py
>> > > index 8400b0e07f65..c53fd354d955 100644
>> > > --- a/tests/vm/basevm.py
>> > > +++ b/tests/vm/basevm.py
>> > > @@ -213,6 +213,9 @@ class BaseVM(object):
>> > >       def console_init(self, timeout = 120):
>> > >           vm = self._guest
>> > >           vm.console_socket.settimeout(timeout)
>> > > +        self.console_raw_path = os.path.join(vm._temp_dir,
>> > > +                                             vm._name + "-console.raw")
>> > > +        self.console_raw_file = open(self.console_raw_path, 'wb')
>> > >       def console_log(self, text):
>> > >           for line in re.split("[\r\n]", text):
>> > > @@ -234,6 +237,9 @@ class BaseVM(object):
>> > >           while True:
>> > >               try:
>> > >                   chars = vm.console_socket.recv(1)
>> > > +                if self.console_raw_file:
>> > > +                    self.console_raw_file.write(chars)
>> > > +                    self.console_raw_file.flush()
>> > >               except socket.timeout:
>> > >                   sys.stderr.write("console: *** read timeout ***\n")
>> > >                   sys.stderr.write("console: waiting for: '%s'\n" % expect)

Apologies - it looks like I got misled although I hope you'll forgive me
because it wasn't clear from the backtrace. I've re-based and bisected
and it turned out to be broken by:

  tests/acceptance: skip the mips_malta -smp tests on Travis

  These could potentially be MTTCG failures which are exacerbated by the
  reduced number of cores on Travis. Additionally the 1 core test
  started failing while I was re-basing the series. However the error
  message is inconsistent on the various systems I run on.

  Signed-off-by: Alex Bennée <alex.bennee@linaro.org>

  1 file changed, 6 insertions(+)
  tests/acceptance/machine_mips_malta.py | 6 ++++++

  modified   tests/acceptance/machine_mips_malta.py
  @@ -91,6 +91,8 @@ class MaltaMachineFramebuffer(Test):
               cv2.imwrite(debug_png, screendump_bgr)
           self.assertGreaterEqual(tuxlogo_count, cpu_cores_count)

  +    # FIXME: this seems to be failing due to some sort of import error
  +    @skipIf(os.getenv('CONTINUOUS_INTEGRATION'), 'Running on Travis-CI')
       def test_mips_malta_i6400_framebuffer_logo_1core(self):
           """
           :avocado: tags=arch:mips64el
  @@ -99,6 +101,9 @@ class MaltaMachineFramebuffer(Test):
           """
           self.do_test_i6400_framebuffer_logo(1)

  +    # FIXME: There seems to be an MTTCG related bug that shows up more
  +    # on Travis due to the ease of hitting a race with less cores.
  +    @skipIf(os.getenv('CONTINUOUS_INTEGRATION'), 'Running on Travis-CI')
       def test_mips_malta_i6400_framebuffer_logo_7cores(self):
           """
           :avocado: tags=arch:mips64el
  @@ -108,6 +113,7 @@ class MaltaMachineFramebuffer(Test):
           """
           self.do_test_i6400_framebuffer_logo(7)

  +    @skipIf(os.getenv('CONTINUOUS_INTEGRATION'), 'Running on Travis-CI')
       def test_mips_malta_i6400_framebuffer_logo_8cores(self):
           """
           :avocado: tags=arch:mips64el

Which I had earlier in the patch series as it was failing on Travis.
I'll trigger another Travis run and see if I can drop them.

-- 
Alex Bennée