[RFC][PATCH] printk: Add option to append kernel version to the dict

[RFC][PATCH] printk: Add option to append kernel version to the dict

[Calvin Owens]

We use netconsole to collect kernel logs from all the servers at
Facebook. We use this patch internally so each logline has a record of
which kernel version emitted it.

At first glance, this might seem lazy: as you would expect, we have a
database which records which kernel version a host is currently running.
But there are a lot of situations where that database cannot be current:
early-ish boot crashes are probably the best example, but even beyond
that there are lots of varieties of kernel brokenness that can prevent
the database from being updated. Doing it explicitly this way ensures
that we always know exactly what version emitted a given message.

Doing it in printk() itself rather than extended netconsole ends up
being much simpler, and has the advantage that future extended console
implementations will be able to benefit from this as well.

Signed-off-by: Calvin Owens <calvinowens@fb.com>
---
 init/Kconfig           |  8 ++++++++
 kernel/printk/printk.c | 14 ++++++++++++++
 2 files changed, 22 insertions(+)

diff --git a/init/Kconfig b/init/Kconfig
index 0dfd09d..f800256 100644
--- a/init/Kconfig
+++ b/init/Kconfig
@@ -1454,6 +1454,14 @@ config PRINTK
 	  very difficult to diagnose system problems, saying N here is
 	  strongly discouraged.
 
+config PRINTK_APPEND_UNAME
+	default n
+	bool "Append the kernel version to the printk() dict" if EXPERT
+	help
+	  This option causes the printk() implementation to append the kernel
+	  version for extended console messages. This can be very useful for
+	  monitoring a large deployment of servers with extended netconsole.
+
 config BUG
 	bool "BUG() support" if EXPERT
 	default y
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index bfbf284..3f8debd 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -608,6 +608,18 @@ static ssize_t msg_print_ext_body(char *buf, size_t size,
 	return p - buf;
 }
 
+#if defined(CONFIG_PRINTK_APPEND_UNAME)
+static ssize_t msg_print_ext_uname(char *buf, size_t size)
+{
+	return scnprintf(buf, size, " UNAME=%s\n", init_utsname()->release);
+}
+#else
+static ssize_t msg_print_ext_uname(char *buf, size_t size)
+{
+	return 0;
+}
+#endif
+
 /* /dev/kmsg - userspace message inject/listen interface */
 struct devkmsg_user {
 	u64 seq;
@@ -2305,6 +2317,8 @@ skip:
 						sizeof(ext_text) - ext_len,
 						log_dict(msg), msg->dict_len,
 						log_text(msg), msg->text_len);
+			ext_len += msg_print_ext_uname(ext_text + ext_len,
+						sizeof(ext_text) - ext_len);
 		}
 		console_idx = log_next(console_idx);
 		console_seq++;
-- 
2.8.0.rc2

Re: [RFC][PATCH] printk: Add option to append kernel version to the dict

[Richard Weinberger]

On Fri, May 13, 2016 at 10:58 PM, Calvin Owens <calvinowens@fb.com> wrote:
> We use netconsole to collect kernel logs from all the servers at
> Facebook. We use this patch internally so each logline has a record of
> which kernel version emitted it.
>
> At first glance, this might seem lazy: as you would expect, we have a
> database which records which kernel version a host is currently running.
> But there are a lot of situations where that database cannot be current:
> early-ish boot crashes are probably the best example, but even beyond
> that there are lots of varieties of kernel brokenness that can prevent
> the database from being updated. Doing it explicitly this way ensures
> that we always know exactly what version emitted a given message.
>
> Doing it in printk() itself rather than extended netconsole ends up
> being much simpler, and has the advantage that future extended console
> implementations will be able to benefit from this as well.
>
> Signed-off-by: Calvin Owens <calvinowens@fb.com>
> ---
>  init/Kconfig           |  8 ++++++++
>  kernel/printk/printk.c | 14 ++++++++++++++
>  2 files changed, 22 insertions(+)

