Escaping the arguments of kernel messages for sane user-space localisation

Alan,

I send here the simplified patch to emit log messages with markers for the message arguments, as per your suggestion. Do you still think this is over-kill?

The rigour exists in order to preserve the generality of snprintf(), instead of changing it to include printk-specific code, which in my opinion does not belong there.

If these changes to make snprintf() more customizable will never be used in any other place in the kernel, then they are clearly also over-kill.

These functions make it quite easy to make snprintf() automatically escape certain characters in string arguments, for example. I think they are also well suited to printing to variable-sized buffers, though the last time I looked, there was no krealloc in the kernel, which makes it again useless. Perhaps there are other uses, though?

This patch in particular makes printk() put a \x1f (ASCII "unit separator") before and after each argument. It seems that user-space terminal emulators handle this (by not printing anything, so in effect there is no visual change), but the VGA console will print funny symbols instead. I've tried to change this in drivers/char/vt.c by masking out this character from the ones to display, but to no avail. I am sure it is possible, but I am not able to do it.

Please let me know what you think.

Kind regards,
Vegard

 include/linux/xprintf.h |   28 +++++
 kernel/printk.c         |   89 ++++++++++++++-
 lib/vsprintf.c          |  296 ++++++++++++++++++++++++++++----------------
 3 files changed, 292 insertions(+), 121 deletions(-)

new file mode 100644
index 0000000..76efc43
@@ -0,0 +1,28 @@
+#ifndef LINUX_XPRINTF_H
+#define LINUX_XPRINTF_H
+
+#include <stdarg.h>
+#include <linux/kernel.h>
+
+struct xprintf_ops {
+	void (*begin)(void *data);
+	void (*end)(void *data);
+	void (*put_format)(void *data, char c);
+
+	void (*begin_param)(void *data);
+	void (*end_param)(void *data);
+	void (*put_param)(void *data, char c);
+
+	long (*size)(void *data);
+
+	void (*unknown_conversion)(void *data, char c);
+};
+
+extern void xprintf(void *data, const struct xprintf_ops *ops,
+	const char *fmt, ...)
+	__attribute__ ((format (printf, 3, 4)));
+extern void vxprintf(void *data, const struct xprintf_ops *ops,
+	const char *fmt, va_list args)
+	__attribute__ ((format (printf, 3, 0)));
+
+#endif

Hello again,

I have now found what I think is another valid use. What I have done is to make xprintf() emit the output directly to the kernel ring-buffer.

This means two things:
1. We get rid of a (static) 1K temporary buffer in printk().
2. A single log message (as emitted by a single call to printk()) is no longer limited to 1K bytes, but is limited to the size of the ring buffer (this was obviously always true).

In particular, I think this output from bloat-o-meter is interesting:

add/remove: 25/3 grow/shrink: 0/2 up/down: 1955/-2585 (-630)
function old new delta

vxprintf                                       -    1048   +1048
xprintf_number                                 -     499    +499
vsnprintf_unknown_conversion                   -      44     +44
printk_put                                     -      35     +35
printk_unknown_conversion                      -      34     +34
vsnprintf_end                                  -      33     +33
xprintf                                        -      32     +32
vsnprintf_put_char                             -      24     +24
printk_end_param                               -      22     +22
printk_begin_param                             -      22     +22
vsnprintf_begin                                -      21     +21
vsnprintf_put_param                            -      20     +20
vsnprintf_put_format                           -      20     +20
printk_put_param                               -      16     +16
printk_put_format                              -      16     +16
printk_begin                                   -      15     +15
vsnprintf_size                                 -      13     +13
printk_size                                    -      10     +10
vsnprintf_end_param                            -       5      +5
vsnprintf_begin_param                          -       5      +5
printk_end                                     -       5      +5
static.log_level                               -       4      +4
printed_len                                    -       4      +4
new_line                                       -       4      +4
escape_args                                    -       4      +4
static.log_level_unknown                       4       -      -4
vprintk                                      537     396    -141
number                                       488       -    -488
vsnprintf                                   1052     124    -928

static.printk_buf 1024 - -1024

There is only one very small caveat (that I can see) to be mentioned:
You can still use multiple printk() calls to append new text to a partial message, but you can NOT output several messages in a single call. I think, however, that no sanely written code would do this anyway, with perhaps the exception of writes to /proc/kmsg, which may contain newlines which will NOT be preceded by log-levels (or timestamps). The solution would be to change this location to output the user-provided data as an argument to %s (like my first kprint patches did anyway), and maybe escape any newlines. I don't think it's an issue.

So please consider this patch instead of the first I submitted. New diffstat looks like this:

 include/linux/xprintf.h |   28 +++++
 kernel/printk.c         |  171 +++++++++++++++++----------
 lib/vsprintf.c          |  296 ++++++++++++++++++++++++++++-------------------
 3 files changed, 314 insertions(+), 181 deletions(-)

Kind regards,
Vegard Nossum

new file mode 100644
index 0000000..76efc43
@@ -0,0 +1,28 @@
+#ifndef LINUX_XPRINTF_H
+#define LINUX_XPRINTF_H
+
+#include <stdarg.h>
+#include <linux/kernel.h>
+
+struct xprintf_ops {
+	void (*begin)(void *data);
+	void (*end)(void *data);
+	void (*put_format)(void *data, char c);
+
+	void (*begin_param)(void *data);
+	void (*end_param)(void *data);
+	void (*put_param)(void *data, char c);
+
+	long (*size)(void *data);
+
+	void (*unknown_conversion)(void *data, char c);
+};
+
+extern void xprintf(void *data, const struct xprintf_ops *ops,
+	const char *fmt, ...)
+	__attribute__ ((format (printf, 3, 4)));
+extern void vxprintf(void *data, const struct xprintf_ops *ops,
+	const char *fmt, va_list args)
+	__attribute__ ((format (printf, 3, 0)));
+
+#endif

Thats nice.

A quick search suggests otherwise (eg intel_rng)

Alan