Re: [PATCH] printk: inject caller information into the body of message

[Sergey Senozhatsky]

On (05/11/18 20:58), Tetsuo Handa wrote:
[..]
> -	if (nr_ext_console_drivers || cont.len + len > sizeof(cont.buf)) {
> +	if (nr_ext_console_drivers) {
> +		cont_flush();
> +		return false;
> +	}
> +
> +	/* Inject before memcpy() in order to avoid overflow. */
> +	if (!cont.len)
> +		text = printk_inject_caller_info(text, &len);
> +
> +	/* If the line gets too long, split it up in separate records. */
> +	if (cont.len + len > sizeof(cont.buf)) {
>  		cont_flush();
>  		return false;
>  	}
> @@ -1820,6 +1860,9 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
>  			return text_len;
>  	}
>  
> +	/* Inject caller info. */
> +	text = printk_inject_caller_info(text, &text_len);
> +
>  	/* Store it in the record log */
>  	return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len);
>  }

[..]

I think this is slightly intrusive. I understand that you want to avoid
struct printk_log modification, let's try to see if we have any other
options.

Dunno...
For instance, can we store context tracking info as a extended record
data? We have that dict/dict_len thing. So may we can store tracking
info there? Extended records will appear on the serial console /* if
console supports extended data */ or can be read in via devkmsg_read().
Any other options?

>  #include "internal.h"
>  
> @@ -83,6 +84,17 @@ static __printf(2, 0) int printk_safe_log_store(struct printk_safe_seq_buf *s,
[..]
>  	len = atomic_read(&s->len);
> @@ -102,7 +114,15 @@ static __printf(2, 0) int printk_safe_log_store(struct printk_safe_seq_buf *s,
>  		smp_rmb();
>  
>  	va_copy(ap, args);
> -	add = vscnprintf(s->buffer + len, sizeof(s->buffer) - len, fmt, ap);
> +	if (printk_caller_info) {
> +		struct va_format vaf = { .fmt = fmt, .va = &ap };
> +
> +		add = scnprintf(s->buffer + len, sizeof(s->buffer) - len,
> +				"(%c%u) %pV", c, v, &vaf);
> +	} else {
> +		add = vscnprintf(s->buffer + len, sizeof(s->buffer) - len,
> +				 fmt, ap);
> +	}

A bit of a silly question - do we want to modify printk_safe at this
point? With this implementation printk_safe entries will have two context
info-s attached: one from original printk_safe_log_store and another one
from printk_safe_flush->log_store. I suspect that adding context info in
printk_safe_log_store is, probably, not really needed. We flush printk_safe
from irq work on the CPU that issued unsafe printk, so part of the context
info will be valid if you append context info only in printk log_store - at
least the correct smp_processor_id.

	-ss