Re: [RFC PATCH v1 2/2] printk: external log buffer (CONFIG_LOGBUFFER)

[Sean Hudson]

On 9/30/2016 7:39 AM, Petr Mladek wrote:
> On Thu 2016-09-29 19:55:56, Sean Hudson wrote:
>> This debug feature provides a convenient way to collect log entries across
>> multiple, warmboot cycles and to share those entries with a boot loader.
>> It allows the kernel to use an external buffer for kernel log messages and
>> is controlled by an optional command line parameter. The buffer can contain
>> existing log messages from previous boot cycles and/or the bootloader. The
>> command line parameter was chosen for flexibility, cross arch portability,
>> and the ability to dynamically enable/disable this feature. The parameter
>> specifies the address of a control block used to replace the default log
>> buffer.  Existing bootloader and kernel log messages are kept, in order,
>> inside the new buffer.  After a boot that preserves the buffer contents, a
>> bootloader can display both kernel and bootloader log entries from
>> multiple, previous boots. It also allows the kernel to display bootloader
>> log entries along with its own messages.
>>
>> This feature is intended for debug purposes and has no effect unless the
>> command line parameter is specified.  Further, it validates the passed
>> control block carefully and if any checks fail, it falls back to the
>> default behaviour.  As such, it can be left enabled by default.
>>
>> Memory Reservation
>> ------------------
>> This feature expects the bootloader to reserve/preserve the shared buffer
>> memory. This reservation needs to prevent the kernel from overwriting the
>> external log control block and log entries. In my testing, I've used the
>> 'fdt' commands in uboot to dynamically inject reserved memory regions via
>> the DT to the kernel.
>>
>> Based on the initial work of Wolfgang Denk and Igor Lisitsin [1].
>> Also based on work by: Alexander Streit <Alexander.Streit@xxxxxxxxxxxxxxxxxxxxxxxxxxx>
>>
>> [1] http://git.denx.de/?p=linux-2.6-denx.git;a=commitdiff;h=212f61c7fd3b952a81d1459dd32a86a32ddfd4ce
>>
>> Signed-off-by: Sean Hudson <sean_hudson@xxxxxxxxxx>
>> ---
>>  init/Kconfig           |  12 +++
>>  init/main.c            |   2 +
>>  kernel/printk/printk.c | 267 +++++++++++++++++++++++++++++++++++++++++++++++--
>>  3 files changed, 275 insertions(+), 6 deletions(-)
>>
>> diff --git a/init/Kconfig b/init/Kconfig
>> index cac3f09..746183b 100644
>> --- a/init/Kconfig
>> +++ b/init/Kconfig
>> @@ -1493,6 +1493,18 @@ config PRINTK
>>  	  very difficult to diagnose system problems, saying N here is
>>  	  strongly discouraged.
>>  
>> +config LOGBUFFER
>> +	bool "External logbuffer" if PRINTK
>> +	default n
>> +	depends on PRINTK
>> +	help
>> +	  This option enables support for an alternative, "external" printk log
>> +	  buffer. If memory contents are preserved, e.g. after a warmboot, this
>> +	  provides a known location for the boot loader to read and display printk
>> +	  entries from the kernel.  If desired, the bootloader can write its own
>> +	  log entries which the kernel will display with its own log entries.
>> +	  Further, this capability can be used across multiple warmboot cycles.
>> +
>>  config PRINTK_NMI
>>  	def_bool y
>>  	depends on PRINTK
>> diff --git a/init/main.c b/init/main.c
>> index a8a58e2..4a5913c 100644
>> --- a/init/main.c
>> +++ b/init/main.c
>> @@ -93,6 +93,7 @@ static int kernel_init(void *);
>>  extern void init_IRQ(void);
>>  extern void fork_init(void);
>>  extern void radix_tree_init(void);
>> +extern void setup_ext_logbuff(void);
>>  
>>  /*
>>   * Debug helper: via this flag we know that we are in 'early bootup code'
>> @@ -535,6 +536,7 @@ asmlinkage __visible void __init start_kernel(void)
>>  	sort_main_extable();
>>  	trap_init();
>>  	mm_init();
>> +	setup_ext_logbuff();
>>  
>>  	/*
>>  	 * Set up the scheduler prior starting any interrupts (such as the
>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>> index 7a441f5..017b4d4 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -395,13 +402,42 @@ struct lcb_t {
>> +/*
>> + * The bootloader may write an unexpected version/format of the log, so
>> + * these values provide a way to check that the format agrees.
>> + */
>> +#define LOGBUFF_MAGIC			0xc0de4ced
>> +#define LOGBUFF_LOG_VERSION		3
>> +#define LOGBUFF_CB_PADDED_LENGTH	1024
>>  
>>  static struct lcb_t __lcb = {
>> +	__log_buf, __LOG_BUF_LEN, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
>> +	LOGBUFF_LOG_VERSION, LOGBUFF_CB_PADDED_LENGTH, sizeof(struct lcb_t),
>> +	sizeof(struct printk_log), 0, LOGBUFF_MAGIC
>> +};
>> +#else
>> +static struct lcb_t __lcb = {
>>  	__log_buf, __LOG_BUF_LEN, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 };
>> +#endif /* CONFIG_LOGBUFFER */
>>  
>>  static struct lcb_t *lcb = &__lcb;
>>  
>> +void setup_ext_logbuff(void);
>> +
>>  /* Return log buffer address */
>>  char *log_buf_addr_get(void)
>>  {
>> +/*
>> + * The bootloader may write a different version of the log than expected.
>> + * So, check that the incoming lcb matches that values that the kernel
>> + * expects.
>> + */
>> +static bool is_valid_external_cb(const struct lcb_t * const new_lcb)
>> +{
>> +	/* Validate the new control buffer */
>> +	return (new_lcb &&
>> +		new_lcb->log_version == LOGBUFF_LOG_VERSION &&
>> +		new_lcb->lcb_magic == LOGBUFF_MAGIC &&
> 
> The bootloader might be able to write the messages in different
> formats. How would it know which one will be the right one
> for the given kernel, please?
> 
> What are the plans? Do you want to add and maintain the compatibility
> in U-boot or also in other bootloaders?
> 
> BTW: I always wanted to put all these infornation into a struct.
> Also I wanted to rename struct printk_log to a less confusing
> name, e.g. printk_msg. The problem is that these structures
> are used also by external aplications, .e.g crash, makedumpfine
> that need to be updated as well. It is a pain. So, I am a bit
> scared to add even more external applications that depend
> on these structures.
> 
> 
>> +		new_lcb->lcb_padded_len == LOGBUFF_CB_PADDED_LENGTH &&
>> +		new_lcb->lcb_size == sizeof(struct lcb_t) &&
>> +		new_lcb->log_hdr_size == sizeof(struct printk_log) &&
>> +		new_lcb->lcb_size <= new_lcb->lcb_padded_len &&
>> +		new_lcb->log_first_idx <= new_lcb->log_buf_len &&
>> +		new_lcb->log_next_idx <= new_lcb->log_buf_len &&
>> +		new_lcb->syslog_idx <= new_lcb->log_buf_len &&
>> +		new_lcb->console_idx <= new_lcb->log_buf_len &&
>> +		new_lcb->clear_idx <= new_lcb->log_buf_len &&
>> +		new_lcb->log_phys_addr != 0);
>> +}
>> +
>> +/*
>> + * Copy the kernel log entries that have occurred so far in this boot cycle
>> + * into the new log buffer location found in the log control block specified
>> + * on the kernel command line. Then switch to using that location from this
>> + * point onward.
>> + * To ensure correctness, we must consider :
>> + *  - the bootloader may be using a different structure
>> + *  - size of the external buffer may not match the size of the default
>> + *  - an unknown number of bootloader log entries may be present
>> + *  - an unknown number of kernel log entries may be present
>> + *  - wrapping of the bootloader log may have already occurred (unlikely)
>> + *  - wrapping of the kernel log may have already occurred (unlikely)
>> + *
>> + * Memory Reservation
>> + * ------------------
>> + *  This feature expects the bootloader to reserve/preserve the shared buffer
>> + *  memory. This reservation needs to prevent the kernel from overwriting the
>> + *  external log control block and log entries. In my testing, I've used the
>> + *  'fdt' commands in uboot to dynamically inject reserved memory regions via
>> + *  the DT to the kernel.
>> + *
>> + */
>> +void __init setup_ext_logbuff(void)
>> +{
>> +	struct printk_log *nextblmsg, *currkmsg;
>> +	u64 currkmsg_seq;
>> +	u32 currkmsg_idx, offset_idx;
>> +	struct lcb_t *new_lcb;
>> +	unsigned long flags;
>> +	int ret;
>> +
>> +	if (!lcb_phys_addr)
>> +		return;
>> +
>> +	new_lcb = phys_to_virt(lcb_phys_addr);
>> +	new_lcb->log_buf = phys_to_virt(new_lcb->log_phys_addr);
>> +
>> +	/* Validate the new control buffer */
>> +	if (!is_valid_external_cb(new_lcb)) {
>> +		pr_warn("log : External log cb failed validation. Ignored\n");
>> +		pr_debug
>> +		    ("Kernel logbuffer of size %u at 0x%p (virtual address)\n",
>> +		     lcb->log_buf_len, lcb->log_buf);
>> +		return;
>> +	}
>> +
>> +	if (!new_log_buf_len)
>> +		pr_warn("log_buf_len ignored in favor of external log\n");
>> +
>> +	pr_debug
>> +	    ("log : Replacing cb @ 0x%p of %lu bytes with cb @ 0x%p of %d/%d bytes\n",
>> +	     lcb, sizeof(struct lcb_t), new_lcb, new_lcb->lcb_size,
>> +	     new_lcb->lcb_padded_len);
>> +
>> +	/* Capture the virtual address for the buffer */
>> +	new_lcb->log_buf = phys_to_virt(new_lcb->log_phys_addr);
>> +	pr_debug("log : Replacing buffer @ 0x%p (VA) of %d bytes with one @ 0x%p (VA) of %d bytes\n",
>> +		 lcb->log_buf, lcb->log_buf_len, new_lcb->log_buf,
>> +		 new_lcb->log_buf_len);
>> +
>> +	raw_spin_lock_irqsave(&logbuf_lock, flags);
>> +
>> +	/*
>> +	 * Offset sequence numbers by the number of existing bootloader msgs
>> +	 * NOTE: Functions above handle if the first seq becomes > than these
>> +	 */
>> +	if (lcb->syslog_seq != new_lcb->log_first_seq)
>> +		new_lcb->syslog_seq = lcb->syslog_seq + new_lcb->log_next_seq;
>> +	if (lcb->console_seq != new_lcb->log_first_seq)
>> +		new_lcb->console_seq = lcb->console_seq + new_lcb->log_next_seq;
>> +	if (lcb->clear_seq != new_lcb->log_first_seq)
>> +		new_lcb->clear_seq = lcb->clear_seq + new_lcb->log_next_seq;
>> +
>> +	/* Copy kernel specific data into the new/shared control block. */
>> +	new_lcb->syslog_prev = lcb->syslog_prev;
>> +	new_lcb->syslog_partial = lcb->syslog_partial;
>> +	new_lcb->console_prev = lcb->console_prev;
>> +
>> +	/*
>> +	 * Copy existing entries one at a time into the external buffer space.
>> +	 * The new CB will incrementally update as each kernel entry is added.
>> +	 * The existing CB will not be modified.
>> +	 */
>> +	for (currkmsg_seq = lcb->log_first_seq,
>> +	     currkmsg_idx = lcb->log_first_idx;
>> +	     currkmsg_seq <= lcb->log_next_seq &&
>> +	     currkmsg_idx < lcb->log_buf_len;
>> +	     currkmsg_idx = log_next(currkmsg_idx), currkmsg_seq++) {
>> +		currkmsg = log_from_idx_and_base(lcb->log_buf, currkmsg_idx);
>> +
>> +		/* If necessary, free bl entries to fit kernel entries */
>> +		while (new_lcb->log_first_seq < new_lcb->log_next_seq) {
>> +			u32 free;
>> +
>> +			if (new_lcb->log_next_idx > new_lcb->log_first_idx)
>> +				free = max(new_lcb->log_buf_len -
>> +					   new_lcb->log_next_idx,
>> +					   new_lcb->log_first_idx);
>> +			else
>> +				free = new_lcb->log_first_idx -
>> +				    new_lcb->log_next_idx;
>> +
>> +			if (free > currkmsg->len + sizeof(struct printk_log))
>> +				break;
>> +
>> +			/* Drop oldest messages until there is enough space */
>> +			new_lcb->log_first_idx =
>> +			    log_next_idx_from_idx(new_lcb->log_buf,
>> +						  new_lcb->log_first_idx);
>> +			new_lcb->log_first_seq++;
>> +		}
>> +
>> +		nextblmsg = (struct printk_log *)
>> +		    (new_lcb->log_buf + new_lcb->log_next_idx);
>> +
>> +		/* Check if the next record will fit along with a wrap record */
>> +		if (new_lcb->log_next_idx + currkmsg->len +
>> +		    sizeof(struct printk_log) >= new_lcb->log_buf_len) {
>> +			memset(nextblmsg, 0, sizeof(struct printk_log));
>> +			nextblmsg = (struct printk_log *)new_lcb->log_buf;
>> +			new_lcb->log_next_idx = 0;
>> +		}
>> +		/* Copy kernel message to bootloader buffer */
>> +		memcpy(nextblmsg, currkmsg, currkmsg->len);
>> +
>> +		/* Before moving to the next kernel entry, adjust indices */
>> +		if (currkmsg_seq == lcb->log_first_seq)
>> +			offset_idx = new_lcb->log_first_seq;
>> +		else
>> +			offset_idx = new_lcb->log_next_idx;
>> +
>> +		if (currkmsg_seq == lcb->syslog_seq)
>> +			new_lcb->syslog_idx = offset_idx;
>> +		if (currkmsg_seq == lcb->console_seq)
>> +			new_lcb->console_idx = offset_idx;
>> +		if (currkmsg_seq == lcb->clear_seq)
>> +			new_lcb->clear_idx = offset_idx;
>> +
>> +		/* Update next offset and sequence */
>> +		if (currkmsg_seq < lcb->log_next_seq) {
>> +			new_lcb->log_next_idx += currkmsg->len;
>> +			new_lcb->log_next_seq++;
>> +		}
>> +	}
>> +
>> +	/* Overwrite the default lcb pointer, buffer pointer, and length. */
>> +	lcb = new_lcb;
>> +	lcb->log_buf = (char *)new_lcb->log_buf;
>> +	lcb->log_buf_len = new_lcb->log_buf_len;
> 
> Is the bootloader allowed to write to the shared buffer from this
> point on? How will be synchronized the writes from the kernel and
> the bootloader?

I am a bit confused by this question.  I assume that the kernel and
bootloader will not be accessing the same log space simultaneously.
While each one is running, they will utilize the same data structures to
keep track of current entries.

> 
> How protected will the address of the shared buffer? Would not
> it open a security hole? We need to make sure that non-privileged
> user or non-trusted application must not read sensitive data
> from the log or break the structure of the log by writing
> invalid data.
> 

There is no notion of protection of the address.  However, additional
checking could be added. Currently, there is potential for corrupt log
entries from the bootloader causing the kernel to crash.  I can't think
of a way to prevent that from happening.  Also, as you point out, a
bootloader could read log contents from the shared region.  Of course,
in order for either to happen, the bootloader would already be
compromised and I'm not sure that reading log entries or crashing the
kernel is such a big consideration.

-- 
Sean