I don't think adding a new config option is appropriate.
How about adding a log format string tunable to netconsole?

-- 
Thanks,
//richard

Re: [RFC][PATCH] printk: Add option to append kernel version to the dict

[Sergey Senozhatsky]

Hello,

On (05/13/16 13:58), Calvin Owens wrote:
[..]
> +#if defined(CONFIG_PRINTK_APPEND_UNAME)
> +static ssize_t msg_print_ext_uname(char *buf, size_t size)
> +{
> +	return scnprintf(buf, size, " UNAME=%s\n", init_utsname()->release);
> +}
> +#else
> +static ssize_t msg_print_ext_uname(char *buf, size_t size)
> +{
> +	return 0;
> +}
> +#endif
> +
>  /* /dev/kmsg - userspace message inject/listen interface */
>  struct devkmsg_user {
>  	u64 seq;
> @@ -2305,6 +2317,8 @@ skip:
>  						sizeof(ext_text) - ext_len,
>  						log_dict(msg), msg->dict_len,
>  						log_text(msg), msg->text_len);
> +			ext_len += msg_print_ext_uname(ext_text + ext_len,
> +						sizeof(ext_text) - ext_len);
>  		}

what if there is no place left for init_utsname() after msg_print_ext_header() + msg_print_ext_body()?
do you need init_utsname in every message? or just in WARN/ERR ones?

	-ss

Re: [RFC][PATCH] printk: Add option to append kernel version to the dict

[Calvin Owens]

On Sunday 05/15 at 00:19 +0200, Richard Weinberger wrote:
> On Fri, May 13, 2016 at 10:58 PM, Calvin Owens <calvinowens@fb.com> wrote:
> > We use netconsole to collect kernel logs from all the servers at
> > Facebook. We use this patch internally so each logline has a record of
> > which kernel version emitted it.
> >
> > At first glance, this might seem lazy: as you would expect, we have a
> > database which records which kernel version a host is currently running.
> > But there are a lot of situations where that database cannot be current:
> > early-ish boot crashes are probably the best example, but even beyond
> > that there are lots of varieties of kernel brokenness that can prevent
> > the database from being updated. Doing it explicitly this way ensures
> > that we always know exactly what version emitted a given message.
> >
> > Doing it in printk() itself rather than extended netconsole ends up
> > being much simpler, and has the advantage that future extended console
> > implementations will be able to benefit from this as well.
> >
> > Signed-off-by: Calvin Owens <calvinowens@fb.com>
> > ---
> >  init/Kconfig           |  8 ++++++++
> >  kernel/printk/printk.c | 14 ++++++++++++++
> >  2 files changed, 22 insertions(+)
> 
> I don't think adding a new config option is appropriate.
> How about adding a log format string tunable to netconsole?

Like a generic way to append arbitrary key/val to the dict? It would still
need to be configured via the kernel cmdline or at compile time: I can't
rely getting to userspace.

I had steered away from something more general like that because it
didn't seem worth the trobule, but I can certainly go that route: what
sort of format specifiers would we want? I only care about UTS_RELEASE,
but I suppose UTS_NODENAME and UTS_VERSION might be handy in some cases?

Thanks,
Calvin

> -- 
> Thanks,
> //richard

Re: [RFC][PATCH] printk: Add option to append kernel version to the dict

[Calvin Owens]

