[PATCH 0/8] Rework KERN_<LEVEL>

[PATCH 0/8] Rework KERN_<LEVEL>

[Joe Perches]

KERN_<LEVEL> currently takes up 3 bytes.
Shrink the kernel size by using an ASCII SOH and then the level byte.
Remove the need for KERN_CONT.
Convert directly embedded uses of <.> to KERN_<LEVEL>

Joe Perches (8):
  printk: Add generic functions to find KERN_<LEVEL> headers
  printk: Add kern_levels.h to make KERN_<LEVEL> available for asm use
  arch: Remove direct definitions of KERN_<LEVEL> uses
  btrfs: Use printk_get_level and printk_skip_level, add __printf, fix fallout
  sound: Use printk_get_level and printk_skip_level
  staging: wlags49_h2: Remove direct declarations of KERN_<LEVEL> prefixes
  printk: Convert the format for KERN_<LEVEL> to a 2 byte pattern
  printk: Remove the now unnecessary "C" annotation for KERN_CONT

 arch/arm/lib/io-acorn.S              |    3 +-
 arch/arm/vfp/vfphw.S                 |    7 +++--
 arch/frv/kernel/kernel_thread.S      |    2 +-
 drivers/staging/wlags49_h2/hcf.c     |    8 +++---
 drivers/staging/wlags49_h2/wl_main.c |    4 +-
 fs/btrfs/ctree.h                     |   13 ++++++++++
 fs/btrfs/disk-io.c                   |    2 +-
 fs/btrfs/relocation.c                |    2 +-
 fs/btrfs/super.c                     |   41 +++++++++++++++++++++++++++++-----
 include/linux/kern_levels.h          |   25 ++++++++++++++++++++
 include/linux/printk.h               |   41 +++++++++++++++++++--------------
 kernel/printk.c                      |   14 +++++++----
 sound/core/misc.c                    |   13 +++++++---
 13 files changed, 130 insertions(+), 45 deletions(-)
 create mode 100644 include/linux/kern_levels.h

-- 
1.7.8.111.gad25c.dirty

[PATCH 3/8] arch: Remove direct definitions of KERN_<LEVEL> uses

[Joe Perches]

Add #include <linux/kern_levels.h> so that the #define KERN_<LEVEL>
macros don't have to be duplicated.

Signed-off-by: Joe Perches <joe@perches.com>
---
 arch/arm/lib/io-acorn.S         |    3 ++-
 arch/arm/vfp/vfphw.S            |    7 ++++---
 arch/frv/kernel/kernel_thread.S |    2 +-
 3 files changed, 7 insertions(+), 5 deletions(-)

diff --git a/arch/arm/lib/io-acorn.S b/arch/arm/lib/io-acorn.S
index 1b197ea..69719ba 100644
--- a/arch/arm/lib/io-acorn.S
+++ b/arch/arm/lib/io-acorn.S
@@ -11,13 +11,14 @@
  *
  */
 #include <linux/linkage.h>
+#include <linux/kern_levels.h>
 #include <asm/assembler.h>
 
 		.text
 		.align
 
 .Liosl_warning:
-		.ascii	"<4>insl/outsl not implemented, called from %08lX\0"
+		.ascii	KERN_WARNING "insl/outsl not implemented, called from %08lX\0"
 		.align
 
 /*
diff --git a/arch/arm/vfp/vfphw.S b/arch/arm/vfp/vfphw.S
index 2d30c7f..d50f0e4 100644
--- a/arch/arm/vfp/vfphw.S
+++ b/arch/arm/vfp/vfphw.S
@@ -16,6 +16,7 @@
  */
 #include <asm/thread_info.h>
 #include <asm/vfpmacros.h>
+#include <linux/kern_levels.h>
 #include "../kernel/entry-header.S"
 
 	.macro	DBGSTR, str
@@ -24,7 +25,7 @@
 	add	r0, pc, #4
 	bl	printk
 	b	1f
-	.asciz  "<7>VFP: \str\n"
+	.asciz  KERN_DEBUG "VFP: \str\n"
 	.balign 4
 1:	ldmfd	sp!, {r0-r3, ip, lr}
 #endif
@@ -37,7 +38,7 @@
 	add	r0, pc, #4
 	bl	printk
 	b	1f
-	.asciz  "<7>VFP: \str\n"
+	.asciz  KERN_DEBUG "VFP: \str\n"
 	.balign 4
 1:	ldmfd	sp!, {r0-r3, ip, lr}
 #endif
@@ -52,7 +53,7 @@
 	add	r0, pc, #4
 	bl	printk
 	b	1f
-	.asciz  "<7>VFP: \str\n"
+	.asciz  KERN_DEBUG "VFP: \str\n"
 	.balign 4
 1:	ldmfd	sp!, {r0-r3, ip, lr}
 #endif
diff --git a/arch/frv/kernel/kernel_thread.S b/arch/frv/kernel/kernel_thread.S
index 4531c83..f0e5294 100644
--- a/arch/frv/kernel/kernel_thread.S
+++ b/arch/frv/kernel/kernel_thread.S
@@ -10,10 +10,10 @@
  */
 
 #include <linux/linkage.h>
