Re: printk: what is going on with additional newlines?

From: Sergey Senozhatsky
Date: Sun Sep 17 2017 - 02:31:29 EST


On (09/06/17 09:55), Petr Mladek wrote:
[..]
> > but I'm not super eager to have printk-safe based buffering.
> > that's why I never posted a patch set. this approach has its
> > limitations.
>
> Ah, I am happy to read this. From the previous mails,
> I got the feeling that you were eager to go this way.

naaah, not really :)

[..]
> > I prepend every line with the CPU number that has printk()-ed it.
> > and that's helpful because one can grep and filter out messages
> > from other CPUs. it's quite OK thing to have given that messages
> > can be really mixed sometimes.
> >
> > so adding extra information to `struct printk_log' could be helpful.
> > I think we had this discussion before and you didn't want to change
> > the size of `struct printk_log' because that might break gdb/crash/etc
> > user space tools. has it changed?
>
> Yup, there should be a serious reason to change 'struct printk_log'.
> I am not sure if this is the case. But I am sure that there will
> be need to change the structure sooner or later.
>
> Anyway, it seems that we will need to update all the tools
> for the different time stamps, see
> https://lkml.kernel.org/r/1504613201-23868-1-git-send-email-prarit@xxxxxxxxxx
> Then we will be more clever how painful it is.
>
>
> > may be we can #ifdef CONFIG_PRINTK_ABC them.

so... I think we don't have to update 'struct printk_log'. we can store
that "extended data" at the beginning of every message, right after the
prefix.

NOTE:

below is a very-very quick hack. so quick, that it has known problems.
- the code does not handle !PREFIX messages (like printk("foo")).
but I guess we can come up with a solution here.
- and printk_vscnprintf() should have that CONFIG_PRINTK_ABC,
which is missing in the code below.


dmesg looks like this

[ 3.338129] [ext: kworker/3:2/3] input: ETPS/2 Elantech Touchpad as /devices/platform/i8042/serio1/input/input7
[ 3.340653] [ext: systemd-udevd/0] mousedev: PS/2 mouse device common for all mice
[ 5.554184] [ext: swapper/0/0] random: crng init done
[ 33.410639] [ext: wpa_supplicant/6] IPv6: ADDRCONF(NETDEV_UP): wlp2s0: link is not ready
[ 36.812187] [ext: kworker/u16:5/1] wlp2s0: associated
[ 36.812231] [ext: kworker/1:1/1] IPv6: ADDRCONF(NETDEV_CHANGE): wlp2s0: link becomes ready



if we will ever decide to add any sort of "extended data" to every
message, then may be we can do it this way?

---

kernel/printk/printk.c | 31 ++++++++++++++++++++++++++++++-
1 file changed, 30 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index a64c52c19b03..d7380cb70fb5 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1936,6 +1936,35 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len);
}

+static size_t printk_vscnprintf(char *text, size_t text_sz,
+ const char *fmt, va_list args)
+{
+ size_t printed = 0;
+ bool do_prefix = false;
+
+ if (fmt[0] == KERN_SOH_ASCII) {
+ text[0] = fmt[0];
+ text[1] = fmt[1];
+
+ if (fmt[1] != 'c')
+ do_prefix = true;
+
+ fmt += 2;
+ printed = 2;
+ }
+
+ if (do_prefix) {
+ printed += snprintf(text + printed,
+ text_sz - printed,
+ "[ext: %s/%d] ",
+ current->comm,
+ smp_processor_id());
+ }
+
+ printed += vscnprintf(text + printed, text_sz - printed, fmt, args);
+ return printed;
+}
+
asmlinkage int vprintk_emit(int facility, int level,
const char *dict, size_t dictlen,
const char *fmt, va_list args)
@@ -1962,7 +1991,7 @@ asmlinkage int vprintk_emit(int facility, int level,
* The printf needs to come first; we need the syslog
* prefix which might be passed-in as a parameter.
*/
- text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
+ text_len = printk_vscnprintf(text, sizeof(textbuf), fmt, args);

/* mark and strip a trailing newline */
if (text_len && text[text_len-1] == '\n') {