Re: [Qemu-devel] [PULL 6/6] travis: Make check-acceptance job more verbose

[Cleber Rosa <crosa@redhat.com>]

On Wed, Jun 12, 2019 at 10:49:18PM +0200, Philippe Mathieu-Daudé wrote:
> On 6/11/19 7:14 PM, Eduardo Habkost wrote:
> > It will help us debug issues when tests fail.
> > 
> > Signed-off-by: Eduardo Habkost <ehabkost@redhat.com>
> > ---
> >  .travis.yml | 2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> > 
> > diff --git a/.travis.yml b/.travis.yml
> > index b053a836a3..a08a7b7278 100644
> > --- a/.travis.yml
> > +++ b/.travis.yml
> > @@ -225,7 +225,7 @@ matrix:
> >      # Acceptance (Functional) tests
> >      - env:
> >          - CONFIG="--python=/usr/bin/python3 --target-list=x86_64-softmmu,mips-softmmu,mips64el-softmmu,aarch64-softmmu,arm-softmmu,s390x-softmmu,alpha-softmmu"
> > -        - TEST_CMD="make check-acceptance"
> > +        - TEST_CMD="make AVOCADO_SHOW=test check-acceptance"
> >        addons:
> >          apt:
> >            packages:
> > 
> 
> Cleber, can you help figuring what's wrong here?
> 
> https://travis-ci.org/qemu/qemu/jobs/544805900
> 
> The tests seems successfull, is it possible the verbose logging returns
> error to the shell even if the test succeed?
>

There's some confusion here... To the best of my knowledge this failure is
not associated with Eduardo's change of the of the AVOCADO_SHOW variable.
This seems to be we hitting this:

  https://bugs.launchpad.net/qemu/+bug/1829779

Which was also discussed in other threads, such as:

  https://lists.gnu.org/archive/html/qemu-devel/2019-06/msg01254.html

We have identified two ways to work around this, and about two days
ago Eduardo and myself settled on one of them.  I'll send a patch in
a few.

> INIT
> 05-/home/travis/build/qemu/qemu/tests/acceptance/boot_linux_console.py:BootLinuxConsole.test_aarch64_virt
> PARAMS (key=timeout, path=*, default=90) => 90
> Test metadata:
>   filename:
> /home/travis/build/qemu/qemu/tests/acceptance/boot_linux_console.py
>   teststmpdir: /tmp/avocado_6tk1s4nz
>   workdir:
> /tmp/avocado_ifg2df04/avocado_job_zqdrt4ht/05-_home_travis_build_qemu_qemu_tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_aarch64_virt
> START
> 05-/home/travis/build/qemu/qemu/tests/acceptance/boot_linux_console.py:BootLinuxConsole.test_aarch64_virt
> DATA (filename=output.expected) => NOT FOUND (data sources: variant,
> test, file)
> PARAMS (key=arch, path=*, default=aarch64) => 'aarch64'
> PARAMS (key=qemu_bin, path=*,
> default=aarch64-softmmu/qemu-system-aarch64) =>
> 'aarch64-softmmu/qemu-system-aarch64'
> Fetching
> https://download.fedoraproject.org/pub/fedora/linux/releases/29/Everything/aarch64/os/images/pxeboot/vmlinuz
> ->
> /home/travis/avocado/data/cache/by_location/e959d0e1dd72e77653e218e666198db1f3d0c213/vmlinuz.g3ehffso
> Retrieved URL
> "https://download.fedoraproject.org/pub/fedora/linux/releases/29/Everything/aarch64/os/images/pxeboot/vmlinuz":
> content-length 8623423, date: "Wed, 12 Jun 2019 18:54:21 GMT",
> last-modified: "Sun, 21 Oct 2018 00:43:09 GMT"
> VM launch command: 'aarch64-softmmu/qemu-system-aarch64 -chardev
> socket,id=mon,path=/var/tmp/tmptpv0noew/qemu-6334-monitor.sock -mon
> chardev=mon,mode=control -display none -vga none -machine virt -chardev
> socket,id=console,path=/var/tmp/tmptpv0noew/qemu-6334-console.sock,server,nowait
> -serial chardev:console -cpu cortex-a53 -kernel
> /home/travis/avocado/data/cache/by_location/e959d0e1dd72e77653e218e666198db1f3d0c213/vmlinuz
> -append printk.time=0 console=ttyAMA0'
> >>> {'execute': 'qmp_capabilities'}
> <<< {'return': {}}
> Booting Linux on physical CPU 0x0000000000 [0x410fd034]
> Linux version 4.18.16-300.fc29.aarch64
> (mockbuild@buildvm-aarch64-02.arm.fedoraproject.org) (gcc version 8.2.1
> 20180801 (Red Hat 8.2.1-2) (GCC)) #1 SMP Sat Oct 20 23:12:22 UTC 2018
> Machine model: linux,dummy-virt
> efi: Getting EFI parameters from FDT:
> efi: UEFI not found.
> cma: Failed to reserve 64 MiB
> NUMA: No NUMA configuration found
> NUMA: Faking a node at [mem 0x0000000000000000-0x0000000047ffffff]
> NUMA: NODE_DATA [mem 0x47f9c780-0x47fa9fff]
> Zone ranges:
> DMA32    [mem 0x0000000040000000-0x0000000047ffffff]
> Normal   empty
> Movable zone start for each node
> Early memory node ranges
> node   0: [mem 0x0000000040000000-0x0000000047ffffff]
> Initmem setup node 0 [mem 0x0000000040000000-0x0000000047ffffff]
> psci: probing for conduit method from DT.
> psci: PSCIv0.2 detected in firmware.
> psci: Using standard PSCI v0.2 function IDs
> psci: Trusted OS migration not required
> percpu: Embedded 23 pages/cpu @(____ptrval____) s53528 r8192 d32488 u94208
> Detected VIPT I-cache on CPU0
> CPU features: enabling workaround for ARM erratum 843419
> CPU features: detected: Kernel page table isolation (KPTI)
> Built 1 zonelists, mobility grouping on.  Total pages: 32256
> Policy zone: DMA32
> Kernel command line: printk.time=0 console=ttyAMA0
> >>> {'execute': 'quit'}

