Wrong printk return value

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

@@ -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)

@@ -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;

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.

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.

This is not broken, from the standpoint of printk. But it's weird from the standpoint of kmsg_write.

OK, this is wrong. The math got messed up somewhere. This should have been 5.

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.

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

Guillaume

diff -r d18e06f9c571 kernel/printk.c
@@ -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)

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.

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

Guillaume

diff -r d18e06f9c571 drivers/char/mem.c
@@ -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;

This is clearly a bug, but due to (almost) no one ever checking the return value, it has gone unnoticed.

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
=============================