printk: fix loglevels as used by x86 stack dump code

printk: fix loglevels as used by x86 stack dump code

[Alan Jenkins]

Following commit 5fd29d6 "printk: clean up handling of log-levels and newlines",
I noticed some loglevel oddities in my crash logs -

 Stack:
  00000020 dbe23e7c dbe23f8c c01a62bd 00000001 d759c400 dbc61840 00000000
  <0> 08088728 08088750 00000000 dbe23e74 dbe23ea4 00000000 00000000 00000000
  <0> dbe23c18 00c7afc0 c01a6eb1 ffffffff 00000000 dbc61840 00000000 00000000


This series is the result of my investigation.  The main fixes are

[PATCH 6/7] x86 dumpstack: fix printing of stack dump loglevels
 - fixes the problem shown above

[PATCH 5/7] printk: fix printk(KERN_EMERG) followed by printk("emergency message\n")
 - make sure the call trace which follows the stack dump is logged as KERN_EMERG,
   and not KERN_DEFAULT.

Regards
Alan

[PATCH 1/7] printk: clean up return value

[Alan Jenkins]

Commit 5fd29d6 "printk: clean up handling of log-levels and newlines"
causes printk() to return the wrong number of characters.

It counts the first loglevel tag twice: once in the original message
string, and a second time when we actually print the loglevel.

We could fix this up, but it seems pointless.  Callers don't really care
about the extra characters added by printk().  Instead, let's return the
length of the original message as formatted (and possibly truncated)
by vscnprintf().

Signed-off-by: Alan Jenkins <alan-jenkins@tuffmail.co.uk>
---
 kernel/printk.c |   10 +++++-----
 1 files changed, 5 insertions(+), 5 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index f38b07f..9d3d594 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -669,7 +669,7 @@ static inline void printk_delay(void)
 
 asmlinkage int vprintk(const char *fmt, va_list args)
 {
-	int printed_len = 0;
+	int message_len = 0;
 	int current_log_level = default_message_loglevel;
 	unsigned long flags;
 	int this_cpu;
@@ -708,11 +708,11 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	if (recursion_bug) {
 		recursion_bug = 0;
 		strcpy(printk_buf, recursion_bug_msg);
-		printed_len = strlen(recursion_bug_msg);
+		message_len = strlen(recursion_bug_msg);
 	}
 	/* Emit the output into the temporary buffer */
-	printed_len += vscnprintf(printk_buf + printed_len,
-				  sizeof(printk_buf) - printed_len, fmt, args);
+	message_len = vscnprintf(printk_buf + message_len,
+				  sizeof(printk_buf) - message_len, fmt, args);
 
 
 	p = printk_buf;
@@ -796,7 +796,7 @@ out_restore_irqs:
 	raw_local_irq_restore(flags);
 
 	preempt_enable();
-	return printed_len;
+	return message_len;
 }
 EXPORT_SYMBOL(printk);
 EXPORT_SYMBOL(vprintk);
-- 
1.6.3.2

Re: [PATCH 1/7] printk: clean up return value

[Joe Perches]

On Wed, 2009-10-07 at 09:39 +0100, Alan Jenkins wrote:
> Commit 5fd29d6 "printk: clean up handling of log-levels and newlines"
> causes printk() to return the wrong number of characters.

Maybe it'd be better to return void?

These may be the only uses of the value returned,
and both files are trivial to modify.

kernel/lockdep.c:	len += printk("%*s   %s", depth, "", usage_str[bit]);
kernel/lockdep.c:	len += printk(" at:\n");
drivers/char/mem.c:	ret = printk("%s", tmp);

Re: [PATCH 1/7] printk: clean up return value

[Linus Torvalds]

On Wed, 7 Oct 2009, Alan Jenkins wrote:
> 
> We could fix this up, but it seems pointless.  Callers don't really care
> about the extra characters added by printk().  Instead, let's return the
> length of the original message as formatted (and possibly truncated)
> by vscnprintf().

Hmm. I kind of agree with this, but at the same time I suspect that no 
caller should ever care about the loglevel characters (since they won't be 
_shown_), so your change still doesn't make it return a sensible value.

So I get the feeling that you should also add a

	message_len -= 3;

