Commit f943fe0f authored by Dmitry Vyukov's avatar Dmitry Vyukov Committed by Ingo Molnar

lockdep: Fix report formatting

Since commit:

  4bcc595c ("printk: reinstate KERN_CONT for printing continuation lines")

printk() requires KERN_CONT to continue log messages. Lots of printk()
in lockdep.c and print_ip_sym() don't have it. As the result lockdep
reports are completely messed up.

Add missing KERN_CONT and inline print_ip_sym() where necessary.

Example of a messed up report:

  0-rc5+ #41 Not tainted
  -------------------------------------------------------
  syz-executor0/5036 is trying to acquire lock:
   (
  rtnl_mutex
  ){+.+.+.}
  , at:
  [<ffffffff86b3d6ac>] rtnl_lock+0x1c/0x20
  but task is already holding lock:
   (
  &net->packet.sklist_lock
  ){+.+...}
  , at:
  [<ffffffff873541a6>] packet_diag_dump+0x1a6/0x1920
  which lock already depends on the new lock.
  the existing dependency chain (in reverse order) is:
  -> #3
   (
  &net->packet.sklist_lock
  +.+...}
  ...

Without this patch all scripts that parse kernel bug reports are broken.
Signed-off-by: default avatarDmitry Vyukov <dvyukov@google.com>
Signed-off-by: default avatarPeter Zijlstra (Intel) <peterz@infradead.org>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: andreyknvl@google.com
Cc: aryabinin@virtuozzo.com
Cc: joe@perches.com
Cc: syzkaller@googlegroups.com
Link: http://lkml.kernel.org/r/1480343083-48731-1-git-send-email-dvyukov@google.comSigned-off-by: default avatarIngo Molnar <mingo@kernel.org>
parent 1be5d4fa
...@@ -506,13 +506,13 @@ static void __print_lock_name(struct lock_class *class) ...@@ -506,13 +506,13 @@ static void __print_lock_name(struct lock_class *class)
name = class->name; name = class->name;
if (!name) { if (!name) {
name = __get_key_name(class->key, str); name = __get_key_name(class->key, str);
printk("%s", name); printk(KERN_CONT "%s", name);
} else { } else {
printk("%s", name); printk(KERN_CONT "%s", name);
if (class->name_version > 1) if (class->name_version > 1)
printk("#%d", class->name_version); printk(KERN_CONT "#%d", class->name_version);
if (class->subclass) if (class->subclass)
printk("/%d", class->subclass); printk(KERN_CONT "/%d", class->subclass);
} }
} }
...@@ -522,9 +522,9 @@ static void print_lock_name(struct lock_class *class) ...@@ -522,9 +522,9 @@ static void print_lock_name(struct lock_class *class)
get_usage_chars(class, usage); get_usage_chars(class, usage);
printk(" ("); printk(KERN_CONT " (");
__print_lock_name(class); __print_lock_name(class);
printk("){%s}", usage); printk(KERN_CONT "){%s}", usage);
} }
static void print_lockdep_cache(struct lockdep_map *lock) static void print_lockdep_cache(struct lockdep_map *lock)
...@@ -536,7 +536,7 @@ static void print_lockdep_cache(struct lockdep_map *lock) ...@@ -536,7 +536,7 @@ static void print_lockdep_cache(struct lockdep_map *lock)
if (!name) if (!name)
name = __get_key_name(lock->key->subkeys, str); name = __get_key_name(lock->key->subkeys, str);
printk("%s", name); printk(KERN_CONT "%s", name);
} }
static void print_lock(struct held_lock *hlock) static void print_lock(struct held_lock *hlock)
...@@ -551,13 +551,13 @@ static void print_lock(struct held_lock *hlock) ...@@ -551,13 +551,13 @@ static void print_lock(struct held_lock *hlock)
barrier(); barrier();
if (!class_idx || (class_idx - 1) >= MAX_LOCKDEP_KEYS) { if (!class_idx || (class_idx - 1) >= MAX_LOCKDEP_KEYS) {
printk("<RELEASED>\n"); printk(KERN_CONT "<RELEASED>\n");
return; return;
} }
print_lock_name(lock_classes + class_idx - 1); print_lock_name(lock_classes + class_idx - 1);
printk(", at: "); printk(KERN_CONT ", at: [<%p>] %pS\n",
print_ip_sym(hlock->acquire_ip); (void *)hlock->acquire_ip, (void *)hlock->acquire_ip);
} }
static void lockdep_print_held_locks(struct task_struct *curr) static void lockdep_print_held_locks(struct task_struct *curr)
...@@ -792,8 +792,8 @@ register_lock_class(struct lockdep_map *lock, unsigned int subclass, int force) ...@@ -792,8 +792,8 @@ register_lock_class(struct lockdep_map *lock, unsigned int subclass, int force)
printk("\nnew class %p: %s", class->key, class->name); printk("\nnew class %p: %s", class->key, class->name);
if (class->name_version > 1) if (class->name_version > 1)
printk("#%d", class->name_version); printk(KERN_CONT "#%d", class->name_version);
printk("\n"); printk(KERN_CONT "\n");
dump_stack(); dump_stack();
if (!graph_lock()) { if (!graph_lock()) {
...@@ -1071,7 +1071,7 @@ print_circular_bug_entry(struct lock_list *target, int depth) ...@@ -1071,7 +1071,7 @@ print_circular_bug_entry(struct lock_list *target, int depth)
return 0; return 0;
printk("\n-> #%u", depth); printk("\n-> #%u", depth);
print_lock_name(target->class); print_lock_name(target->class);
printk(":\n"); printk(KERN_CONT ":\n");
print_stack_trace(&target->trace, 6); print_stack_trace(&target->trace, 6);
return 0; return 0;
...@@ -1102,11 +1102,11 @@ print_circular_lock_scenario(struct held_lock *src, ...@@ -1102,11 +1102,11 @@ print_circular_lock_scenario(struct held_lock *src,
if (parent != source) { if (parent != source) {
printk("Chain exists of:\n "); printk("Chain exists of:\n ");
__print_lock_name(source); __print_lock_name(source);
printk(" --> "); printk(KERN_CONT " --> ");
__print_lock_name(parent); __print_lock_name(parent);
printk(" --> "); printk(KERN_CONT " --> ");
__print_lock_name(target); __print_lock_name(target);
printk("\n\n"); printk(KERN_CONT "\n\n");
} }
printk(" Possible unsafe locking scenario:\n\n"); printk(" Possible unsafe locking scenario:\n\n");
...@@ -1114,16 +1114,16 @@ print_circular_lock_scenario(struct held_lock *src, ...@@ -1114,16 +1114,16 @@ print_circular_lock_scenario(struct held_lock *src,
printk(" ---- ----\n"); printk(" ---- ----\n");
printk(" lock("); printk(" lock(");
__print_lock_name(target); __print_lock_name(target);
printk(");\n"); printk(KERN_CONT ");\n");
printk(" lock("); printk(" lock(");
__print_lock_name(parent); __print_lock_name(parent);
printk(");\n"); printk(KERN_CONT ");\n");
printk(" lock("); printk(" lock(");
__print_lock_name(target); __print_lock_name(target);
printk(");\n"); printk(KERN_CONT ");\n");
printk(" lock("); printk(" lock(");
__print_lock_name(source); __print_lock_name(source);
printk(");\n"); printk(KERN_CONT ");\n");
printk("\n *** DEADLOCK ***\n\n"); printk("\n *** DEADLOCK ***\n\n");
} }
...@@ -1359,22 +1359,22 @@ static void print_lock_class_header(struct lock_class *class, int depth) ...@@ -1359,22 +1359,22 @@ static void print_lock_class_header(struct lock_class *class, int depth)
printk("%*s->", depth, ""); printk("%*s->", depth, "");
print_lock_name(class); print_lock_name(class);
printk(" ops: %lu", class->ops); printk(KERN_CONT " ops: %lu", class->ops);
printk(" {\n"); printk(KERN_CONT " {\n");
for (bit = 0; bit < LOCK_USAGE_STATES; bit++) { for (bit = 0; bit < LOCK_USAGE_STATES; bit++) {
if (class->usage_mask & (1 << bit)) { if (class->usage_mask & (1 << bit)) {
int len = depth; int len = depth;
len += printk("%*s %s", depth, "", usage_str[bit]); len += printk("%*s %s", depth, "", usage_str[bit]);
len += printk(" at:\n"); len += printk(KERN_CONT " at:\n");
print_stack_trace(class->usage_traces + bit, len); print_stack_trace(class->usage_traces + bit, len);
} }
} }
printk("%*s }\n", depth, ""); printk("%*s }\n", depth, "");
printk("%*s ... key at: ",depth,""); printk("%*s ... key at: [<%p>] %pS\n",
print_ip_sym((unsigned long)class->key); depth, "", class->key, class->key);
} }
/* /*
...@@ -1437,11 +1437,11 @@ print_irq_lock_scenario(struct lock_list *safe_entry, ...@@ -1437,11 +1437,11 @@ print_irq_lock_scenario(struct lock_list *safe_entry,
if (middle_class != unsafe_class) { if (middle_class != unsafe_class) {
printk("Chain exists of:\n "); printk("Chain exists of:\n ");
__print_lock_name(safe_class); __print_lock_name(safe_class);
printk(" --> "); printk(KERN_CONT " --> ");
__print_lock_name(middle_class); __print_lock_name(middle_class);
printk(" --> "); printk(KERN_CONT " --> ");
__print_lock_name(unsafe_class); __print_lock_name(unsafe_class);
printk("\n\n"); printk(KERN_CONT "\n\n");
} }
printk(" Possible interrupt unsafe locking scenario:\n\n"); printk(" Possible interrupt unsafe locking scenario:\n\n");
...@@ -1449,18 +1449,18 @@ print_irq_lock_scenario(struct lock_list *safe_entry, ...@@ -1449,18 +1449,18 @@ print_irq_lock_scenario(struct lock_list *safe_entry,
printk(" ---- ----\n"); printk(" ---- ----\n");
printk(" lock("); printk(" lock(");
__print_lock_name(unsafe_class); __print_lock_name(unsafe_class);
printk(");\n"); printk(KERN_CONT ");\n");
printk(" local_irq_disable();\n"); printk(" local_irq_disable();\n");
printk(" lock("); printk(" lock(");
__print_lock_name(safe_class); __print_lock_name(safe_class);
printk(");\n"); printk(KERN_CONT ");\n");
printk(" lock("); printk(" lock(");
__print_lock_name(middle_class); __print_lock_name(middle_class);
printk(");\n"); printk(KERN_CONT ");\n");
printk(" <Interrupt>\n"); printk(" <Interrupt>\n");
printk(" lock("); printk(" lock(");
__print_lock_name(safe_class); __print_lock_name(safe_class);
printk(");\n"); printk(KERN_CONT ");\n");
printk("\n *** DEADLOCK ***\n\n"); printk("\n *** DEADLOCK ***\n\n");
} }
...@@ -1497,9 +1497,9 @@ print_bad_irq_dependency(struct task_struct *curr, ...@@ -1497,9 +1497,9 @@ print_bad_irq_dependency(struct task_struct *curr,
print_lock(prev); print_lock(prev);
printk("which would create a new lock dependency:\n"); printk("which would create a new lock dependency:\n");
print_lock_name(hlock_class(prev)); print_lock_name(hlock_class(prev));
printk(" ->"); printk(KERN_CONT " ->");
print_lock_name(hlock_class(next)); print_lock_name(hlock_class(next));
printk("\n"); printk(KERN_CONT "\n");
printk("\nbut this new dependency connects a %s-irq-safe lock:\n", printk("\nbut this new dependency connects a %s-irq-safe lock:\n",
irqclass); irqclass);
...@@ -1521,8 +1521,7 @@ print_bad_irq_dependency(struct task_struct *curr, ...@@ -1521,8 +1521,7 @@ print_bad_irq_dependency(struct task_struct *curr,
lockdep_print_held_locks(curr); lockdep_print_held_locks(curr);
printk("\nthe dependencies between %s-irq-safe lock", irqclass); printk("\nthe dependencies between %s-irq-safe lock and the holding lock:\n", irqclass);
printk(" and the holding lock:\n");
if (!save_trace(&prev_root->trace)) if (!save_trace(&prev_root->trace))
return 0; return 0;
print_shortest_lock_dependencies(backwards_entry, prev_root); print_shortest_lock_dependencies(backwards_entry, prev_root);
...@@ -1694,10 +1693,10 @@ print_deadlock_scenario(struct held_lock *nxt, ...@@ -1694,10 +1693,10 @@ print_deadlock_scenario(struct held_lock *nxt,
printk(" ----\n"); printk(" ----\n");
printk(" lock("); printk(" lock(");
__print_lock_name(prev); __print_lock_name(prev);
printk(");\n"); printk(KERN_CONT ");\n");
printk(" lock("); printk(" lock(");
__print_lock_name(next); __print_lock_name(next);
printk(");\n"); printk(KERN_CONT ");\n");
printk("\n *** DEADLOCK ***\n\n"); printk("\n *** DEADLOCK ***\n\n");
printk(" May be due to missing lock nesting notation\n\n"); printk(" May be due to missing lock nesting notation\n\n");
} }
...@@ -1891,9 +1890,9 @@ check_prev_add(struct task_struct *curr, struct held_lock *prev, ...@@ -1891,9 +1890,9 @@ check_prev_add(struct task_struct *curr, struct held_lock *prev,
graph_unlock(); graph_unlock();
printk("\n new dependency: "); printk("\n new dependency: ");
print_lock_name(hlock_class(prev)); print_lock_name(hlock_class(prev));
printk(" => "); printk(KERN_CONT " => ");
print_lock_name(hlock_class(next)); print_lock_name(hlock_class(next));
printk("\n"); printk(KERN_CONT "\n");
dump_stack(); dump_stack();
return graph_lock(); return graph_lock();
} }
...@@ -2343,11 +2342,11 @@ print_usage_bug_scenario(struct held_lock *lock) ...@@ -2343,11 +2342,11 @@ print_usage_bug_scenario(struct held_lock *lock)
printk(" ----\n"); printk(" ----\n");
printk(" lock("); printk(" lock(");
__print_lock_name(class); __print_lock_name(class);
printk(");\n"); printk(KERN_CONT ");\n");
printk(" <Interrupt>\n"); printk(" <Interrupt>\n");
printk(" lock("); printk(" lock(");
__print_lock_name(class); __print_lock_name(class);
printk(");\n"); printk(KERN_CONT ");\n");
printk("\n *** DEADLOCK ***\n\n"); printk("\n *** DEADLOCK ***\n\n");
} }
...@@ -2522,14 +2521,18 @@ check_usage_backwards(struct task_struct *curr, struct held_lock *this, ...@@ -2522,14 +2521,18 @@ check_usage_backwards(struct task_struct *curr, struct held_lock *this,
void print_irqtrace_events(struct task_struct *curr) void print_irqtrace_events(struct task_struct *curr)
{ {
printk("irq event stamp: %u\n", curr->irq_events); printk("irq event stamp: %u\n", curr->irq_events);
printk("hardirqs last enabled at (%u): ", curr->hardirq_enable_event); printk("hardirqs last enabled at (%u): [<%p>] %pS\n",
print_ip_sym(curr->hardirq_enable_ip); curr->hardirq_enable_event, (void *)curr->hardirq_enable_ip,
printk("hardirqs last disabled at (%u): ", curr->hardirq_disable_event); (void *)curr->hardirq_enable_ip);
print_ip_sym(curr->hardirq_disable_ip); printk("hardirqs last disabled at (%u): [<%p>] %pS\n",
printk("softirqs last enabled at (%u): ", curr->softirq_enable_event); curr->hardirq_disable_event, (void *)curr->hardirq_disable_ip,
print_ip_sym(curr->softirq_enable_ip); (void *)curr->hardirq_disable_ip);
printk("softirqs last disabled at (%u): ", curr->softirq_disable_event); printk("softirqs last enabled at (%u): [<%p>] %pS\n",
print_ip_sym(curr->softirq_disable_ip); curr->softirq_enable_event, (void *)curr->softirq_enable_ip,
(void *)curr->softirq_enable_ip);
printk("softirqs last disabled at (%u): [<%p>] %pS\n",
curr->softirq_disable_event, (void *)curr->softirq_disable_ip,
(void *)curr->softirq_disable_ip);
} }
static int HARDIRQ_verbose(struct lock_class *class) static int HARDIRQ_verbose(struct lock_class *class)
...@@ -3235,8 +3238,8 @@ static int __lock_acquire(struct lockdep_map *lock, unsigned int subclass, ...@@ -3235,8 +3238,8 @@ static int __lock_acquire(struct lockdep_map *lock, unsigned int subclass,
if (very_verbose(class)) { if (very_verbose(class)) {
printk("\nacquire class [%p] %s", class->key, class->name); printk("\nacquire class [%p] %s", class->key, class->name);
if (class->name_version > 1) if (class->name_version > 1)
printk("#%d", class->name_version); printk(KERN_CONT "#%d", class->name_version);
printk("\n"); printk(KERN_CONT "\n");
dump_stack(); dump_stack();
} }
...@@ -3378,7 +3381,7 @@ print_unlock_imbalance_bug(struct task_struct *curr, struct lockdep_map *lock, ...@@ -3378,7 +3381,7 @@ print_unlock_imbalance_bug(struct task_struct *curr, struct lockdep_map *lock,
printk("%s/%d is trying to release lock (", printk("%s/%d is trying to release lock (",
curr->comm, task_pid_nr(curr)); curr->comm, task_pid_nr(curr));
print_lockdep_cache(lock); print_lockdep_cache(lock);
printk(") at:\n"); printk(KERN_CONT ") at:\n");
print_ip_sym(ip); print_ip_sym(ip);
printk("but there are no more locks to release!\n"); printk("but there are no more locks to release!\n");
printk("\nother info that might help us debug this:\n"); printk("\nother info that might help us debug this:\n");
...@@ -3871,7 +3874,7 @@ print_lock_contention_bug(struct task_struct *curr, struct lockdep_map *lock, ...@@ -3871,7 +3874,7 @@ print_lock_contention_bug(struct task_struct *curr, struct lockdep_map *lock,
printk("%s/%d is trying to contend lock (", printk("%s/%d is trying to contend lock (",
curr->comm, task_pid_nr(curr)); curr->comm, task_pid_nr(curr));
print_lockdep_cache(lock); print_lockdep_cache(lock);
printk(") at:\n"); printk(KERN_CONT ") at:\n");
print_ip_sym(ip); print_ip_sym(ip);
printk("but there are no locks held!\n"); printk("but there are no locks held!\n");
printk("\nother info that might help us debug this:\n"); printk("\nother info that might help us debug this:\n");
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment