Add a hash value for each line in /dev/kmsg

Hello,

This patch series adds hash values of printk format strings into each line of /dev/kmsg outputs as follows:

        6,154,325061,-,b7db707c@kernel/smp.c:554;Brought up 4 CPUs

Background
==========
We sometimes want to identify each kernel message automatically because of the following purposes:

(1) Show more detailed information about the message by cooperating with external system
(2) Take actions automatically depending on the message, for example trigger a fail over or collect related information to analyze the problem

However, most of printk messages have dynamically generated parts, so it is difficult to identify the messages. Even if you can, it will be expensive.

To solve this issue, this patch series add a hash value of each printk format string. A catalog file which consists of hash, location, and format string lines is also generated at the kernel build time. Userland tools can easily identify kernel messages by utilizing the catalog file.

Design
======
Hash values are displayed only when reading /dev/kmsg. Console and /proc/kmsg outputs are not affected by this feature.

The format in /dev/kmsg output is like this:

        6,154,325061,-,b7db707c@kernel/smp.c:554;Brought up 4 CPUs

The 5th field is added, and it means "<32-bit hash>@<filename>:<lineno>". If you disable this feature (CONFIG_KMSG_HASH=n) or any cases the hash value is not calculated, the 5th field shows '-'.

The function printk() is replaced with macro version to create a metadata table which is used to calculate and keep hash values. Hash value calculation is done at the kernel build time, but not execution time. scripts/msghash tools scan the metadata table in vmlinux, calculate hash values, and put them back into the table. At the same time, msghash creates a catalog file named "<objfile>.msglist". Here is an example of its contents:

    ...
    b6be0058@init/main.c:180,"Parameter %s is obsolete, ignored"
    72dfe336@init/main.c:403,"Malformed early option '%s'"
    85788d36@init/do_mounts.c:573,"Waiting for root device %s..."
    ...

The format is <32-bit hash>@<filename>:<lineno>,"<message format>". Similar to /dev/kmsg, unprintable characters in message formats are escaped and a trailing newline is dropped.

Restrictions
============
Currently, only printk, pr_xxx, dev_printk, and dev_xxx are supported except for pr_debug with dynamic printk. Other printk variants won't show meaningful hash values. I'm going to support some of them in the future patches.

KERN_CONT cases are not dealt with well. Only the first printk's hash is output and continued printks are ignored.

Kernel module support has not been implemented yet. I'm going to do this in the future patches.

Note
====
When CONFIG_KMSG_HASH=y, a metadata table and additional file name strings are allocated in object files, and it increases the kernel size. Below is the difference of CONFIG_KMSG_HASH=n/y in some configuration. The total size increases about 2%.

text data bss dec hex filename
8135284 2395144 2211840 12742268 c26e7c vmlinux_hash_disabled
8255079 2519368 2211840 12986287 c627af vmlinux_hash_enabled

Thanks,
---

Hidehiro Kawai (5):
printk: Add msghash support for dev_printk
msghash: Add userland msghash tool tools/include: Add jhash.h
printk: add message hash values in /dev/kmsg output
printk: make printk a macro

 .gitignore                        |    1 
 Makefile                          |    7 +
 drivers/base/core.c               |   57 ++-------
 drivers/usb/storage/debug.c       |    2 
 include/asm-generic/vmlinux.lds.h |    5 +
 include/linux/device.h            |   73 +++++++----
 include/linux/kmsghash.h          |   19 +++
 include/linux/printk.h            |   31 ++++-
 kernel/printk.c                   |   81 +++++++++---
 lib/Kconfig.debug                 |   22 +++
 lib/dynamic_debug.c               |    4 -
 net/core/dev.c                    |    2 
 scripts/Makefile                  |    1 
 scripts/link-vmlinux.sh           |    5 +
 scripts/msghash/.gitignore        |    1 
 scripts/msghash/Makefile          |    7 +
 scripts/msghash/msghash.c         |  241 +++++++++++++++++++++++++++++++++++++
 scripts/msghash/msghash.sh        |   45 +++++++
 tools/include/tools/jhash.h       |  192 +++++++++++++++++++++++++++++
 19 files changed, 698 insertions(+), 98 deletions(-)
 create mode 100644 include/linux/kmsghash.h
 create mode 100644 scripts/msghash/.gitignore
 create mode 100644 scripts/msghash/Makefile
 create mode 100644 scripts/msghash/msghash.c
 create mode 100755 scripts/msghash/msghash.sh
 create mode 100644 tools/include/tools/jhash.h

Hidehiro Kawai
Hitach, Yokohama Research Laboratory
Linux Technology Center

To allow building up metadata transparently for each printk(), make printk() a macro while keeping printk()'s API. Then, printk() calls _printk() which implements the original printk() function.

