Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1733396 > unrolled thread

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

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-09-17 08:40 +0200
    Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-09-17 11:40 +0200
    Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-09-17 17:40 +0200
      Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-18 02:50 +0200
        Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-09-18 04:30 +0200
          Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-09-18 04:50 +0200
            Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-18 05:00 +0200
              Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-09-18 05:10 +0200
                Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-18 06:50 +0200
          Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-18 04:50 +0200

#1733396 — Re: printk: what is going on with additional newlines?

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') {
 

[toc] | [next] | [standalone]

#1733424

On (09/17/17 15:26), Sergey Senozhatsky wrote:
[..]
> > 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 store that "really helpful different timestamps"
in "extended data"? IOW, as part of message text?

	-ss

[toc] | [prev] | [next] | [standalone]

#1733482

On Sat, Sep 16, 2017 at 11:26 PM, Sergey Senozhatsky
<sergey.senozhatsky@gmail.com> wrote:
>
> 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.

No, we really can't. That just means that all the tools would have to
be changed to get the normal messages without the extra crud. And
since it will have lost the difference, that's not even easy to do.

So this is exactly the wrong way around.

If people want to see the extra data, it really should be extra data
that you can get with a new interface from the kernel logs. Not a
"let's just a add it to all lines and make every line uglier and
harder to read.

              Linus

[toc] | [prev] | [next] | [standalone]

#1733580

Hello Linus,

On (09/17/17 08:35), Linus Torvalds wrote:
> On Sat, Sep 16, 2017 at 11:26 PM, Sergey Senozhatsky
> <sergey.senozhatsky@gmail.com> wrote:
> >
> > 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.
> 
> No, we really can't. That just means that all the tools would have to
> be changed to get the normal messages without the extra crud. And
> since it will have lost the difference, that's not even easy to do.

well, that extra crud is meant to be there only when people explicitly
enable CONFIG_PRINTK_ADD_EXTRA_CRUD_PLEASE. so it's a debugging option.


> So this is exactly the wrong way around.
> 
> If people want to see the extra data, it really should be extra data
> that you can get with a new interface from the kernel logs. Not a
> "let's just a add it to all lines and make every line uglier and
> harder to read.

there is another reason why I think that, yes, we probably better do
it some other way. and the reason is that not every message that looks
like !PREFIX (does not start with KERN_SOH_ASCII) is _actually_ a
!PREFIX message. the normal/usual way is to have something like

	printk(KERN_SOH_ASCII %d " foo bar / %s %s\n", "foo", "bar");

but some messages look like

	printk("%s", KERN_SOH_ASCII %d "foo bar\n");

so we end up having a "normal" message with KERN_SOH_ASCII %d at
offsets 0 and 1 in the resulting text, but only after we do vscnprintf()
in vprintk_emit(). so the proposed _pre-processing_ is complicated.
post-processing -- the one we do in vprintk_emit() -- is still simple.


that's why last night I thought that may be we can do something more
radical - double the number of logbuf lines. IOW, every time we do

	log_store(facility, level, lflags, 0, dict, dictlen, text, text_len)

we also will do

	static char ext_data[...];

	size_t ext_sz = sprintf(ext_data, .....);
	log_store(facility, level, lflags, 0, dict, dictlen, ext_data, ext_sz);

so every message will now have "extra message" before (or after) it. we
do log_store() under logbuf lock, so no other messages should appear
(um, hopefully). every extra message will contain "[extra:" text, so it'll
be possible to filter it out... but, once again, the extra stuff is printed
only when people ask for it.


we are currently looking at
	lkml.kernel.org/r/1504613201-23868-1-git-send-email-prarit@redhat.com

which will definitely break some user space tools (well, if enabled in
.config); so I thought that may be that "helpful" timestamp can go as
extra payload.

p.s.
while I'm not entire sold on the whole timestamps in printk help
resolve issues thing. first, printk() can spin on logbuf lock before
it will read the timestamp. second, between
printk()->va_start->vprintk_func->{...this_cpu_read...}->vprintk_emit->logbuf_lock->...

and printk_get_ts() many things can happen - irq, preemption, etc. - so
timestamp that we take under ->logbuf_lock is of somewhat questionable
accurateness.

	-ss

[toc] | [prev] | [next] | [standalone]

#1733619

On Mon, 2017-09-18 at 09:46 +0900, Sergey Senozhatsky wrote:
> there is another reason why I think that, yes, we probably better do
> it some other way. and the reason is that not every message that looks
> like !PREFIX (does not start with KERN_SOH_ASCII) is _actually_ a
> !PREFIX message. the normal/usual way is to have something like
> 
> 	printk(KERN_SOH_ASCII %d " foo bar / %s %s\n", "foo", "bar");
> 
> but some messages look like
> 
> 	printk("%s", KERN_SOH_ASCII %d "foo bar\n");

There are no messages that look like that.

There are 2 entries somewhat like that though