+#include <linux/kern_levels.h>
 #include <asm/unistd.h>
 
 #define CLONE_VM	0x00000100	/* set if VM shared between processes */
-#define	KERN_ERR	"<3>"
 
 	.section .rodata
 kernel_thread_emsg:
-- 
1.7.8.111.gad25c.dirty

[PATCH 0/8] Rework KERN_<LEVEL>

[Andrew Morton]

On Tue,  5 Jun 2012 02:46:29 -0700
Joe Perches <joe@perches.com> wrote:

> KERN_<LEVEL> currently takes up 3 bytes.
> Shrink the kernel size by using an ASCII SOH and then the level byte.
> Remove the need for KERN_CONT.
> Convert directly embedded uses of <.> to KERN_<LEVEL>

What an epic patchset.  I guess that saving a byte per printk does make
the world a better place, and forcibly ensuring that nothing is
dependent upon the internal format of the KERN_foo strings is nice.


Unfortunately the <n> thing is part of the kernel ABI:

	echo "<4>foo" > /dev/kmsg

devkmsg_writev() does weird and wonderful things with
facilities/levels.  That function incorrectly returns "success" when
copy_from_user() faults, btw.  It also babbles on about LOG_USER and
LOG_KERN without ever defining these things.  I guess they're
userspace-only concepts and are hardwired to 0 and 1 in the kernel.  Or
not.

So what to do about /dev/kmsg?  I'd say "nothing": we retain "<n>" as
the externally-presented kernel format for a facility level, and the
fact that the kernel internally uses a different encoding is hidden
from userspace.

And if the user does

	echo "\0014foo" > /dev/kmsg

then I guess we should pass it straight through, retaining the \0014. 
But from my reading of your code, this doesn't work - vprintk_emit()
will go ahead and strip and interpret the \0014, evading the stuff
which devkmsg_writev() did.

[PATCH 0/8] Rework KERN_<LEVEL>

[Kay Sievers]

On Tue, Jun 5, 2012 at 11:28 PM, Andrew Morton
<akpm@linux-foundation.org> wrote:
> On Tue, ?5 Jun 2012 02:46:29 -0700
> Joe Perches <joe@perches.com> wrote:
>
>> KERN_<LEVEL> currently takes up 3 bytes.
>> Shrink the kernel size by using an ASCII SOH and then the level byte.
>> Remove the need for KERN_CONT.
>> Convert directly embedded uses of <.> to KERN_<LEVEL>
>
> What an epic patchset. ?I guess that saving a byte per printk does make
> the world a better place, and forcibly ensuring that nothing is
> dependent upon the internal format of the KERN_foo strings is nice.
>
>
> Unfortunately the <n> thing is part of the kernel ABI:
>
> ? ? ? ?echo "<4>foo" > /dev/kmsg
>
> devkmsg_writev() does weird and wonderful things with
> facilities/levels. ?That function incorrectly returns "success" when
> copy_from_user() faults, btw. ?It also babbles on about LOG_USER and
> LOG_KERN without ever defining these things. ?I guess they're
> userspace-only concepts and are hardwired to 0 and 1 in the kernel. ?Or
> not.

It's as old as BSD, defined by syslog(3), used by glibc. The whole
<%u> prefix notation and the LOG_* names come from there.

The kernel is just user/facility == 0, so it never really was apparent
that the whole concept has more than a log level in that number.

Userspace syslog defines these pretty stupid numbers:
  /* facility codes */
  #define LOG_KERN        (0<<3)  /* kernel messages */
  #define LOG_USER        (1<<3)  /* random user-level messages */
  #define LOG_MAIL        (2<<3)  /* mail system */
  #define LOG_DAEMON      (3<<3)  /* system daemons */
  #define LOG_AUTH        (4<<3)  /* security/authorization messages */
  #define LOG_SYSLOG      (5<<3)  /* messages generated internally by syslogd */
  #define LOG_LPR         (6<<3)  /* line printer subsystem */
  #define LOG_NEWS        (7<<3)  /* network news subsystem */
  #define LOG_UUCP        (8<<3)  /* UUCP subsystem */
  #define LOG_CRON        (9<<3)  /* clock daemon */
  #define LOG_AUTHPRIV    (10<<3) /* security/authorization messages
(private) */
  #define LOG_FTP         (11<<3) /* ftp daemon */

but it *can* still all be pretty useful, and people *can* get creative
with facility numbers if they want to, as we have like 13 bits@the
moment to use for the facility which is stored in the kernel log
buffer. :)

/dev/kmsg just enforces LOG_USER, if userspace tries to inject stuff
with LOG_KERN, which it should not be allowed. The non-LOG_KERN number
itself has not much meaning it just says: "this is not from the
kernel" which is important to keep in the message.

Als, dmesg(1) has a -k option, that filters out all userspace-injected stuff.

> So what to do about /dev/kmsg? ?I'd say "nothing": we retain "<n>" as
> the externally-presented kernel format for a facility level, and the
> fact that the kernel internally uses a different encoding is hidden
> from userspace.

