From mboxrd@z Thu Jan 1 00:00:00 1970 From: AKASHI Takahiro Date: Thu, 21 May 2020 18:55:56 +0900 Subject: [PATCH 1/1] test: stabilize test_efi_secboot In-Reply-To: <41b8f036-723f-2c82-a385-ff35d7117921@gmx.de> References: <20200504103326.88607-1-xypron.glpk@gmx.de> <20200507003612.GE20621@laputa> <949189ef-25e4-ba5d-0342-cf83666f5505@gmx.de> <20200507231028.GA30323@laputa> <20200511065656.GA6650@laputa> <20200521002330.GA24154@laputa> <41b8f036-723f-2c82-a385-ff35d7117921@gmx.de> Message-ID: <20200521095556.GA10651@laputa> List-Id: MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit To: u-boot@lists.denx.de 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 === ... 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 => ... 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 => ... 
=> fatload host 0:1 4000000 KEK.auth
2045 bytes read in 0 ms
=>
... 
=> 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=>
... === 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 > >>>>>> --- > >>>>>> 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 > >>>>>> > >>>> >