net/bridge/netfilter/ebt_log.c: printk(KERN_SOH "%c%s IN=%s OUT=%s MAC source = %pM MAC dest = %pM proto = 0x%04x",
net/netfilter/nf_log_common.c:  nf_log_buf_add(m, KERN_SOH "%c%sIN=%s OUT=%s ",

[toc] | [prev] | [next] | [standalone]

#1733620

On Mon, 2017-09-18 at 11:41 +0900, Sergey Senozhatsky wrote:
> On (09/17/17 19:22), Joe Perches wrote:
> > On Mon, 2017-09-18 at 09:46 +0900, Sergey Senozhatsky wrote:
> > > there is another reason why I think that, yes, we probably better do
> > > it some other way. and the reason is that not every message that looks
> > > like !PREFIX (does not start with KERN_SOH_ASCII) is _actually_ a
> > > !PREFIX message. the normal/usual way is to have something like
> > > 
> > > 	printk(KERN_SOH_ASCII %d " foo bar / %s %s\n", "foo", "bar");
> > > 
> > > but some messages look like
> > > 
> > > 	printk("%s", KERN_SOH_ASCII %d "foo bar\n");
> > 
> > There are no messages that look like that.
> > 
> > There are 2 entries somewhat like that though
> > 
> > net/bridge/netfilter/ebt_log.c: printk(KERN_SOH "%c%s IN=%s OUT=%s MAC source = %pM MAC dest = %pM proto = 0x%04x",
> > net/netfilter/nf_log_common.c:  nf_log_buf_add(m, KERN_SOH "%c%sIN=%s OUT=%s ",
> 
> take a look at ACPI acpi_os_vprintf(). for instance.

I've looked.

Try git grep KERN_SOH.

[toc] | [prev] | [next] | [standalone]

#1733625

On (09/17/17 19:45), Joe Perches wrote:
[..]
> > take a look at ACPI acpi_os_vprintf(). for instance.
> 
> I've looked.

I don't get your point.

#define ACPI_MSG_ERROR          KERN_ERR "ACPI Error: "
#define ACPI_MSG_EXCEPTION      KERN_ERR "ACPI Exception: "
#define ACPI_MSG_WARNING        KERN_WARNING "ACPI Warning: "
#define ACPI_MSG_INFO           KERN_INFO "ACPI: "

so when we do

	acpi_os_printf(ACPI_MSG_WARNING "%s: ", pathname);

we end up with

	printk("%s",  KERN_WARNING "ACPI Warning: %%pathname%%");

note how acpi_os_vprintf() calls printk_get_level() _on_ the
buffer is passes to

	printk("%s", buffer)

because KERN_WARNING is part of the buffer, not the fmt.

there are also other examples that do similar things.


> Try git grep KERN_SOH.

what for?

	-ss

[toc] | [prev] | [next] | [standalone]

#1733627

On Mon, 2017-09-18 at 11:55 +0900, Sergey Senozhatsky wrote:
> Try git grep KERN_SOH.
> 
> what for?

Did you read your own email?

>	printk(KERN_SOH_ASCII %d " foo bar / %s %s\n", "foo", "bar");

_nothing_ looks like that.

It wouldn't even compile.

[toc] | [prev] | [next] | [standalone]

#1733641

On (09/17/17 20:07), Joe Perches wrote:
> On Mon, 2017-09-18 at 11:55 +0900, Sergey Senozhatsky wrote:
> > Try git grep KERN_SOH.
> > 
> > what for?
> 
> Did you read your own email?
> 
> >	printk(KERN_SOH_ASCII %d " foo bar / %s %s\n", "foo", "bar");
> 
> _nothing_ looks like that.

OK... got it. I obviously meant the way we treat the
prefix - KERN_SOH_ASCII and int loglevel that we store
in msg->level - and not the way the prefix actually looks
(KERN_SOH %c). I thought that was kinda clear. anyway,
the point of my email was completely different.

sorry if that confused you, or anybody else.


> It wouldn't even compile.

well, don't try to compile my emails  ;)

	-ss

[toc] | [prev] | [next] | [standalone]

#1733623

On (09/17/17 19:22), Joe Perches wrote:
> On Mon, 2017-09-18 at 09:46 +0900, Sergey Senozhatsky wrote:
> > there is another reason why I think that, yes, we probably better do
> > it some other way. and the reason is that not every message that looks
> > like !PREFIX (does not start with KERN_SOH_ASCII) is _actually_ a
> > !PREFIX message. the normal/usual way is to have something like
> > 
> > 	printk(KERN_SOH_ASCII %d " foo bar / %s %s\n", "foo", "bar");
> > 
> > but some messages look like
> > 
> > 	printk("%s", KERN_SOH_ASCII %d "foo bar\n");
> 
> There are no messages that look like that.
> 
> There are 2 entries somewhat like that though
> 
> net/bridge/netfilter/ebt_log.c: printk(KERN_SOH "%c%s IN=%s OUT=%s MAC source = %pM MAC dest = %pM proto = 0x%04x",
> net/netfilter/nf_log_common.c:  nf_log_buf_add(m, KERN_SOH "%c%sIN=%s OUT=%s ",

take a look at ACPI acpi_os_vprintf(). for instance.

	-ss

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web