printk() is used from assembly sources, but they don't include printk.h and don't use this new printk() macro. This is addressed by assigning the printk symbol to _printk in the linker script.

---

 include/asm-generic/vmlinux.lds.h |    1 +
 include/linux/printk.h            |    4 +++-
 kernel/printk.c                   |   12 ++++++++----
 3 files changed, 12 insertions(+), 5 deletions(-)

index eb58d2d..0380add 100644
@@ -416,6 +416,7 @@
 		*(.text.hot)						\
 		*(.text)						\
 		*(.ref.text)						\
+	VMLINUX_SYMBOL(printk) = VMLINUX_SYMBOL(_printk);		\
 	DEV_KEEP(init.text)						\
 	DEV_KEEP(exit.text)						\
 	CPU_KEEP(init.text)						\

index 22c7052..c7a8c6b 100644
@@ -121,7 +121,9 @@ asmlinkage int printk_emit(int facility, int level,
 			   const char *fmt, ...);
 
 asmlinkage __printf(1, 2) __cold
-int printk(const char *fmt, ...);
+int _printk(const char *fmt, ...);
+
+#define printk(fmt, args...) _printk(fmt, ## args)
 
 /*
  * Special printk facility for scheduler use only, _DO_NOT_USE_ !

index 8212c1a..1ec264e 100644
@@ -1658,10 +1658,14 @@ asmlinkage int printk_emit(int facility, int level,
 EXPORT_SYMBOL(printk_emit);
 
 /**
- * printk - print a kernel message
+ * _printk - print a kernel message
  * @fmt: format string
  *
- * This is printk(). It can be called from any context. We want it to work.
+ * Now, printk() is a macro defined in include/linux/printk.h, and this
+ * function is its body.  It can be called from any context, but please
+ * use printk() macro.  Directly calling _printk() is not recommended.
+ * In assembly sources, you can call printk as in the past because the
+ * linker program links the printk symbol in assembly sources to _printk.
  *
  * We try to grab the console_lock. If we succeed, it's easy - we log the
  * output and call the console drivers.  If we fail to get the semaphore, we

@@ -1678,7 +1682,7 @@ EXPORT_SYMBOL(printk_emit);
  *
  * See the vsnprintf() documentation for format string extensions over C99.
  */
-asmlinkage int printk(const char *fmt, ...)
+asmlinkage int _printk(const char *fmt, ...)
 {
 	va_list args;
 	int r;

@@ -1697,7 +1701,7 @@ asmlinkage int printk(const char *fmt, ...)
 
 	return r;
 }
-EXPORT_SYMBOL(printk);
+EXPORT_SYMBOL(_printk);
 
 #else /* CONFIG_PRINTK */
 

This patch adds the hash value for each printk line when reading /dev/kmsg as bellow:

	6,154,325061,-,b7db707c@kernel/smp.c:554;Brought up 4 CPUs

Here, the 5th field is the 32-bit hash value followed by @<filename>:<lineno>. If this feature is disabled, i.e. CONFIG_KMSG_HASH=n, or the hash value hasn't be calculated, the 5th field simply shows '-'. Hash values don't appear in other than /dev/kmsg, thus they are not't displayed on the console and won't be written to /var/log/messages.

A metadata table which includes pointers to the format strings and location info of printk is placed between __start___kmsg_meta to __stop___kmsg_meta. Since the kernel doesn't calculate hash values dynamically, userland tools need to calculate hash values and place them into the table before running the kernel. To save the space, the pointers to the format strings are replaced with the calculated hash values.

In the current implementation, KERN_CONT cases are not dealt with well. Only a hash value of the first printk in the sequence is printed.

---

 drivers/base/core.c               |    3 +-
 include/asm-generic/vmlinux.lds.h |    4 ++
 include/linux/kmsghash.h          |   19 ++++++++++
 include/linux/printk.h            |   29 ++++++++++++++--
 kernel/printk.c                   |   69 ++++++++++++++++++++++++++++---------
 lib/Kconfig.debug                 |   17 +++++++++
 6 files changed, 122 insertions(+), 19 deletions(-)
 create mode 100644 include/linux/kmsghash.h

index 2499cef..558017d 100644
@@ -1959,7 +1959,8 @@ int dev_vprintk_emit(int level, const struct device *dev,
 
 	hdrlen = create_syslog_header(dev, hdr, sizeof(hdr));
 
-	return vprintk_emit(0, level, hdrlen ? hdr : NULL, hdrlen, fmt, args);
+	return vprintk_emit(0, level, hdrlen ? hdr : NULL, hdrlen,
+			    fmt, args, NULL);
 }
 EXPORT_SYMBOL(dev_vprintk_emit);
 

index 0380add..3d82844 100644
@@ -200,6 +200,10 @@
 	VMLINUX_SYMBOL(__start___verbose) = .;                          \
 	*(__verbose)                                                    \
 	VMLINUX_SYMBOL(__stop___verbose) = .;				\
+	. = ALIGN(8);							\
+	VMLINUX_SYMBOL(__start___kmsg_meta) = .;			\
+	*(__kmsg_meta)							\
+	VMLINUX_SYMBOL(__stop___kmsg_meta) = .;				\
 	LIKELY_PROFILE()		       				\
 	BRANCH_PROFILE()						\
 	TRACE_PRINTKS()

new file mode 100644
index 0000000..6cfe373
@@ -0,0 +1,19 @@
+#ifndef _LINUX_KMSGHASH_H
+#define _LINUX_KMSGHASH_H
+
+/* kernel message metadata flags */
+#define KMSG_FLAGS_HASH_VALID	(1<<0)
+#define KMSG_FLAGS_DEFAULT	0
+
+struct kmsg_meta {
+	const char *filename;
+	union {
+		/* format is replaced with hash at build time */
+		const char *format;
+		u32 hash;
+	} u;
+	unsigned int lineno:18;
+	unsigned int flags:8;
+} __attribute__((aligned(8)));
+
+#endif

index c7a8c6b..fe6b350 100644
@@ -5,6 +5,7 @@
 #include <linux/init.h>
 #include <linux/kern_levels.h>
 #include <linux/linkage.h>
+#include <linux/kmsghash.h>
 
 extern const char linux_banner[];
 extern const char linux_proc_banner[];

@@ -110,7 +111,7 @@ void early_printk(const char *s, ...) { }
 asmlinkage __printf(5, 0)
 int vprintk_emit(int facility, int level,
 		 const char *dict, size_t dictlen,
-		 const char *fmt, va_list args);
+		 const char *fmt, va_list args, struct kmsg_meta *meta);
 
 asmlinkage __printf(1, 0)
 int vprintk(const char *fmt, va_list args);