Yeah, I think so.

Yeah, we strip the <>  at printk() time, add the <> back at output
time; they are not stored internally anymore, so that should not
affect the current behaviour.

> And if the user does
>
> ? ? ? ?echo "\0014foo" > /dev/kmsg
>
> then I guess we should pass it straight through, retaining the \0014.
> But from my reading of your code, this doesn't work - vprintk_emit()
> will go ahead and strip and interpret the \0014, evading the stuff
> which devkmsg_writev() did.

We should make it not accept faked prefixes, yes. It should be
impossible to let messages look like they originated from the kernel,
just like the current code enforces a non-LOG_KERN <> prefix.

Kay

[PATCH 0/8] Rework KERN_<LEVEL>

[Joe Perches]

On Tue, 2012-06-05 at 14:28 -0700, Andrew Morton wrote:
> Unfortunately the <n> thing is part of the kernel ABI:
> 
> 	echo "<4>foo" > /dev/kmsg

Which works the same way it did before.

[PATCH 0/8] Rework KERN_<LEVEL>

[Andrew Morton]

On Tue, 05 Jun 2012 15:11:43 -0700
Joe Perches <joe@perches.com> wrote:

> On Tue, 2012-06-05 at 14:28 -0700, Andrew Morton wrote:
> > Unfortunately the <n> thing is part of the kernel ABI:
> > 
> > 	echo "<4>foo" > /dev/kmsg
> 
> Which works the same way it did before.

I didn't say it didn't.

What I did say is that echo "\0014">/dev/kmsg will subvert the intent
of the new logging code.  Or might.  But you just ignored all that,
forcing me to repeat myself, irritatedly.

[PATCH 0/8] Rework KERN_<LEVEL>

[Joe Perches]

On Tue, 2012-06-05 at 15:17 -0700, Andrew Morton wrote:
> On Tue, 05 Jun 2012 15:11:43 -0700
> Joe Perches <joe@perches.com> wrote:
> 
> > On Tue, 2012-06-05 at 14:28 -0700, Andrew Morton wrote:
> > > Unfortunately the <n> thing is part of the kernel ABI:
> > > 
> > > 	echo "<4>foo" > /dev/kmsg
> > 
> > Which works the same way it did before.
> 
> I didn't say it didn't.
> 
> What I did say is that echo "\0014">/dev/kmsg will subvert the intent
> of the new logging code.  Or might.  But you just ignored all that,
> forcing me to repeat myself, irritatedly.

It works the same way before and after the patch.

Any write to /dev/kmsg without a KERN_<LEVEL>
emits at (1 << 3) + KERN_DEFAULT.

Writes with <n> values >= 8 are emitted at
that level.

[PATCH 0/8] Rework KERN_<LEVEL>

[Andrew Morton]

On Tue, 05 Jun 2012 15:49:32 -0700
Joe Perches <joe@perches.com> wrote:

> On Tue, 2012-06-05 at 15:17 -0700, Andrew Morton wrote:
> > On Tue, 05 Jun 2012 15:11:43 -0700
> > Joe Perches <joe@perches.com> wrote:
> > 
> > > On Tue, 2012-06-05 at 14:28 -0700, Andrew Morton wrote:
> > > > Unfortunately the <n> thing is part of the kernel ABI:
> > > > 
> > > > 	echo "<4>foo" > /dev/kmsg
> > > 
> > > Which works the same way it did before.
> > 
> > I didn't say it didn't.
> > 
> > What I did say is that echo "\0014">/dev/kmsg will subvert the intent
> > of the new logging code.  Or might.  But you just ignored all that,
> > forcing me to repeat myself, irritatedly.
> 
> It works the same way before and after the patch.
> 
> Any write to /dev/kmsg without a KERN_<LEVEL>
> emits at (1 << 3) + KERN_DEFAULT.
> 
> Writes with <n> values >= 8 are emitted at
> that level.

What about writes starting with \001n?  AFACIT, that will be stripped
away and the printk level will be altered.  This is new behavior.

[PATCH 0/8] Rework KERN_<LEVEL>

[Joe Perches]

On Tue, 2012-06-05 at 16:29 -0700, Andrew Morton wrote:
> What about writes starting with \001n?  AFACIT, that will be stripped
> away and the printk level will be altered.  This is new behavior.

Nope.

# echo "\001Hello Andrew" > /dev/kmsg
/dev/kmsg has
12,774,2462339252;\001Hello Andrew

12 is 8 + KERN_DEFAULT

# echo "<1>Hello Andrew" > /dev/kmsg
/dev/kmsg has:
9,775,2516023444;Hello Andrew

[PATCH 0/8] Rework KERN_<LEVEL>

[Kay Sievers]

On Wed, Jun 6, 2012 at 1:35 AM, Joe Perches <joe@perches.com> wrote:
> On Tue, 2012-06-05 at 16:29 -0700, Andrew Morton wrote:
>> What about writes starting with \001n? ?AFACIT, that will be stripped
>> away and the printk level will be altered. ?This is new behavior.
>
> Nope.
>
> # echo "\001Hello Andrew" > /dev/kmsg
> /dev/kmsg has
> 12,774,2462339252;\001Hello Andrew

