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: <20181130154024.ls3mntfdr4zvluub@pathway.suse.cz>
Date:   Fri, 30 Nov 2018 16:40:24 +0100
From:   Petr Mladek <pmladek@...e.com>
To:     Tetsuo Handa <penguin-kernel@...ove.SAKURA.ne.jp>
Cc:     Sergey Senozhatsky <sergey.senozhatsky.work@...il.com>,
        Sergey Senozhatsky <sergey.senozhatsky@...il.com>,
        Dmitriy Vyukov <dvyukov@...gle.com>,
        Steven Rostedt <rostedt@...dmis.org>,
        Linus Torvalds <torvalds@...ux-foundation.org>,
        Andrew Morton <akpm@...ux-foundation.org>,
        LKML <linux-kernel@...r.kernel.org>
Subject: Re: [PATCH] printk: Add caller information to printk() output.

On Sat 2018-11-24 16:37:55, Tetsuo Handa wrote:
> Sometimes we want to print a whole line without being disturbed by
> concurrent printk() from interrupts and/or other threads, for printk()
> which does not end with '\n' can be disturbed.
> 
> We tried to allow printk() callers to explicitly use their local buffer
> in order to make sure that a whole line is printed by one printk() call.
> But it turned out that it is not realistic to ask printk() callers to
> update their function arguments only for handling rare race conditions.
> Also, like Steven Rostedt mentioned at [1], buffering sometimes makes
> the situation worse. Therefore, we should not enforce buffering in a way
> that requires modification of printk() callers.
> 
> I need to give up (at least for now) manipulating text which will be
> passed to printk(). Instead, I propose allow saving caller information
> as of calling log_store() and adding it as "T$thread_id" or
> "C$processor_id" upon printing each line of printk() output.

It looks like the best solution that I can think of at the moment.
I suggest only few cosmetic changes.

> 
> Some examples for console output:
> 
>   [    0.293000] [T1] smpboot: CPU0: Intel(R) Core(TM) i5-4440S CPU @ 2.80GHz (family: 0x6, model: 0x3c, stepping: 0x3)
>   [    0.299733] [T1] Performance Events: Haswell events, core PMU driver.
>   [    2.813808] [T35] clocksource: Switched to clocksource tsc
>   [    2.893984] [C0] random: fast init done
                  ^

Please, remove the space between the timestamp and the from field.

>  kernel/printk/printk.c | 33 +++++++++++++++++++++++++++++++++
>  lib/Kconfig.debug      | 17 +++++++++++++++++
>  2 files changed, 50 insertions(+)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 5c2079d..5ace5ba 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -609,6 +612,12 @@ static int log_store(int facility, int level,
>  
>  	/* fill message */
>  	msg = (struct printk_log *)(log_buf + log_next_idx);
> +#ifdef CONFIG_PRINTK_FROM
> +	if (in_task())
> +		msg->from_id = current->pid;
> +	else
> +		msg->from_id = 0x80000000 + raw_smp_processor_id();
> +#endif

Please, move this below. It better fits after msg->ts_nsec assignment.

>  	memcpy(log_text(msg), text, text_len);
>  	msg->text_len = text_len;
>  	if (trunc_msg_len) {
> @@ -690,9 +699,17 @@ static ssize_t msg_print_ext_header(char *buf, size_t size,
>  
>  	do_div(ts_usec, 1000);
>  
> +#ifdef CONFIG_PRINTK_FROM
> +	return scnprintf(buf, size, "%u,%llu,%llu,%c,from=%c%u;",
> +			 (msg->facility << 3) | msg->level, seq, ts_usec,
> +			 msg->flags & LOG_CONT ? 'c' : '-',
> +			 msg->from_id & 0x80000000 ? 'C' : 'T',
> +			 msg->from_id & ~0x80000000);
> +#else
>  	return scnprintf(buf, size, "%u,%llu,%llu,%c;",
>  		       (msg->facility << 3) | msg->level, seq, ts_usec,
>  		       msg->flags & LOG_CONT ? 'c' : '-');

Please, avoid cut&pasting.

> +#endif
>  }
>  
>  static ssize_t msg_print_ext_body(char *buf, size_t size,
> @@ -1037,6 +1054,9 @@ void log_buf_vmcoreinfo_setup(void)
>  	VMCOREINFO_OFFSET(printk_log, len);
>  	VMCOREINFO_OFFSET(printk_log, text_len);
>  	VMCOREINFO_OFFSET(printk_log, dict_len);
> +#ifdef CONFIG_PRINTK_FROM
> +	VMCOREINFO_OFFSET(printk_log, from_id);
> +#endif

The crash tool would need to be updated if anyone wanted to read
the log from the extended structure. Well, it might be done later
if people start using it more widely.

I think about adding one more filed "u8 version". It would help
to solve the external compatibility in the long term.


Anyway, I like this feature. It is compatible with /dev/kmsg
format. dmesg works well. It helps to sort any mixed output
from both full and continuous lines.

Best Regards,
Petr

Powered by blists - more mailing lists

Powered by Openwall GNU/*/Linux Powered by OpenVZ