to the case where we peel off the "<.>" loglevel part at the head of the 
string. No?

Or we could just change it to 'void'. As Joe Perches says, nobody really 
cares deeply enough for this to generally even matter.

		Linus

Re: [PATCH 1/7] printk: clean up return value

[Alan Jenkins]

Linus Torvalds wrote:
> Hmm. I kind of agree with this, but at the same time I suspect that no 
> caller should ever care about the loglevel characters (since they won't be 
> _shown_), so your change still doesn't make it return a sensible value.
>
> So I get the feeling that you should also add a
>
> 	message_len -= 3;
>
> to the case where we peel off the "<.>" loglevel part at the head of the 
> string. No?
>   

The value is only really sensible for partial printk()s... except that
they're supposed to be prefixed with KERN_CONT.  So yes, good point.

> Or we could just change it to 'void'. As Joe Perches says, nobody really 
> cares deeply enough for this to generally even matter.
>   

That involves more work, which explains why I shied away from it :-). 
Ok, I'll do it.

Alan

Re: [PATCH 1/7] printk: clean up return value

[Joe Perches]

On Wed, 2009-10-07 at 08:36 -0700, Linus Torvalds wrote:
> On Wed, 7 Oct 2009, Alan Jenkins wrote:
> > We could fix this up, but it seems pointless.  Callers don't really care
> > about the extra characters added by printk().  Instead, let's return the
> > length of the original message as formatted (and possibly truncated)
> > by vscnprintf().
> Or we could just change it to 'void'. As Joe Perches says, nobody really 
> cares deeply enough for this to generally even matter.

Here are changes to make printk/vprintk return void
to the only uses I found:

 arch/arm/mach-iop13xx/pci.c   |    2 +-
 arch/arm/mach-iop13xx/setup.c |    2 +-
 drivers/char/mem.c            |    6 ++----
 drivers/md/md.c               |    3 +--
 drivers/md/raid5.c            |    3 ++-
 drivers/net/e100.c            |    9 +++++----
 include/linux/kernel.h        |   16 ++++++++--------
 include/net/sctp/sctp.h       |    6 +++---
 kernel/lockdep.c              |    4 ++--
 kernel/printk.c               |   10 +++-------
 net/sunrpc/svc.c              |    9 +++------
 11 files changed, 31 insertions(+), 39 deletions(-)

diff --git a/arch/arm/mach-iop13xx/pci.c b/arch/arm/mach-iop13xx/pci.c
index 4873f26..eb58d0a 100644
--- a/arch/arm/mach-iop13xx/pci.c
+++ b/arch/arm/mach-iop13xx/pci.c
@@ -28,7 +28,7 @@
 #include <mach/pci.h>
 
 #define IOP13XX_PCI_DEBUG 0
-#define PRINTK(x...) ((void)(IOP13XX_PCI_DEBUG && printk(x)))
+#define PRINTK(x...) do { if (IOP13XX_PCI_DEBUG) printk(x); } while (0)
 
 u32 iop13xx_atux_pmmr_offset; /* This offset can change based on strapping */
 u32 iop13xx_atue_pmmr_offset; /* This offset can change based on strapping */
diff --git a/arch/arm/mach-iop13xx/setup.c b/arch/arm/mach-iop13xx/setup.c
index 5c147fb..f6595ad 100644
--- a/arch/arm/mach-iop13xx/setup.c
+++ b/arch/arm/mach-iop13xx/setup.c
@@ -29,7 +29,7 @@
 
 #define IOP13XX_UART_XTAL 33334000
 #define IOP13XX_SETUP_DEBUG 0
-#define PRINTK(x...) ((void)(IOP13XX_SETUP_DEBUG && printk(x)))
+#define PRINTK(x...) do { if (IOP13XX_SETUP_DEBUG) printk(x); } while (0)
 
 /* Standard IO mapping for all IOP13XX based systems
  */