On Sunday 05/15 at 15:36 +0900, Sergey Senozhatsky wrote:
> Hello,
> 
> On (05/13/16 13:58), Calvin Owens wrote:
> [..]
> > +#if defined(CONFIG_PRINTK_APPEND_UNAME)
> > +static ssize_t msg_print_ext_uname(char *buf, size_t size)
> > +{
> > +	return scnprintf(buf, size, " UNAME=%s\n", init_utsname()->release);
> > +}
> > +#else
> > +static ssize_t msg_print_ext_uname(char *buf, size_t size)
> > +{
> > +	return 0;
> > +}
> > +#endif
> > +
> >  /* /dev/kmsg - userspace message inject/listen interface */
> >  struct devkmsg_user {
> >  	u64 seq;
> > @@ -2305,6 +2317,8 @@ skip:
> >  						sizeof(ext_text) - ext_len,
> >  						log_dict(msg), msg->dict_len,
> >  						log_text(msg), msg->text_len);
> > +			ext_len += msg_print_ext_uname(ext_text + ext_len,
> > +						sizeof(ext_text) - ext_len);
> >  		}
> 
> what if there is no place left for init_utsname() after
> msg_print_ext_header() + msg_print_ext_body()?

It ends up being truncated, like either of the preceeding calls would.

> do you need init_utsname in every message? or just in WARN/ERR ones?

I need it added to anything which netconsole actually emits: so I could
filter based on loglevel here if you like.

Thanks,
Calvin

> 
> 	-ss

Re: [RFC][PATCH] printk: Add option to append kernel version to the dict

[Petr Mladek]

On Fri 2016-05-13 13:58:04, Calvin Owens wrote:
> We use netconsole to collect kernel logs from all the servers at
> Facebook. We use this patch internally so each logline has a record of
> which kernel version emitted it.
> 
> At first glance, this might seem lazy: as you would expect, we have a
> database which records which kernel version a host is currently running.
> But there are a lot of situations where that database cannot be current:
> early-ish boot crashes are probably the best example, but even beyond
> that there are lots of varieties of kernel brokenness that can prevent
> the database from being updated. Doing it explicitly this way ensures
> that we always know exactly what version emitted a given message.
> 
> Doing it in printk() itself rather than extended netconsole ends up
> being much simpler, and has the advantage that future extended console
> implementations will be able to benefit from this as well.

I do not have strong opinion about it. I am just not sure that repeating the
very same string in each message is efficient and practical in general.

If you store the entire log somewhere, you should be able to find
the kernel version from the early boot messages, e.g. from
pr_notice("%s", linux_banner). Of course, this does not help
if the boot fails earlier but it is rather a corner case.

The risk is that someone else might need another information.
If we do it more generic, we might end up with quite complex code.

If we really need such a feature. It might make sense to print
the identifier at the beginning of each message. It will be the same
on each line and it might be easier to parse.

Best Regards,
Petr

Re: [RFC][PATCH] printk: Add option to append kernel version to the dict

[Tejun Heo]

Hello,

On Tue, May 17, 2016 at 11:24:46AM +0200, Petr Mladek wrote:
> The risk is that someone else might need another information.
> If we do it more generic, we might end up with quite complex code.

It can be pretty simple given that there's no real ordering or
formatting involved.

  enum {
	  ECON_APPEND_RELEASE	= 1 << 0,
  ];

  static unsigned int ext_con_append_mask;

  static int __init ext_con_append_setup(char *str)
  {
	  while (*str) {
		  switch (*str) {
			  case 'r':
				  ext_con_append_mask |= ECON_APPEND_RELEASE;
				  break;
			  default:
				  pr_warning("Unknown ext ext con append format '%c'\n", *str);
		  }
		  str++;
	  }
	  return 1;
  }
  __setup("ext_con_append=", ext_con_append_setup);

And we can expand the list as necessary.  I don't think it needs to be
a compile time option either.  The code involved is minimal after all.

Thanks.

-- 
tejun

Re: [RFC][PATCH] printk: Add option to append kernel version to the dict

[Tejun Heo]

On Tue, May 17, 2016 at 11:42:57PM +0900, Sergey Senozhatsky wrote:
> > > what if there is no place left for init_utsname() after
> > > msg_print_ext_header() + msg_print_ext_body()?
> > 
> > It ends up being truncated, like either of the preceeding calls would.
> 
> well, I meant once it's truncated your matching doesn't work anymore.

