linux-kernel - Re: [PATCH] printk: Add printk_flush() to force buffered text to console

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <20120622071718.GC22167@gmail.com>
Date:	Fri, 22 Jun 2012 09:17:18 +0200
From:	Ingo Molnar <mingo@...nel.org>
To:	Steven Rostedt <rostedt@...dmis.org>
Cc:	LKML <linux-kernel@...r.kernel.org>,
	Linus Torvalds <torvalds@...ux-foundation.org>,
	Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
	"kay.sievers" <kay.sievers@...y.org>,
	Fengguang Wu <fengguang.wu@...el.com>,
	Ingo Molnar <mingo@...e.hu>,
	AndrewMorton <akpm@...ux-foundation.org>
Subject: Re: [PATCH] printk: Add printk_flush() to force buffered text to
 console


* Steven Rostedt <rostedt@...dmis.org> wrote:

> Fengguang Wu had a config that caused the system to lockup. It reported:
> 
> [    6.086395] type=2000 audit(1339501575.085:1): initialized
> [    6.116356] Kprobe smoke test started
> [    6.125915] Kprobe smoke test passed successfully
> [    6.127478] rcu-torture:--- Start of test: nreaders=2 nfakewriters=4 stat_interval=0 verbose=0 test_no_idle_hz=0 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0
> +fqs_holdoff=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 onoff_interval=0 onoff_holdoff=0
> 
> and then froze. So naturally, the suspected bug was with rcu-torture.
> Fengguang did a git bisect and discovered that the crash came with a
> function trace update. He also noticed that if he reverted that update,
> the system got farther and showed:
> 
> [    1.611901] Testing tracer function: PASSED
> 
> His time was wasted by the fact that the function tracing self test
> first prints:
> 
>   "Testing tracer function: "
> 
> then runs the test, and if it succeeds, it prints "PASSED", giving us
> the nice output you see above.
> 
> But with the new printk() changes, text without a newline gets buffered
> and does not print out to the console at the location of the printk.
> This caused the "Testing tracer function: " not to print out and because
> the test caused the kernel to lock up, we are clueless to the fact that
> the problem was with the function tracer test and not the rcu_torture
> test. As it made sense that the rcu_torture test could lock up the
> system, many kernel developer hours were wasted chasing the wrong wild
> goose.
> 
> If the "Testing tracer function: " had printed out in the first place,
> we would have caught the correct wild goose and saved precious kernel
> developer's time.
> 
> Thus a need for the following utility. That is to add a 'printk_flush()'
> that acts like a fflush() in userspace to flush out the buffers used by
> the printing facility so we don't have unexpected hunts for nature
> roaming fowl.
> 
> I hooked onto the 'facility' infrastructure and used '0x1ffc' (the max
> number) as a way to communicate printk() commands to the msg_print_text()
> which is performed at a later time (console_unlock()).
> 
> I tested this out, (adding pr_flush() after my printk) and now the
> lockup shows:
> 
> [    9.018231] Kprobe smoke test passed successfully
> [    9.023084] rcu-torture:--- Start of test: nreaders=4 nfakewriters=4 stat_interval=0 verbose=0 test_no_idle_hz=0 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0 fqs_hold
> off=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 onoff_interval=0 onoff_holdoff=0
> [    9.066065] Testing tracer function:
> 
> To prevent the flush to cause the next printk to have a timestamp that
> would produce the following:
> 
> [    6.834073] Testing tracer function: [    7.136194] PASSED
> 
> I made the KERN_CONT ("<c>") use the facility as well to pass info to
> not print the timestamp. This fixes the abve issue to print:
> 
> [    1.291025] Testing tracer function: PASSED
> 
> Link: http://lkml.kernel.org/r/1339649173.13377.191.camel@gandalf.stny.rr.com
> 
> Cc: Linus Torvalds <torvalds@...ux-foundation.org>
> Cc: Greg Kroah-Hartman <gregkh@...uxfoundation.org>
> Cc: "kay.sievers" <kay.sievers@...y.org>
> Cc: "Paul E. McKenney" <paulmck@...ibm.com>
> Cc: Fengguang Wu <fengguang.wu@...el.com>
> Cc: Ingo Molnar <mingo@...e.hu>
> Cc: Andrew Morton <akpm@...ux-foundation.org>
> Signed-off-by: Steven Rostedt <rostedt@...dmis.org>
> ---
>  include/linux/printk.h |    8 ++++
>  kernel/printk.c        |  104 ++++++++++++++++++++++++++++++++++++++++++-----
>  2 files changed, 101 insertions(+), 11 deletions(-)

Maybe also add the actual usage sites, to demonstrate how it's 
going to be used?

Thanks,

	Ingo
--
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/