[coreboot] CBMEM Console corruption with fsp_baytrail in coreboot 4.2

[Ben Gardner]

On Fri, Nov 20, 2015 at 12:17 PM, Aaron Durbin <adurbin at google.com> wrote:
> On Fri, Nov 20, 2015 at 7:30 AM, Ben Gardner <gardner.ben at gmail.com> wrote:
>> Hi Aaron,
>>
>> That patch didn't make a difference that I could see. The console
>> buffer is still filled with garbage that cbmemc_reinit() copies into
>> the final buffer.
>> The issue was also with the timestamps, so special handling of the
>> console may not do the trick.
>>
>> I'm not sure if it is helpful, but here is my logging function (gmail
>> eats the tabs):
>> void log_current_console(const char *func)
>> {
>> struct cbmem_console *cbm_cons_p = current_console();
>> #ifdef __PRE_RAM__
>>     hexdump(BIOS_ERR, _car_data_start, _car_data_end - _car_data_start);
>> #endif
>> if (cbm_cons_p) {
>> printk(BIOS_ERR, "%s: cbm_cons_p: %p size=%d cur=%d\n", func,
>>       cbm_cons_p,
>>       cbm_cons_p->buffer_size,
>>       cbm_cons_p->buffer_cursor);
>>         hexdump(BIOS_ERR, cbm_cons_p, 64);
>> } else {
>> printk(BIOS_ERR, "%s: cbm_cons_p: NULL\n", func);
>> }
>> }
>>
>> Logs with your patch:
>> fef00c00: 00 00 00 00 00 00 f0 fe                          ........
>> romstage_fsp_rt_buffer_callback: cbm_cons_p: fef00000 size=3064 cur=2434
>> fef00000: f8 0b 00 00 e0 09 00 00 66 65 66 30 30 63 30 30  ........fef00c00
>> fef00010: 3a 20 30 30 20 30 30 20 30 30 20 30 30 20 30 30  : 00 00 00 00 00
>> fef00020: 20 30 30 20 66 30 20 66 65 20 20 20 20 20 20 20   00 f0 fe
>> fef00030: 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20
>> fef00c00: 00 00 00 00 00 00 f0 fe                          ........
>> fsp_early_init: cbm_cons_p: fef00000 size=3064 cur=2879
>> fef00000: f8 0b 00 00 8c 0b 00 00 66 65 66 30 30 63 30 30  ........fef00c00
>> fef00010: 3a 20 30 30 20 30 30 20 30 30 20 30 30 20 30 30  : 00 00 00 00 00
>> fef00020: 20 30 30 20 66 30 20 66 65 20 20 20 20 20 20 20   00 f0 fe
>> fef00030: 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20
>> fef00c00: ff ff ff ff ff ff ff ff                          ........
>> romstage_main_continue: cbm_cons_p: 00000ca7 size=1241003328 cur=1794134956
>> 00000ca7: 40 35 f8 49 0d 54 f0 6a c6 bc 50 1e 75 07 7c 2c  @5.I7T.j..P.u.|,
>> 00000cb7: 6b 85 35 98 82 cf 75 97 1b 55 8e 5c c9 1f 85 ad  k.5...u..U.\....
>> 00000cc7: 32 1e df fc 10 ef e0 81 46 73 b5 cf b1 f5 3b b5  2.......Fs....;.
>> 00000cd7: af 95 2c 32 16 25 75 2a 14 a4 42 46 bf 62 93 6a  ..,2.%u*..BF.b.j
>> romstage_main_continue status: 0  hob_list_ptr: 7ae20000
>>
>> Logs with my modification to car.ld:
>> fef00000: 00 00 00 00 08 00 f0 fe                          ........
>> romstage_fsp_rt_buffer_callback: cbm_cons_p: fef00008 size=3064 cur=2434
>> fef00008: f8 0b 00 00 e0 09 00 00 66 65 66 30 30 30 30 30  ........fef00000
>> fef00018: 3a 20 30 30 20 30 30 20 30 30 20 30 30 20 30 38  : 00 00 00 00 08
>> fef00028: 20 30 30 20 66 30 20 66 65 20 20 20 20 20 20 20   00 f0 fe
>> fef00038: 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20
>> fef00000: 00 00 00 00 08 00 f0 fe                          ........
>> fsp_early_init: cbm_cons_p: fef00008 size=3064 cur=2879
>> fef00008: f8 0b 00 00 8c 0b 00 00 66 65 66 30 30 30 30 30  ........fef00000
>> fef00018: 3a 20 30 30 20 30 30 20 30 30 20 30 30 20 30 38  : 00 00 00 00 08
>> fef00028: 20 30 30 20 66 30 20 66 65 20 20 20 20 20 20 20   00 f0 fe
>> fef00038: 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20
>> fef00000: ff ff ff ff ff ff ff ff                          ........
>> romstage_main_continue: cbm_cons_p: 7ae230a8 size=3064 cur=3307
>> 7ae230a8: f8 0b 00 00 40 0d 00 00 66 65 66 30 30 30 30 30  ....j...fef00000
>> 7ae230b8: 3a 20 30 30 20 30 30 20 30 30 20 30 30 20 30 38  : 00 00 00 00 08
>> 7ae230c8: 20 30 30 20 66 30 20 66 65 20 20 20 20 20 20 20   00 f0 fe
>> 7ae230d8: 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20
>> romstage_main_continue status: 0  hob_list_ptr: 7ae20000
>>
>> The only difference is in the _car_data_start output, byte 4. 0x00 vs 0x08.
>>
>>
>> The romstage.map files I think are quite interesting.
>>
>> romstage.map snipppet with your patch:
>> fef00000 B _preram_cbmem_console
>> fef00001 b _
>> fef00c00 B _car_data_start
>> fef00c00 B _car_global_start
>> fef00c00 B _epreram_cbmem_console
>> fef00c00 b car_migrated
>> fef00c04 b cbmem_console_p
>> fef00c08 B _car_data_end
>> fef00c08 B _car_global_end
>>
>>
>> romstage.map snipppet with the change to car.ld:
>> fef00000 B _car_data_start
>> fef00000 B _car_global_start
>> fef00000 b car_migrated
>> fef00001 b _
>> fef00004 b cbmem_console_p
>> fef00008 B _car_data_end
>> fef00008 B _car_global_end
>> fef00008 B _preram_cbmem_console
>> fef00c08 B _epreram_cbmem_console
>>
>>
>> It looks like the _preram_cbmem_console is overlapping the car data!
>
> It's not overlapping in either map. The *_end' and
> _epreram_cbmem_console symbols are exclusive of the range.
>
> cbm_cons_p: 00000ca7  <- that is the biggest issue. The
> cbmem_console_p is being updated to a not so great value.
>
> current_console() returns the console using car_sync_var(cbmem_console_p);
>
> car_sync_var() is a macro which is expanded to:
>
> *(typeof (var) *)car_sync_var_ptr(&(var))
>
> which would be *(struct cbmem_console **)car_sync_var_ptr(&cbmem_console_p);
>
> So we are calling car_sync_var_ptr(0xfef00c04);
>
> At the beginning of car_sync_var_ptr() we call this: car_get_var_ptr(var);
>
> Which is car_get_var_ptr(0xfef00c04);
>
> It would be interesting to see the migrated_base value in
> car_get_var_ptr(), but that will be impossible w/ cbmem console proper
> since it will recursively call back down this sequence. Assuming
> migrated base is correct we should be seeing the value in that area
> for cbmem_console_p to be 0xfef00000 which is _preram_cbmem_console.

I added a version of printk that only sends data to the UART.
migrated_base is either 0 or 0x7ae230a0.
It becomes 0x7ae230a0 right after the FSP call.

> The symbols are all relative to one another so I'd expect the
> migration adjustment to be valid. When I said assuming migrated base
> is correct I am probably wrong because we're getting whacky pointers.
>
> I'm still not clear how FSP 1.0 does memory migration. But it might be
> interesting to dump the contents of the region found in
> find_saved_temp_mem(), but I'm not sure how big it is.

I'll start by logging 64 bytes and see what that gets us.