Try "echo -e"? The stuff is copied verbatim otherwise.

Kay

[PATCH 0/8] Rework KERN_<LEVEL>

[Joe Perches]

On Wed, 2012-06-06 at 01:39 +0200, Kay Sievers wrote:
> On Wed, Jun 6, 2012 at 1:35 AM, Joe Perches <joe@perches.com> wrote:
> > On Tue, 2012-06-05 at 16:29 -0700, Andrew Morton wrote:
> >> What about writes starting with \001n?  AFACIT, that will be stripped
> >> away and the printk level will be altered.  This is new behavior.
> >
> > Nope.
> >
> > # echo "\001Hello Andrew" > /dev/kmsg
> > /dev/kmsg has
> > 12,774,2462339252;\001Hello Andrew
> 
> Try "echo -e"? The stuff is copied verbatim otherwise.

# echo -e "\001Hello Kay" > /dev/kmsg
gives
12,776,3046752764;\x01Hello Kay

[PATCH 0/8] Rework KERN_<LEVEL>

[Kay Sievers]

On Wed, Jun 6, 2012 at 1:43 AM, Joe Perches <joe@perches.com> wrote:
> On Wed, 2012-06-06 at 01:39 +0200, Kay Sievers wrote:

>> > # echo "\001Hello Andrew" > /dev/kmsg
>> > /dev/kmsg has
>> > 12,774,2462339252;\001Hello Andrew
>>
>> Try "echo -e"? The stuff is copied verbatim otherwise.
>
> # echo -e "\001Hello Kay" > /dev/kmsg
> gives
> 12,776,3046752764;\x01Hello Kay

Don't you need two bytes to trigger the logic?

Kay

[PATCH 0/8] Rework KERN_<LEVEL>

[Joe Perches]

On Wed, 2012-06-06 at 01:48 +0200, Kay Sievers wrote:
> On Wed, Jun 6, 2012 at 1:43 AM, Joe Perches <joe@perches.com> wrote:
> > On Wed, 2012-06-06 at 01:39 +0200, Kay Sievers wrote:
> 
> >> > # echo "\001Hello Andrew" > /dev/kmsg
> >> > /dev/kmsg has
> >> > 12,774,2462339252;\001Hello Andrew
> >>
> >> Try "echo -e"? The stuff is copied verbatim otherwise.
> >
> > # echo -e "\001Hello Kay" > /dev/kmsg
> > gives
> > 12,776,3046752764;\x01Hello Kay
> 
> Don't you need two bytes to trigger the logic?

Yes.  Angle brackets fore and aft.

If you use a "<n>" prefix for write to /dev/kmsg,
then it's supported just like before.

Otherwise, it's emitted at KERN_DEFAULT.

cheers, Joe

[PATCH 0/8] Rework KERN_<LEVEL>

[Andrew Morton]

On Tue, 05 Jun 2012 16:52:25 -0700
Joe Perches <joe@perches.com> wrote:

> On Wed, 2012-06-06 at 01:48 +0200, Kay Sievers wrote:
> > On Wed, Jun 6, 2012 at 1:43 AM, Joe Perches <joe@perches.com> wrote:
> > > On Wed, 2012-06-06 at 01:39 +0200, Kay Sievers wrote:
> > 
> > >> > # echo "\001Hello Andrew" > /dev/kmsg
> > >> > /dev/kmsg has
> > >> > 12,774,2462339252;\001Hello Andrew
> > >>
> > >> Try "echo -e"? The stuff is copied verbatim otherwise.
> > >
> > > # echo -e "\001Hello Kay" > /dev/kmsg
> > > gives
> > > 12,776,3046752764;\x01Hello Kay
> > 
> > Don't you need two bytes to trigger the logic?
> 
> Yes.  Angle brackets fore and aft.

he means

	echo "\0014Hello Joe" > /dev/kmsg
	          ^

It needs one of [0-7cd] to trigger the prefix handling.

[PATCH 0/8] Rework KERN_<LEVEL>

[Joe Perches]

On Tue, 2012-06-05 at 16:58 -0700, Andrew Morton wrote:
>  echo "\0014Hello Joe" > /dev/kmsg

# echo -e "\x014Hello Me" > /dev/kmsg
gives:
12,778,4057982669;Hello Me

#echo -e "\x011Hello Me_2" > /dev/kmsg
gives:
12,779,4140452093;Hello Me_2

I didn't change devkmsg_writev so the
original parsing style for "<.>" is
unchanged.

from printk.c:

static ssize_t devkmsg_writev(struct kiocb *iocb, const struct iovec *iv,
			      unsigned long count, loff_t pos)
[...]
	int level = default_message_loglevel;
[...]
	if (line[0] == '<') {
		char *endp = NULL;

		i = simple_strtoul(line+1, &endp, 10);
		if (endp && endp[0] == '>') {
			level = i & 7;
			if (i >> 3)
				facility = i >> 3;
			endp++;
			len -= endp - line;
			line = endp;
		}
	}
	line[len] = '\0';

	printk_emit(facility, level, NULL, 0, "%s", line);