@@ -123,7 +124,31 @@ asmlinkage int printk_emit(int facility, int level,
 asmlinkage __printf(1, 2) __cold
 int _printk(const char *fmt, ...);
 
-#define printk(fmt, args...) _printk(fmt, ## args)
+__printf(2, 3) __cold
+int __printk(struct kmsg_meta *meta, const char *fmt, ...);
+
+#ifdef CONFIG_KMSG_HASH
+#define DEFINE_KMSG_METADATA(name, fmt)					\
+	static struct kmsg_meta __aligned(8)				\
+	__attribute__((section("__kmsg_meta"))) name = {		\
+		.filename = __FILE__,					\
+		.u.format = __builtin_constant_p(fmt) ? (fmt) : 0,	\
+		.lineno = __LINE__,					\
+		.flags = KMSG_FLAGS_DEFAULT,				\
+	}
+
+#define printk_(fmt, args...)				\
+({							\
+	DEFINE_KMSG_METADATA(_meta, (fmt));		\
+	__printk(&_meta, (fmt), ##args);		\
+})
+
+#define printk(fmt, args...) printk_(fmt, ##args)
+
+#else
+
+#define printk(fmt, args...) __printk(0, fmt, ##args)
+#endif /* CONFIG_KMSG_HASH */
 
 /*
  * Special printk facility for scheduler use only, _DO_NOT_USE_ !

index 566cf2b..9302ece 100644
@@ -14,6 +14,23 @@ config PRINTK_TIME
 	  The behavior is also controlled by the kernel command line
 	  parameter printk.time=1. See Documentation/kernel-parameters.txt
 
+config KMSG_HASH
+	bool "Show the hash value of each printk message format"
+	depends on PRINTK
+	default n
+	help
+	  If you say y here, the hash value of each printk message
+	  format is displayed when reading /dev/kmsg as bellow:
+
+	    6,154,325061,-,b7db707c@kernel/smp.c:554;Brought up 4 CPUs
+
+	  Here, the 5th field is the 32-bit hash value followed by
+	  @<location>.  If this feature is disabled or the hash value
+	  couldn't be calculated, the 5th field simply shows '-'.
+
+	  Please note that the kernel image size gets larger by
+	  hundres Kbytes when this feature is enabled.
+
 config DEFAULT_MESSAGE_LOGLEVEL
 	int "Default message log level (1-7)"
 	range 1 7

Copy include/linux/jhash.h to tools/include/tools/ for userland tools. The original jhash.h includes a couple of header files which is not suitable for userland. So unfold the only necessary part in those header files to the copied jhash.h

---

 tools/include/tools/jhash.h |  192 +++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 192 insertions(+), 0 deletions(-)
 create mode 100644 tools/include/tools/jhash.h

new file mode 100644
index 0000000..872d7f9
@@ -0,0 +1,192 @@
+#ifndef _TOOLS_JHASH_H
+#define _TOOLS_JHASH_H
+
+/* jhash.h: Jenkins hash support.
+ *
+ * Copyright (C) 2006. Bob Jenkins ([email protected])
+ *
+ * http://burtleburtle.net/bob/hash/
+ *
+ * These are the credits from Bob's sources:
+ *
+ * lookup3.c, by Bob Jenkins, May 2006, Public Domain.
+ *
+ * These are functions for producing 32-bit hashes for hash table lookup.
+ * hashword(), hashlittle(), hashlittle2(), hashbig(), mix(), and final()
+ * are externally useful functions.  Routines to test the hash are included
+ * if SELF_TEST is defined.  You can use this free for any purpose.  It's in
+ * the public domain.  It has no warranty.
+ *
+ * Copyright (C) 2009-2010 Jozsef Kadlecsik ([email protected])
+ *
+ * I've modified Bob's hash to be useful in the Linux kernel, and
+ * any bugs present are my fault.
+ * Jozsef
+ */
+
+#define __packed	__attribute__((packed))
+
+/*
+ * __get_unaligned_cpu32 was copied from
+ * include/linux/unaligned/packed_struct.h
+ */
+struct __una_u32 { u32 x; } __packed;
+static inline u32 __get_unaligned_cpu32(const void *p)
+{
+	const struct __una_u32 *ptr = (const struct __una_u32 *)p;
+	return ptr->x;
+}
+
+/* rol32 was copied from include/linux/bitops.h */
+/**
+ * rol32 - rotate a 32-bit value left
+ * @word: value to rotate
+ * @shift: bits to roll
+ */
+static inline u32 rol32(u32 word, unsigned int shift)
+{
+	return (word << shift) | (word >> (32 - shift));
+}
+
+/* Best hash sizes are of power of two */
+#define jhash_size(n)   ((u32)1<<(n))
+/* Mask the hash value, i.e (value & jhash_mask(n)) instead of (value % n) */
+#define jhash_mask(n)   (jhash_size(n)-1)
+
+/* __jhash_mix -- mix 3 32-bit values reversibly. */
+#define __jhash_mix(a, b, c)			\
+{						\
+	a -= c;  a ^= rol32(c, 4);  c += b;	\
+	b -= a;  b ^= rol32(a, 6);  a += c;	\
+	c -= b;  c ^= rol32(b, 8);  b += a;	\
+	a -= c;  a ^= rol32(c, 16); c += b;	\
+	b -= a;  b ^= rol32(a, 19); a += c;	\
+	c -= b;  c ^= rol32(b, 4);  b += a;	\
+}
+
+/* __jhash_final - final mixing of 3 32-bit values (a,b,c) into c */
+#define __jhash_final(a, b, c)			\
+{						\
+	c ^= b; c -= rol32(b, 14);		\
+	a ^= c; a -= rol32(c, 11);		\
+	b ^= a; b -= rol32(a, 25);		\
+	c ^= b; c -= rol32(b, 16);		\
+	a ^= c; a -= rol32(c, 4);		\
+	b ^= a; b -= rol32(a, 14);		\
+	c ^= b; c -= rol32(b, 24);		\
+}
+
+/* An arbitrary initial parameter */
+#define JHASH_INITVAL		0xdeadbeef
+
+/* jhash - hash an arbitrary key
+ * @k: sequence of bytes as key
+ * @length: the length of the key
+ * @initval: the previous hash, or an arbitray value
+ *
+ * The generic version, hashes an arbitrary sequence of bytes.
+ * No alignment or length assumptions are made about the input key.
+ *
+ * Returns the hash value of the key. The result depends on endianness.
+ */
+static inline u32 jhash(const void *key, u32 length, u32 initval)
+{
+	u32 a, b, c;
+	const u8 *k = key;
+
+	/* Set up the internal state */
+	a = b = c = JHASH_INITVAL + length + initval;
+
+	/* All but the last block: affect some 32 bits of (a,b,c) */
+	while (length > 12) {
+		a += __get_unaligned_cpu32(k);
+		b += __get_unaligned_cpu32(k + 4);
+		c += __get_unaligned_cpu32(k + 8);
+		__jhash_mix(a, b, c);
+		length -= 12;
+		k += 12;
+	}
+	/* Last block: affect all 32 bits of (c) */
+	/* All the case statements fall through */
+	switch (length) {
+	case 12: c += (u32)k[11]<<24;
+	case 11: c += (u32)k[10]<<16;
+	case 10: c += (u32)k[9]<<8;
+	case 9:  c += k[8];
+	case 8:  b += (u32)k[7]<<24;
+	case 7:  b += (u32)k[6]<<16;
+	case 6:  b += (u32)k[5]<<8;
+	case 5:  b += k[4];
+	case 4:  a += (u32)k[3]<<24;
+	case 3:  a += (u32)k[2]<<16;
+	case 2:  a += (u32)k[1]<<8;
+	case 1:  a += k[0];
+		 __jhash_final(a, b, c);
+	case 0: /* Nothing left to add */
+		break;
+	}
+
+	return c;
+}
+
+/* jhash2 - hash an array of u32's
+ * @k: the key which must be an array of u32's
+ * @length: the number of u32's in the key
+ * @initval: the previous hash, or an arbitray value
+ *
+ * Returns the hash value of the key.
+ */
+static inline u32 jhash2(const u32 *k, u32 length, u32 initval)
+{
+	u32 a, b, c;
+
+	/* Set up the internal state */
+	a = b = c = JHASH_INITVAL + (length<<2) + initval;
+
+	/* Handle most of the key */
+	while (length > 3) {
+		a += k[0];
+		b += k[1];
+		c += k[2];
+		__jhash_mix(a, b, c);
+		length -= 3;
+		k += 3;
+	}
+
+	/* Handle the last 3 u32's: all the case statements fall through */
+	switch (length) {
+	case 3: c += k[2];
+	case 2: b += k[1];
+	case 1: a += k[0];
+		__jhash_final(a, b, c);
+	case 0:	/* Nothing left to add */
+		break;
+	}
+
+	return c;
+}
+
+
+/* jhash_3words - hash exactly 3, 2 or 1 word(s) */
+static inline u32 jhash_3words(u32 a, u32 b, u32 c, u32 initval)
+{
+	a += JHASH_INITVAL;
+	b += JHASH_INITVAL;
+	c += initval;
+
+	__jhash_final(a, b, c);
+
+	return c;
+}
+
+static inline u32 jhash_2words(u32 a, u32 b, u32 initval)
+{
+	return jhash_3words(a, b, 0, initval);
+}
+
+static inline u32 jhash_1word(u32 a, u32 initval)
+{
+	return jhash_3words(a, 0, 0, initval);
+}
+
+#endif /* _TOOLS_JHASH_H */

This patch adds scripts/msghash/msghash. msghash scans a kmsg_meta table between __start___kmsg_meta to __stop___kmsg_meta in the target object file (vmlinux), computes a hash value for each message format string, then replaces the format string with the hash value. Valid flags are also set to entries in the kmsg_meta table. When computing the hash value, prefixed loglevel characters are ignored.

Even if configured with CONFIG_KMSG_HASH=y, without running msghash, no hash values are output via /dev/kmsg. So msghash is executed during the build process, just after generating vmlinux.

msghash also generate a Hash-and-message catalog named "<objfile>.msglist". Each line in the .msglist file is output in the form of:
<hash in hex>@<file>:<lineno>,<message format>

.msglist file is useful to match /dev/kmsg messages with messages you concern.

Here is the example of .msglist:
...
b6be0058@init/main.c:180,"Parameter %s is obsolete, ignored" 72dfe336@init/main.c:403,"Malformed early option '%s'" 85788d36@init/do_mounts.c:573,"Waiting for root device %s..."
...

Currently, only vmlinux is supported. msghash can't update the kmsg_meta tables of kernel modules.

---

 .gitignore                 |    1 
 Makefile                   |    7 +
 lib/Kconfig.debug          |    5 +
 scripts/Makefile           |    1 
 scripts/link-vmlinux.sh    |    5 +
 scripts/msghash/.gitignore |    1 
 scripts/msghash/Makefile   |    7 +
 scripts/msghash/msghash.c  |  241 ++++++++++++++++++++++++++++++++++++++++++++
 scripts/msghash/msghash.sh |   45 ++++++++
 9 files changed, 312 insertions(+), 1 deletions(-)
 create mode 100644 scripts/msghash/.gitignore
 create mode 100644 scripts/msghash/Makefile
 create mode 100644 scripts/msghash/msghash.c
 create mode 100755 scripts/msghash/msghash.sh

index 3b8b9b3..3bb5735 100644
@@ -32,6 +32,7 @@ modules.builtin
 *.lzo
 *.patch
 *.gcno
+*.msglist
 
 #
 # Top-level generic files

index e5e3ba0..2693d7d 100644
@@ -766,6 +766,10 @@ vmlinux-deps := $(KBUILD_LDS) $(KBUILD_VMLINUX_INIT) $(KBUILD_VMLINUX_MAIN)
       cmd_link-vmlinux = $(CONFIG_SHELL) $< $(LD) $(LDFLAGS) $(LDFLAGS_vmlinux)
 quiet_cmd_link-vmlinux = LINK    $@
 
+# Remove old .msglist
+      cmd_rm-msglist = echo rm -f [email protected]
+quiet_cmd_rm-msglist = CLEAN   [email protected]
+
 # Include targets which we want to
 # execute if the rest of the kernel build went well.
 vmlinux: scripts/link-vmlinux.sh $(vmlinux-deps) FORCE

@@ -1273,7 +1277,8 @@ clean: $(clean-dirs)
 		-o -name '.*.d' -o -name '.*.tmp' -o -name '*.mod.c' \
 		-o -name '*.symtypes' -o -name 'modules.order' \
 		-o -name modules.builtin -o -name '.tmp_*.o.*' \
-		-o -name '*.gcno' \) -type f -print | xargs rm -f
+		-o -name '*.gcno' -o -name '*.msglist' \) -type f -print |\
+		xargs rm -f
 
 # Generate tags for editors
 # ---------------------------------------------------------------------------