diff --git a/drivers/char/mem.c b/drivers/char/mem.c
index a074fce..6fd98d0 100644
--- a/drivers/char/mem.c
+++ b/drivers/char/mem.c
@@ -851,10 +851,8 @@ static ssize_t kmsg_write(struct file * file, const char __user * buf,
 	ret = -EFAULT;
 	if (!copy_from_user(tmp, buf, count)) {
 		tmp[count] = 0;
-		ret = printk("%s", tmp);
-		if (ret > count)
-			/* printk can add a prefix */
-			ret = count;
+		printk("%s", tmp);
+		ret = count;
 	}
 	kfree(tmp);
 	return ret;
diff --git a/drivers/md/md.c b/drivers/md/md.c
index 26ba42a..02173fd 100644
--- a/drivers/md/md.c
+++ b/drivers/md/md.c
@@ -51,8 +51,7 @@
 #include "bitmap.h"
 
 #define DEBUG 0
-#define dprintk(x...) ((void)(DEBUG && printk(x)))
-
+#define dprintk(x...) do { if (DEBUG) printk(x); } while (0)
 
 #ifndef MODULE
 static void autostart_arrays(int part);
diff --git a/drivers/md/raid5.c b/drivers/md/raid5.c
index 9482980..1e4b018 100644
--- a/drivers/md/raid5.c
+++ b/drivers/md/raid5.c
@@ -94,7 +94,8 @@
 #define __inline__
 #endif
 
-#define printk_rl(args...) ((void) (printk_ratelimit() && printk(args)))
+#define printk_rl(args...) \
+	do { if (printk_ratelimit()) printk(args); } while (0)
 
 /*
  * We maintain a biased count of active stripes in the bottom 16 bits of
diff --git a/drivers/net/e100.c b/drivers/net/e100.c
index 679965c..9e35650 100644
--- a/drivers/net/e100.c
+++ b/drivers/net/e100.c
@@ -198,10 +198,11 @@ module_param(use_io, int, 0);
 MODULE_PARM_DESC(debug, "Debug level (0=none,...,16=all)");
 MODULE_PARM_DESC(eeprom_bad_csum_allow, "Allow bad eeprom checksums");
 MODULE_PARM_DESC(use_io, "Force use of i/o access mode");
-#define DPRINTK(nlevel, klevel, fmt, args...) \
-	(void)((NETIF_MSG_##nlevel & nic->msg_enable) && \
-	printk(KERN_##klevel PFX "%s: %s: " fmt, nic->netdev->name, \
-		__func__ , ## args))
+#define DPRINTK(nlevel, klevel, fmt, args...) do {			\
+	if (NETIF_MSG_##nlevel & nic->msg_enable)			\
+		printk(KERN_##klevel PFX "%s: %s: " fmt,		\
+		       nic->netdev->name, __func__ , ## args);		\
+	} while (0)
 
 #define INTEL_8255X_ETHERNET_DEVICE(device_id, ich) {\
 	PCI_VENDOR_ID_INTEL, device_id, PCI_ANY_ID, PCI_ANY_ID, \
diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index d3cd23f..c75bad4 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -236,9 +236,9 @@ extern struct pid *session_of_pgrp(struct pid *pgrp);
 #define FW_INFO		"[Firmware Info]: "
 
 #ifdef CONFIG_PRINTK
-asmlinkage int vprintk(const char *fmt, va_list args)
+asmlinkage void vprintk(const char *fmt, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
-asmlinkage int printk(const char * fmt, ...)
+asmlinkage void printk(const char * fmt, ...)
 	__attribute__ ((format (printf, 1, 2))) __cold;
 
 extern struct ratelimit_state printk_ratelimit_state;
@@ -262,12 +262,12 @@ extern int printk_delay_msec;
 
 void log_buf_kexec_setup(void);
 #else
-static inline int vprintk(const char *s, va_list args)
+static inline void vprintk(const char *s, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
-static inline int vprintk(const char *s, va_list args) { return 0; }
-static inline int printk(const char *s, ...)
+static inline void vprintk(const char *s, va_list args) {}
+static inline void printk(const char *s, ...)
 	__attribute__ ((format (printf, 1, 2)));
-static inline int __cold printk(const char *s, ...) { return 0; }
+static inline void __cold printk(const char *s, ...) {}
 static inline int printk_ratelimit(void) { return 0; }
 static inline bool printk_timed_ratelimit(unsigned long *caller_jiffies, \
 					  unsigned int interval_msec)	\
@@ -389,7 +389,7 @@ static inline char *pack_hex_byte(char *buf, u8 byte)
 	printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #else
 #define pr_devel(fmt, ...) \
-	({ if (0) printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__); 0; })
+	({ if (0) printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__); ; })
 #endif
 
 /* If you are writing a driver, please use dev_dbg instead */
@@ -403,7 +403,7 @@ static inline char *pack_hex_byte(char *buf, u8 byte)
 	} while (0)
 #else
 #define pr_debug(fmt, ...) \
