show_regs() use show_stack_log_lvl() with KERN_EMERG.
The code of show_stack_log_lvl and show_trace_log_lvl does not print
the logs at the desired level, the messages are thus split into
different levels.
EMERG Stack:
DEFAULT <stack>
EMERG Trace:
DEFAULT <trace>
Adrien Schildknecht (2):
x86: fix output of show_stack_log_lvl()
x86: fix output of show_trace_log_lvl()
arch/x86/kernel/dumpstack.c | 10 +++++-----
arch/x86/kernel/dumpstack_32.c | 9 ++++++---
arch/x86/kernel/dumpstack_64.c | 9 ++++++---
3 files changed, 17 insertions(+), 11 deletions(-)
--
2.2.1
Prepend the log level at the message following a newline.
It is not possible to use pr_cont after a newline, the log level will be
reseted.
Signed-off-by: Adrien Schildknecht <[email protected]>
---
arch/x86/kernel/dumpstack_32.c | 9 ++++++---
arch/x86/kernel/dumpstack_64.c | 9 ++++++---
2 files changed, 12 insertions(+), 6 deletions(-)
diff --git a/arch/x86/kernel/dumpstack_32.c b/arch/x86/kernel/dumpstack_32.c
index 5abd4cd..efff5ed 100644
--- a/arch/x86/kernel/dumpstack_32.c
+++ b/arch/x86/kernel/dumpstack_32.c
@@ -108,9 +108,12 @@ 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))
- pr_cont("\n");
- pr_cont(" %08lx", *stack++);
+ if ((i % STACKSLOTS_PER_LINE) == 0) {
+ if (i != 0)
+ pr_cont("\n");
+ printk("%s %08lx", log_lvl, *stack++);
+ } else
+ pr_cont(" %08lx", *stack++);
touch_nmi_watchdog();
}
pr_cont("\n");
diff --git a/arch/x86/kernel/dumpstack_64.c b/arch/x86/kernel/dumpstack_64.c
index ff86f19..553573b 100644
--- a/arch/x86/kernel/dumpstack_64.c
+++ b/arch/x86/kernel/dumpstack_64.c
@@ -283,9 +283,12 @@ 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))
- pr_cont("\n");
- pr_cont(" %016lx", *stack++);
+ if ((i % STACKSLOTS_PER_LINE) == 0) {
+ if (i != 0)
+ pr_cont("\n");
+ printk("%s %016lx", log_lvl, *stack++);
+ } else
+ pr_cont(" %016lx", *stack++);
touch_nmi_watchdog();
}
preempt_enable();
--
2.2.1
Prepend the log level in printk_stack_address.
Using printk with just a log level is ignored and thus has no effect on
the next pr_cont.
Signed-off-by: Adrien Schildknecht <[email protected]>
---
arch/x86/kernel/dumpstack.c | 10 +++++-----
1 file changed, 5 insertions(+), 5 deletions(-)
diff --git a/arch/x86/kernel/dumpstack.c b/arch/x86/kernel/dumpstack.c
index cf3df1d..da1ab6a 100644
--- a/arch/x86/kernel/dumpstack.c
+++ b/arch/x86/kernel/dumpstack.c
@@ -25,10 +25,12 @@ unsigned int code_bytes = 64;
int kstack_depth_to_print = 3 * STACKSLOTS_PER_LINE;
static int die_counter;
-static void printk_stack_address(unsigned long address, int reliable)
+static void printk_stack_address(unsigned long address, int reliable,
+ void *data)
{
- pr_cont(" [<%p>] %s%pB\n",
- (void *)address, reliable ? "" : "? ", (void *)address);
+ pr_cont("%s [<%p>] %s%pB\n",
+ (char *)data, (void *)address, reliable ? "" : "? ",
+ (void *)address);
}
void printk_address(unsigned long address)
@@ -155,8 +157,7 @@ static int print_trace_stack(void *data, char *name)
static void print_trace_address(void *data, unsigned long addr, int reliable)
{
touch_nmi_watchdog();
- printk(data);
- printk_stack_address(addr, reliable);
+ printk_stack_address(addr, reliable, data);
}
static const struct stacktrace_ops print_trace_ops = {
--
2.2.1
On Thu, Feb 19, 2015 at 11:43:15PM +0100, Adrien Schildknecht wrote:
> Prepend the log level at the message following a newline.
> It is not possible to use pr_cont after a newline, the log level will be
> reseted.
>
> Signed-off-by: Adrien Schildknecht <[email protected]>
> ---
> arch/x86/kernel/dumpstack_32.c | 9 ++++++---
> arch/x86/kernel/dumpstack_64.c | 9 ++++++---
> 2 files changed, 12 insertions(+), 6 deletions(-)
So those two patches belong into one as they logically are one fix.
Please merge them.
Then, please change your commit message to the format:
"Problem is A.
We need to do B.
This patch does it or this patch does C in order fix it."
Something like that in free form. Being verbose is a good thing when
explaning why this fix is needed and for people looking at those commit
messages months and years from now.
Thanks.
--
Regards/Gruss,
Boris.
ECO tip #101: Trim your mails when you reply.
--
show_stack_log_lvl() does not set the log level after a new line,
the following messages printed with pr_cont are thus assigned to the
default log level.
This patch prepends the log level to the next message following a new
line.
print_trace_address() uses printk(log_lvl). Using printk with just
a log level is ignored and thus has no effect on the next pr_cont.
We need to prepend the log level directly into the message.
Signed-off-by: Adrien Schildknecht <[email protected]>
---
arch/x86/kernel/dumpstack.c | 11 ++++++-----
arch/x86/kernel/dumpstack_32.c | 9 ++++++---
arch/x86/kernel/dumpstack_64.c | 9 ++++++---
3 files changed, 18 insertions(+), 11 deletions(-)
diff --git a/arch/x86/kernel/dumpstack.c b/arch/x86/kernel/dumpstack.c
index cf3df1d..81b3932 100644
--- a/arch/x86/kernel/dumpstack.c
+++ b/arch/x86/kernel/dumpstack.c
@@ -25,10 +25,12 @@ unsigned int code_bytes = 64;
int kstack_depth_to_print = 3 * STACKSLOTS_PER_LINE;
static int die_counter;
-static void printk_stack_address(unsigned long address, int reliable)
+static void printk_stack_address(unsigned long address, int reliable,
+ void *data)
{
- pr_cont(" [<%p>] %s%pB\n",
- (void *)address, reliable ? "" : "? ", (void *)address);
+ printk("%s [<%p>] %s%pB\n",
+ (char *)data, (void *)address, reliable ? "" : "? ",
+ (void *)address);
}
void printk_address(unsigned long address)
@@ -155,8 +157,7 @@ static int print_trace_stack(void *data, char *name)
static void print_trace_address(void *data, unsigned long addr, int reliable)
{
touch_nmi_watchdog();
- printk(data);
- printk_stack_address(addr, reliable);
+ printk_stack_address(addr, reliable, data);
}
static const struct stacktrace_ops print_trace_ops = {
diff --git a/arch/x86/kernel/dumpstack_32.c b/arch/x86/kernel/dumpstack_32.c
index 5abd4cd..efff5ed 100644
--- a/arch/x86/kernel/dumpstack_32.c
+++ b/arch/x86/kernel/dumpstack_32.c
@@ -108,9 +108,12 @@ 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))
- pr_cont("\n");
- pr_cont(" %08lx", *stack++);
+ if ((i % STACKSLOTS_PER_LINE) == 0) {
+ if (i != 0)
+ pr_cont("\n");
+ printk("%s %08lx", log_lvl, *stack++);
+ } else
+ pr_cont(" %08lx", *stack++);
touch_nmi_watchdog();
}
pr_cont("\n");
diff --git a/arch/x86/kernel/dumpstack_64.c b/arch/x86/kernel/dumpstack_64.c
index ff86f19..553573b 100644
--- a/arch/x86/kernel/dumpstack_64.c
+++ b/arch/x86/kernel/dumpstack_64.c
@@ -283,9 +283,12 @@ 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))
- pr_cont("\n");
- pr_cont(" %016lx", *stack++);
+ if ((i % STACKSLOTS_PER_LINE) == 0) {
+ if (i != 0)
+ pr_cont("\n");
+ printk("%s %016lx", log_lvl, *stack++);
+ } else
+ pr_cont(" %016lx", *stack++);
touch_nmi_watchdog();
}
preempt_enable();
--
2.2.1
On Fri, 20 Feb 2015 03:34:21 +0100
Adrien Schildknecht <[email protected]> wrote:
> show_stack_log_lvl() does not set the log level after a new line,
> the following messages printed with pr_cont are thus assigned to the
> default log level.
This looks like a bug in printk(). Why doesn't pr_cont() continue? It
shouldn't care if there's a newline or not. pr_cont() is supposed to
continue whatever the last printk log level was.
If this is broken here, it's probably broken elsewhere. The fix is to
fix printk, not to hunt and peck for the places with work arounds that
are broken by it.
-- Steve
> This patch prepends the log level to the next message following a new
> line.
>
> print_trace_address() uses printk(log_lvl). Using printk with just
> a log level is ignored and thus has no effect on the next pr_cont.
> We need to prepend the log level directly into the message.
>
> Signed-off-by: Adrien Schildknecht <[email protected]>
* Adrien Schildknecht <[email protected]> wrote:
> show_stack_log_lvl() does not set the log level after a new line,
> the following messages printed with pr_cont are thus assigned to the
> default log level.
> This patch prepends the log level to the next message following a new
> line.
>
> print_trace_address() uses printk(log_lvl). Using printk with just
> a log level is ignored and thus has no effect on the next pr_cont.
> We need to prepend the log level directly into the message.
This approach looks good to me, we want to print multi-line
messages with the same consistent loglevel.
Totally unrelated observation:
> +++ b/arch/x86/kernel/dumpstack.c
> touch_nmi_watchdog();
> + printk_stack_address(addr, reliable, data);
The whole code is sprinkled with touch_nmi_watchdog()
calls. Shouldn't we simply make it a rule that if a printk
message makes it to a real console (as opposed to the log
buffer only), it should imply a touch_nmi_watchdog()?
Then all of those crappy touch_nmi_watchdog() calls could
be removed here and in other places where long printk
streams may happen.
Totally unrelated observation #2:
> if (kstack_end(stack))
> break;
> - if (i && ((i % STACKSLOTS_PER_LINE) == 0))
> - pr_cont("\n");
> +++ b/arch/x86/kernel/dumpstack_64.c
> if (((long) stack & (THREAD_SIZE-1)) == 0)
> break;
> }
> - if (i && ((i % STACKSLOTS_PER_LINE) == 0))
> - pr_cont("\n");
Looks like kstack_end() could be defined on 64-bit as well,
unifying the stack printing logic some more?
( I'd no go so far as to unify the two functions, but the
closer to each other the better it is to make changes
that affect both of them. )
Thanks,
Ingo
On Fri, Feb 20, 2015 at 09:10:03AM +0100, Ingo Molnar wrote:
> This approach looks good to me, we want to print multi-line
> messages with the same consistent loglevel.
Right, I'll pick this one up for now as it is obviously correct and
whatever we end up doing to pr_cont() won't influence it.
> Totally unrelated observation #2:
>
> > if (kstack_end(stack))
> > break;
> > - if (i && ((i % STACKSLOTS_PER_LINE) == 0))
> > - pr_cont("\n");
>
> > +++ b/arch/x86/kernel/dumpstack_64.c
>
> > if (((long) stack & (THREAD_SIZE-1)) == 0)
> > break;
> > }
> > - if (i && ((i % STACKSLOTS_PER_LINE) == 0))
> > - pr_cont("\n");
>
> Looks like kstack_end() could be defined on 64-bit as well,
> unifying the stack printing logic some more?
>
> ( I'd no go so far as to unify the two functions, but the
> closer to each other the better it is to make changes
> that affect both of them. )
Adrien, want to take care of that one too?
--
Regards/Gruss,
Boris.
ECO tip #101: Trim your mails when you reply.
--
> > Looks like kstack_end() could be defined on 64-bit as well,
> > unifying the stack printing logic some more?
> >
> > ( I'd no go so far as to unify the two functions, but the
> > closer to each other the better it is to make changes
> > that affect both of them. )
>
> Adrien, want to take care of that one too?
Sure, I can do that.
--
Adrien Schildknecht
On Thu, 19 Feb 2015 21:13:29 -0800
Linus Torvalds <[email protected]> wrote:
> On Feb 19, 2015 8:45 PM, "Steven Rostedt" <[email protected]> wrote:
> >
> > This looks like a bug in printk(). Why doesn't pr_cont() continue? It
> > shouldn't care if there's a newline or not. pr_cont() is supposed to
> > continue whatever the last printk log level was.
>
> pr_cont() should continue the current line. If there was a behind, and it's
> a new line, then pr_cont() is meaningless.
Ah, you are right. I got confused by the lack of comments around
pr_cont. Now KERN_CONT is nicely commented, but unfortunately that
comment exists in a different file.
How about adding the below patch so people like me wont get confused
again.
-- Steve
printk: Comment pr_cont() stating it is only to continue a line
KERN_CONT is nicely commented in kern_levels.h, but pr_cont() is now
used more often, and it lacks the comment stating what it is used for.
It can be confused as continuing the log level, but that is not its
purpose. It's purpose is to continue a line that had no newline
enclosed. This should be documented by pr_cont() as well.
Signed-off-by: Steven Rostedt <[email protected]>
---
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 4d5bf57..937d2f3 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -255,6 +255,11 @@ extern asmlinkage void dump_stack(void) __cold;
printk(KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)
#define pr_info(fmt, ...) \
printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
+/*
+ * Like KERN_CONT, pr_cont() should only be used when continuing
+ * a line with no newline ('\n') enclosed. Otherwise it defaults
+ * back to KERN_DEFAULT.
+ */
#define pr_cont(fmt, ...) \
printk(KERN_CONT fmt, ##__VA_ARGS__)
On Fri, Feb 20, 2015 at 12:05:06PM -0500, Steven Rostedt wrote:
> printk: Comment pr_cont() stating it is only to continue a line
>
> KERN_CONT is nicely commented in kern_levels.h, but pr_cont() is now
> used more often, and it lacks the comment stating what it is used for.
> It can be confused as continuing the log level, but that is not its
> purpose. It's purpose is to continue a line that had no newline
> enclosed. This should be documented by pr_cont() as well.
>
> Signed-off-by: Steven Rostedt <[email protected]>
I sure could've used that info when looking at this yesterday. Good
patch.
Acked-by: Borislav Petkov <[email protected]>
--
Regards/Gruss,
Boris.
ECO tip #101: Trim your mails when you reply.
--
On Fri, 2015-02-20 at 12:05 -0500, Steven Rostedt wrote:
> On Thu, 19 Feb 2015 21:13:29 -0800
> Linus Torvalds <[email protected]> wrote:
>
> > On Feb 19, 2015 8:45 PM, "Steven Rostedt" <[email protected]> wrote:
> > >
> > > This looks like a bug in printk(). Why doesn't pr_cont() continue? It
> > > shouldn't care if there's a newline or not. pr_cont() is supposed to
> > > continue whatever the last printk log level was.
> >
> > pr_cont() should continue the current line. If there was a behind, and it's
> > a new line, then pr_cont() is meaningless.
>
> Ah, you are right. I got confused by the lack of comments around
> pr_cont. Now KERN_CONT is nicely commented, but unfortunately that
> comment exists in a different file.
>
> How about adding the below patch so people like me wont get confused
> again.
>
> -- Steve
>
> printk: Comment pr_cont() stating it is only to continue a line
>
> KERN_CONT is nicely commented in kern_levels.h, but pr_cont() is now
> used more often, and it lacks the comment stating what it is used for.
> It can be confused as continuing the log level, but that is not its
> purpose. It's purpose is to continue a line that had no newline
> enclosed. This should be documented by pr_cont() as well.
>
> Signed-off-by: Steven Rostedt <[email protected]>
> ---
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index 4d5bf57..937d2f3 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -255,6 +255,11 @@ extern asmlinkage void dump_stack(void) __cold;
> printk(KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)
> #define pr_info(fmt, ...) \
> printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
> +/*
> + * Like KERN_CONT, pr_cont() should only be used when continuing
> + * a line with no newline ('\n') enclosed. Otherwise it defaults
> + * back to KERN_DEFAULT.
> + */
The first sentence is basically true though the
"enclosed" use is at best awkward.
Maybe "closing" or "terminating" is better.
There are still a few dozen uses of this pattern:
pr_info("Some message line 1\nNext line: ");
for (...)
pr_cont(" part %d", i);
pr_cont('\n");
The second sentence is not true.
KERN_DEFAULT is an odd-ball variable level that likely
could be removed altogether. It's like a naked printk,
but if the last emitted char is not a newline, one is
prepended.
How about something like:
Use pr_cont() when continuing a message that does
not end in a '\n'. Do not use pr_cont when continuing
a dynamic_debug type message.
On Fri, 2015-02-20 at 09:52 -0800, Linus Torvalds wrote:
> On Feb 20, 2015 9:40 AM, "Joe Perches" <[email protected]> wrote:
> >
> > There are still a few dozen uses of this pattern:
> >
> > pr_info("Some message line 1\nNext line: ");
> > for (...)
> > pr_cont(" part %d", i);
> > pr_cont('\n");
>
> That, btw, is a buglet anyway.
>
> We don't really support newlines in the middle of printouts any more. We
> used to, but it for deprecated. It doesn't really work with the "printk is
> a message packet" model.
>
> Admittedly neither does the "pr_cont()" model, but pr_cont() is
> fundamentally useful, in a way that newlines in the middle are not (they
> can always just be split up, while the pr_cont() cannot generally be
> combined).
>
> So we should generally try to get rid of the newline in the middle cases.
True. Also fix the pr_debug/dev_dbg cases
like drivers/dma/ppc4xx/adma.c:
static void prep_dma_pq_dbg(int id, dma_addr_t *dst, dma_addr_t *src,
unsigned int src_cnt)
{
int i;
pr_debug("\n%s(%d):\nsrc: ", __func__, id);
for (i = 0; i < src_cnt; i++)
pr_debug("\t0x%016llx ", src[i]);
pr_debug("dst: ");
for (i = 0; i < 2; i++)
pr_debug("\t0x%016llx ", dst[i]);
}
On Fri, Feb 20, 2015 at 10:03 AM, Joe Perches <[email protected]> wrote:
>
> True. Also fix the pr_debug/dev_dbg cases
> like drivers/dma/ppc4xx/adma.c:
Yup, that's just garbage, and doesn't actually do what is intended.
Also, rather than
pr_debug("\n%s(%d):\nsrc: ", __func__, id);
for (i = 0; i < src_cnt; i++)
pr_debug("\t0x%016llx ", src[i]);
...
t should probably just use
pr_debug("%s(%d):\n", __func__, id);
pr_debug("%src: %*phN\n", src_cnt*sizeof(*src), src);
or similar. Yes, that will just print out the byte-stream rather than
do it in chunkcs of 64-bit entries, but..
Linus
On Fri, 2015-02-20 at 10:51 -0800, Linus Torvalds wrote:
> On Fri, Feb 20, 2015 at 10:03 AM, Joe Perchens <[email protected]> wrote:
> >
> > True. Also fix the pr_debug/dev_dbg cases
> > like drivers/dma/ppc4xx/adma.c:
>
> Yup, that's just garbage, and doesn't actually do what is intended.
>
> Also, rather than
>
> pr_debug("\n%s(%d):\nsrc: ", __func__, id);
> for (i = 0; i < src_cnt; i++)
> pr_debug("\t0x%016llx ", src[i]);
> ...
>
> t should probably just use
>
> pr_debug("%s(%d):\n", __func__, id);
> pr_debug("%src: %*phN\n", src_cnt*sizeof(*src), src);
>
> or similar. Yes, that will just print out the byte-stream rather than
> do it in chunkcs of 64-bit entries, but..
That won't work for > 64 byte output.
This would probably be better:
print_hex_dump_debug("src: ", DUMP_PREFIX_OFFSET, 16, sizeof(*src),
src, src_cnt * sizeof(*src), false);