[]

level is what matters.

from dmesg -r

<12>[ 2462.339252] \001Hello Andrew
<9>[ 2516.023444] Hello Andrew
<12>[ 3046.752764] \x01Hello Kay
<12>[ 3940.871850] \x01Hello Kay
<12>[ 4057.982669] Hello Me
<12>[ 4140.452093] Hello Me_2

[PATCH 0/8] Rework KERN_<LEVEL>

[Kay Sievers]

On Wed, Jun 6, 2012 at 2:07 AM, Joe Perches <joe@perches.com> wrote:
> On Tue, 2012-06-05 at 16:58 -0700, Andrew Morton wrote:
>> ?echo "\0014Hello Joe" > /dev/kmsg
>
> # echo -e "\x014Hello Me" > /dev/kmsg
> gives:
> 12,778,4057982669;Hello Me
>
> #echo -e "\x011Hello Me_2" > /dev/kmsg
> gives:
> 12,779,4140452093;Hello Me_2
>
> I didn't change devkmsg_writev so the
> original parsing style for "<.>" is
> unchanged.
>
> from printk.c:
>
> static ssize_t devkmsg_writev(struct kiocb *iocb, const struct iovec *iv,
> ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?unsigned long count, loff_t pos)
> [...]
> ? ? ? ?int level = default_message_loglevel;
> [...]
> ? ? ? ?if (line[0] == '<') {
> ? ? ? ? ? ? ? ?char *endp = NULL;
>
> ? ? ? ? ? ? ? ?i = simple_strtoul(line+1, &endp, 10);
> ? ? ? ? ? ? ? ?if (endp && endp[0] == '>') {
> ? ? ? ? ? ? ? ? ? ? ? ?level = i & 7;
> ? ? ? ? ? ? ? ? ? ? ? ?if (i >> 3)
> ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?facility = i >> 3;
> ? ? ? ? ? ? ? ? ? ? ? ?endp++;
> ? ? ? ? ? ? ? ? ? ? ? ?len -= endp - line;
> ? ? ? ? ? ? ? ? ? ? ? ?line = endp;
> ? ? ? ? ? ? ? ?}
> ? ? ? ?}
> ? ? ? ?line[len] = '\0';
>
> ? ? ? ?printk_emit(facility, level, NULL, 0, "%s", line);
> []
>
> level is what matters.
>
> from dmesg -r
>
> <12>[ 2462.339252] \001Hello Andrew
> <9>[ 2516.023444] Hello Andrew
> <12>[ 3046.752764] \x01Hello Kay
> <12>[ 3940.871850] \x01Hello Kay
> <12>[ 4057.982669] Hello Me
> <12>[ 4140.452093] Hello Me_2

The question is what happens if you inject your new binary two-byte
prefix, like:
  echo -e "\x01\x02Hello" > /dev/kmsg

And if that changes the log-level to "2" instead of the default "4"?

(assuming that I read your patch right, otherwise please correct the
bytes, but use the full sequence which your patch will recognize as an
internal level marker; seems your examples are all not triggering that)

Kay

[PATCH 0/8] Rework KERN_<LEVEL>

[Joe Perches]

On Wed, 2012-06-06 at 02:13 +0200, Kay Sievers wrote:
> The question is what happens if you inject your new binary two-byte
> prefix, like:
>   echo -e "\x01\x02Hello" > /dev/kmsg

It's not a 2 byte binary.
It's a leading ascii SOH and a standard ascii char
'0' ... '7' or 'd'.

#define KERN_EMERG	KERN_SOH "0"	/* system is unusable */
#define KERN_ALERT	KERN_SOH "1"	/* action must be taken immediately */
etc...

> And if that changes the log-level to "2" instead of the default "4"?

No it doesn't.

It's not triggering that because devkmsg_writev does
prefix parsing only on the old "<n>" form.

[PATCH 0/8] Rework KERN_<LEVEL>

[Kay Sievers]

On Wed, Jun 6, 2012 at 2:19 AM, Joe Perches <joe@perches.com> wrote:
> On Wed, 2012-06-06 at 02:13 +0200, Kay Sievers wrote:
>> The question is what happens if you inject your new binary two-byte
>> prefix, like:
>> ? echo -e "\x01\x02Hello" > /dev/kmsg
>
> It's not a 2 byte binary.
> It's a leading ascii SOH and a standard ascii char
> '0' ... '7' or 'd'.
>
> #define KERN_EMERG ? ? ?KERN_SOH "0" ? ?/* system is unusable */
> #define KERN_ALERT ? ? ?KERN_SOH "1" ? ?/* action must be taken immediately */
> etc...

Ok.

>> And if that changes the log-level to "2" instead of the default "4"?
>
> No it doesn't.

So:
   echo -e "\x012Hello" > /dev/kmsg
is still level 4? Sounds all fine then.

> It's not triggering that because devkmsg_writev does
> prefix parsing only on the old "<n>" form.