Notice how QEMU gets stuck here.

- Cleber.

> qemu received signal 9: aarch64-softmmu/qemu-system-aarch64 -chardev
> socket,id=mon,path=/var/tmp/tmptpv0noew/qemu-6334-monitor.sock -mon
> chardev=mon,mode=control -display none -vga none -machine virt -chardev
> socket,id=console,path=/var/tmp/tmptpv0noew/qemu-6334-console.sock,server,nowait
> -serial chardev:console -cpu cortex-a53 -kernel
> /home/travis/avocado/data/cache/by_location/e959d0e1dd72e77653e218e666198db1f3d0c213/vmlinuz
> -append printk.time=0 console=ttyAMA0
> DATA (filename=output.expected) => NOT FOUND (data sources: variant,
> test, file)
> DATA (filename=stdout.expected) => NOT FOUND (data sources: variant,
> test, file)
> DATA (filename=stderr.expected) => NOT FOUND (data sources: variant,
> test, file)
> Not logging /var/log/syslog (lack of permissions)
> PASS
> 05-/home/travis/build/qemu/qemu/tests/acceptance/boot_linux_console.py:BootLinuxConsole.test_aarch64_virt
> Runner error occurred: Timeout reached
> Original status: PASS
> {'fail_class': None, 'name':
> '05-/home/travis/build/qemu/qemu/tests/acceptance/boot_linux_console.py:BootLinuxConsole.test_aarch64_virt',
> 'timeout': 90, 'time_elapsed': 90.49569606781006, 'params': [],
> 'time_end': 1560365750.8509598, 'logdir':
> '/home/travis/build/qemu/qemu/tests/results/job-2019-06-12T18.51-6779368/test-results/05-_home_travis_build_qemu_qemu_tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_aarch64_virt',
> 'status': 'PASS', 'whiteboard': '', 'fail_reason': None, 'traceback':
> None, 'job_unique_id': '6779368b0faa619be34d024bad5ee46367c44df0',
> 'class_name': 'BootLinuxConsole', 'paused': False, 'time_start':
> 1560365660.3552637, 'job_logdir':
> '/home/travis/build/qemu/qemu/tests/results/job-2019-06-12T18.51-6779368',
> 'running': False, 'logfile':
> '/home/travis/build/qemu/qemu/tests/results/job-2019-06-12T18.51-6779368/test-results/05-_home_travis_build_qemu_qemu_tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_aarch64_virt/debug.log'}
> File /etc/avocado/sysinfo/commands does not exist.
> File /etc/avocado/sysinfo/files does not exist.
> File /etc/avocado/sysinfo/profilers does not exist.
> Journalctl collection failed: Command 'journalctl --quiet --lines 1
> --output json' failed.
> stdout: b''
> stderr: b'No journal files were opened due to insufficient permissions.\n'
> additional_info: None
> 
> Thanks,
> 
> Phil.
>