index 9302ece..bd05088 100644
@@ -11,6 +11,11 @@ config PRINTK_TIME
 	  to /dev/kmsg. This flag just specifies if the timestamp should
 	  be included, not that the timestamp is recorded.
 
+	  Hash values are calculated during the build process and
+	  put into a table in object files.  Hash-and-message catalogs
+	  named <objfile>.msglist are also generated for convenience
+	  in message handling in userland.
+
 	  The behavior is also controlled by the kernel command line
 	  parameter printk.time=1. See Documentation/kernel-parameters.txt
 

index 01e7adb..7568e35 100644
@@ -37,6 +37,7 @@ subdir-$(CONFIG_MODVERSIONS) += genksyms
 subdir-y                     += mod
 subdir-$(CONFIG_SECURITY_SELINUX) += selinux
 subdir-$(CONFIG_DTC)         += dtc
+subdir-$(CONFIG_KMSG_HASH) += msghash
 
 # Let clean descend into subdirs
 subdir-	+= basic kconfig package selinux

index 0149949..575c2bb 100644
@@ -228,5 +228,10 @@ if [ -n "${CONFIG_KALLSYMS}" ]; then
 	fi
 fi
 
+if [ -n "${CONFIG_KMSG_HASH}" ]; then
+	rm -f vmlinux.msglist
+	${srctree}/scripts/msghash/msghash.sh vmlinux || exit 1
+fi
+
 # We made a new kernel - delete old version file
 rm -f .old_version