Yeah, but printk_emit() will not try to parse it? I did not check, but
with your change, the prefix parsing in printk_emit() is still skipped
if a level is given as a parameter to printk_emit(), right?

Kay

[PATCH 0/8] Rework KERN_<LEVEL>

[Joe Perches]

On Wed, 2012-06-06 at 02:28 +0200, Kay Sievers wrote:
> On Wed, Jun 6, 2012 at 2:19 AM, Joe Perches <joe@perches.com> wrote:
> > On Wed, 2012-06-06 at 02:13 +0200, Kay Sievers wrote:
> >> The question is what happens if you inject your new binary two-byte
> >> prefix, like:
> >>   echo -e "\x01\x02Hello" > /dev/kmsg
> >
> > It's not a 2 byte binary.
> > It's a leading ascii SOH and a standard ascii char
> > '0' ... '7' or 'd'.
> >
> > #define KERN_EMERG      KERN_SOH "0"    /* system is unusable */
> > #define KERN_ALERT      KERN_SOH "1"    /* action must be taken immediately */
> > etc...
> 
> Ok.
> 
> >> And if that changes the log-level to "2" instead of the default "4"?
> >
> > No it doesn't.
> 
> So:
>    echo -e "\x012Hello" > /dev/kmsg
> is still level 4? Sounds all fine then.

Yes.
# echo -e "\x012Hello again Kay" > /dev/kmsg
gives:
12,780,6031964979;Hello again Kay

> > It's not triggering that because devkmsg_writev does
> > prefix parsing only on the old "<n>" form.
> 
> Yeah, but printk_emit() will not try to parse it? I did not check, but
> with your change, the prefix parsing in printk_emit() is still skipped
> if a level is given as a parameter to printk_emit(), right?

If level is not -1, then whatever prefix level the
string has is ignored by vprintk_emit.

from vprintk_emit:

	/* strip syslog prefix and extract log level or control flags */
	kern_level = printk_get_level(text);
	if (kern_level) {
		const char *end_of_header = printk_skip_level(text);
		switch (kern_level) {
		case '0' ... '7':
			if (level == -1)
				level = kern_level - '0';
		case 'd': /* Strip d KERN_DEFAULT, start new line */
			plen = 0;
		default:
			if (!new_text_line) {
				log_buf_emit_char('\n');
				new_text_line = 1;
			}
		}
		text_len -=  end_of_header - text;
		text = (char *)end_of_header;
	}

Only level == -1 will use the prefix level.

devkmsg_writev always passes a non -1 level.

cheers, Joe

[PATCH 0/8] Rework KERN_<LEVEL>

[Andrew Morton]

On Tue, 05 Jun 2012 17:07:27 -0700 Joe Perches <joe@perches.com> wrote:

> On Tue, 2012-06-05 at 16:58 -0700, Andrew Morton wrote:
> >  echo "\0014Hello Joe" > /dev/kmsg
> 
> # echo -e "\x014Hello Me" > /dev/kmsg
> gives:
> 12,778,4057982669;Hello Me

That's changed behavior.

On Wed, 6 Jun 2012 02:28:39 +0200 Kay Sievers <kay@vrfy.org> wrote:

> Yeah, but printk_emit() will not try to parse it? I did not check, but
> with your change, the prefix parsing in printk_emit() is still skipped
> if a level is given as a parameter to printk_emit(), right?

printk_emit() does parse the leading \0014, and then skips over it,
removing it from the output stream.  printk_emit() then throws away the
resulting level because devkmsg_writev() did not pass in level==-1.

[PATCH 0/8] Rework KERN_<LEVEL>

[Joe Perches]

On Tue, 2012-06-05 at 17:37 -0700, Andrew Morton wrote:
> On Tue, 05 Jun 2012 17:07:27 -0700 Joe Perches <joe@perches.com> wrote:
> 
> > On Tue, 2012-06-05 at 16:58 -0700, Andrew Morton wrote:
> > >  echo "\0014Hello Joe" > /dev/kmsg
> > 
> > # echo -e "\x014Hello Me" > /dev/kmsg
> > gives:
> > 12,778,4057982669;Hello Me
> 
> That's changed behavior.

Which is an improvement too.
I very much doubt a single app will change
because of this.

> printk_emit() does parse the leading \0014, and then skips over it,
> removing it from the output stream.  printk_emit() then throws away the
> resulting level because devkmsg_writev() did not pass in level==-1.

I'm glad you know how it works now.

cheers, Joe

[PATCH 0/8] Rework KERN_<LEVEL>

[Andrew Morton]

On Tue, 05 Jun 2012 17:40:05 -0700 Joe Perches <joe@perches.com> wrote:

> On Tue, 2012-06-05 at 17:37 -0700, Andrew Morton wrote:
> > On Tue, 05 Jun 2012 17:07:27 -0700 Joe Perches <joe@perches.com> wrote:
> > 
> > > On Tue, 2012-06-05 at 16:58 -0700, Andrew Morton wrote:
> > > >  echo "\0014Hello Joe" > /dev/kmsg
> > > 
> > > # echo -e "\x014Hello Me" > /dev/kmsg
> > > gives:
> > > 12,778,4057982669;Hello Me
> > 
> > That's changed behavior.
> 
> Which is an improvement too.

