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@10002000, eth5: eth@10003000, eth3: sbe5, eth1: eth@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@10002000, eth5: eth@10003000, eth3: sbe5, eth1: eth@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
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:
- revert your commits commit 16ad946f41d3 ("efi_loader: change setup sequence") commit 5827c2545849 ("test: stabilize test_efi_secboot")
- 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@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 >