-	({ if (0) printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__); 0; })
+	({ if (0) printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__); ; })
 #endif
 
 /*
diff --git a/include/net/sctp/sctp.h b/include/net/sctp/sctp.h
index 8a6d529..9330780 100644
--- a/include/net/sctp/sctp.h
+++ b/include/net/sctp/sctp.h
@@ -276,9 +276,9 @@ struct sctp_mib {
 #if SCTP_DEBUG
 extern int sctp_debug_flag;
 #define SCTP_DEBUG_PRINTK(whatever...) \
-	((void) (sctp_debug_flag && printk(KERN_DEBUG whatever)))
+	do { if (sctp_debug_flag) printk(KERN_DEBUG whatever); } while (0)
 #define SCTP_DEBUG_PRINTK_IPADDR(lead, trail, leadparm, saddr, otherparms...) \
-	if (sctp_debug_flag) { \
+	do { if (sctp_debug_flag) {					\
 		if (saddr->sa.sa_family == AF_INET6) { \
 			printk(KERN_DEBUG \
 			       lead "%pI6" trail, \
@@ -292,7 +292,7 @@ extern int sctp_debug_flag;
 			       &saddr->v4.sin_addr.s_addr, \
 			       otherparms); \
 		} \
-	}
+	} while (0)
 #define SCTP_ENABLE_DEBUG { sctp_debug_flag = 1; }
 #define SCTP_DISABLE_DEBUG { sctp_debug_flag = 0; }
 
diff --git a/kernel/lockdep.c b/kernel/lockdep.c
index 3815ac1..2f77f23 100644
--- a/kernel/lockdep.c
+++ b/kernel/lockdep.c
@@ -1281,8 +1281,8 @@ static void print_lock_class_header(struct lock_class *class, int depth)
 		if (class->usage_mask & (1 << bit)) {
 			int len = depth;
 
-			len += printk("%*s   %s", depth, "", usage_str[bit]);
-			len += printk(" at:\n");
+			printk("%*s   %s at:\n", depth, "", usage_str[bit]);
+			len += depth + strlen(usage_str[bit]) + 8;
 			print_stack_trace(class->usage_traces + bit, len);
 		}
 	}
diff --git a/kernel/printk.c b/kernel/printk.c
index f38b07f..276f40f 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -586,16 +586,13 @@ static int have_callable_console(void)
  * See the vsnprintf() documentation for format string extensions over C99.
  */
 
-asmlinkage int printk(const char *fmt, ...)
+asmlinkage void printk(const char *fmt, ...)
 {
 	va_list args;
-	int r;
 
 	va_start(args, fmt);
-	r = vprintk(fmt, args);
+	vprintk(fmt, args);
 	va_end(args);
-
-	return r;
 }
 
 /* cpu currently holding logbuf_lock */
@@ -667,7 +664,7 @@ static inline void printk_delay(void)
 	}
 }
 
-asmlinkage int vprintk(const char *fmt, va_list args)
+asmlinkage void vprintk(const char *fmt, va_list args)
 {
 	int printed_len = 0;
 	int current_log_level = default_message_loglevel;
@@ -796,7 +793,6 @@ out_restore_irqs:
 	raw_local_irq_restore(flags);
 
 	preempt_enable();
-	return printed_len;
 }
 EXPORT_SYMBOL(printk);
 EXPORT_SYMBOL(vprintk);
diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
index 952f206..33cf786 100644
--- a/net/sunrpc/svc.c
+++ b/net/sunrpc/svc.c
@@ -953,25 +953,22 @@ static void svc_unregister(const struct svc_serv *serv)
 /*
  * Printk the given error with the address of the client that caused it.
  */