Given that most of the messages are written minding typical console
widths, whether for editing or outputting, I don't think that's a
practical concern.  We're not talking about appending kilobytes worth
of additional information here.

Thanks.

-- 
tejun

Re: [RFC][PATCH] printk: Add option to append kernel version to the dict

[Sergey Senozhatsky]

On (05/16/16 15:02), Calvin Owens wrote:
[..]
> > > @@ -2305,6 +2317,8 @@ skip:
> > >  						sizeof(ext_text) - ext_len,
> > >  						log_dict(msg), msg->dict_len,
> > >  						log_text(msg), msg->text_len);
> > > +			ext_len += msg_print_ext_uname(ext_text + ext_len,
> > > +						sizeof(ext_text) - ext_len);
> > >  		}
> > 
> > what if there is no place left for init_utsname() after
> > msg_print_ext_header() + msg_print_ext_body()?
> 
> It ends up being truncated, like either of the preceeding calls would.

well, I meant once it's truncated your matching doesn't work anymore.

	-ss

Re: [RFC][PATCH] printk: Add option to append kernel version to the dict

[Sergey Senozhatsky]

Hello Tejun,

On (05/17/16 06:51), Tejun Heo wrote:
> On Tue, May 17, 2016 at 11:42:57PM +0900, Sergey Senozhatsky wrote:
> > > > what if there is no place left for init_utsname() after
> > > > msg_print_ext_header() + msg_print_ext_body()?
> > > 
> > > It ends up being truncated, like either of the preceeding calls would.
> > 
> > well, I meant once it's truncated your matching doesn't work anymore.
> 
> Given that most of the messages are written minding typical console
> widths, whether for editing or outputting, I don't think that's a
> practical concern.  We're not talking about appending kilobytes worth
> of additional information here.

hm, I'd probably agree. any chance printk(KERN_CONT) can cause any problems?
for example,

mem_cgroup_print_oom_info():

	for_each_mem_cgroup_tree(iter, memcg) {
		pr_info("Memory cgroup stats for ");
		pr_cont_cgroup_path(iter->css.cgroup);
		pr_cont(":");

		for (i = 0; i < MEM_CGROUP_STAT_NSTATS; i++) {
			if (i == MEM_CGROUP_STAT_SWAP && !do_swap_account)
				continue;
			pr_cont(" %s:%luKB", mem_cgroup_stat_names[i],
				K(mem_cgroup_read_stat(iter, i)));
		}

		for (i = 0; i < NR_LRU_LISTS; i++)
			pr_cont(" %s:%luKB", mem_cgroup_lru_names[i],
				K(mem_cgroup_nr_lru_pages(iter, BIT(i))));

		pr_cont("\n");
	}


there are some other places that do KERN_CONT. e.g. ACPI does KERN_CONT
printk-s from acpi_error/acpi_warning/etc functions. but I've no idea if
there is anything long enough to cause the truncation.


	-ss

Re: [RFC][PATCH] printk: Add option to append kernel version to the dict

[Tejun Heo]

On Wed, May 18, 2016 at 12:43:10AM +0900, Sergey Senozhatsky wrote:
> > Given that most of the messages are written minding typical console
> > widths, whether for editing or outputting, I don't think that's a
> > practical concern.  We're not talking about appending kilobytes worth
> > of additional information here.
> 
> hm, I'd probably agree. any chance printk(KERN_CONT) can cause any problems?
> for example,

Plain printk messages are capped at around 1k (LONG_LINE_MAX) while
extended messages can grow upto 8k in size.  Because extended messages
are escaped, plain message can theoretically be blown upto 4k but that
still leaves us with 4k buffer.  Direct extended messages can use more
but given that our only usages are for tagging some metadata, that's
only a theoretical possibility at this point.  So, I don't think we
have anything to worry about at this point.

Thanks.

-- 
tejun