new file mode 100644
index 0000000..8bcfa1d
@@ -0,0 +1 @@
+msghash

new file mode 100644
index 0000000..add1e14
@@ -0,0 +1,7 @@
+hostprogs-y	:= msghash
+
+HOST_EXTRACFLAGS += -I$(srctree)/tools/include -I$(srctree)/include
+
+always		:= $(hostprogs-y)
+clean-files	:= $(hostprogs-y)
+

Add msghash support for dev_printk and its variants (dev_xxx). Without this patch, no kmsg_meta data are passed to vprintk_emit, and this means no hash value is output.

To pass the metadata, this patch changes dev_printk and its variants to macros which construct the metadata in the similar way of printk. No API of those functions are changed.

---

 drivers/base/core.c         |   56 +++++++++------------------------
 drivers/usb/storage/debug.c |    2 +
 include/linux/device.h      |   73 +++++++++++++++++++++++++------------------
 lib/dynamic_debug.c         |    4 +-
 net/core/dev.c              |    2 +
 5 files changed, 62 insertions(+), 75 deletions(-)

index 558017d..4b12e8a1 100644
@@ -1951,8 +1951,8 @@ create_syslog_header(const struct device *dev, char *hdr, size_t hdrlen)
 }
 EXPORT_SYMBOL(create_syslog_header);
 
-int dev_vprintk_emit(int level, const struct device *dev,
-		     const char *fmt, va_list args)
+int dev_vprintk_emit(struct kmsg_meta *meta, int level,
+		     const struct device *dev, const char *fmt, va_list args)
 {
 	char hdr[128];
 	size_t hdrlen;

@@ -1960,18 +1960,19 @@ int dev_vprintk_emit(int level, const struct device *dev,
 	hdrlen = create_syslog_header(dev, hdr, sizeof(hdr));
 
 	return vprintk_emit(0, level, hdrlen ? hdr : NULL, hdrlen,
-			    fmt, args, NULL);
+			    fmt, args, meta);
 }
 EXPORT_SYMBOL(dev_vprintk_emit);
 
