Re: [PATCH 1/2] HABv4: remove useless error message

[Sascha Hauer <s.hauer@pengutronix.de>]

On Tue, Dec 03, 2019 at 03:04:45PM +0100, Marc Kleine-Budde wrote:
> On 12/2/19 3:30 PM, Juergen Borleis wrote:
> > Am Montag, den 02.12.2019, 14:24 +0100 schrieb Marc Kleine-Budde:
> >> On 12/2/19 2:07 PM, Roland Hieber wrote:
> >>> On Mon, Dec 02, 2019 at 11:24:48AM +0100, Juergen Borleis wrote:
> >>>> This change removes the stupid error message at the end of the generated
> >>>
> >>> I think there was some reason behind that code, so it is probably not
> >>> stupid, and you've run into an edge case that never happened before (at
> >>> least I've never seen this on any of my boards when using HABv4).
> >>
> >> The last time, I've seen this messages was before implementing:
> >>
> >> 81e2b508e785 i.MX habv4: habv4_get_status(): display warning events, too
> >>
> >> So Roland is probably right, you've hit a corner case, that's not
> >> correctly handled.
> > 
> > Hmmm:
> > 
> > […]
> > barebox 2019.11.0-20191121-3 #1 Thu Nov 21 14:28:21 UTC 2019
> > 
> > Board: <some customer board>
> > detected i.MX6 UltraLite revision 1.2
> > i.MX reset reason WDG (SRSR: 0x00000010)
> > i.MX6 UltraLite unique ID: xxxxxxxxxxxxxxxx
> > HABv4: Status: Operation failed (0x33)
> > HABv4: Config: Non-secure IC (0xf0)
> > HABv4: State: Non-secure state (0x66)
> > HABv4: -------- HAB failure Event 0 --------
> > HABv4: event data:
> > HABv4:  db 00 08 42  33 22 0a 00
> > HABv4: Status: Operation failed (0x33)
> > HABv4: Reason: Invalid address: access denied (0x22)
> > HABv4: Context: Logged in hab_rvt.authenticate_image() (0x0a)
> > HABv4: Engine: Select first compatible engine (0x00)
> > HABv4: -------- HAB failure Event 1 --------
> > HABv4: event data:
> > HABv4:  db 00 14 42  33 0c a0 00
> > HABv4:  00 00 00 00  80 00 04 00
> > HABv4:  00 00 00 20
> > HABv4: Status: Operation failed (0x33)
> > HABv4: Reason: Invalid assertion (0x0c)
> > HABv4: Context: Event logged in hab_rvt.assert() (0xa0)
> > HABv4: Engine: Select first compatible engine (0x00)
> > HABv4: -------- HAB failure Event 2 --------
> > HABv4: event data:
> > HABv4:  db 00 14 42  33 0c a0 00
> > HABv4:  00 00 00 00  80 00 04 20
> > HABv4:  00 00 00 01
> > HABv4: Status: Operation failed (0x33)
> > HABv4: Reason: Invalid assertion (0x0c)
> > HABv4: Context: Event logged in hab_rvt.assert() (0xa0)
> > HABv4: Engine: Select first compatible engine (0x00)
> > HABv4: -------- HAB failure Event 3 --------
> > HABv4: event data:
> > HABv4:  db 00 14 42  33 0c a0 00
> > HABv4:  00 00 00 00  80 00 10 00
> > HABv4:  00 00 00 04
> > HABv4: Status: Operation failed (0x33)
> > HABv4: Reason: Invalid assertion (0x0c)
> > HABv4: Context: Event logged in hab_rvt.assert() (0xa0)
> > HABv4: Engine: Select first compatible engine (0x00)
> > HABv4: ERROR: Recompile with larger event data buffer (at least 8 bytes)
> > […]
> > 
> > barebox 2019.11.0-20191126-1 #1 Wed Nov 27 10:19:22 UTC 2019
> > 
> > Board: <some customer board>
> > detected i.MX6 UltraLite revision 1.2
> > i.MX reset reason POR (SRSR: 0x00000001)
> > i.MX6 UltraLite unique ID: xxxxxxxxxxxxxxxx
> > HABv4: Status: Operation failed (0x33)
> > HABv4: Config: Secure IC (0xcc)
> > HABv4: State: Trusted state (0x99)
> > HABv4: -------- HAB failure Event 0 --------
> > HABv4: event data:
> > HABv4:  db 00 14 42  33 22 33 00
> > HABv4:  00 00 00 55  02 1d 01 08
> > HABv4:  00 00 00 04
> > HABv4: Status: Operation failed (0x33)
> > HABv4: Reason: Invalid address: access denied (0x22)
> > HABv4: Context: Event logged in hab_rvt.check_target() (0x33)
> > HABv4: Engine: Select first compatible engine (0x00)
> > HABv4: ERROR: Recompile with larger event data buffer (at least 20 bytes)
> > […]
> > 
> >>> The code goes back until the first incarnaction of HABv4 in commit
> >>> 29abc10d44c2 - Marc, do you still know more details why it was done this
> >>> way?
> >>
> >> This was part of the patches I picked up from fsl, see commit message
> >> for more details:
> >>
> >> 29abc10d44c2 habv4: add High Assurance Boot v4
> >>
> >> Albeit giving an incorrect error message, it showed that there were
> >> warnings events on the new mx6 silicon revisions that were not handled
> >> before 81e2b508e785.
> > 
> > Hmm, 81e2b508e785 does not match the documented API and breaks the report. It
> > was fixed by e7c33540d0c092c28b227d4b7602cef8ab203ef3 later on.
> > 
> > But also with e7c33540d0c092c28b227d4b7602cef8ab203ef3 the query related to this
> > error message was changed to index 0 as well. And now, if at least one event is
> > in the  buffer, this error message will always be printed. Before
> > e7c33540d0c092c28b227d4b7602cef8ab203ef3 it was (most of the time) never be
> > printed, because it tries once again to query an index which was already the
> > cause to leave the loop before.
> > And let me guess: you saw the error message, because your event buffer contained
> > one failure and two warnings...
> 
> I think there is just one warning in the buffer:
> 
> > HABv4: Status: Operation completed with warning (0x69)
> > HABv4: Config: Secure IC (0xcc)
> > HABv4: State: Trusted state (0x99)
> > HABv4: ERROR: Recompile with larger event data buffer (at least 36 bytes)
> 
> The barebox producing that output is missing both patches:
> 
> 81e2b508e785 i.MX habv4: habv4_get_status(): display warning events, too
> e7c33540d0c0 i.MX: HABv4: Reset index variable after error type
> 
> The question is, do we know why we see this error message? I don't have
> good feeling when we remove it, because it's annoying and we don't
> understand why we see it.

The message is wrong because the code is wrong. Let's see:

        /* Check reason for stopping */
        len = sizeof(data);
        index = 0;
        if (rvt->report_event(HAB_STATUS_ANY, index, NULL, &len) == HAB_STATUS_SUCCESS)
                pr_err("ERROR: Recompile with larger event data buffer (at least %d bytes)\n\n", len);

report_event() like called above will give you the first message of any
type (HAB_STATUS_ANY) with index 0. It will do so successfully, so it
returns HAB_STATUS_SUCCESS.

&len on entry means the length of the buffer (here sizeof(data), large
enough). &len on exit is the length of the actual message returned. If
&len is smaller than on entry it means the message buffer was big
enough. If it's bigger, then we must increase the buffer size and call
again.

The message buffer is big enough, so report_event copies the buffer
and returns 36 bytes were copied, but we answer with "Error: Recompile
with a larger event data buffer".

Sascha

-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

_______________________________________________
barebox mailing list
barebox@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/barebox