No it isn't.  It exposes internal kernel implementation details in
random weird inexplicable ways.  It doesn't seem at all important
though.

> I very much doubt a single app will change
> because of this.

I doubt it as well.

> > printk_emit() does parse the leading \0014, and then skips over it,
> > removing it from the output stream.  printk_emit() then throws away the
> > resulting level because devkmsg_writev() did not pass in level==-1.
> 
> I'm glad you know how it works now.

It's nice to see you learning about it as well.

[PATCH 0/8] Rework KERN_<LEVEL>

[Kay Sievers]

On Wed, Jun 6, 2012 at 2:46 AM, Andrew Morton <akpm@linux-foundation.org> wrote:
> On Tue, 05 Jun 2012 17:40:05 -0700 Joe Perches <joe@perches.com> wrote:
>
>> On Tue, 2012-06-05 at 17:37 -0700, Andrew Morton wrote:
>> > On Tue, 05 Jun 2012 17:07:27 -0700 Joe Perches <joe@perches.com> wrote:
>> >
>> > > On Tue, 2012-06-05 at 16:58 -0700, Andrew Morton wrote:
>> > > > ?echo "\0014Hello Joe" > /dev/kmsg
>> > >
>> > > # echo -e "\x014Hello Me" > /dev/kmsg
>> > > gives:
>> > > 12,778,4057982669;Hello Me
>> >
>> > That's changed behavior.
>>
>> Which is an improvement too.
>
> No it isn't. ?It exposes internal kernel implementation details in
> random weird inexplicable ways. ?It doesn't seem at all important
> though.
>
>> I very much doubt a single app will change
>> because of this.
>
> I doubt it as well.

Yeah, the value of injecting such binary data is kind of questionable. :)

Joe, maybe you can change printk_emit() to skip the prefix
detection/stripping if a prefix is already passed to the function?

Kay

[PATCH 0/8] Rework KERN_<LEVEL>

[Joe Perches]

On Wed, 2012-06-06 at 03:10 +0200, Kay Sievers wrote:
> On Wed, Jun 6, 2012 at 2:46 AM, Andrew Morton <akpm@linux-foundation.org> wrote:
> > On Tue, 05 Jun 2012 17:40:05 -0700 Joe Perches <joe@perches.com> wrote:
> >
> >> On Tue, 2012-06-05 at 17:37 -0700, Andrew Morton wrote:
> >> > On Tue, 05 Jun 2012 17:07:27 -0700 Joe Perches <joe@perches.com> wrote:
> >> >
> >> > > On Tue, 2012-06-05 at 16:58 -0700, Andrew Morton wrote:
> >> > > >  echo "\0014Hello Joe" > /dev/kmsg
> >> > >
> >> > > # echo -e "\x014Hello Me" > /dev/kmsg
> >> > > gives:
> >> > > 12,778,4057982669;Hello Me
> >> >
> >> > That's changed behavior.
> >>
> >> Which is an improvement too.
> >
> > No it isn't.  It exposes internal kernel implementation details in
> > random weird inexplicable ways.  It doesn't seem at all important
> > though.
> >
> >> I very much doubt a single app will change
> >> because of this.
> >
> > I doubt it as well.
> 
> Yeah, the value of injecting such binary data is kind of questionable. :)
> 
> Joe, maybe you can change printk_emit() to skip the prefix
> detection/stripping if a prefix is already passed to the function?

Sure, it's pretty trivial.

Perhaps all binary data data should be elided.
Maybe print . for all non-printable ascii chars.

[PATCH 9/8] printk: Only look for prefix levels in kernel messages

[Joe Perches]

vprintk_emit prefix parsing should only be done for internal
kernel messages.  This allows existing behavior to be kept
in all cases.

