diff mbox series

[1/1] test: stabilize test_efi_secboot

Message ID 20200504103326.88607-1-xypron.glpk@gmx.de
State Accepted
Commit 5827c2545849441dd60467565aac11964259972f
Headers show
Series [1/1] test: stabilize test_efi_secboot | expand

Commit Message

Heinrich Schuchardt May 4, 2020, 10:33 a.m. UTC
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.

We can avoid the problem if the first UEFI command passed to
u_boot_console.run_command_list() produces output. This patch achieves this
by appending '; echo' to the first UEFI related command of the problematic
tests.

Signed-off-by: Heinrich Schuchardt <xypron.glpk at gmx.de>
---
 test/py/tests/test_efi_secboot/test_authvar.py  | 8 ++++----
 test/py/tests/test_efi_secboot/test_signed.py   | 4 ++--
 test/py/tests/test_efi_secboot/test_unsigned.py | 6 +++---
 3 files changed, 9 insertions(+), 9 deletions(-)

--
2.26.2

Comments

AKASHI Takahiro May 7, 2020, 12:36 a.m. UTC | #1
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?

> We can avoid the problem if the first UEFI command passed to
> u_boot_console.run_command_list() produces output. This patch achieves this
> by appending '; echo' to the first UEFI related command of the problematic
> tests.

It looks to be a workaround.
We'd better have another approach to fix the problem.
Otherwise, similar issues will occur again.

Thanks,
-Takahiro Akashi

