Messages in this thread | | | Date | Thu, 13 Aug 2020 09:51:17 +0200 | From | Petr Mladek <> | Subject | Re: POC: Alternative solution: Re: [PATCH 0/4] printk: reimplement LOG_CONT handling |
| |
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
| |