diff mbox

[PATCH/RFC] Make sure linux_banner is the first message in log_buf

Message ID 20120523023513.GA22235@lizard
State New
Headers show

Commit Message

Anton Vorontsov May 23, 2012, 2:35 a.m. UTC 
For scripting it is important to have a consistent header that tells
where the kernel log starts. At least to me it always seemed that
linux_banner served this purpose.

Though, an early kernel code may print things before the Linux banner.
When we parse logs from multiple boots grabbed from serial or pstore
consoles, we might miss these messages.

The only bulletproof, arch-independent and whatnot way to ensure that
we have the banner printed first is to print it from the printk itself.
The resulting code looks quite obvious.

Sure, this doesn't address bootloader or low-level very early arch-
dependent console output that goes to the HW directly, but there's
nothing we can do about it (in pstore console we don't see them anyway).

Signed-off-by: Anton Vorontsov <anton.vorontsov@linaro.org>
---

On Tue, May 22, 2012 at 11:06:29AM -0700, Colin Cross wrote:
> >
> > Now to get the only most recent messages we can do:
> >
> >        tac ramoops-console | sed '/^Linux version.*(.*@.*)/ q' | tac
> 
> Lots of problems with this.
> "Linux version ..." is not the first line in the console log on my
> devices, there are messages before it that shouldn't be dropped by
> automated logs collectors using this regexp.

Ouch. This seems not right. And the same issue exist if we collect
logs from e.g. serial console, there (unlike to just reading /proc/kmsg)
we don't know where current kernel's messages start, and more than
that, in serial console case we don't know where the messages end
(unlike to pstore).

So it's a general problem, not only related to pstore.

But we can fix this. How about the patch below?

> There is a timestamp before "Linux version", so the regexp never matches.

This is also fixable.

tac ramoops-console | sed '/\(^\|] \)Linux version.*(.*@.*)/ q' | tac

> There is often no newline at the end of the old log, so if "Linux
> version" was the first line in the log, it would still not get
> matched.

Yeah, true. We will have to add at least a new line in pstore.

> Relying on the first line in the log to not change seems likely to
> cause problems for scripts in the future.  Why not separate them where
> the code knows for sure that the old log is ending and the new log is
> starting?

I'm not opposed to a header (or a footer) at all, and you're right,
one of them is obviously needed.

I just don't like introducing yet another ad-hoc header format that
we will only use for pstore/console. We have "start of the Linux
kernel log" header, so let's try to use it?..

If it is not suitable for us today, let's think how to fix that, and
if anything, we can fall-back to your plan, i.e. adding our own footer
(or zapping prz) at boot time.

But so far I can see this solution:

1. Make sure we printk linux_banner as the first string in the
   log_buf (this patch). This is an improvement not only for pstore;

2. In pstore, add a newline to previous' boot log (we'll add it
   unconditinally, so that it we won't loose the information about
   the last new line :-).

 init/main.c     |    1 -
 kernel/printk.c |    3 +++
 2 files changed, 3 insertions(+), 1 deletion(-)

Comments

Linus Torvalds May 23, 2012, 2:50 a.m. UTC | #1 
On Tue, May 22, 2012 at 7:35 PM, Anton Vorontsov
<anton.vorontsov@linaro.org> wrote:
> @@ -749,6 +749,9 @@ asmlinkage int printk(const char *fmt, ...)
>        va_list args;
>        int r;
>
> +       /* Make sure linux_banner is kernel's first message. */
> +       printk_once(KERN_NOTICE "%s", linux_banner);
> +

Ugh. No. That is too disgusting for words.

                  Linus
David Miller May 23, 2012, 2:55 a.m. UTC | #2 
From: Anton Vorontsov <anton.vorontsov@linaro.org>
Date: Tue, 22 May 2012 19:35:16 -0700

> For scripting it is important to have a consistent header that tells
> where the kernel log starts. At least to me it always seemed that
> linux_banner served this purpose.

Your change will not achieve this goal, many architectures
print things long before control passes to init/main.c
Anton Vorontsov May 23, 2012, 3:59 a.m. UTC | #3 
On Tue, May 22, 2012 at 10:55:12PM -0400, David Miller wrote:
> From: Anton Vorontsov <anton.vorontsov@linaro.org>
> Date: Tue, 22 May 2012 19:35:16 -0700
> 
> > For scripting it is important to have a consistent header that tells
> > where the kernel log starts. At least to me it always seemed that
> > linux_banner served this purpose.
> 
> Your change will not achieve this goal, many architectures
> print things long before control passes to init/main.c

If they use printk, we'll catch these messages, no? It is true that
if they just write to the HW directly, the messages are lost for us,
and there's nothing we can do about it (and we don't see these
messages from the kernel anyway, neither in dmesg, nor in pstore).

So, for serial (or arch-specific) console it is still cumbersome to
make proper parsing of all messages, but for pstore/ramconsole it is
OK. So, I dunno. I guess I'll have to add a custom header to pstore,
heh.

Thanks,
diff mbox

Patch

diff --git a/init/main.c b/init/main.c
index 44b2433..df3711d 100644
--- a/init/main.c
+++ b/init/main.c
@@ -492,7 +492,6 @@  asmlinkage void __init start_kernel(void)
 	tick_init();
 	boot_cpu_init();
 	page_address_init();
-	printk(KERN_NOTICE "%s", linux_banner);
 	setup_arch(&command_line);
 	mm_init_owner(&init_mm, &init_task);
 	mm_init_cpumask(&init_mm);
diff --git a/kernel/printk.c b/kernel/printk.c
index b663c2c..1e1461b 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -749,6 +749,9 @@  asmlinkage int printk(const char *fmt, ...)
 	va_list args;
 	int r;
 
+	/* Make sure linux_banner is kernel's first message. */
+	printk_once(KERN_NOTICE "%s", linux_banner);
+
 #ifdef CONFIG_KGDB_KDB
 	if (unlikely(kdb_trap_printk)) {
 		va_start(args, fmt);