[PATCH 1/1] test: stabilize test_efi_secboot

Fri May 22 08:13:51 CEST 2020

On 5/21/20 11:55 AM, AKASHI Takahiro wrote:
> Heinrich,
>
> On Thu, May 21, 2020 at 10:17:43AM +0200, Heinrich Schuchardt wrote:
>> On 5/21/20 2:23 AM, AKASHI Takahiro wrote:
>>> Heinrich,
>>>
>>> On Mon, May 11, 2020 at 03:56:56PM +0900, AKASHI Takahiro wrote:
>>>> Heinrich,
>>>>
>>>> On Fri, May 08, 2020 at 08:10:28AM +0900, AKASHI Takahiro wrote:
>>>>> On Thu, May 07, 2020 at 11:14:17PM +0200, Heinrich Schuchardt wrote:
>>>>>> On 5/7/20 2:36 AM, AKASHI Takahiro wrote:
>>>>>>> Heinrich,
>>>>>>>
>>>>>>> On Mon, May 04, 2020 at 12:33:26PM +0200, Heinrich Schuchardt wrote:
>>>>>>>> When setting up the console via function efi_console_register() we call
>>>>>>>> query_console_serial(). This functions sends an escape sequence to the
>>>>>>>> terminal to query the display size. The response is another escape
>>>>>>>> sequence.
>>>>>>>>
>>>>>>>> console.run_command_list() is looking for a regular expression '^==>'.
>>>>>>>> If the escape sequence for the screen size precedes the prompt without a
>>>>>>>> line break, no match is found.
>>>>>>>>
>>>>>>>> When efi_disk_register() is called before efi_console_register() this leads
>>>>>>>> to a test failuere of the UEFI secure boot tests.
>>>>>>>
>>>>>>> Why does the order of those calls affect test results?
>>>>>>
>>>>>> Please, have a look at function query_console_serial() and at
>>>>>> run_command_list().
>>>>>>
>>>>>> As described above:
>>>>>> '\e7\e[r\e[999;999H\e[6n\e8==>' cannot be matched by regular expression
>>>>>> '^==>'.
>>>>>
>>>>> (Probably) right, but what I don't get here is why efi_disk_register()
>>>>> have an impact on efi_console_register(). The former function has
>>>>> nothing to do with any console behaviors.
>>
>> efi_console_register writes ''\e7\e[r\e[999;999H\e[6n\e8' to the console.
>>
>> efi_disk_register writes to the console, e.g. "Found 2 disks\n". This
>> output occurs before the output of the command line prompt.
>
> How on earth the output can occur *before* the command line?
>
> After applying your patch to efi_setup.c, the sequence of initialization
> looks like:
>    efi_init_obj_list()
>       efi_disk_register()
>       efi_console_register()
>
> But anyhow, efi_init_obj_list() will be called when the first "efi"
> command is executed.
> Therefore, the captured output of console must be logically
>    1. text of command line (efi command)
>    2. output from efi_init_obj_list()
>       2.1 output from efi_disk_register()
>       2.2 output from efi_console_register()
>
> Again, why can the output (2.1) lead to (1)?
>
> As a matter of fact, the real output log from pytest clearly
> shows the order of output:
> (I left html tags as they are.)
>
> === from test-log.html of pytest ===
> <html>
> ...
> U-Boot 2020.07-rc2-00021-gbd934e4844d5-dirty (May 21 2020 - 18:25:14 +0900)
>
> Model: sandbox
> DRAM:  128 MiB
> WDT:   Started with servicing (60s timeout)
> MMC:   mmc2: 2 (SD), mmc1: 1 (SD), mmc0: 0 (SD)
> In:    serial
> Out:   vidconsole
> Err:   vidconsole
> Model: sandbox
> SCSI:
> Net:   eth0: eth at 10002000, eth5: eth at 10003000, eth3: sbe5, eth1: eth at 10004000
> Hit any key to stop autoboot:  2 %08%08%08 0
> => </pre>
>
> ...
>
> U-Boot 2020.07-rc2-00021-gbd934e4844d5-dirty (May 21 2020 - 18:25:14 +0900)
>
> Model: sandbox
> DRAM:  128 MiB
> WDT:   Started with servicing (60s timeout)
> MMC:   mmc2: 2 (SD), mmc1: 1 (SD), mmc0: 0 (SD)
> In:    serial
> Out:   vidconsole
> Err:   vidconsole
> Model: sandbox
> SCSI:
> Net:   eth0: eth at 10002000, eth5: eth at 10003000, eth3: sbe5, eth1: eth at 10004000
> Hit any key to stop autoboot:  2 %08%08%08 0
> => </pre>
>
> ...
>
> <pre><span class="implicit">=> </span>fatload host 0:1 4000000 KEK.auth
> 2045 bytes read in 0 ms
> => </pre>
>
> ...
>
> <pre><span class="implicit">=> </span>setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK
> Scanning disk mmc2.blk...
> ** Unrecognized filesystem type **
> Scanning disk mmc1.blk...
> ** Unrecognized filesystem type **
> Scanning disk mmc0.blk...
> ** Unrecognized filesystem type **
> Scanning disk host0...
> Found 5 disks
> %1b7%1b[r%1b[999;999H%1b[6n%1b8=> </pre>
>
> ...
>
> </html>
> === end of log ===
>
>> Now the Python test can match the regular expression '^==>' because the
>> prompt is the first output on the line.
>
> No. Python failed to match against "^==>."
>
> -Takahiro Akashi

Hello Takahiro,

I did my best to get your patches merged. If you have a better solution
that works in Gitlab CI and Travis CI, please, send a patch.

Best regards

Heinrich