-static int
+static void
 __attribute__ ((format (printf, 2, 3)))
 svc_printk(struct svc_rqst *rqstp, const char *fmt, ...)
 {
 	va_list args;
-	int 	r;
 	char 	buf[RPC_MAX_ADDRBUFLEN];
 
 	if (!net_ratelimit())
-		return 0;
+		return;
 
 	printk(KERN_WARNING "svc: %s: ",
 		svc_print_addr(rqstp, buf, sizeof(buf)));
 
 	va_start(args, fmt);
-	r = vprintk(fmt, args);
+	vprintk(fmt, args);
 	va_end(args);
-
-	return r;
 }
 
 /*

Re: [PATCH 1/7] printk: clean up return value

[Alan Jenkins]

Joe Perches wrote:
> On Wed, 2009-10-07 at 08:36 -0700, Linus Torvalds wrote:
>   
>> On Wed, 7 Oct 2009, Alan Jenkins wrote:
>>     
>>> We could fix this up, but it seems pointless.  Callers don't really care
>>> about the extra characters added by printk().  Instead, let's return the
>>> length of the original message as formatted (and possibly truncated)
>>> by vscnprintf().
>>>       
>> Or we could just change it to 'void'. As Joe Perches says, nobody really 
>> cares deeply enough for this to generally even matter.
>>     
>
> Here are changes to make printk/vprintk return void
> to the only uses I found:
>
>  arch/arm/mach-iop13xx/pci.c   |    2 +-
>  arch/arm/mach-iop13xx/setup.c |    2 +-
>  drivers/char/mem.c            |    6 ++----
>  drivers/md/md.c               |    3 +--
>  drivers/md/raid5.c            |    3 ++-
>  drivers/net/e100.c            |    9 +++++----
>  include/linux/kernel.h        |   16 ++++++++--------
>  include/net/sctp/sctp.h       |    6 +++---
>  kernel/lockdep.c              |    4 ++--
>  kernel/printk.c               |   10 +++-------
>  net/sunrpc/svc.c              |    9 +++------
>  11 files changed, 31 insertions(+), 39 deletions(-)
>   

Ok, you beat me to it.

My second patch will depend on this.  Two questions -

- May I add it to my series with your Signed-off-by?
- May I split it up, so I can CC individual maintainers with the
revelant portions?

Thanks
Alan

Re: [PATCH 1/7] printk: clean up return value

[Joe Perches]

On Wed, 2009-10-07 at 17:57 +0100, Alan Jenkins wrote:
> Joe Perches wrote:
> > On Wed, 2009-10-07 at 08:36 -0700, Linus Torvalds wrote:
> >> On Wed, 7 Oct 2009, Alan Jenkins wrote:
> >>> We could fix this up, but it seems pointless.  Callers don't really care
> >>> about the extra characters added by printk().  Instead, let's return the
> >>> length of the original message as formatted (and possibly truncated)
> >>> by vscnprintf().
> >> Or we could just change it to 'void'. As Joe Perches says, nobody really 
> >> cares deeply enough for this to generally even matter.
> > Here are changes to make printk/vprintk return void
> > to the only uses I found:
> >  arch/arm/mach-iop13xx/pci.c   |    2 +-
> >  arch/arm/mach-iop13xx/setup.c |    2 +-
> >  drivers/char/mem.c            |    6 ++----
> >  drivers/md/md.c               |    3 +--
> >  drivers/md/raid5.c            |    3 ++-
> >  drivers/net/e100.c            |    9 +++++----
> >  include/linux/kernel.h        |   16 ++++++++--------
> >  include/net/sctp/sctp.h       |    6 +++---
> >  kernel/lockdep.c              |    4 ++--
> >  kernel/printk.c               |   10 +++-------
> >  net/sunrpc/svc.c              |    9 +++------
> >  11 files changed, 31 insertions(+), 39 deletions(-)
> Ok, you beat me to it.
> My second patch will depend on this.  Two questions -
> - May I add it to my series with your Signed-off-by?

Hi Alan.

Sure.  I suggest you verify it first though.

Signed-off-by: Joe Perches <joe@perches.com>

> May I split it up, so I can CC individual maintainers with the
> relevant portions?

Please.  Thanks.  Joe

[PATCH 2/7] kmsg: no need to limit the return value of printk

[Alan Jenkins]

Prefixes added by printk() are no longer included in the count of
characters which it returns.

Signed-off-by: Alan Jenkins <alan-jenkins@tuffmail.co.uk>
---
 drivers/char/mem.c |    3 ---
 1 files changed, 0 insertions(+), 3 deletions(-)

diff --git a/drivers/char/mem.c b/drivers/char/mem.c
index a074fce..8599f65 100644
--- a/drivers/char/mem.c
+++ b/drivers/char/mem.c
@@ -852,9 +852,6 @@ static ssize_t kmsg_write(struct file * file, const char __user * buf,
 	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;
-- 
1.6.3.2

[PATCH 3/7] printk: move the printing of the loglevel tag into a separate function

[Alan Jenkins]

This is preparation only; it does not change any behaviour.

Signed-off-by: Alan Jenkins <alan-jenkins@tuffmail.co.uk>
---
 kernel/printk.c |   48 ++++++++++++++++++++++++++----------------------
 1 files changed, 26 insertions(+), 22 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 9d3d594..69f717a 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -667,6 +667,30 @@ static inline void printk_delay(void)
 	}
 }
 
+static void printk_token(int log_level)
+{
+	emit_log_char('<');
+	emit_log_char(log_level + '0');
+	emit_log_char('>');
+
+	if (printk_time) {
+		/* Follow the token with the time */
+		char tbuf[50], *tp;
+		unsigned tlen;
+		unsigned long long t;
+		unsigned long nanosec_rem;
+
+		t = cpu_clock(printk_cpu);
+		nanosec_rem = do_div(t, 1000000000);
+		tlen = sprintf(tbuf, "[%5lu.%06lu] ",
+					(unsigned long) t,
+					nanosec_rem / 1000);
+
+		for (tp = tbuf; tp < tbuf + tlen; tp++)
+			emit_log_char(*tp);
+	}
+}
+
 asmlinkage int vprintk(const char *fmt, va_list args)
 {
 	int message_len = 0;
@@ -744,30 +768,10 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	 */
 	for ( ; *p; p++) {
 		if (new_text_line) {
-			/* Always output the token */
-			emit_log_char('<');
-			emit_log_char(current_log_level + '0');
-			emit_log_char('>');
-			printed_len += 3;
 			new_text_line = 0;
 
-			if (printk_time) {
-				/* Follow the token with the time */
-				char tbuf[50], *tp;
-				unsigned tlen;
-				unsigned long long t;
-				unsigned long nanosec_rem;
-
-				t = cpu_clock(printk_cpu);
-				nanosec_rem = do_div(t, 1000000000);
-				tlen = sprintf(tbuf, "[%5lu.%06lu] ",
-						(unsigned long) t,
-						nanosec_rem / 1000);
-
-				for (tp = tbuf; tp < tbuf + tlen; tp++)
-					emit_log_char(*tp);
-				printed_len += tlen;
-			}
+			/* Always output the token */
+			printk_token(current_log_level);
 
 			if (!*p)
 				break;
-- 
1.6.3.2

[PATCH 4/7] printk: remove redundant test

[Alan Jenkins]

print_token() cannot change the value of p.  So there is no need to test
*p again after calling print_token().

Signed-off-by: Alan Jenkins <alan-jenkins@tuffmail.co.uk>
---
 kernel/printk.c |    3 ---
 1 files changed, 0 insertions(+), 3 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 69f717a..1714435 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -772,9 +772,6 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 
 			/* Always output the token */
 			printk_token(current_log_level);
-
-			if (!*p)
-				break;
 		}
 
 		emit_log_char(*p);
-- 
1.6.3.2

[PATCH 5/7] printk: fix printk(KERN_EMERG) followed by printk("emergency message\n")

[Alan Jenkins]

Commit 5fd29d6 "printk: clean up handling of log-levels and newlines"
causes printk(KERN_EMERG) to be ignored. Any "emergency message" which
follows will be printed as KERN_DEFAULT.

This affects arch/x86/dumpstack.c, causing critical crash information to
be logged as KERN_DEFAULT.

Signed-off-by: Alan Jenkins <alan-jenkins@tuffmail.co.uk>
---
 kernel/printk.c |   11 +++++++----
 1 files changed, 7 insertions(+), 4 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 1714435..c7a1a85 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -763,14 +763,17 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	}
 
 	/*
-	 * Copy the output into log_buf.  If the caller didn't provide
-	 * appropriate log level tags, we insert them here
+	 * Now copy the output into log_buf.
+	 * We add a log level tag at the start of each new line.
 	 */
+	if (new_text_line) {
+		new_text_line = 0;
+		printk_token(current_log_level);
+	}
+
 	for ( ; *p; p++) {
 		if (new_text_line) {
 			new_text_line = 0;
-
-			/* Always output the token */
 			printk_token(current_log_level);
 		}
 
-- 
1.6.3.2

[PATCH 6/7] x86 dumpstack: fix printing of stack dump loglevels

[Alan Jenkins]

Commit 5fd29d6 "printk: clean up handling of log-levels and newlines"
breaks the log level in the output of the x86 stack dumper:

    Pid: 2199, comm: klauncher Not tainted (2.6.32-rc2eeepc-test #483) 701
     EFLAGS: 00010296 CPU: 0
     EIP is at fget_light+0x39/0x79
     ...
     Stack:
     00000020 dbe23e7c dbe23f8c c01a62bd 00000001 d759c400 dbc61840 00000000
     <0> 08088728 08088750 00000000 dbe23e74 dbe23ea4 00000000 00000000 00000000
     <0> dbe23c18 00c7afc0 c01a6eb1 ffffffff 00000000 dbc61840 00000000 00000000

      ^ stray loglevel tokens

Those last two lines will also be incorrectly output as KERN_DEFAULT.

In this case the problem is effectively

    printk("\n" KERN_EMERG);

Changing printk() to accept loglevels in the middle of the string again
would be non-trivial.  Let's accept this limitation and simply split the
above code into two separate calls to printk().

Signed-off-by: Alan Jenkins <alan-jenkins@tuffmail.co.uk>
---
 arch/x86/kernel/dumpstack_32.c |    6 ++++--
 arch/x86/kernel/dumpstack_64.c |    6 ++++--
 2 files changed, 8 insertions(+), 4 deletions(-)

diff --git a/arch/x86/kernel/dumpstack_32.c b/arch/x86/kernel/dumpstack_32.c
index f7dd2a7..8f1fb21 100644
--- a/arch/x86/kernel/dumpstack_32.c
+++ b/arch/x86/kernel/dumpstack_32.c
@@ -88,8 +88,10 @@ show_stack_log_lvl(struct task_struct *task, struct pt_regs *regs,
 	for (i = 0; i < kstack_depth_to_print; i++) {
 		if (kstack_end(stack))
 			break;
-		if (i && ((i % STACKSLOTS_PER_LINE) == 0))
-			printk("\n%s", log_lvl);
+		if (i && ((i % STACKSLOTS_PER_LINE) == 0)) {
+			printk("\n");
+			printk("%s", log_lvl);
+		}
 		printk(" %08lx", *stack++);
 		touch_nmi_watchdog();
 	}
diff --git a/arch/x86/kernel/dumpstack_64.c b/arch/x86/kernel/dumpstack_64.c
index a071e6b..dbe1734 100644
--- a/arch/x86/kernel/dumpstack_64.c
+++ b/arch/x86/kernel/dumpstack_64.c
@@ -235,8 +235,10 @@ show_stack_log_lvl(struct task_struct *task, struct pt_regs *regs,
 		if (((long) stack & (THREAD_SIZE-1)) == 0)
 			break;
 		}
-		if (i && ((i % STACKSLOTS_PER_LINE) == 0))
-			printk("\n%s", log_lvl);
+		if (i && ((i % STACKSLOTS_PER_LINE) == 0)) {
+			printk("\n");
+			printk("%s", log_lvl);
+		}
 		printk(" %016lx", *stack++);
 		touch_nmi_watchdog();
 	}
-- 
1.6.3.2

Re: [PATCH 6/7] x86 dumpstack: fix printing of stack dump loglevels

[Linus Torvalds]

On Wed, 7 Oct 2009, Alan Jenkins wrote:
> 
> Changing printk() to accept loglevels in the middle of the string again
> would be non-trivial.  Let's accept this limitation and simply split the
> above code into two separate calls to printk().

Actually, let's just drop the log_lvl printout in the middle.

And to do that, let's clean up printk() a bit further - just make it say 
"if there is no loglevel, use the previous loglevel". That's going to 
simplify _all_ kinds of multi-line code.

As far as I can tell, that's a oneliner: make 'current_log_level' be a 
'static' variable.

Wouldn't that be much simpler for everybody?

(And yes, if you mix multi-line messages that are printed as separate 
printk's and with different loglevels, output will be confused. But quite 
frankly, it will be confused regardless)

				Linus

Re: [PATCH 6/7] x86 dumpstack: fix printing of stack dump loglevels

[Alan Jenkins]

Linus Torvalds wrote:
> On Wed, 7 Oct 2009, Alan Jenkins wrote:
>   
>> Changing printk() to accept loglevels in the middle of the string again
>> would be non-trivial.  Let's accept this limitation and simply split the
>> above code into two separate calls to printk().
>>     
>
> Actually, let's just drop the log_lvl printout in the middle.
>
> And to do that, let's clean up printk() a bit further - just make it say 
> "if there is no loglevel, use the previous loglevel". That's going to 
> simplify _all_ kinds of multi-line code.
>   

I think its more of a special case.  It's most useful where we output a
multi-line hexdump (or some other sort of array).  I think that's just
stack dumps (albeit potentially one for each architecture).  Is there
really anything else?  If not, I would lean against doing this.

None of the other architectures seem to set any loglevel in
dump_stack(), so this would change their behaviour.  I.e. dump_stack()
would print with the current loglevel, whatever that is.  That's a neat
behaviour and we could simplify x86 to match.  But it seems less simple
overall.  This one arch function would rely implicitly on the new, not
immediately obvious behaviour of printk().

> As far as I can tell, that's a oneliner: make 'current_log_level' be a 
> 'static' variable.
>
> Wouldn't that be much simpler for everybody?
>
> (And yes, if you mix multi-line messages that are printed as separate 
> printk's and with different loglevels, output will be confused. But quite 
> frankly, it will be confused regardless)
>   

It is more obvious that there is confusion when you see "<0>" in the
middle of a line though :-).

Regards
Alan

[PATCH 7/7] x86 dumpstack: fix log level of the first line in the stack dump

[Alan Jenkins]

The first line of the stack dump is currently missing a log level;
it will be printed as KERN_DEFAULT.

Signed-off-by: Alan Jenkins <alan-jenkins@tuffmail.co.uk>
---
 arch/x86/kernel/dumpstack_32.c |    1 +
 arch/x86/kernel/dumpstack_64.c |    1 +
 2 files changed, 2 insertions(+), 0 deletions(-)

diff --git a/arch/x86/kernel/dumpstack_32.c b/arch/x86/kernel/dumpstack_32.c
index 8f1fb21..9db2370 100644
--- a/arch/x86/kernel/dumpstack_32.c
+++ b/arch/x86/kernel/dumpstack_32.c
@@ -84,6 +84,7 @@ show_stack_log_lvl(struct task_struct *task, struct pt_regs *regs,
 			sp = (unsigned long *)&sp;
 	}
 
+	printk("%s", log_lvl);
 	stack = sp;
 	for (i = 0; i < kstack_depth_to_print; i++) {
 		if (kstack_end(stack))
diff --git a/arch/x86/kernel/dumpstack_64.c b/arch/x86/kernel/dumpstack_64.c
index dbe1734..5b766a4 100644
--- a/arch/x86/kernel/dumpstack_64.c
+++ b/arch/x86/kernel/dumpstack_64.c
@@ -224,6 +224,7 @@ show_stack_log_lvl(struct task_struct *task, struct pt_regs *regs,
 			sp = (unsigned long *)&sp;
 	}
 
+	printk("%s", log_lvl);
 	stack = sp;
 	for (i = 0; i < kstack_depth_to_print; i++) {
 		if (stack >= irq_stack && stack <= irq_stack_end) {
-- 
1.6.3.2