-int dev_printk_emit(int level, const struct device *dev, const char *fmt, ...)
+int dev_printk_emit(struct kmsg_meta *meta, int level,
+		    const struct device *dev, const char *fmt, ...)
 {
 	va_list args;
 	int r;
 
 	va_start(args, fmt);
 
-	r = dev_vprintk_emit(level, dev, fmt, args);
+	r = dev_vprintk_emit(meta, level, dev, fmt, args);
 
 	va_end(args);
 

@@ -1979,19 +1980,20 @@ int dev_printk_emit(int level, const struct device *dev, const char *fmt, ...)
 }
 EXPORT_SYMBOL(dev_printk_emit);
 
-static int __dev_printk(const char *level, const struct device *dev,
-			struct va_format *vaf)
+static int __dev_printk(struct kmsg_meta *meta, const char *level,
+			const struct device *dev, struct va_format *vaf)
 {
 	if (!dev)
-		return printk("%s(NULL device *): %pV", level, vaf);
+		return __printk(meta, "%s(NULL device *): %pV", level, vaf);
 
-	return dev_printk_emit(level[1] - '0', dev,
+	return dev_printk_emit(meta, level[1] - '0', dev,
 			       "%s %s: %pV",
 			       dev_driver_string(dev), dev_name(dev), vaf);
 }
 
-int dev_printk(const char *level, const struct device *dev,
-	       const char *fmt, ...)
+__printf(4, 5)
+int _dev_printk(struct kmsg_meta *meta, const char *level,
+		const struct device *dev, const char *fmt, ...)
 {
 	struct va_format vaf;
 	va_list args;

@@ -2002,40 +2004,12 @@ int dev_printk(const char *level, const struct device *dev,
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
-	r = __dev_printk(level, dev, &vaf);
+	r = __dev_printk(meta, level, dev, &vaf);
 
 	va_end(args);
 
 	return r;
 }
-EXPORT_SYMBOL(dev_printk);
-
-#define define_dev_printk_level(func, kern_level)		\
-int func(const struct device *dev, const char *fmt, ...)	\
-{								\
-	struct va_format vaf;					\
-	va_list args;						\
-	int r;							\
-								\
-	va_start(args, fmt);					\
-								\
-	vaf.fmt = fmt;						\
-	vaf.va = &args;						\
-								\
-	r = __dev_printk(kern_level, dev, &vaf);		\
-								\
-	va_end(args);						\
-								\
-	return r;						\
-}								\
-EXPORT_SYMBOL(func);
-
-define_dev_printk_level(dev_emerg, KERN_EMERG);
-define_dev_printk_level(dev_alert, KERN_ALERT);
-define_dev_printk_level(dev_crit, KERN_CRIT);
-define_dev_printk_level(dev_err, KERN_ERR);
-define_dev_printk_level(dev_warn, KERN_WARNING);
-define_dev_printk_level(dev_notice, KERN_NOTICE);
-define_dev_printk_level(_dev_info, KERN_INFO);
+EXPORT_SYMBOL(_dev_printk);
 
 #endif

index e08f647..22e1115 100644
@@ -186,7 +186,7 @@ int usb_stor_dbg(const struct us_data *us, const char *fmt, ...)
 
 	va_start(args, fmt);
 
-	r = dev_vprintk_emit(7, &us->pusb_dev->dev, fmt, args);
+	r = dev_vprintk_emit(NULL, 7, &us->pusb_dev->dev, fmt, args);
 
 	va_end(args);
 

index 99fec3a..46283dd 100644
@@ -578,7 +578,7 @@ int __dynamic_dev_dbg(struct _ddebug *descriptor,
 	} else {
 		char buf[PREFIX_SIZE];
 
-		res = dev_printk_emit(7, dev, "%s%s %s: %pV",
+		res = dev_printk_emit(NULL, 7, dev, "%s%s %s: %pV",
 				      dynamic_emit_prefix(descriptor, buf),
 				      dev_driver_string(dev), dev_name(dev),
 				      &vaf);

@@ -610,7 +610,7 @@ int __dynamic_netdev_dbg(struct _ddebug *descriptor,
 	if (dev && dev->dev.parent) {
 		char buf[PREFIX_SIZE];
 
-		res = dev_printk_emit(7, dev->dev.parent,
+		res = dev_printk_emit(NULL, 7, dev->dev.parent,
 				      "%s%s %s %s: %pV",
 				      dynamic_emit_prefix(descriptor, buf),
 				      dev_driver_string(dev->dev.parent),

index faebb39..2a16898 100644
@@ -6111,7 +6111,7 @@ static int __netdev_printk(const char *level, const struct net_device *dev,
 	int r;
 
 	if (dev && dev->dev.parent) {
-		r = dev_printk_emit(level[1] - '0',
+		r = dev_printk_emit(NULL, level[1] - '0',
 				    dev->dev.parent,
 				    "%s %s %s: %pV",
 				    dev_driver_string(dev->dev.parent),

/dev/kmsg is to a certain degree a kernel ABI. Having source code locations in exported log records might cause people / userspace tools to rely on these strings and expect stability here. The kernel though cannot make any promises of its source code layout.

The hash is supposed to identify the content of a message, but what if someone fixes the string? Maybe someone just fixes a one char typo, the hash will change and the message will not be recognizable any more.

As much as "automated" hash creation sounds simple; I really think adding explicit "manually" created random message ids to the bunch of messages that are interesting is the better option long-term. It shouldn't be that many messages, most of the printk output is not really useful for automated inspection or to trigger specific actions.

Messages ideally should not have any direct context to the code that emits them, they should just identify the message and add a few structured properties to the message.

This is how userspace identifies log messages and maintains abstract descriptions of the specific messages to act when they appear:
http://www.freedesktop.org/wiki/Software/systemd/catalog/

Connecting kernel log message texts and source code locations with message identifiers looks quite dangerous, hard to keep stable if things are evolving. It might cause serious problems over time.

Thanks,
Kay

Hello,

(2013/07/26 21:43), Kay Sievers wrote:> On Wed, Jul 3, 2013 at 3:46 AM, Hidehiro Kawai

All we have to keep as kABI is <hash>@<filename>:<lineno> of the 5th field. I regard the 5th field including hash as just a hint; it's not guaranteed either the hash is unique or filename:lineno is unchanged. Userspace tools can use the hash to identify the message quickly, but if a hash collision occurs, the user space need to do message matching in a traditional way. Please note that userspace tools can know which ones collide from a catalog generated at build time.

As for <filename>:<lineno>, it wouldn't be needed for the most of the cases. So I think I can introduce an option to suppress the output of <filename>:<lineno> to reduce memory space.

A catalog file which includes hash, location info, and message is generated at build time. Combining this information with diff between two kernel versions, userspace tools will be able to track where messages moved and which messages changed. Then, the userspace tool updates the message DB managed by it. So I don't think it's a hard problem.

Yes, as far as the use case goes, it may be true. But it has some drawbacks. Please also see my reply to Joe Perches in another thread (I resent the patches on July 25th). Also, I heard about the discussion at the kernel summit 2 years ago. According to the article of LWN, it seems that Linus objected your approach (i.e. adding random bit as message ID). Were there some agreements on this issue at the kernel summit?

Regards,

Hidehiro Kawai
Hitachi, Yokohama Research Laboratory
Linux Technology Center

No, there are no further discussions about this.

Pre-allocated, static, randomly created 128-bit IDs are just the simplest and most robust option to identify messages. It's an unmanaged namespace that needs no coordination, the IDs are always stable, never change and are guaranteed to be unique. None of the hashing-of-the strings solutions can provide that by default.

I would expect that over time, the automatic hashes would end up becoming static numbers explicitly add to the messages anyway, because changing the message text will change the hash, which is nothing we really want to deal with. For that reason, I think that we can add the ID right away, without any of the hashing; and do that only for a very tiny fraction of the messages where such IDs make sense and add value.

Message IDs is how userspace logging works today; so from the userspace side this would fit into the already existing infrastructure, while possibly changing hashes which require another type of translation catalog would not.

Kay

Hello,

(2013/07/29 21:46), Kay Sievers wrote:> On Mon, Jul 29, 2013 at 1:54 PM, Hidehiro Kawai

So, how are you going to push patches to add random 128-bit IDs into upstream? To be honest, I don't mind if we take the way of adding random IDs, because I'm interested in only limited number of messages for my use case (taking some actions automatically when seeing particular messages).
The reasons why I took the way of message hashing are for upstream acceptance and flexibility for various usages.

I think it depends on use cases and user space tools. Strict uniqueness and stability wouldn't always be needed.

Adding ID to particular printks will work well for some use cases, but not all. For example, there is a web service, OSS message pedia, which provides kernel message details edited by community. Currently, it looks like it lists search results based on similarity with an input string. If it utilizes message hashes or IDs, it can provide more values. However, the fixed message ID approach wouldn't work well, because it deals with hundreds messages at this moment.

Do you say about systemd? It is one of the user space tools which handle messages. There can be several use cases and value-added tools regarding that, so we shouldn't assume one particular tool, I think.

Randomly generated IDs make message handling in user space simple, but put some maintenance costs on kernel developers. Automatically generated hashes give some complexity to user space tools, but there is no maintenance cost for respective printks. There are tradeoffs. The problem is which ways are acceptable for the upstream kernel (may be both or none?).

Regards,

Hidehiro Kawai
Hitachi, Yokohama Research Laboratory
Linux Technology Center