> Signed-off-by: Heinrich Schuchardt <xypron.glpk at gmx.de>
> ---
>  test/py/tests/test_efi_secboot/test_authvar.py  | 8 ++++----
>  test/py/tests/test_efi_secboot/test_signed.py   | 4 ++--
>  test/py/tests/test_efi_secboot/test_unsigned.py | 6 +++---
>  3 files changed, 9 insertions(+), 9 deletions(-)
> 
> diff --git a/test/py/tests/test_efi_secboot/test_authvar.py b/test/py/tests/test_efi_secboot/test_authvar.py
> index 55dcaa95f1..9912694a3e 100644
> --- a/test/py/tests/test_efi_secboot/test_authvar.py
> +++ b/test/py/tests/test_efi_secboot/test_authvar.py
> @@ -133,7 +133,7 @@ class TestEfiAuthVar(object):
>              output = u_boot_console.run_command_list([
>                  'host bind 0 %s' % disk_img,
>                  'fatload host 0:1 4000000 PK.auth',
> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
>                  'fatload host 0:1 4000000 KEK.auth',
>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>                  'fatload host 0:1 4000000 db.auth',
> @@ -174,7 +174,7 @@ class TestEfiAuthVar(object):
>              output = u_boot_console.run_command_list([
>                  'host bind 0 %s' % disk_img,
>                  'fatload host 0:1 4000000 PK.auth',
> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
>                  'fatload host 0:1 4000000 KEK.auth',
>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>                  'fatload host 0:1 4000000 db.auth',
> @@ -215,7 +215,7 @@ class TestEfiAuthVar(object):
>              output = u_boot_console.run_command_list([
>                  'host bind 0 %s' % disk_img,
>                  'fatload host 0:1 4000000 PK.auth',
> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
>                  'fatload host 0:1 4000000 KEK.auth',
>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>                  'fatload host 0:1 4000000 db.auth',
> @@ -249,7 +249,7 @@ class TestEfiAuthVar(object):
>              output = u_boot_console.run_command_list([
>                  'host bind 0 %s' % disk_img,
>                  'fatload host 0:1 4000000 PK.auth',
> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
>                  'fatload host 0:1 4000000 KEK.auth',
>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>                  'fatload host 0:1 4000000 db.auth',
> diff --git a/test/py/tests/test_efi_secboot/test_signed.py b/test/py/tests/test_efi_secboot/test_signed.py
> index 584282b338..fc722ab506 100644
> --- a/test/py/tests/test_efi_secboot/test_signed.py
> +++ b/test/py/tests/test_efi_secboot/test_signed.py
> @@ -29,7 +29,7 @@ class TestEfiSignedImage(object):
>              # Test Case 1a, run signed image if no db/dbx
>              output = u_boot_console.run_command_list([
>                  'host bind 0 %s' % disk_img,
> -                'efidebug boot add 1 HELLO1 host 0:1 /helloworld.efi.signed ""',
> +                'efidebug boot add 1 HELLO1 host 0:1 /helloworld.efi.signed ""; echo',
>                  'efidebug boot next 1',
>                  'bootefi bootmgr'])
>              assert(re.search('Hello, world!', ''.join(output)))
> @@ -81,7 +81,7 @@ class TestEfiSignedImage(object):
>              output = u_boot_console.run_command_list([
>                  'host bind 0 %s' % disk_img,
>                  'fatload host 0:1 4000000 db.auth',
> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx',
> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx; echo',
>                  'fatload host 0:1 4000000 KEK.auth',
>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>                  'fatload host 0:1 4000000 PK.auth',
> diff --git a/test/py/tests/test_efi_secboot/test_unsigned.py b/test/py/tests/test_efi_secboot/test_unsigned.py
> index 22d849afb8..a4af845c51 100644
> --- a/test/py/tests/test_efi_secboot/test_unsigned.py
> +++ b/test/py/tests/test_efi_secboot/test_unsigned.py
> @@ -30,7 +30,7 @@ class TestEfiUnsignedImage(object):
>              output = u_boot_console.run_command_list([
>                  'host bind 0 %s' % disk_img,
>  		'fatload host 0:1 4000000 KEK.auth',
> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK; echo',
>  		'fatload host 0:1 4000000 PK.auth',
>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK'])
>              assert(not re.search('Failed to set EFI variable', ''.join(output)))
> @@ -58,7 +58,7 @@ class TestEfiUnsignedImage(object):
>              output = u_boot_console.run_command_list([
>                  'host bind 0 %s' % disk_img,
>  		'fatload host 0:1 4000000 db_hello.auth',
> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize db',
> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize db; echo',
>  		'fatload host 0:1 4000000 KEK.auth',
>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>  		'fatload host 0:1 4000000 PK.auth',
> @@ -82,7 +82,7 @@ class TestEfiUnsignedImage(object):
>              output = u_boot_console.run_command_list([
>                  'host bind 0 %s' % disk_img,
>  		'fatload host 0:1 4000000 db_hello.auth',
> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx',
> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx; echo',
>  		'fatload host 0:1 4000000 KEK.auth',
>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>  		'fatload host 0:1 4000000 PK.auth',
> --
> 2.26.2
>
Heinrich Schuchardt May 7, 2020, 9:14 p.m. UTC | #2
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
'^==>'.

>
>> We can avoid the problem if the first UEFI command passed to
>> u_boot_console.run_command_list() produces output. This patch achieves this
>> by appending '; echo' to the first UEFI related command of the problematic
>> tests.
>
> It looks to be a workaround.
> We'd better have another approach to fix the problem.
> Otherwise, similar issues will occur again.

I would not like to change the logic in Python to detect the U-Boot
prompt for something UEFI specific. And we need a method to determine
the size of a serial console.

The current approach allowed me to merge your patch series which
otherwise might not have reached the v2020.07 release. Did the problem
not show up in your Travis CI testing?

If you have a better solution, we can easily merge your patch.

Best regards

Heinrich

>
> Thanks,
> -Takahiro Akashi
>
>> Signed-off-by: Heinrich Schuchardt <xypron.glpk at gmx.de>
>> ---
>>  test/py/tests/test_efi_secboot/test_authvar.py  | 8 ++++----
>>  test/py/tests/test_efi_secboot/test_signed.py   | 4 ++--
>>  test/py/tests/test_efi_secboot/test_unsigned.py | 6 +++---
>>  3 files changed, 9 insertions(+), 9 deletions(-)
>>
>> diff --git a/test/py/tests/test_efi_secboot/test_authvar.py b/test/py/tests/test_efi_secboot/test_authvar.py
>> index 55dcaa95f1..9912694a3e 100644
>> --- a/test/py/tests/test_efi_secboot/test_authvar.py
>> +++ b/test/py/tests/test_efi_secboot/test_authvar.py
>> @@ -133,7 +133,7 @@ class TestEfiAuthVar(object):
>>              output = u_boot_console.run_command_list([
>>                  'host bind 0 %s' % disk_img,
>>                  'fatload host 0:1 4000000 PK.auth',
>> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
>> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
>>                  'fatload host 0:1 4000000 KEK.auth',
>>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>>                  'fatload host 0:1 4000000 db.auth',
>> @@ -174,7 +174,7 @@ class TestEfiAuthVar(object):
>>              output = u_boot_console.run_command_list([
>>                  'host bind 0 %s' % disk_img,
>>                  'fatload host 0:1 4000000 PK.auth',
>> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
>> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
>>                  'fatload host 0:1 4000000 KEK.auth',
>>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>>                  'fatload host 0:1 4000000 db.auth',
>> @@ -215,7 +215,7 @@ class TestEfiAuthVar(object):
>>              output = u_boot_console.run_command_list([
>>                  'host bind 0 %s' % disk_img,
>>                  'fatload host 0:1 4000000 PK.auth',
>> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
>> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
>>                  'fatload host 0:1 4000000 KEK.auth',
>>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>>                  'fatload host 0:1 4000000 db.auth',
>> @@ -249,7 +249,7 @@ class TestEfiAuthVar(object):
>>              output = u_boot_console.run_command_list([
>>                  'host bind 0 %s' % disk_img,
>>                  'fatload host 0:1 4000000 PK.auth',
>> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
>> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
>>                  'fatload host 0:1 4000000 KEK.auth',
>>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>>                  'fatload host 0:1 4000000 db.auth',
>> diff --git a/test/py/tests/test_efi_secboot/test_signed.py b/test/py/tests/test_efi_secboot/test_signed.py
>> index 584282b338..fc722ab506 100644
>> --- a/test/py/tests/test_efi_secboot/test_signed.py
>> +++ b/test/py/tests/test_efi_secboot/test_signed.py
>> @@ -29,7 +29,7 @@ class TestEfiSignedImage(object):
>>              # Test Case 1a, run signed image if no db/dbx
>>              output = u_boot_console.run_command_list([
>>                  'host bind 0 %s' % disk_img,
>> -                'efidebug boot add 1 HELLO1 host 0:1 /helloworld.efi.signed ""',
>> +                'efidebug boot add 1 HELLO1 host 0:1 /helloworld.efi.signed ""; echo',
>>                  'efidebug boot next 1',
>>                  'bootefi bootmgr'])
>>              assert(re.search('Hello, world!', ''.join(output)))
>> @@ -81,7 +81,7 @@ class TestEfiSignedImage(object):
>>              output = u_boot_console.run_command_list([
>>                  'host bind 0 %s' % disk_img,
>>                  'fatload host 0:1 4000000 db.auth',
>> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx',
>> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx; echo',
>>                  'fatload host 0:1 4000000 KEK.auth',
>>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>>                  'fatload host 0:1 4000000 PK.auth',
>> diff --git a/test/py/tests/test_efi_secboot/test_unsigned.py b/test/py/tests/test_efi_secboot/test_unsigned.py
>> index 22d849afb8..a4af845c51 100644
>> --- a/test/py/tests/test_efi_secboot/test_unsigned.py
>> +++ b/test/py/tests/test_efi_secboot/test_unsigned.py
>> @@ -30,7 +30,7 @@ class TestEfiUnsignedImage(object):
>>              output = u_boot_console.run_command_list([
>>                  'host bind 0 %s' % disk_img,
>>  		'fatload host 0:1 4000000 KEK.auth',
>> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK; echo',
>>  		'fatload host 0:1 4000000 PK.auth',
>>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK'])
>>              assert(not re.search('Failed to set EFI variable', ''.join(output)))
>> @@ -58,7 +58,7 @@ class TestEfiUnsignedImage(object):
>>              output = u_boot_console.run_command_list([
>>                  'host bind 0 %s' % disk_img,
>>  		'fatload host 0:1 4000000 db_hello.auth',
>> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize db',
>> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize db; echo',
>>  		'fatload host 0:1 4000000 KEK.auth',
>>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>>  		'fatload host 0:1 4000000 PK.auth',
>> @@ -82,7 +82,7 @@ class TestEfiUnsignedImage(object):
>>              output = u_boot_console.run_command_list([
>>                  'host bind 0 %s' % disk_img,
>>  		'fatload host 0:1 4000000 db_hello.auth',
>> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx',
>> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx; echo',
>>  		'fatload host 0:1 4000000 KEK.auth',
>>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>>  		'fatload host 0:1 4000000 PK.auth',
>> --
>> 2.26.2
>>
AKASHI Takahiro May 7, 2020, 11:10 p.m. UTC | #3
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.

Moreover, I wonder
- why you want to move efi_console_register() after efi_disk_register().
- why python script can see such escape sequences.

> 
> >
> >> We can avoid the problem if the first UEFI command passed to
> >> u_boot_console.run_command_list() produces output. This patch achieves this
> >> by appending '; echo' to the first UEFI related command of the problematic
> >> tests.
> >
> > It looks to be a workaround.
> > We'd better have another approach to fix the problem.
> > Otherwise, similar issues will occur again.
> 
> I would not like to change the logic in Python to detect the U-Boot
> prompt for something UEFI specific. And we need a method to determine
> the size of a serial console.
> 
> The current approach allowed me to merge your patch series which
> otherwise might not have reached the v2020.07 release. Did the problem
> not show up in your Travis CI testing?

No. If your saying is correct, this can happen only if efi_console_register()
is moved after efi_disk_register(). Right?

> If you have a better solution, we can easily merge your patch.

First, I want to understand what's happening.

-Takahiro Akashi

> Best regards
> 
> Heinrich
> 
> >
> > Thanks,
> > -Takahiro Akashi
> >
> >> Signed-off-by: Heinrich Schuchardt <xypron.glpk at gmx.de>
> >> ---
> >>  test/py/tests/test_efi_secboot/test_authvar.py  | 8 ++++----
> >>  test/py/tests/test_efi_secboot/test_signed.py   | 4 ++--
> >>  test/py/tests/test_efi_secboot/test_unsigned.py | 6 +++---
> >>  3 files changed, 9 insertions(+), 9 deletions(-)
> >>
> >> diff --git a/test/py/tests/test_efi_secboot/test_authvar.py b/test/py/tests/test_efi_secboot/test_authvar.py
> >> index 55dcaa95f1..9912694a3e 100644
> >> --- a/test/py/tests/test_efi_secboot/test_authvar.py
> >> +++ b/test/py/tests/test_efi_secboot/test_authvar.py
> >> @@ -133,7 +133,7 @@ class TestEfiAuthVar(object):
> >>              output = u_boot_console.run_command_list([
> >>                  'host bind 0 %s' % disk_img,
> >>                  'fatload host 0:1 4000000 PK.auth',
> >> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> >> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
> >>                  'fatload host 0:1 4000000 KEK.auth',
> >>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> >>                  'fatload host 0:1 4000000 db.auth',
> >> @@ -174,7 +174,7 @@ class TestEfiAuthVar(object):
> >>              output = u_boot_console.run_command_list([
> >>                  'host bind 0 %s' % disk_img,
> >>                  'fatload host 0:1 4000000 PK.auth',
> >> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> >> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
> >>                  'fatload host 0:1 4000000 KEK.auth',
> >>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> >>                  'fatload host 0:1 4000000 db.auth',
> >> @@ -215,7 +215,7 @@ class TestEfiAuthVar(object):
> >>              output = u_boot_console.run_command_list([
> >>                  'host bind 0 %s' % disk_img,
> >>                  'fatload host 0:1 4000000 PK.auth',
> >> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> >> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
> >>                  'fatload host 0:1 4000000 KEK.auth',
> >>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> >>                  'fatload host 0:1 4000000 db.auth',
> >> @@ -249,7 +249,7 @@ class TestEfiAuthVar(object):
> >>              output = u_boot_console.run_command_list([
> >>                  'host bind 0 %s' % disk_img,
> >>                  'fatload host 0:1 4000000 PK.auth',
> >> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> >> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
> >>                  'fatload host 0:1 4000000 KEK.auth',
> >>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> >>                  'fatload host 0:1 4000000 db.auth',
> >> diff --git a/test/py/tests/test_efi_secboot/test_signed.py b/test/py/tests/test_efi_secboot/test_signed.py
> >> index 584282b338..fc722ab506 100644
> >> --- a/test/py/tests/test_efi_secboot/test_signed.py
> >> +++ b/test/py/tests/test_efi_secboot/test_signed.py
> >> @@ -29,7 +29,7 @@ class TestEfiSignedImage(object):
> >>              # Test Case 1a, run signed image if no db/dbx
> >>              output = u_boot_console.run_command_list([
> >>                  'host bind 0 %s' % disk_img,
> >> -                'efidebug boot add 1 HELLO1 host 0:1 /helloworld.efi.signed ""',
> >> +                'efidebug boot add 1 HELLO1 host 0:1 /helloworld.efi.signed ""; echo',
> >>                  'efidebug boot next 1',
> >>                  'bootefi bootmgr'])
> >>              assert(re.search('Hello, world!', ''.join(output)))
> >> @@ -81,7 +81,7 @@ class TestEfiSignedImage(object):
> >>              output = u_boot_console.run_command_list([
> >>                  'host bind 0 %s' % disk_img,
> >>                  'fatload host 0:1 4000000 db.auth',
> >> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx',
> >> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx; echo',
> >>                  'fatload host 0:1 4000000 KEK.auth',
> >>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> >>                  'fatload host 0:1 4000000 PK.auth',
> >> diff --git a/test/py/tests/test_efi_secboot/test_unsigned.py b/test/py/tests/test_efi_secboot/test_unsigned.py
> >> index 22d849afb8..a4af845c51 100644
> >> --- a/test/py/tests/test_efi_secboot/test_unsigned.py
> >> +++ b/test/py/tests/test_efi_secboot/test_unsigned.py
> >> @@ -30,7 +30,7 @@ class TestEfiUnsignedImage(object):
> >>              output = u_boot_console.run_command_list([
> >>                  'host bind 0 %s' % disk_img,
> >>  		'fatload host 0:1 4000000 KEK.auth',
> >> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> >> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK; echo',
> >>  		'fatload host 0:1 4000000 PK.auth',
> >>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK'])
> >>              assert(not re.search('Failed to set EFI variable', ''.join(output)))
> >> @@ -58,7 +58,7 @@ class TestEfiUnsignedImage(object):
> >>              output = u_boot_console.run_command_list([
> >>                  'host bind 0 %s' % disk_img,
> >>  		'fatload host 0:1 4000000 db_hello.auth',
> >> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize db',
> >> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize db; echo',
> >>  		'fatload host 0:1 4000000 KEK.auth',
> >>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> >>  		'fatload host 0:1 4000000 PK.auth',
> >> @@ -82,7 +82,7 @@ class TestEfiUnsignedImage(object):
> >>              output = u_boot_console.run_command_list([
> >>                  'host bind 0 %s' % disk_img,
> >>  		'fatload host 0:1 4000000 db_hello.auth',
> >> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx',
> >> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx; echo',
> >>  		'fatload host 0:1 4000000 KEK.auth',
> >>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> >>  		'fatload host 0:1 4000000 PK.auth',
> >> --
> >> 2.26.2
> >>
>
AKASHI Takahiro May 11, 2020, 6:56 a.m. UTC | #4
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.

You have merged your patch without replying to my comment.

> Moreover, I wonder
> - why you want to move efi_console_register() after efi_disk_register().
> - why python script can see such escape sequences.

I don't like your fix.
With your fixes, my secure boot pytest now fails to run
on sandbox locally.

Instead, I propose:
1. revert your commits
   commit 16ad946f41d3 ("efi_loader: change setup sequence")
   commit 5827c2545849 ("test: stabilize test_efi_secboot")
2. move efi_console_register() forward *before* efi_console_register()


Then my secure boot test should work again without any modification.
I believe that my solution is much better than your workaround.

-Takahiro Akashi

> > 
> > >
> > >> We can avoid the problem if the first UEFI command passed to
> > >> u_boot_console.run_command_list() produces output. This patch achieves this
> > >> by appending '; echo' to the first UEFI related command of the problematic
> > >> tests.
> > >
> > > It looks to be a workaround.
> > > We'd better have another approach to fix the problem.
> > > Otherwise, similar issues will occur again.
> > 
> > I would not like to change the logic in Python to detect the U-Boot
> > prompt for something UEFI specific. And we need a method to determine
> > the size of a serial console.
> > 
> > The current approach allowed me to merge your patch series which
> > otherwise might not have reached the v2020.07 release. Did the problem
> > not show up in your Travis CI testing?
> 
> No. If your saying is correct, this can happen only if efi_console_register()
> is moved after efi_disk_register(). Right?
> 
> > If you have a better solution, we can easily merge your patch.
> 
> First, I want to understand what's happening.
> 
> -Takahiro Akashi
> 
> > Best regards
> > 
> > Heinrich
> > 
> > >
> > > Thanks,
> > > -Takahiro Akashi
> > >
> > >> Signed-off-by: Heinrich Schuchardt <xypron.glpk at gmx.de>
> > >> ---
> > >>  test/py/tests/test_efi_secboot/test_authvar.py  | 8 ++++----
> > >>  test/py/tests/test_efi_secboot/test_signed.py   | 4 ++--
> > >>  test/py/tests/test_efi_secboot/test_unsigned.py | 6 +++---
> > >>  3 files changed, 9 insertions(+), 9 deletions(-)
> > >>
> > >> diff --git a/test/py/tests/test_efi_secboot/test_authvar.py b/test/py/tests/test_efi_secboot/test_authvar.py
> > >> index 55dcaa95f1..9912694a3e 100644
> > >> --- a/test/py/tests/test_efi_secboot/test_authvar.py
> > >> +++ b/test/py/tests/test_efi_secboot/test_authvar.py
> > >> @@ -133,7 +133,7 @@ class TestEfiAuthVar(object):
> > >>              output = u_boot_console.run_command_list([
> > >>                  'host bind 0 %s' % disk_img,
> > >>                  'fatload host 0:1 4000000 PK.auth',
> > >> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> > >> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
> > >>                  'fatload host 0:1 4000000 KEK.auth',
> > >>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> > >>                  'fatload host 0:1 4000000 db.auth',
> > >> @@ -174,7 +174,7 @@ class TestEfiAuthVar(object):
> > >>              output = u_boot_console.run_command_list([
> > >>                  'host bind 0 %s' % disk_img,
> > >>                  'fatload host 0:1 4000000 PK.auth',
> > >> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> > >> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
> > >>                  'fatload host 0:1 4000000 KEK.auth',
> > >>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> > >>                  'fatload host 0:1 4000000 db.auth',
> > >> @@ -215,7 +215,7 @@ class TestEfiAuthVar(object):
> > >>              output = u_boot_console.run_command_list([
> > >>                  'host bind 0 %s' % disk_img,
> > >>                  'fatload host 0:1 4000000 PK.auth',
> > >> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> > >> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
> > >>                  'fatload host 0:1 4000000 KEK.auth',
> > >>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> > >>                  'fatload host 0:1 4000000 db.auth',
> > >> @@ -249,7 +249,7 @@ class TestEfiAuthVar(object):
> > >>              output = u_boot_console.run_command_list([
> > >>                  'host bind 0 %s' % disk_img,
> > >>                  'fatload host 0:1 4000000 PK.auth',
> > >> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> > >> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
> > >>                  'fatload host 0:1 4000000 KEK.auth',
> > >>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> > >>                  'fatload host 0:1 4000000 db.auth',
> > >> diff --git a/test/py/tests/test_efi_secboot/test_signed.py b/test/py/tests/test_efi_secboot/test_signed.py
> > >> index 584282b338..fc722ab506 100644
> > >> --- a/test/py/tests/test_efi_secboot/test_signed.py
> > >> +++ b/test/py/tests/test_efi_secboot/test_signed.py
> > >> @@ -29,7 +29,7 @@ class TestEfiSignedImage(object):
> > >>              # Test Case 1a, run signed image if no db/dbx
> > >>              output = u_boot_console.run_command_list([
> > >>                  'host bind 0 %s' % disk_img,
> > >> -                'efidebug boot add 1 HELLO1 host 0:1 /helloworld.efi.signed ""',
> > >> +                'efidebug boot add 1 HELLO1 host 0:1 /helloworld.efi.signed ""; echo',
> > >>                  'efidebug boot next 1',
> > >>                  'bootefi bootmgr'])
> > >>              assert(re.search('Hello, world!', ''.join(output)))
> > >> @@ -81,7 +81,7 @@ class TestEfiSignedImage(object):
> > >>              output = u_boot_console.run_command_list([
> > >>                  'host bind 0 %s' % disk_img,
> > >>                  'fatload host 0:1 4000000 db.auth',
> > >> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx',
> > >> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx; echo',
> > >>                  'fatload host 0:1 4000000 KEK.auth',
> > >>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> > >>                  'fatload host 0:1 4000000 PK.auth',
> > >> diff --git a/test/py/tests/test_efi_secboot/test_unsigned.py b/test/py/tests/test_efi_secboot/test_unsigned.py
> > >> index 22d849afb8..a4af845c51 100644
> > >> --- a/test/py/tests/test_efi_secboot/test_unsigned.py
> > >> +++ b/test/py/tests/test_efi_secboot/test_unsigned.py
> > >> @@ -30,7 +30,7 @@ class TestEfiUnsignedImage(object):
> > >>              output = u_boot_console.run_command_list([
> > >>                  'host bind 0 %s' % disk_img,
> > >>  		'fatload host 0:1 4000000 KEK.auth',
> > >> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> > >> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK; echo',
> > >>  		'fatload host 0:1 4000000 PK.auth',
> > >>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK'])
> > >>              assert(not re.search('Failed to set EFI variable', ''.join(output)))
> > >> @@ -58,7 +58,7 @@ class TestEfiUnsignedImage(object):
> > >>              output = u_boot_console.run_command_list([
> > >>                  'host bind 0 %s' % disk_img,
> > >>  		'fatload host 0:1 4000000 db_hello.auth',
> > >> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize db',
> > >> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize db; echo',
> > >>  		'fatload host 0:1 4000000 KEK.auth',
> > >>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> > >>  		'fatload host 0:1 4000000 PK.auth',
> > >> @@ -82,7 +82,7 @@ class TestEfiUnsignedImage(object):
> > >>              output = u_boot_console.run_command_list([
> > >>                  'host bind 0 %s' % disk_img,
> > >>  		'fatload host 0:1 4000000 db_hello.auth',
> > >> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx',
> > >> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx; echo',
> > >>  		'fatload host 0:1 4000000 KEK.auth',
> > >>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> > >>  		'fatload host 0:1 4000000 PK.auth',
> > >> --
> > >> 2.26.2
> > >>
> >
AKASHI Takahiro May 21, 2020, 12:23 a.m. UTC | #5
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.
> 
> You have merged your patch without replying to my comment.


Not yet


> > Moreover, I wonder
> > - why you want to move efi_console_register() after efi_disk_register().
> > - why python script can see such escape sequences.
> 
> I don't like your fix.
> With your fixes, my secure boot pytest now fails to run
> on sandbox locally.
> 
> Instead, I propose:
> 1. revert your commits
>    commit 16ad946f41d3 ("efi_loader: change setup sequence")
>    commit 5827c2545849 ("test: stabilize test_efi_secboot")
> 2. move efi_console_register() forward *before* efi_console_register()
> 
> 
> Then my secure boot test should work again without any modification.
> I believe that my solution is much better than your workaround.


Any comment?
Or do you want me to post a patch?


> -Takahiro Akashi
> 
> > > 
> > > >
> > > >> We can avoid the problem if the first UEFI command passed to
> > > >> u_boot_console.run_command_list() produces output. This patch achieves this
> > > >> by appending '; echo' to the first UEFI related command of the problematic
> > > >> tests.
> > > >
> > > > It looks to be a workaround.
> > > > We'd better have another approach to fix the problem.
> > > > Otherwise, similar issues will occur again.
> > > 
> > > I would not like to change the logic in Python to detect the U-Boot
> > > prompt for something UEFI specific. And we need a method to determine
> > > the size of a serial console.
> > > 
> > > The current approach allowed me to merge your patch series which
> > > otherwise might not have reached the v2020.07 release. Did the problem
> > > not show up in your Travis CI testing?
> > 
> > No. If your saying is correct, this can happen only if efi_console_register()
> > is moved after efi_disk_register(). Right?
> > 
> > > If you have a better solution, we can easily merge your patch.
> > 
> > First, I want to understand what's happening.
> > 
> > -Takahiro Akashi
> > 
> > > Best regards
> > > 
> > > Heinrich
> > > 
> > > >
> > > > Thanks,
> > > > -Takahiro Akashi
> > > >
> > > >> Signed-off-by: Heinrich Schuchardt <xypron.glpk at gmx.de>
> > > >> ---
> > > >>  test/py/tests/test_efi_secboot/test_authvar.py  | 8 ++++----
> > > >>  test/py/tests/test_efi_secboot/test_signed.py   | 4 ++--
> > > >>  test/py/tests/test_efi_secboot/test_unsigned.py | 6 +++---
> > > >>  3 files changed, 9 insertions(+), 9 deletions(-)
> > > >>
> > > >> diff --git a/test/py/tests/test_efi_secboot/test_authvar.py b/test/py/tests/test_efi_secboot/test_authvar.py
> > > >> index 55dcaa95f1..9912694a3e 100644
> > > >> --- a/test/py/tests/test_efi_secboot/test_authvar.py
> > > >> +++ b/test/py/tests/test_efi_secboot/test_authvar.py
> > > >> @@ -133,7 +133,7 @@ class TestEfiAuthVar(object):
> > > >>              output = u_boot_console.run_command_list([
> > > >>                  'host bind 0 %s' % disk_img,
> > > >>                  'fatload host 0:1 4000000 PK.auth',
> > > >> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> > > >> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
> > > >>                  'fatload host 0:1 4000000 KEK.auth',
> > > >>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> > > >>                  'fatload host 0:1 4000000 db.auth',
> > > >> @@ -174,7 +174,7 @@ class TestEfiAuthVar(object):
> > > >>              output = u_boot_console.run_command_list([
> > > >>                  'host bind 0 %s' % disk_img,
> > > >>                  'fatload host 0:1 4000000 PK.auth',
> > > >> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> > > >> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
> > > >>                  'fatload host 0:1 4000000 KEK.auth',
> > > >>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> > > >>                  'fatload host 0:1 4000000 db.auth',
> > > >> @@ -215,7 +215,7 @@ class TestEfiAuthVar(object):
> > > >>              output = u_boot_console.run_command_list([
> > > >>                  'host bind 0 %s' % disk_img,
> > > >>                  'fatload host 0:1 4000000 PK.auth',
> > > >> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> > > >> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
> > > >>                  'fatload host 0:1 4000000 KEK.auth',
> > > >>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> > > >>                  'fatload host 0:1 4000000 db.auth',
> > > >> @@ -249,7 +249,7 @@ class TestEfiAuthVar(object):
> > > >>              output = u_boot_console.run_command_list([
> > > >>                  'host bind 0 %s' % disk_img,
> > > >>                  'fatload host 0:1 4000000 PK.auth',
> > > >> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> > > >> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
> > > >>                  'fatload host 0:1 4000000 KEK.auth',
> > > >>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> > > >>                  'fatload host 0:1 4000000 db.auth',
> > > >> diff --git a/test/py/tests/test_efi_secboot/test_signed.py b/test/py/tests/test_efi_secboot/test_signed.py
> > > >> index 584282b338..fc722ab506 100644
> > > >> --- a/test/py/tests/test_efi_secboot/test_signed.py
> > > >> +++ b/test/py/tests/test_efi_secboot/test_signed.py
> > > >> @@ -29,7 +29,7 @@ class TestEfiSignedImage(object):
> > > >>              # Test Case 1a, run signed image if no db/dbx
> > > >>              output = u_boot_console.run_command_list([
> > > >>                  'host bind 0 %s' % disk_img,
> > > >> -                'efidebug boot add 1 HELLO1 host 0:1 /helloworld.efi.signed ""',
> > > >> +                'efidebug boot add 1 HELLO1 host 0:1 /helloworld.efi.signed ""; echo',
> > > >>                  'efidebug boot next 1',
> > > >>                  'bootefi bootmgr'])
> > > >>              assert(re.search('Hello, world!', ''.join(output)))
> > > >> @@ -81,7 +81,7 @@ class TestEfiSignedImage(object):
> > > >>              output = u_boot_console.run_command_list([
> > > >>                  'host bind 0 %s' % disk_img,
> > > >>                  'fatload host 0:1 4000000 db.auth',
> > > >> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx',
> > > >> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx; echo',
> > > >>                  'fatload host 0:1 4000000 KEK.auth',
> > > >>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> > > >>                  'fatload host 0:1 4000000 PK.auth',
> > > >> diff --git a/test/py/tests/test_efi_secboot/test_unsigned.py b/test/py/tests/test_efi_secboot/test_unsigned.py
> > > >> index 22d849afb8..a4af845c51 100644
> > > >> --- a/test/py/tests/test_efi_secboot/test_unsigned.py
> > > >> +++ b/test/py/tests/test_efi_secboot/test_unsigned.py
> > > >> @@ -30,7 +30,7 @@ class TestEfiUnsignedImage(object):
> > > >>              output = u_boot_console.run_command_list([
> > > >>                  'host bind 0 %s' % disk_img,
> > > >>  		'fatload host 0:1 4000000 KEK.auth',
> > > >> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> > > >> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK; echo',
> > > >>  		'fatload host 0:1 4000000 PK.auth',
> > > >>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK'])
> > > >>              assert(not re.search('Failed to set EFI variable', ''.join(output)))
> > > >> @@ -58,7 +58,7 @@ class TestEfiUnsignedImage(object):
> > > >>              output = u_boot_console.run_command_list([
> > > >>                  'host bind 0 %s' % disk_img,
> > > >>  		'fatload host 0:1 4000000 db_hello.auth',
> > > >> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize db',
> > > >> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize db; echo',
> > > >>  		'fatload host 0:1 4000000 KEK.auth',
> > > >>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> > > >>  		'fatload host 0:1 4000000 PK.auth',
> > > >> @@ -82,7 +82,7 @@ class TestEfiUnsignedImage(object):
> > > >>              output = u_boot_console.run_command_list([
> > > >>                  'host bind 0 %s' % disk_img,
> > > >>  		'fatload host 0:1 4000000 db_hello.auth',
> > > >> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx',
> > > >> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx; echo',
> > > >>  		'fatload host 0:1 4000000 KEK.auth',
> > > >>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> > > >>  		'fatload host 0:1 4000000 PK.auth',
> > > >> --
> > > >> 2.26.2
> > > >>
> > >
Heinrich Schuchardt May 21, 2020, 8:17 a.m. UTC | #6
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.

Now the Python test can match the regular expression '^==>' because the
prompt is the first output on the line.

>>
>> You have merged your patch without replying to my comment.

Your comment was written after my pull request.

>
>
> Not yet
>
>
>>> Moreover, I wonder
>>> - why you want to move efi_console_register() after efi_disk_register().
>>> - why python script can see such escape sequences.
>>
>> I don't like your fix.
>> With your fixes, my secure boot pytest now fails to run
>> on sandbox locally.

Why is it failing?

Best regards

Heinrich

>>
>> Instead, I propose:
>> 1. revert your commits
>>    commit 16ad946f41d3 ("efi_loader: change setup sequence")
>>    commit 5827c2545849 ("test: stabilize test_efi_secboot")
>> 2. move efi_console_register() forward *before* efi_console_register()
>>
>>
>> Then my secure boot test should work again without any modification.
>> I believe that my solution is much better than your workaround.
>
>
> Any comment?
> Or do you want me to post a patch?
>
>
>> -Takahiro Akashi
>>
>>>>
>>>>>
>>>>>> We can avoid the problem if the first UEFI command passed to
>>>>>> u_boot_console.run_command_list() produces output. This patch achieves this
>>>>>> by appending '; echo' to the first UEFI related command of the problematic
>>>>>> tests.
>>>>>
>>>>> It looks to be a workaround.
>>>>> We'd better have another approach to fix the problem.
>>>>> Otherwise, similar issues will occur again.
>>>>
>>>> I would not like to change the logic in Python to detect the U-Boot
>>>> prompt for something UEFI specific. And we need a method to determine
>>>> the size of a serial console.
>>>>
>>>> The current approach allowed me to merge your patch series which
>>>> otherwise might not have reached the v2020.07 release. Did the problem
>>>> not show up in your Travis CI testing?
>>>
>>> No. If your saying is correct, this can happen only if efi_console_register()
>>> is moved after efi_disk_register(). Right?
>>>
>>>> If you have a better solution, we can easily merge your patch.
>>>
>>> First, I want to understand what's happening.
>>>
>>> -Takahiro Akashi
>>>
>>>> Best regards
>>>>
>>>> Heinrich
>>>>
>>>>>
>>>>> Thanks,
>>>>> -Takahiro Akashi
>>>>>
>>>>>> Signed-off-by: Heinrich Schuchardt <xypron.glpk at gmx.de>
>>>>>> ---
>>>>>>  test/py/tests/test_efi_secboot/test_authvar.py  | 8 ++++----
>>>>>>  test/py/tests/test_efi_secboot/test_signed.py   | 4 ++--
>>>>>>  test/py/tests/test_efi_secboot/test_unsigned.py | 6 +++---
>>>>>>  3 files changed, 9 insertions(+), 9 deletions(-)
>>>>>>
>>>>>> diff --git a/test/py/tests/test_efi_secboot/test_authvar.py b/test/py/tests/test_efi_secboot/test_authvar.py
>>>>>> index 55dcaa95f1..9912694a3e 100644
>>>>>> --- a/test/py/tests/test_efi_secboot/test_authvar.py
>>>>>> +++ b/test/py/tests/test_efi_secboot/test_authvar.py
>>>>>> @@ -133,7 +133,7 @@ class TestEfiAuthVar(object):
>>>>>>              output = u_boot_console.run_command_list([
>>>>>>                  'host bind 0 %s' % disk_img,
>>>>>>                  'fatload host 0:1 4000000 PK.auth',
>>>>>> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
>>>>>> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
>>>>>>                  'fatload host 0:1 4000000 KEK.auth',
>>>>>>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>>>>>>                  'fatload host 0:1 4000000 db.auth',
>>>>>> @@ -174,7 +174,7 @@ class TestEfiAuthVar(object):
>>>>>>              output = u_boot_console.run_command_list([
>>>>>>                  'host bind 0 %s' % disk_img,
>>>>>>                  'fatload host 0:1 4000000 PK.auth',
>>>>>> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
>>>>>> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
>>>>>>                  'fatload host 0:1 4000000 KEK.auth',
>>>>>>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>>>>>>                  'fatload host 0:1 4000000 db.auth',
>>>>>> @@ -215,7 +215,7 @@ class TestEfiAuthVar(object):
>>>>>>              output = u_boot_console.run_command_list([
>>>>>>                  'host bind 0 %s' % disk_img,
>>>>>>                  'fatload host 0:1 4000000 PK.auth',
>>>>>> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
>>>>>> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
>>>>>>                  'fatload host 0:1 4000000 KEK.auth',
>>>>>>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>>>>>>                  'fatload host 0:1 4000000 db.auth',
>>>>>> @@ -249,7 +249,7 @@ class TestEfiAuthVar(object):
>>>>>>              output = u_boot_console.run_command_list([
>>>>>>                  'host bind 0 %s' % disk_img,
>>>>>>                  'fatload host 0:1 4000000 PK.auth',
>>>>>> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
>>>>>> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
>>>>>>                  'fatload host 0:1 4000000 KEK.auth',
>>>>>>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>>>>>>                  'fatload host 0:1 4000000 db.auth',
>>>>>> diff --git a/test/py/tests/test_efi_secboot/test_signed.py b/test/py/tests/test_efi_secboot/test_signed.py
>>>>>> index 584282b338..fc722ab506 100644
>>>>>> --- a/test/py/tests/test_efi_secboot/test_signed.py
>>>>>> +++ b/test/py/tests/test_efi_secboot/test_signed.py
>>>>>> @@ -29,7 +29,7 @@ class TestEfiSignedImage(object):
>>>>>>              # Test Case 1a, run signed image if no db/dbx
>>>>>>              output = u_boot_console.run_command_list([
>>>>>>                  'host bind 0 %s' % disk_img,
>>>>>> -                'efidebug boot add 1 HELLO1 host 0:1 /helloworld.efi.signed ""',
>>>>>> +                'efidebug boot add 1 HELLO1 host 0:1 /helloworld.efi.signed ""; echo',
>>>>>>                  'efidebug boot next 1',
>>>>>>                  'bootefi bootmgr'])
>>>>>>              assert(re.search('Hello, world!', ''.join(output)))
>>>>>> @@ -81,7 +81,7 @@ class TestEfiSignedImage(object):
>>>>>>              output = u_boot_console.run_command_list([
>>>>>>                  'host bind 0 %s' % disk_img,
>>>>>>                  'fatload host 0:1 4000000 db.auth',
>>>>>> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx',
>>>>>> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx; echo',
>>>>>>                  'fatload host 0:1 4000000 KEK.auth',
>>>>>>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>>>>>>                  'fatload host 0:1 4000000 PK.auth',
>>>>>> diff --git a/test/py/tests/test_efi_secboot/test_unsigned.py b/test/py/tests/test_efi_secboot/test_unsigned.py
>>>>>> index 22d849afb8..a4af845c51 100644
>>>>>> --- a/test/py/tests/test_efi_secboot/test_unsigned.py
>>>>>> +++ b/test/py/tests/test_efi_secboot/test_unsigned.py
>>>>>> @@ -30,7 +30,7 @@ class TestEfiUnsignedImage(object):
>>>>>>              output = u_boot_console.run_command_list([
>>>>>>                  'host bind 0 %s' % disk_img,
>>>>>>  		'fatload host 0:1 4000000 KEK.auth',
>>>>>> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>>>>>> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK; echo',
>>>>>>  		'fatload host 0:1 4000000 PK.auth',
>>>>>>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK'])
>>>>>>              assert(not re.search('Failed to set EFI variable', ''.join(output)))
>>>>>> @@ -58,7 +58,7 @@ class TestEfiUnsignedImage(object):
>>>>>>              output = u_boot_console.run_command_list([
>>>>>>                  'host bind 0 %s' % disk_img,
>>>>>>  		'fatload host 0:1 4000000 db_hello.auth',
>>>>>> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize db',
>>>>>> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize db; echo',
>>>>>>  		'fatload host 0:1 4000000 KEK.auth',
>>>>>>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>>>>>>  		'fatload host 0:1 4000000 PK.auth',
>>>>>> @@ -82,7 +82,7 @@ class TestEfiUnsignedImage(object):
>>>>>>              output = u_boot_console.run_command_list([
>>>>>>                  'host bind 0 %s' % disk_img,
>>>>>>  		'fatload host 0:1 4000000 db_hello.auth',
>>>>>> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx',
>>>>>> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx; echo',
>>>>>>  		'fatload host 0:1 4000000 KEK.auth',
>>>>>>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
>>>>>>  		'fatload host 0:1 4000000 PK.auth',
>>>>>> --
>>>>>> 2.26.2
>>>>>>
>>>>
AKASHI Takahiro May 21, 2020, 9:55 a.m. UTC | #7
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
=&gt; </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
=&gt; </pre>

...

<pre><span class="implicit">=&gt; </span>fatload host 0:1 4000000 KEK.auth
2045 bytes read in 0 ms
=&gt; </pre>

...

<pre><span class="implicit">=&gt; </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=&gt; </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

> >>
> >> You have merged your patch without replying to my comment.
> 
> Your comment was written after my pull request.
> 
> >
> >
> > Not yet
> >
> >
> >>> Moreover, I wonder
> >>> - why you want to move efi_console_register() after efi_disk_register().
> >>> - why python script can see such escape sequences.
> >>
> >> I don't like your fix.
> >> With your fixes, my secure boot pytest now fails to run
> >> on sandbox locally.
> 
> Why is it failing?
> 
> Best regards
> 
> Heinrich
> 
> >>
> >> Instead, I propose:
> >> 1. revert your commits
> >>    commit 16ad946f41d3 ("efi_loader: change setup sequence")
> >>    commit 5827c2545849 ("test: stabilize test_efi_secboot")
> >> 2. move efi_console_register() forward *before* efi_console_register()
> >>
> >>
> >> Then my secure boot test should work again without any modification.
> >> I believe that my solution is much better than your workaround.
> >
> >
> > Any comment?
> > Or do you want me to post a patch?
> >
> >
> >> -Takahiro Akashi
> >>
> >>>>
> >>>>>
> >>>>>> We can avoid the problem if the first UEFI command passed to
> >>>>>> u_boot_console.run_command_list() produces output. This patch achieves this
> >>>>>> by appending '; echo' to the first UEFI related command of the problematic
> >>>>>> tests.
> >>>>>
> >>>>> It looks to be a workaround.
> >>>>> We'd better have another approach to fix the problem.
> >>>>> Otherwise, similar issues will occur again.
> >>>>
> >>>> I would not like to change the logic in Python to detect the U-Boot
> >>>> prompt for something UEFI specific. And we need a method to determine
> >>>> the size of a serial console.
> >>>>
> >>>> The current approach allowed me to merge your patch series which
> >>>> otherwise might not have reached the v2020.07 release. Did the problem
> >>>> not show up in your Travis CI testing?
> >>>
> >>> No. If your saying is correct, this can happen only if efi_console_register()
> >>> is moved after efi_disk_register(). Right?
> >>>
> >>>> If you have a better solution, we can easily merge your patch.
> >>>
> >>> First, I want to understand what's happening.
> >>>
> >>> -Takahiro Akashi
> >>>
> >>>> Best regards
> >>>>
> >>>> Heinrich
> >>>>
> >>>>>
> >>>>> Thanks,
> >>>>> -Takahiro Akashi
> >>>>>
> >>>>>> Signed-off-by: Heinrich Schuchardt <xypron.glpk at gmx.de>
> >>>>>> ---
> >>>>>>  test/py/tests/test_efi_secboot/test_authvar.py  | 8 ++++----
> >>>>>>  test/py/tests/test_efi_secboot/test_signed.py   | 4 ++--
> >>>>>>  test/py/tests/test_efi_secboot/test_unsigned.py | 6 +++---
> >>>>>>  3 files changed, 9 insertions(+), 9 deletions(-)
> >>>>>>
> >>>>>> diff --git a/test/py/tests/test_efi_secboot/test_authvar.py b/test/py/tests/test_efi_secboot/test_authvar.py
> >>>>>> index 55dcaa95f1..9912694a3e 100644
> >>>>>> --- a/test/py/tests/test_efi_secboot/test_authvar.py
> >>>>>> +++ b/test/py/tests/test_efi_secboot/test_authvar.py
> >>>>>> @@ -133,7 +133,7 @@ class TestEfiAuthVar(object):
> >>>>>>              output = u_boot_console.run_command_list([
> >>>>>>                  'host bind 0 %s' % disk_img,
> >>>>>>                  'fatload host 0:1 4000000 PK.auth',
> >>>>>> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> >>>>>> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
> >>>>>>                  'fatload host 0:1 4000000 KEK.auth',
> >>>>>>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> >>>>>>                  'fatload host 0:1 4000000 db.auth',
> >>>>>> @@ -174,7 +174,7 @@ class TestEfiAuthVar(object):
> >>>>>>              output = u_boot_console.run_command_list([
> >>>>>>                  'host bind 0 %s' % disk_img,
> >>>>>>                  'fatload host 0:1 4000000 PK.auth',
> >>>>>> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> >>>>>> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
> >>>>>>                  'fatload host 0:1 4000000 KEK.auth',
> >>>>>>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> >>>>>>                  'fatload host 0:1 4000000 db.auth',
> >>>>>> @@ -215,7 +215,7 @@ class TestEfiAuthVar(object):
> >>>>>>              output = u_boot_console.run_command_list([
> >>>>>>                  'host bind 0 %s' % disk_img,
> >>>>>>                  'fatload host 0:1 4000000 PK.auth',
> >>>>>> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> >>>>>> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
> >>>>>>                  'fatload host 0:1 4000000 KEK.auth',
> >>>>>>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> >>>>>>                  'fatload host 0:1 4000000 db.auth',
> >>>>>> @@ -249,7 +249,7 @@ class TestEfiAuthVar(object):
> >>>>>>              output = u_boot_console.run_command_list([
> >>>>>>                  'host bind 0 %s' % disk_img,
> >>>>>>                  'fatload host 0:1 4000000 PK.auth',
> >>>>>> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
> >>>>>> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
> >>>>>>                  'fatload host 0:1 4000000 KEK.auth',
> >>>>>>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> >>>>>>                  'fatload host 0:1 4000000 db.auth',
> >>>>>> diff --git a/test/py/tests/test_efi_secboot/test_signed.py b/test/py/tests/test_efi_secboot/test_signed.py
> >>>>>> index 584282b338..fc722ab506 100644
> >>>>>> --- a/test/py/tests/test_efi_secboot/test_signed.py
> >>>>>> +++ b/test/py/tests/test_efi_secboot/test_signed.py
> >>>>>> @@ -29,7 +29,7 @@ class TestEfiSignedImage(object):
> >>>>>>              # Test Case 1a, run signed image if no db/dbx
> >>>>>>              output = u_boot_console.run_command_list([
> >>>>>>                  'host bind 0 %s' % disk_img,
> >>>>>> -                'efidebug boot add 1 HELLO1 host 0:1 /helloworld.efi.signed ""',
> >>>>>> +                'efidebug boot add 1 HELLO1 host 0:1 /helloworld.efi.signed ""; echo',
> >>>>>>                  'efidebug boot next 1',
> >>>>>>                  'bootefi bootmgr'])
> >>>>>>              assert(re.search('Hello, world!', ''.join(output)))
> >>>>>> @@ -81,7 +81,7 @@ class TestEfiSignedImage(object):
> >>>>>>              output = u_boot_console.run_command_list([
> >>>>>>                  'host bind 0 %s' % disk_img,
> >>>>>>                  'fatload host 0:1 4000000 db.auth',
> >>>>>> -                'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx',
> >>>>>> +                'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx; echo',
> >>>>>>                  'fatload host 0:1 4000000 KEK.auth',
> >>>>>>                  'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> >>>>>>                  'fatload host 0:1 4000000 PK.auth',
> >>>>>> diff --git a/test/py/tests/test_efi_secboot/test_unsigned.py b/test/py/tests/test_efi_secboot/test_unsigned.py
> >>>>>> index 22d849afb8..a4af845c51 100644
> >>>>>> --- a/test/py/tests/test_efi_secboot/test_unsigned.py
> >>>>>> +++ b/test/py/tests/test_efi_secboot/test_unsigned.py
> >>>>>> @@ -30,7 +30,7 @@ class TestEfiUnsignedImage(object):
> >>>>>>              output = u_boot_console.run_command_list([
> >>>>>>                  'host bind 0 %s' % disk_img,
> >>>>>>  		'fatload host 0:1 4000000 KEK.auth',
> >>>>>> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> >>>>>> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK; echo',
> >>>>>>  		'fatload host 0:1 4000000 PK.auth',
> >>>>>>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK'])
> >>>>>>              assert(not re.search('Failed to set EFI variable', ''.join(output)))
> >>>>>> @@ -58,7 +58,7 @@ class TestEfiUnsignedImage(object):
> >>>>>>              output = u_boot_console.run_command_list([
> >>>>>>                  'host bind 0 %s' % disk_img,
> >>>>>>  		'fatload host 0:1 4000000 db_hello.auth',
> >>>>>> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize db',
> >>>>>> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize db; echo',
> >>>>>>  		'fatload host 0:1 4000000 KEK.auth',
> >>>>>>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> >>>>>>  		'fatload host 0:1 4000000 PK.auth',
> >>>>>> @@ -82,7 +82,7 @@ class TestEfiUnsignedImage(object):
> >>>>>>              output = u_boot_console.run_command_list([
> >>>>>>                  'host bind 0 %s' % disk_img,
> >>>>>>  		'fatload host 0:1 4000000 db_hello.auth',
> >>>>>> -		'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx',
> >>>>>> +		'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx; echo',
> >>>>>>  		'fatload host 0:1 4000000 KEK.auth',
> >>>>>>  		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
> >>>>>>  		'fatload host 0:1 4000000 PK.auth',
> >>>>>> --
> >>>>>> 2.26.2
> >>>>>>
> >>>>
>
Heinrich Schuchardt May 22, 2020, 6:13 a.m. UTC | #8
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
> =&gt; </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
> =&gt; </pre>
>
> ...
>
> <pre><span class="implicit">=&gt; </span>fatload host 0:1 4000000 KEK.auth
> 2045 bytes read in 0 ms
> =&gt; </pre>
>
> ...
>
> <pre><span class="implicit">=&gt; </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=&gt; </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
diff mbox series

Patch

diff --git a/test/py/tests/test_efi_secboot/test_authvar.py b/test/py/tests/test_efi_secboot/test_authvar.py
index 55dcaa95f1..9912694a3e 100644
--- a/test/py/tests/test_efi_secboot/test_authvar.py
+++ b/test/py/tests/test_efi_secboot/test_authvar.py
@@ -133,7 +133,7 @@  class TestEfiAuthVar(object):
             output = u_boot_console.run_command_list([
                 'host bind 0 %s' % disk_img,
                 'fatload host 0:1 4000000 PK.auth',
-                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
+                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
                 'fatload host 0:1 4000000 KEK.auth',
                 'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
                 'fatload host 0:1 4000000 db.auth',
@@ -174,7 +174,7 @@  class TestEfiAuthVar(object):
             output = u_boot_console.run_command_list([
                 'host bind 0 %s' % disk_img,
                 'fatload host 0:1 4000000 PK.auth',
-                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
+                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
                 'fatload host 0:1 4000000 KEK.auth',
                 'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
                 'fatload host 0:1 4000000 db.auth',
@@ -215,7 +215,7 @@  class TestEfiAuthVar(object):
             output = u_boot_console.run_command_list([
                 'host bind 0 %s' % disk_img,
                 'fatload host 0:1 4000000 PK.auth',
-                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
+                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
                 'fatload host 0:1 4000000 KEK.auth',
                 'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
                 'fatload host 0:1 4000000 db.auth',
@@ -249,7 +249,7 @@  class TestEfiAuthVar(object):
             output = u_boot_console.run_command_list([
                 'host bind 0 %s' % disk_img,
                 'fatload host 0:1 4000000 PK.auth',
-                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK',
+                'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK; echo',
                 'fatload host 0:1 4000000 KEK.auth',
                 'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
                 'fatload host 0:1 4000000 db.auth',
diff --git a/test/py/tests/test_efi_secboot/test_signed.py b/test/py/tests/test_efi_secboot/test_signed.py
index 584282b338..fc722ab506 100644
--- a/test/py/tests/test_efi_secboot/test_signed.py
+++ b/test/py/tests/test_efi_secboot/test_signed.py
@@ -29,7 +29,7 @@  class TestEfiSignedImage(object):
             # Test Case 1a, run signed image if no db/dbx
             output = u_boot_console.run_command_list([
                 'host bind 0 %s' % disk_img,
-                'efidebug boot add 1 HELLO1 host 0:1 /helloworld.efi.signed ""',
+                'efidebug boot add 1 HELLO1 host 0:1 /helloworld.efi.signed ""; echo',
                 'efidebug boot next 1',
                 'bootefi bootmgr'])
             assert(re.search('Hello, world!', ''.join(output)))
@@ -81,7 +81,7 @@  class TestEfiSignedImage(object):
             output = u_boot_console.run_command_list([
                 'host bind 0 %s' % disk_img,
                 'fatload host 0:1 4000000 db.auth',
-                'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx',
+                'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx; echo',
                 'fatload host 0:1 4000000 KEK.auth',
                 'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
                 'fatload host 0:1 4000000 PK.auth',
diff --git a/test/py/tests/test_efi_secboot/test_unsigned.py b/test/py/tests/test_efi_secboot/test_unsigned.py
index 22d849afb8..a4af845c51 100644
--- a/test/py/tests/test_efi_secboot/test_unsigned.py
+++ b/test/py/tests/test_efi_secboot/test_unsigned.py
@@ -30,7 +30,7 @@  class TestEfiUnsignedImage(object):
             output = u_boot_console.run_command_list([
                 'host bind 0 %s' % disk_img,
 		'fatload host 0:1 4000000 KEK.auth',
-		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
+		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK; echo',
 		'fatload host 0:1 4000000 PK.auth',
 		'setenv -e -nv -bs -rt -at -i 4000000,$filesize PK'])
             assert(not re.search('Failed to set EFI variable', ''.join(output)))
@@ -58,7 +58,7 @@  class TestEfiUnsignedImage(object):
             output = u_boot_console.run_command_list([
                 'host bind 0 %s' % disk_img,
 		'fatload host 0:1 4000000 db_hello.auth',
-		'setenv -e -nv -bs -rt -at -i 4000000,$filesize db',
+		'setenv -e -nv -bs -rt -at -i 4000000,$filesize db; echo',
 		'fatload host 0:1 4000000 KEK.auth',
 		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
 		'fatload host 0:1 4000000 PK.auth',
@@ -82,7 +82,7 @@  class TestEfiUnsignedImage(object):
             output = u_boot_console.run_command_list([
                 'host bind 0 %s' % disk_img,
 		'fatload host 0:1 4000000 db_hello.auth',
-		'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx',
+		'setenv -e -nv -bs -rt -at -i 4000000,$filesize dbx; echo',
 		'fatload host 0:1 4000000 KEK.auth',
 		'setenv -e -nv -bs -rt -at -i 4000000,$filesize KEK',
 		'fatload host 0:1 4000000 PK.auth',