Re: [Qemu-ppc] [PATCH v2 2/6] tests/acceptance: Test Open Firmware on the PReP/40p

[Cleber Rosa]

On Mon, Sep 16, 2019 at 01:59:22PM -0400, Cleber Rosa wrote:
> On Sun, Sep 15, 2019 at 11:19:36PM +0200, Philippe Mathieu-Daudé wrote:
> > User case from:
> > https://tyom.blogspot.com/2019/04/aixprep-under-qemu-how-to.html
> > 
> > Signed-off-by: Philippe Mathieu-Daudé <address@hidden>
> > ---
> >  tests/acceptance/ppc_prep_40p.py | 21 +++++++++++++++++++++
> >  1 file changed, 21 insertions(+)
> > 
> > diff --git a/tests/acceptance/ppc_prep_40p.py 
> > b/tests/acceptance/ppc_prep_40p.py
> > index 53f2d2ecf0..a0eac40d9f 100644
> > --- a/tests/acceptance/ppc_prep_40p.py
> > +++ b/tests/acceptance/ppc_prep_40p.py
> > @@ -61,3 +61,24 @@ class IbmPrep40pMachine(Test):
> >          os_banner = 'NetBSD 4.0 (GENERIC) #0: Sun Dec 16 00:49:40 PST 2007'
> >          self.wait_for_console_pattern(os_banner)
> >          self.wait_for_console_pattern('Model: IBM PPS Model 6015')
> > +
> > +    def test_openfirmware(self):
> > +        """
> > +        :avocado: tags=arch:ppc
> > +        :avocado: tags=machine:40p
> > +        """
> > +        bios_url = ('https://github.com/artyom-tarasenko/openfirmware/'
> > +                    'releases/download/40p-20190413/q40pofw-serial.rom')
> > +        bios_hash = '880c80172ea5b2247c0ac2a8bf36bbe385192c72'
> > +        bios_path = self.fetch_asset(bios_url, asset_hash=bios_hash)
> > +
> > +        self.vm.set_machine('40p')
> > +        self.vm.set_console()
> > +        self.vm.add_args('-bios', bios_path)
> > +
> > +        self.vm.launch()
> > +        self.wait_for_console_pattern('QEMU PReP/40p')
> > +        fw_banner = 'Open Firmware, built  April 13, 2019 09:29:23'
> > +        self.wait_for_console_pattern(fw_banner)
> > +        prompt_msg = 'Type any key to interrupt automatic startup'
> > +        self.wait_for_console_pattern(prompt_msg)
> > -- 
> > 2.20.1
> > 
> 
> Tested-by: Cleber Rosa <address@hidden>
> Reviewed-by: Cleber Rosa <address@hidden>

Actually, I'm seeing random but consistent failures.  I've tracked
it down to the 'Open Firmware, built  April 13, 2019 09:29:23'.  Out
of 100 executions I got 27 failures, with that line logged as:

  2019-09-16 14:44:54,540 ppc_prep_40p     L0033 DEBUG| Firmware, built  April 
13, 2019 09:29:23
  2019-09-16 14:45:00,762 ppc_prep_40p     L0033 DEBUG| n Firmware, built  
April 13, 2019 09:29:23
  2019-09-16 14:45:06,575 ppc_prep_40p     L0033 DEBUG| Firmware, built  April 
13, 2019 09:29:23
  2019-09-16 14:45:12,859 ppc_prep_40p     L0033 DEBUG| n Firmware, built  
April 13, 2019 09:29:23
  2019-09-16 14:45:18,707 ppc_prep_40p     L0033 DEBUG| Firmware, built  April 
13, 2019 09:29:23
  2019-09-16 14:45:21,876 ppc_prep_40p     L0033 DEBUG| en Firmware, built  
April 13, 2019 09:29:23
  2019-09-16 14:45:28,054 ppc_prep_40p     L0033 DEBUG| Firmware, built  April 
13, 2019 09:29:23
  2019-09-16 14:45:31,163 ppc_prep_40p     L0033 DEBUG| Firmware, built  April 
13, 2019 09:29:23
  2019-09-16 14:45:34,291 ppc_prep_40p     L0033 DEBUG| en Firmware, built  
April 13, 2019 09:29:23
  2019-09-16 14:45:57,719 ppc_prep_40p     L0033 DEBUG| Firmware, built  April 
13, 2019 09:29:23
  2019-09-16 14:46:03,610 ppc_prep_40p     L0033 DEBUG| Firmware, built  April 
13, 2019 09:29:23
  2019-09-16 14:46:06,795 ppc_prep_40p     L0033 DEBUG| n Firmware, built  
April 13, 2019 09:29:23
  2019-09-16 14:46:17,087 ppc_prep_40p     L0033 DEBUG| n Firmware, built  
April 13, 2019 09:29:23
  2019-09-16 14:46:21,534 ppc_prep_40p     L0033 DEBUG| Firmware, built  April 
13, 2019 09:29:23
  2019-09-16 14:46:24,694 ppc_prep_40p     L0033 DEBUG| Firmware, built  April 
13, 2019 09:29:23
  2019-09-16 14:46:38,076 ppc_prep_40p     L0033 DEBUG| Firmware, built  April 
13, 2019 09:29:23
  2019-09-16 14:46:49,863 ppc_prep_40p     L0033 DEBUG| n Firmware, built  
April 13, 2019 09:29:23
  2019-09-16 14:46:54,435 ppc_prep_40p     L0033 DEBUG| Firmware, built  April 
13, 2019 09:29:23
  2019-09-16 14:47:00,672 ppc_prep_40p     L0033 DEBUG| Firmware, built  April 
13, 2019 09:29:23
  2019-09-16 14:47:03,834 ppc_prep_40p     L0033 DEBUG| n Firmware, built  
April 13, 2019 09:29:23
  2019-09-16 14:47:06,852 ppc_prep_40p     L0033 DEBUG| Firmware, built  April 
13, 2019 09:29:23
  2019-09-16 14:47:14,276 ppc_prep_40p     L0033 DEBUG| n Firmware, built  
April 13, 2019 09:29:23
  2019-09-16 14:47:17,380 ppc_prep_40p     L0033 DEBUG| Firmware, built  April 
13, 2019 09:29:23
  2019-09-16 14:47:34,749 ppc_prep_40p     L0033 DEBUG| n Firmware, built  
April 13, 2019 09:29:23
  2019-09-16 14:47:39,217 ppc_prep_40p     L0033 DEBUG| n Firmware, built  
April 13, 2019 09:29:23
  2019-09-16 14:47:43,750 ppc_prep_40p     L0033 DEBUG| Firmware, built  April 
13, 2019 09:29:23
  2019-09-16 14:48:04,003 ppc_prep_40p     L0033 DEBUG| Firmware, built  April 
13, 2019 09:29:23

Given that we're not seeing this behavior in other target/marchine
tests, my first impression is that this is what's being produced
by QEMU, and not what's being badly captured by the Avocado and/or
the test code.

Any ideas?

- Cleber.