On Thu 2020-08-13 14:18:53, Sergey Senozhatsky wrote:
> On (20/08/13 02:30), John Ogness wrote:
> > 2. I haven't yet figured out how to preserve calling context when a
> > newline appears. For example:
> >
> > pr_info("text");
> > pr_cont(" 1");
> > pr_cont(" 2\n");
> > pr_cont("3");
> > pr_cont(" 4\n");
> >
> > For "3" the calling context (info, timestamp) is lost because with "2"
> > the record is finalized. Perhaps the above is invalid usage of LOG_CONT?
If I get it correctly, the original code has the same problem.
The cont buffer is flushed when the cont piece ends with newline:
static bool cont_add(u32 caller_id, int facility, int level,
enum log_flags flags, const char *text, size_t len)
{
[...]
// The original flags come from the first line,
// but later continuations can add a newline.
if (flags & LOG_NEWLINE) {
cont.flags |= LOG_NEWLINE;
cont_flush();
}
return true;
}
cont_flush sets cont.len = 0;
static void cont_flush(void)
{
[...]
cont.len = 0;
}
The messages is appended only when cont.len != 0 in log_output:
static size_t log_output(int facility, int level, enum log_flags lflags, const
char *dict, size_t dictlen, char *text, size_t text_len)
{
const u32 caller_id = printk_caller_id();
/*
* If an earlier line was buffered, and we're a continuation
* write from the same context, try to add it to the buffer.
*/
if (cont.len) {
if (cont.caller_id == caller_id && (lflags & LOG_CONT)) {
if (cont_add(caller_id, facility, level, lflags, text,
text_len))
return text_len;
}
[...]
}
Also the original context is overridden when the cont buffer is empty:
static bool cont_add(u32 caller_id, int facility, int level,
enum log_flags flags, const char *text, size_t len)
{
[...]
if (!cont.len) {
cont.facility = facility;
cont.level = level;
cont.caller_id = caller_id;
cont.ts_nsec = local_clock();
cont.flags = flags;
}
[...]
}
So I would ignore this problem for now.
> This is not an unseen pattern, I'm afraid. And the problem here can
> be more general:
>
> pr_info("text");
> pr_cont("1");
> exception/IRQ/NMI
> pr_alert("text\n");
> pr_cont("2");
> pr_cont("\n");
>
Good point.
> I guess the solution would be to store "last log_level" in task_struct
> and get current (new) timestamp for broken cont line?
I think about storing the context in per-CPU and per-context array.
It should be more memory efficient than task_struct and it should
solve even the above problem.
> We have this problem now. E.g. early boot messages from one of my boxes:
>
> 6,173,41837,-;x86: Booting SMP configuration:
> 6,174,41838,-;.... node #0, CPUs: #1 #2 #3 #4
> 4,175,44993,-;MDS CPU bug present and SMT on, data leak possible. See
> https://www.kernel.org/doc/...
> 4,176,44993,c; #5 #6 #7
>
> "CPUs: #1 #2 #3 #4 #5 #6 #7" is supposed to be one cont line with
> loglevel 6. But it gets interrupted and flushed so that "#5 #6 #7"
> appears with the different loglevel.
Nice example. It would be nice to fix this. But it should be done
separately.
Best Regards,
Petr
