[PATCH] Wrong printk return value

[PATCH] Wrong printk return value

[Guillaume Chazarain]

[-- Attachment #1: Type: text/plain, Size: 881 bytes --]

What's the true meaning of the printk return value?
Should it include the prioty prefix length of 3? and what about the timing
information? In both cases it was broken:

strace -e write echo 1 > /dev/kmsg
=> write(1, "1\n", 2)                      = 5

strace -e write echo "<1>1" > /dev/kmsg
=> write(1, "<1>1\n", 5)                   = 8

The returned length was "length of input string + 3", I made it "length
of printed string including any prefix".

Successful printk calls can have a return value different than the input
length (priority prefix, timing), so /bin/echo will still think there is 
an error.
So, to avoid breaking programs that assume write(buff, len) != len is an
error, /dev/kmsg should return the buffer length when the call succeeds.

The only drawback is that now it's no more possible to use /dev/kmsg to
check the printk return value :-(

-- 
Guillaume


[-- Attachment #2: diff --]
[-- Type: text/plain, Size: 1267 bytes --]

--- linux-2.6.13-rc5/kernel/printk.c
+++ linux-2.6.13-rc5/kernel/printk.c
@@ -553,7 +553,7 @@
 				   p[1] <= '7' && p[2] == '>') {
 					loglev_char = p[1];
 					p += 3;
-					printed_len += 3;
+					printed_len -= 3;
 				} else {
 					loglev_char = default_message_loglevel
 						+ '0';
@@ -568,7 +568,7 @@
 
 				for (tp = tbuf; tp < tbuf + tlen; tp++)
 					emit_log_char(*tp);
-				printed_len += tlen - 3;
+				printed_len += tlen;
 			} else {
 				if (p[0] != '<' || p[1] < '0' ||
 				   p[1] > '7' || p[2] != '>') {
@@ -576,8 +576,8 @@
 					emit_log_char(default_message_loglevel
 						+ '0');
 					emit_log_char('>');
+					printed_len += 3;
 				}
-				printed_len += 3;
 			}
 			log_level_unknown = 0;
 			if (!*p)
--- linux-2.6.13-rc5/drivers/char/mem.c
+++ linux-2.6.13-rc5/drivers/char/mem.c
@@ -819,7 +819,7 @@ static ssize_t kmsg_write(struct file * 
 			  size_t count, loff_t *ppos)
 {
 	char *tmp;
-	int ret;
+	ssize_t ret;
 
 	tmp = kmalloc(count + 1, GFP_KERNEL);
 	if (tmp == NULL)
@@ -828,6 +828,9 @@ static ssize_t kmsg_write(struct file * 
 	if (!copy_from_user(tmp, buf, count)) {
 		tmp[count] = 0;
 		ret = printk("%s", tmp);
+		if (ret > count)
+			/* printk can add a prefix */
+			ret = count;
 	}
 	kfree(tmp);
 	return ret;

Re: [PATCH] Wrong printk return value

[Tim Bird]

Guillaume Chazarain wrote:
> What's the true meaning of the printk return value?

Hi,

I was one of the ones to touch this code last.  I
assumed it was meant to represent the number of characters
emitted by printk into the log.  This includes any priority
prefix, time prefix and format character expansion.



> Should it include the prioty prefix length of 3? and what about the timing
> information? In both cases it was broken:
>
> The returned length was "length of input string + 3", I made it "length
> of printed string including any prefix".
>

IMHO, it should behave as much like printf as possible,
which means the return value should represent output length
rather than input length.  It was already accounting for format
expansion, so it wasn't really returning just "length of input
string + 3" (only in the most simple case). I don't think it matters
that there are other systems down the line that mask part
of the value (such as the priority prefix).  Theoretically,
this code could change in the future.  printk should stay
as self-contained as possible in terms of its own operation,
and not predict post-processing.

I would argue it shouldn't be "length of printed string", if
by this you mean the thing that dmesg outputs.
Rather, it should be length of string emitted to log buffer.

> 
> strace -e write echo 1 > /dev/kmsg
> => write(1, "1\n", 2)                      = 5
This is not broken, from the standpoint of printk.
But it's weird from the standpoint of kmsg_write.

> 
> strace -e write echo "<1>1" > /dev/kmsg
> => write(1, "<1>1\n", 5)                   = 8
OK, this is wrong.  The math got messed up somewhere.
This should have been 5.

> Successful printk calls can have a return value different than the input
> length (priority prefix, timing), so /bin/echo will still think there is
> an error.
> So, to avoid breaking programs that assume write(buff, len) != len is an
> error, /dev/kmsg should return the buffer length when the call succeeds.
> 
> The only drawback is that now it's no more possible to use /dev/kmsg to
> check the printk return value :-(
> 
> 
> ------------------------------------------------------------------------
> 
> --- linux-2.6.13-rc5/kernel/printk.c
> +++ linux-2.6.13-rc5/kernel/printk.c
> @@ -553,7 +553,7 @@
>  				   p[1] <= '7' && p[2] == '>') {
>  					loglev_char = p[1];
>  					p += 3;
> -					printed_len += 3;
> +					printed_len -= 3;
>  				} else {
>  					loglev_char = default_message_loglevel
>  						+ '0';
> @@ -568,7 +568,7 @@
>  
>  				for (tp = tbuf; tp < tbuf + tlen; tp++)
>  					emit_log_char(*tp);
> -				printed_len += tlen - 3;
> +				printed_len += tlen;
>  			} else {
>  				if (p[0] != '<' || p[1] < '0' ||
>  				   p[1] > '7' || p[2] != '>') {
> @@ -576,8 +576,8 @@
>  					emit_log_char(default_message_loglevel
>  						+ '0');
>  					emit_log_char('>');
> +					printed_len += 3;
>  				}
> -				printed_len += 3;
>  			}
>  			log_level_unknown = 0;
>  			if (!*p)

I like the above code since it moves the counting closer
to the emitting, and I think it's easier to understand (and apparently
more correct. ;-)  I haven't runtime tested this, but
consider this part to have an:

Acked-By: Tim Bird <tim.bird@am.sony.com>

> --- linux-2.6.13-rc5/drivers/char/mem.c
> +++ linux-2.6.13-rc5/drivers/char/mem.c
> @@ -819,7 +819,7 @@ static ssize_t kmsg_write(struct file * 
>  			  size_t count, loff_t *ppos)
>  {
>  	char *tmp;
> -	int ret;
> +	ssize_t ret;
>  
>  	tmp = kmalloc(count + 1, GFP_KERNEL);
>  	if (tmp == NULL)
> @@ -828,6 +828,9 @@ static ssize_t kmsg_write(struct file * 
>  	if (!copy_from_user(tmp, buf, count)) {
>  		tmp[count] = 0;
>  		ret = printk("%s", tmp);
> +		if (ret > count)
> +			/* printk can add a prefix */
> +			ret = count;
>  	}
>  	kfree(tmp);
>  	return ret;

I'm not sure the side effect of this is.  Someone else will
have to comment.

Overall, if this patch didn't get noticed, please consider sending it again.

Thanks,
 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Electronics
=============================

[-mm PATCH 1/2] printk return value: fix it

[Guillaume Chazarain]

[-- Attachment #1: Type: text/plain, Size: 759 bytes --]

What's the true meaning of the printk return value?
Should it include the priority prefix length of 3? and what about the timing
information? In both cases it was broken:

strace -e write echo 1 > /dev/kmsg
=> write(1, "1\n", 2)                      = 5
strace -e write echo "<1>1" > /dev/kmsg
=> write(1, "<1>1\n", 5)                   = 8

The returned length was "length of input string + 3", I made it "length
of string output to the log buffer".

Note that I couldn't find any printk caller in the kernel interested by its 
return value besides kmsg_write.

Signed-off-by: Guillaume Chazarain <guichaz@yahoo.fr>
Acked-By: Tim Bird <tim.bird@am.sony.com>

---
  printk.c |    6 +++---
  1 files changed, 3 insertions(+), 3 deletions(-)



-- 
Guillaume



[-- Attachment #2: printk.diff --]
[-- Type: text/x-patch, Size: 806 bytes --]

diff -r d18e06f9c571 kernel/printk.c
--- a/kernel/printk.c	Mon Nov 14 10:22:49 2005 +0800
+++ b/kernel/printk.c	Mon Nov 14 15:02:56 2005 +0100
@@ -569,7 +569,7 @@
 				   p[1] <= '7' && p[2] == '>') {
 					loglev_char = p[1];
 					p += 3;
-					printed_len += 3;
+					printed_len -= 3;
 				} else {
 					loglev_char = default_message_loglevel
 						+ '0';
@@ -584,7 +584,7 @@
 
 				for (tp = tbuf; tp < tbuf + tlen; tp++)
 					emit_log_char(*tp);
-				printed_len += tlen - 3;
+				printed_len += tlen;
 			} else {
 				if (p[0] != '<' || p[1] < '0' ||
 				   p[1] > '7' || p[2] != '>') {
@@ -592,8 +592,8 @@
 					emit_log_char(default_message_loglevel
 						+ '0');
 					emit_log_char('>');
+					printed_len += 3;
 				}
-				printed_len += 3;
 			}
 			log_level_unknown = 0;
 			if (!*p)

Re: [-mm PATCH 1/2] printk return value: fix it

[Tim Bird]

Guillaume Chazarain wrote:
> What's the true meaning of the printk return value?
> Should it include the priority prefix length of 3? and what about the
> timing
> information? In both cases it was broken:
> 
> strace -e write echo 1 > /dev/kmsg
> => write(1, "1\n", 2)                      = 5
> strace -e write echo "<1>1" > /dev/kmsg
> => write(1, "<1>1\n", 5)                   = 8
This is clearly a bug, but due to (almost) no one
ever checking the return value, it has gone unnoticed.

> 
> The returned length was "length of input string + 3", I made it "length
> of string output to the log buffer".

I agree with this change.  I think it fits with how
the size is returned from printf in user space,
which can be greater than the length of the format
string when values are replaced in the string.  So
at least for printf, there is a precedent for returning a
number greater than the length of the submitted string.

 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Electronics
=============================

[PATCH 2/2] kmsg_write: don't return printk return value

[Guillaume Chazarain]

[-- Attachment #1: Type: text/plain, Size: 475 bytes --]

kmsg_write returns with printk, so some programs may be confused by
a successful write() with a return value different than the buffer length.

# /bin/echo something > /dev/kmsg
/bin/echo: write error: Inappropriate ioctl for device

The drawbacks is that the printk return value can no more be quickly checked
from userspace.

Signed-off-by: Guillaume Chazarain <guichaz@yahoo.fr>

---
  mem.c |    5 ++++-
  1 files changed, 4 insertions(+), 1 deletion(-)

-- 
Guillaume



[-- Attachment #2: kmsg_write.diff --]
[-- Type: text/x-patch, Size: 522 bytes --]

diff -r d18e06f9c571 drivers/char/mem.c
--- a/drivers/char/mem.c	Mon Nov 14 10:22:49 2005 +0800
+++ b/drivers/char/mem.c	Mon Nov 14 15:03:06 2005 +0100
@@ -817,7 +817,7 @@
 			  size_t count, loff_t *ppos)
 {
 	char *tmp;
-	int ret;
+	ssize_t ret;
 
 	tmp = kmalloc(count + 1, GFP_KERNEL);
 	if (tmp == NULL)
@@ -826,6 +826,9 @@
 	if (!copy_from_user(tmp, buf, count)) {
 		tmp[count] = 0;
 		ret = printk("%s", tmp);
+		if (ret > count)
+			/* printk can add a prefix */
+			ret = count;
 	}
 	kfree(tmp);
 	return ret;