Problem with Avocado and QEMU console

Problem with Avocado and QEMU console

[Philippe Mathieu-Daudé]

[-- Attachment #1: Type: text/plain, Size: 295 bytes --]

Hi Cleber, Willian,

Avocado marked the test_mips64el_fuloong2e as failed while
it succeeded:
https://gitlab.com/qemu-project/qemu/-/jobs/1231363571

Apparently the first part of the console output is missing.
(Normal console output attached).

Any idea what could be the cause?

Thanks,

Phil.

[-- Attachment #2: test_mips64el_fuloong2e-console.log --]
[-- Type: text/x-log, Size: 7172 bytes --]

console: [    0.000000] Initializing cgroup subsys cpuset
console: [    0.000000] Initializing cgroup subsys cpu
console: [    0.000000] Initializing cgroup subsys cpuacct
console: [    0.000000] Linux version 3.16.0-6-loongson-2e (debian-kernel@lists.debian.org) (gcc version 4.8.4 (Debian 4.8.4-1) ) #1 Debian 3.16.56-1+deb8u1 (2018-05-08)
console: [    0.000000] memsize=256, highmemsize=0
console: [    0.000000] CpuClock = 533080000
console: [    0.000000] bootconsole [early0] enabled
console: [    0.000000] CPU0 revision is: 00006302 (ICT Loongson-2)
console: [    0.000000] FPU revision is: 00000501
console: [    0.000000] Checking for the multiply/shift bug... no.
console: [    0.000000] Checking for the daddiu bug... no.
console: [    0.000000] Determined physical RAM map:
console: [    0.000000]  memory: 0000000010000000 @ 0000000000000000 (usable)
console: [    0.000000]  memory: 0000000004000000 @ 0000000010000000 (reserved)
console: [    0.000000]  memory: 0000000003ffffff @ 000000001c000001 (reserved)
console: [    0.000000] Initrd not found or empty - disabling initrd
console: [    0.000000] Zone ranges:
console: [    0.000000]   DMA      [mem 0x00000000-0x00ffffff]
console: [    0.000000]   Normal   [mem 0x01000000-0x0fffffff]
console: [    0.000000] Movable zone start for each node
console: [    0.000000] Early memory node ranges
console: [    0.000000]   node   0: [mem 0x00000000-0x0fffffff]
console: [    0.000000] Reserving 0MB of memory at 0MB for crashkernel
console: [    0.000000] Primary instruction cache 64kB, VIPT, direct mapped, linesize 32 bytes.
console: [    0.000000] Primary data cache 64kB, 4-way, VIPT, no aliases, linesize 32 bytes
console: [    0.000000] Unified secondary cache 512kB 4-way, linesize 32 bytes.
console: [    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 16327
console: [    0.000000] Kernel command line: printk.time=0 console=ttyS0
console: PID hash table entries: 1024 (order: -1, 8192 bytes)
console: Dentry cache hash table entries: 32768 (order: 4, 262144 bytes)
console: Inode-cache hash table entries: 16384 (order: 3, 131072 bytes)
console: Memory: 250752K/262144K available (5597K kernel code, 716K rwdata, 1548K rodata, 480K init, 581K bss, 11392K reserved)
console: NR_IRQS:128
console: Console: colour dummy device 80x25
console: Calibrating delay loop... 1253.37 BogoMIPS (lpj=2506752)
console: pid_max: default: 32768 minimum: 301
console: Security Framework initialized
console: AppArmor: AppArmor disabled by boot time parameter
console: Yama: disabled by default; enable with sysctl kernel.yama.*
console: Mount-cache hash table entries: 2048 (order: 0, 16384 bytes)
console: Mountpoint-cache hash table entries: 2048 (order: 0, 16384 bytes)
console: Initializing cgroup subsys memory
console: Initializing cgroup subsys devices
console: Initializing cgroup subsys freezer
console: Initializing cgroup subsys net_cls
console: Initializing cgroup subsys blkio
console: Initializing cgroup subsys perf_event
console: Initializing cgroup subsys net_prio
console: Checking for the daddi bug... no.
console: ftrace: allocating 17617 entries in 18 pages
console: devtmpfs: initialized
console: futex hash table entries: 256 (order: -2, 6144 bytes)
console: NET: Registered protocol family 16
console: vgaarb: loaded
console: SCSI subsystem initialized
console: PCI host bridge to bus 0000:00
console: pci_bus 0000:00: root bus resource [mem 0x14000000-0x1c000000]
console: pci_bus 0000:00: root bus resource [io  0x4000-0xffff]
console: pci_bus 0000:00: No busn resource found for root bus, will use [bus 00-ff]
console: via686b fix: ISA bridge
console: via686b fix: ISA bridge done
console: pci 0000:00:05.1: legacy IDE quirk: reg 0x10: [io  0x01f0-0x01f7]
console: pci 0000:00:05.1: legacy IDE quirk: reg 0x14: [io  0x03f6]
console: pci 0000:00:05.1: legacy IDE quirk: reg 0x18: [io  0x0170-0x0177]
console: pci 0000:00:05.1: legacy IDE quirk: reg 0x1c: [io  0x0376]
console: via686b fix: IDE
console: via686b fix: IDE done
console: pci 0000:00:07.0: BAR 6: assigned [mem 0x14000000-0x1403ffff pref]
console: pci 0000:00:07.0: BAR 0: assigned [io  0x4000-0x40ff]
console: pci 0000:00:07.0: BAR 1: assigned [mem 0x14040000-0x140400ff]
console: pci 0000:00:05.2: BAR 4: assigned [io  0x4400-0x441f]
console: pci 0000:00:05.3: BAR 4: assigned [io  0x4420-0x443f]
console: pci 0000:00:05.1: BAR 4: assigned [io  0x4440-0x444f]
|console: Switched to clocksource MIPS
console: NET: Registered protocol family 2
console: TCP established hash table entries: 2048 (order: 0, 16384 bytes)
console: TCP bind hash table entries: 2048 (order: 0, 16384 bytes)
console: TCP: Hash tables configured (established 2048 bind 2048)
console: TCP: reno registered
console: UDP hash table entries: 512 (order: 0, 16384 bytes)
console: UDP-Lite hash table entries: 512 (order: 0, 16384 bytes)
console: NET: Registered protocol family 1
console: PCI: Enabling device 0000:00:05.2 (0000 -> 0001)
console: PCI: Enabling device 0000:00:05.3 (0000 -> 0001)
console: audit: initializing netlink subsys (disabled)
console: audit: type=2000 audit(1620046479.132:1): initialized
console: HugeTLB registered 32 MB page size, pre-allocated 0 pages
console: zbud: loaded
console: VFS: Disk quotas dquot_6.5.2
console: Dquot-cache hash table entries: 2048 (order 0, 16384 bytes)
console: msgmni has been set to 489
console: alg: No test for stdrng (krng)
console: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
console: io scheduler noop registered
console: io scheduler deadline registered
console: io scheduler cfq registered (default)
console: Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
console: console [ttyS0] disabled
console: serial8250.0: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
console: console [ttyS0] enabled
console: console [ttyS0] enabled
console: bootconsole [early0] disabled
console: bootconsole [early0] disabled
console: scsi0 : pata_via
console: scsi1 : pata_via
console: ata1: PATA max UDMA/100 cmd 0x1f0 ctl 0x3f6 bmdma 0x4440 irq 14
console: ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0x4448 irq 15
console: serio: i8042 KBD port at 0x60,0x64 irq 1
console: serio: i8042 AUX port at 0x60,0x64 irq 12
console: mousedev: PS/2 mouse device common for all mice
console: rtc_cmos rtc_cmos: rtc core: registered rtc_cmos as rtc0
console: rtc_cmos rtc_cmos: alarms up to one day, 114 bytes nvram
console: ledtrig-cpu: registered to indicate activity on CPUs
console: TCP: cubic registered
console: NET: Registered protocol family 10
console: mip6: Mobile IPv6
console: NET: Registered protocol family 17
console: mpls_gso: MPLS GSO support
console: registered taskstats version 1
console: rtc_cmos rtc_cmos: setting system clock to 2021-05-03 12:54:39 UTC (1620046479)
console: input: AT Raw Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
console: VFS: Cannot open root device "(null)" or unknown-block(0,0): error -6
console: Please append a correct "root=" boot option; here are the available partitions:
console: Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(0,0)

Re: Problem with Avocado and QEMU console

[Willian Rampazzo]

Hi Philippe,

On Mon, May 3, 2021 at 9:59 AM Philippe Mathieu-Daudé <f4bug@amsat.org> wrote:
>
> Hi Cleber, Willian,
>
> Avocado marked the test_mips64el_fuloong2e as failed while
> it succeeded:
> https://gitlab.com/qemu-project/qemu/-/jobs/1231363571
>
> Apparently the first part of the console output is missing.
> (Normal console output attached).
>
> Any idea what could be the cause?
>

The log shows the following:

12:00:37 ERROR| avocado.core.exceptions.TestFail: Failure message
found in console: "Kernel panic - not syncing". Expected: "Kernel
command line: printk.time=0 console=ttyS0"

Does your comment about "console output missing" means the expected
message was supposed to be on this missing part?

> Thanks,
>
> Phil.

Re: Problem with Avocado and QEMU console

[Philippe Mathieu-Daudé]

On 5/3/21 3:12 PM, Willian Rampazzo wrote:
> Hi Philippe,
> 
> On Mon, May 3, 2021 at 9:59 AM Philippe Mathieu-Daudé <f4bug@amsat.org> wrote:
>>
>> Hi Cleber, Willian,
>>
>> Avocado marked the test_mips64el_fuloong2e as failed while
>> it succeeded:
>> https://gitlab.com/qemu-project/qemu/-/jobs/1231363571
>>
>> Apparently the first part of the console output is missing.
>> (Normal console output attached).
>>
>> Any idea what could be the cause?
>>
> 
> The log shows the following:
> 
> 12:00:37 ERROR| avocado.core.exceptions.TestFail: Failure message
> found in console: "Kernel panic - not syncing". Expected: "Kernel
> command line: printk.time=0 console=ttyS0"
> 
> Does your comment about "console output missing" means the expected
> message was supposed to be on this missing part?

Yes, "the first part is missing" so Avocado didn't see the expected
message pass, but the messages emitted *after* it are logged.

Re: Problem with Avocado and QEMU console

[Willian Rampazzo]

On Mon, May 3, 2021 at 10:36 AM Philippe Mathieu-Daudé <f4bug@amsat.org> wrote:
>
> On 5/3/21 3:12 PM, Willian Rampazzo wrote:
> > Hi Philippe,
> >
> > On Mon, May 3, 2021 at 9:59 AM Philippe Mathieu-Daudé <f4bug@amsat.org> wrote:
> >>
> >> Hi Cleber, Willian,
> >>
> >> Avocado marked the test_mips64el_fuloong2e as failed while
> >> it succeeded:
> >> https://gitlab.com/qemu-project/qemu/-/jobs/1231363571
> >>
> >> Apparently the first part of the console output is missing.
> >> (Normal console output attached).
> >>
> >> Any idea what could be the cause?
> >>
> >
> > The log shows the following:
> >
> > 12:00:37 ERROR| avocado.core.exceptions.TestFail: Failure message
> > found in console: "Kernel panic - not syncing". Expected: "Kernel
> > command line: printk.time=0 console=ttyS0"
> >
> > Does your comment about "console output missing" means the expected
> > message was supposed to be on this missing part?
>
> Yes, "the first part is missing" so Avocado didn't see the expected
> message pass, but the messages emitted *after* it are logged.
>

Okay, got it.

The reason for it to fail is here:
https://gitlab.com/qemu-project/qemu/-/blob/master/tests/acceptance/boot_linux_console.py#L53.
The way the `wait_for_console_pattern` method is defined tells the
test to fail if that `failure_message` is found.

I'm still checking why the test missed the first part.

Re: Problem with Avocado and QEMU console

[Philippe Mathieu-Daudé]

On 5/3/21 4:46 PM, Willian Rampazzo wrote:
> On Mon, May 3, 2021 at 10:36 AM Philippe Mathieu-Daudé <f4bug@amsat.org> wrote:
>>
>> On 5/3/21 3:12 PM, Willian Rampazzo wrote:
>>> Hi Philippe,
>>>
>>> On Mon, May 3, 2021 at 9:59 AM Philippe Mathieu-Daudé <f4bug@amsat.org> wrote:
>>>>
>>>> Hi Cleber, Willian,
>>>>
>>>> Avocado marked the test_mips64el_fuloong2e as failed while
>>>> it succeeded:
>>>> https://gitlab.com/qemu-project/qemu/-/jobs/1231363571
>>>>
>>>> Apparently the first part of the console output is missing.
>>>> (Normal console output attached).
>>>>
>>>> Any idea what could be the cause?
>>>>
>>>
>>> The log shows the following:
>>>
>>> 12:00:37 ERROR| avocado.core.exceptions.TestFail: Failure message
>>> found in console: "Kernel panic - not syncing". Expected: "Kernel
>>> command line: printk.time=0 console=ttyS0"
>>>
>>> Does your comment about "console output missing" means the expected
>>> message was supposed to be on this missing part?
>>
>> Yes, "the first part is missing" so Avocado didn't see the expected
>> message pass, but the messages emitted *after* it are logged.
>>
> 
> Okay, got it.
> 
> The reason for it to fail is here:
> https://gitlab.com/qemu-project/qemu/-/blob/master/tests/acceptance/boot_linux_console.py#L53.
> The way the `wait_for_console_pattern` method is defined tells the
> test to fail if that `failure_message` is found.
> 
> I'm still checking why the test missed the first part.

Could this be related to the recent failures in N8x0Machine.test_n810?

https://gitlab.com/qemu-project/qemu/-/jobs/1280746618#L128

Re: Problem with Avocado and QEMU console

[Philippe Mathieu-Daudé]

On 6/1/21 5:40 AM, Philippe Mathieu-Daudé wrote:
> On 5/3/21 4:46 PM, Willian Rampazzo wrote:
>> On Mon, May 3, 2021 at 10:36 AM Philippe Mathieu-Daudé <f4bug@amsat.org> wrote:
>>>
>>> On 5/3/21 3:12 PM, Willian Rampazzo wrote:
>>>> Hi Philippe,
>>>>
>>>> On Mon, May 3, 2021 at 9:59 AM Philippe Mathieu-Daudé <f4bug@amsat.org> wrote:
>>>>>
>>>>> Hi Cleber, Willian,
>>>>>
>>>>> Avocado marked the test_mips64el_fuloong2e as failed while
>>>>> it succeeded:
>>>>> https://gitlab.com/qemu-project/qemu/-/jobs/1231363571
>>>>>
>>>>> Apparently the first part of the console output is missing.
>>>>> (Normal console output attached).
>>>>>
>>>>> Any idea what could be the cause?
>>>>>
>>>>
>>>> The log shows the following:
>>>>
>>>> 12:00:37 ERROR| avocado.core.exceptions.TestFail: Failure message
>>>> found in console: "Kernel panic - not syncing". Expected: "Kernel
>>>> command line: printk.time=0 console=ttyS0"
>>>>
>>>> Does your comment about "console output missing" means the expected
>>>> message was supposed to be on this missing part?
>>>
>>> Yes, "the first part is missing" so Avocado didn't see the expected
>>> message pass, but the messages emitted *after* it are logged.
>>>
>>
>> Okay, got it.
>>
>> The reason for it to fail is here:
>> https://gitlab.com/qemu-project/qemu/-/blob/master/tests/acceptance/boot_linux_console.py#L53.
>> The way the `wait_for_console_pattern` method is defined tells the
>> test to fail if that `failure_message` is found.
>>
>> I'm still checking why the test missed the first part.
> 
> Could this be related to the recent failures in N8x0Machine.test_n810?
> 
> https://gitlab.com/qemu-project/qemu/-/jobs/1280746618#L128

Yet another one:

https://gitlab.com/qemu-project/qemu/-/jobs/1390365314#L129

Re: Problem with Avocado and QEMU console

[Willian Rampazzo]

Hi Phil,

I spent some time trying to debug the problem with
tests/acceptance/machine_arm_n8x0.py:N8x0Machine.test_n810. Although I
could not reproduce it locally, with or without Avocado, I was able to
reproduce it without using Avocado on GitLab CI:

https://gitlab.com/willianrampazzo/qemu/-/pipelines/331342777

From 50 tries, 3 reproduced the problem.

So, answering your question, no, the problem happening with
tests/acceptance/machine_arm_n8x0.py:N8x0Machine.test_n810 is not
related to the problem reported in this thread or to Avocado.

Regards,

On Fri, Jul 2, 2021 at 11:48 AM Philippe Mathieu-Daudé <f4bug@amsat.org> wrote:
>
> On 6/1/21 5:40 AM, Philippe Mathieu-Daudé wrote:
> > On 5/3/21 4:46 PM, Willian Rampazzo wrote:
> >> On Mon, May 3, 2021 at 10:36 AM Philippe Mathieu-Daudé <f4bug@amsat.org> wrote:
> >>>
> >>> On 5/3/21 3:12 PM, Willian Rampazzo wrote:
> >>>> Hi Philippe,
> >>>>
> >>>> On Mon, May 3, 2021 at 9:59 AM Philippe Mathieu-Daudé <f4bug@amsat.org> wrote:
> >>>>>
> >>>>> Hi Cleber, Willian,
> >>>>>
> >>>>> Avocado marked the test_mips64el_fuloong2e as failed while
> >>>>> it succeeded:
> >>>>> https://gitlab.com/qemu-project/qemu/-/jobs/1231363571
> >>>>>
> >>>>> Apparently the first part of the console output is missing.
> >>>>> (Normal console output attached).
> >>>>>
> >>>>> Any idea what could be the cause?
> >>>>>
> >>>>
> >>>> The log shows the following:
> >>>>
> >>>> 12:00:37 ERROR| avocado.core.exceptions.TestFail: Failure message
> >>>> found in console: "Kernel panic - not syncing". Expected: "Kernel
> >>>> command line: printk.time=0 console=ttyS0"
> >>>>
> >>>> Does your comment about "console output missing" means the expected
> >>>> message was supposed to be on this missing part?
> >>>
> >>> Yes, "the first part is missing" so Avocado didn't see the expected
> >>> message pass, but the messages emitted *after* it are logged.
> >>>
> >>
> >> Okay, got it.
> >>
> >> The reason for it to fail is here:
> >> https://gitlab.com/qemu-project/qemu/-/blob/master/tests/acceptance/boot_linux_console.py#L53.
> >> The way the `wait_for_console_pattern` method is defined tells the
> >> test to fail if that `failure_message` is found.
> >>
> >> I'm still checking why the test missed the first part.
> >
> > Could this be related to the recent failures in N8x0Machine.test_n810?
> >
> > https://gitlab.com/qemu-project/qemu/-/jobs/1280746618#L128
>
> Yet another one:
>
> https://gitlab.com/qemu-project/qemu/-/jobs/1390365314#L129
>