Message-ID: <20120523023513.GA22235@lizard>
Date:	Tue, 22 May 2012 19:35:16 -0700
From:	Anton Vorontsov <anton.vorontsov@...aro.org>
To:	Linus Torvalds <torvalds@...ux-foundation.org>,
	Colin Cross <ccross@...roid.com>
Cc:	Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
	Kees Cook <keescook@...omium.org>,
	Tony Luck <tony.luck@...el.com>, Arnd Bergmann <arnd@...db.de>,
	John Stultz <john.stultz@...aro.org>,
	Shuah Khan <shuahkhan@...il.com>, arve@...roid.com,
	Rebecca Schultz Zavin <rebecca@...roid.com>,
	Jesper Juhl <jj@...osbits.net>,
	Randy Dunlap <rdunlap@...otime.net>,
	Stephen Boyd <sboyd@...eaurora.org>,
	Thomas Meyer <thomas@...3r.de>,
	Andrew Morton <akpm@...ux-foundation.org>,
	Marco Stornelli <marco.stornelli@...il.com>,
	WANG Cong <xiyou.wangcong@...il.com>,
	linux-kernel@...r.kernel.org, devel@...verdev.osuosl.org,
	linaro-kernel@...ts.linaro.org, patches@...aro.org,
	kernel-team@...roid.com, Ingo Molnar <mingo@...e.hu>,
	Peter Zijlstra <a.p.zijlstra@...llo.nl>,
	Rusty Russell <rusty@...tcorp.com.au>
Subject: [PATCH/RFC] Make sure linux_banner is the first message in log_buf

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@...aro.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(-)

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);
-- 
1.7.9.2

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Powered by blists - more mailing lists