Signed-off-by: Joe Perches <joe@perches.com>
---
 kernel/printk.c |   32 +++++++++++++++++---------------
 1 files changed, 17 insertions(+), 15 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 5cd73f7..4e72c07 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1267,7 +1267,6 @@ asmlinkage int vprintk_emit(int facility, int level,
 	static char cont_buf[LOG_LINE_MAX];
 	static size_t cont_len;
 	static int cont_level;
-	int kern_level;
 	static struct task_struct *cont_task;
 	static char textbuf[LOG_LINE_MAX];
 	char *text = textbuf;
@@ -1329,21 +1328,24 @@ asmlinkage int vprintk_emit(int facility, int level,
 		newline = true;
 	}
 
-	/* strip syslog prefix and extract log level or control flags */
-	kern_level = printk_get_level(text);
-	if (kern_level) {
-		const char *end_of_header = printk_skip_level(text);
-		switch (kern_level) {
-		case '0' ... '7':
-			if (level == -1)
-				level = kern_level - '0';
-		case 'd':	/* KERN_DEFAULT */
-			prefix = true;
-		case 'c':	/* KERN_CONT */
-			break;
+	/* strip kernel syslog prefix and extract log level or control flags */
+	if (facility == 0) {
+		int kern_level = printk_get_level(text);
+
+		if (kern_level) {
+			const char *end_of_header = printk_skip_level(text);
+			switch (kern_level) {
+			case '0' ... '7':
+				if (level == -1)
+					level = kern_level - '0';
+			case 'd':	/* KERN_DEFAULT */
+				prefix = true;
+			case 'c':	/* KERN_CONT */
+				break;
+			}
+			text_len -= end_of_header - text;
+			text = (char *)end_of_header;
 		}
-		text_len -=  end_of_header - text;
-		text = (char *)end_of_header;
 	}
 
 	if (level == -1)

[PATCH 0/8] Rework KERN_<LEVEL>

[Joe Perches]

On Wed, 2012-06-06 at 01:39 +0200, Kay Sievers wrote:
> Try "echo -e"? The stuff is copied verbatim otherwise.

btw: I didn't change the devkmsg_writev function
which does the decoding of any "<n>" prefix for
printk_emit.

[PATCH 0/8] Rework KERN_<LEVEL>

[Kay Sievers]

On Tue, 2012-06-05 at 14:28 -0700, Andrew Morton wrote:

> devkmsg_writev() does weird and wonderful things with
> facilities/levels.  That function incorrectly returns "success" when
> copy_from_user() faults, btw.

Oh. Better?

Thanks,
Kay


From: Kay Sievers <kay@vrfy.org>
Subject: kmsg: /dev/kmsg - properly return possible copy_from_user() failure

Reported-By: Andrew Morton <akpm@linux-foundation.org>
Signed-off-by: Kay Sievers <kay@vrfy.org
---
 printk.c |    4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 32462d2..6bdacab 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -365,8 +365,10 @@ static ssize_t devkmsg_writev(struct kiocb *iocb, const struct iovec *iv,
 
 	line = buf;
 	for (i = 0; i < count; i++) {
-		if (copy_from_user(line, iv[i].iov_base, iv[i].iov_len))
+		if (copy_from_user(line, iv[i].iov_base, iv[i].iov_len)) {
+			ret = -EFAULT;
 			goto out;
+		}
 		line += iv[i].iov_len;
 	}
 

[PATCH 0/8] Rework KERN_<LEVEL>

[Andrew Morton]

On Wed, 06 Jun 2012 00:55:00 +0200
Kay Sievers <kay@vrfy.org> wrote:

> On Tue, 2012-06-05 at 14:28 -0700, Andrew Morton wrote:
> 
> > devkmsg_writev() does weird and wonderful things with
> > facilities/levels.  That function incorrectly returns "success" when
> > copy_from_user() faults, btw.
> 
> Oh. Better?
> 
> Thanks,
> Kay
> 
> 
> From: Kay Sievers <kay@vrfy.org>
> Subject: kmsg: /dev/kmsg - properly return possible copy_from_user() failure
> 
> Reported-By: Andrew Morton <akpm@linux-foundation.org>
> Signed-off-by: Kay Sievers <kay@vrfy.org
> ---
>  printk.c |    4 +++-
>  1 file changed, 3 insertions(+), 1 deletion(-)
> 
> diff --git a/kernel/printk.c b/kernel/printk.c
> index 32462d2..6bdacab 100644
> --- a/kernel/printk.c
> +++ b/kernel/printk.c
> @@ -365,8 +365,10 @@ static ssize_t devkmsg_writev(struct kiocb *iocb, const struct iovec *iv,
>  
>  	line = buf;
>  	for (i = 0; i < count; i++) {
> -		if (copy_from_user(line, iv[i].iov_base, iv[i].iov_len))
> +		if (copy_from_user(line, iv[i].iov_base, iv[i].iov_len)) {
> +			ret = -EFAULT;
>  			goto out;
> +		}
>  		line += iv[i].iov_len;
>  	}

Strictly speaking, when write() encounters an error it should return
number-of-bytes-written, or an errno if it wrote zero bytes.  So
something like

--- a/kernel/printk.c~a
+++ a/kernel/printk.c
@@ -355,7 +355,7 @@ static ssize_t devkmsg_writev(struct kio
 	int level = default_message_loglevel;
 	int facility = 1;	/* LOG_USER */
 	size_t len = iov_length(iv, count);
-	ssize_t ret = len;
+	ssize_t ret;
 
 	if (len > LOG_LINE_MAX)
 		return -EINVAL;
@@ -365,8 +365,12 @@ static ssize_t devkmsg_writev(struct kio
 
 	line = buf;
 	for (i = 0; i < count; i++) {
-		if (copy_from_user(line, iv[i].iov_base, iv[i].iov_len))
+		if (copy_from_user(line, iv[i].iov_base, iv[i].iov_len)) {
+			ret = line - buf;
+			if (!ret)
+				ret = -EFAULT;
 			goto out;
+		}
 		line += iv[i].iov_len;
 	}
 
@@ -396,6 +400,7 @@ static ssize_t devkmsg_writev(struct kio
 	line[len] = '\0';
 
 	printk_emit(facility, level, NULL, 0, "%s", line);
+	ret = 0;
 out:
 	kfree(buf);
 	return ret;
_