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

[Sergey Senozhatsky <sergey.senozhatsky@gmail.com>]

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@redhat.com
> 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') {