Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S933163AbcK1OY4 (ORCPT ); Mon, 28 Nov 2016 09:24:56 -0500 Received: from mail-wj0-f169.google.com ([209.85.210.169]:33553 "EHLO mail-wj0-f169.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S932506AbcK1OYs (ORCPT ); Mon, 28 Nov 2016 09:24:48 -0500 From: Dmitry Vyukov To: peterz@infradead.org, mingo@redhat.com Cc: Dmitry Vyukov , aryabinin@virtuozzo.com, andreyknvl@google.com, joe@perches.com, linux-kernel@vger.kernel.org, syzkaller@googlegroups.com Subject: [PATCH] lockdep: fix report formatting Date: Mon, 28 Nov 2016 15:24:43 +0100 Message-Id: <1480343083-48731-1-git-send-email-dvyukov@google.com> X-Mailer: git-send-email 2.8.0.rc3.226.g39d4020 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 14837 Lines: 438 Since commit 4bcc595ccd80 ("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. Add missing KERN_CONT and inline print_ip_sym() where necessary. Without this patch all scripts that parse kernel bug reports are broken. So it makes sense to get this into 4.9. Cc: aryabinin@virtuozzo.com Cc: andreyknvl@google.com Cc: joe@perches.com Cc: peterz@infradead.org Cc: mingo@redhat.com Cc: linux-kernel@vger.kernel.org Cc: syzkaller@googlegroups.com --- Any better suggestions on how to fix this systematically rather than sprinkle KERN_CONT here and there? Most likely I got it wrong somewhere. Output tests would be nice... Example of a messed report: [ 332.843850] [ INFO: possible circular locking dependency detected ] [ 332.850253] 4.9.0-rc5+ #41 Not tainted [ 332.854153] ------------------------------------------------------- [ 332.860558] syz-executor0/5036 is trying to acquire lock: [ 332.860565] ( [ 332.860568] rtnl_mutex [ 332.860569] ){+.+.+.} [ 332.860586] , at: [ 332.860587] [] rtnl_lock+0x1c/0x20 [ 332.860589] [ 332.860589] but task is already holding lock: [ 332.860593] ( [ 332.860596] &net->packet.sklist_lock [ 332.860598] ){+.+...} [ 332.860610] , at: [ 332.860611] [] packet_diag_dump+0x1a6/0x1920 [ 332.860613] [ 332.860613] which lock already depends on the new lock. [ 332.860613] [ 332.860615] [ 332.860615] the existing dependency chain (in reverse order) is: [ 332.860619] [ 332.860619] -> #3 [ 332.860622] ( [ 332.860624] &net->packet.sklist_lock [ 332.860626] ){+.+...} [ 332.860626] : [ 332.860638] [ 332.860639] [] __lock_acquire+0x2156/0x3380 [ 332.860647] [ 332.860648] [] lock_acquire+0x2a2/0x790 [ 332.860659] [ 332.860660] [] mutex_lock_nested+0x23f/0xf20 [ 332.860670] [ 332.860670] [] packet_diag_dump+0x1a6/0x1920 [ 332.860681] [ 332.860682] [] netlink_dump+0x576/0xd70 [ 332.860691] [ 332.860691] [] __netlink_dump_start+0x4ea/0x760 [ 332.860701] [ 332.860702] [] packet_diag_handler_dump+0x247/0x310 [ 332.860712] [ 332.860713] [] sock_diag_rcv_msg+0x313/0x390 [ 332.860723] [ 332.860723] [] netlink_rcv_skb+0x2b0/0x390 [ 332.860733] [ 332.860733] [] sock_diag_rcv+0x2f/0x40 [ 332.860743] [ 332.860744] [] netlink_unicast+0x514/0x730 [ 332.860754] [ 332.860754] [] netlink_sendmsg+0xaa4/0xe50 [ 332.860765] [ 332.860766] [] sock_sendmsg+0xcf/0x110 [ 332.860776] [ 332.860776] [] sock_write_iter+0x32b/0x620 [ 332.860787] [ 332.860787] [] do_iter_readv_writev+0x363/0x670 [ 332.860797] [ 332.860797] [] do_readv_writev+0x431/0x9b0 [ 332.860806] [ 332.860807] [] vfs_writev+0x8c/0xc0 [ 332.860815] [ 332.860816] [] do_writev+0x115/0x2d0 [ 332.860825] [ 332.860826] [] SyS_writev+0x2c/0x40 [ 332.860837] [ 332.860837] [] entry_SYSCALL_64_fastpath+0x23/0xc6 [ 332.860841] [ 332.860841] -> #2 [ 332.860844] ( [ 332.860846] nlk->cb_mutex [ 332.860848] ){+.+.+.} [ 332.860849] : [ 332.860858] [ 332.860859] [] __lock_acquire+0x2156/0x3380 [ 332.860866] [ 332.860866] [] lock_acquire+0x2a2/0x790 [ 332.860875] [ 332.860875] [] mutex_lock_nested+0x23f/0xf20 [ 332.860884] [ 332.860885] [] __netlink_dump_start+0xf9/0x760 [ 332.860894] [ 332.860895] [] ctnetlink_get_ct_unconfirmed+0x17f/0x220 [ 332.860904] [ 332.860904] [] nfnetlink_rcv_msg+0x9be/0xd60 [ 332.860919] [ 332.860920] [] netlink_rcv_skb+0x2b0/0x390 [ 332.860926] [ 332.860927] [] nfnetlink_rcv+0x7cc/0x10c0 [ 332.860935] [ 332.860935] [] netlink_unicast+0x514/0x730 [ 332.860951] [ 332.860951] [] netlink_sendmsg+0xaa4/0xe50 [ 332.860961] [ 332.860961] [] sock_sendmsg+0xcf/0x110 [ 332.860970] [ 332.860971] [] sock_write_iter+0x32b/0x620 [ 332.860979] [ 332.860980] [] do_iter_readv_writev+0x363/0x670 [ 332.860988] [ 332.860989] [] do_readv_writev+0x431/0x9b0 [ 332.860997] [ 332.860997] [] vfs_writev+0x8c/0xc0 [ 332.861005] [ 332.861006] [] do_writev+0x115/0x2d0 [ 332.861014] [ 332.861014] [] SyS_writev+0x2c/0x40 --- kernel/locking/lockdep.c | 111 ++++++++++++++++++++++++----------------------- 1 file changed, 57 insertions(+), 54 deletions(-) diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c index 589d763..4d7ffc0 100644 --- a/kernel/locking/lockdep.c +++ b/kernel/locking/lockdep.c @@ -506,13 +506,13 @@ static void __print_lock_name(struct lock_class *class) name = class->name; if (!name) { name = __get_key_name(class->key, str); - printk("%s", name); + printk(KERN_CONT "%s", name); } else { - printk("%s", name); + printk(KERN_CONT "%s", name); if (class->name_version > 1) - printk("#%d", class->name_version); + printk(KERN_CONT "#%d", class->name_version); 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) get_usage_chars(class, usage); - printk(" ("); + printk(KERN_CONT " ("); __print_lock_name(class); - printk("){%s}", usage); + printk(KERN_CONT "){%s}", usage); } static void print_lockdep_cache(struct lockdep_map *lock) @@ -536,7 +536,7 @@ static void print_lockdep_cache(struct lockdep_map *lock) if (!name) name = __get_key_name(lock->key->subkeys, str); - printk("%s", name); + printk(KERN_CONT "%s", name); } static void print_lock(struct held_lock *hlock) @@ -551,13 +551,13 @@ static void print_lock(struct held_lock *hlock) barrier(); if (!class_idx || (class_idx - 1) >= MAX_LOCKDEP_KEYS) { - printk("\n"); + printk(KERN_CONT "\n"); return; } print_lock_name(lock_classes + class_idx - 1); - printk(", at: "); - print_ip_sym(hlock->acquire_ip); + printk(KERN_CONT ", at: [<%p>] %pS\n", + (void *)hlock->acquire_ip, (void *)hlock->acquire_ip); } 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) printk("\nnew class %p: %s", class->key, class->name); if (class->name_version > 1) - printk("#%d", class->name_version); - printk("\n"); + printk(KERN_CONT "#%d", class->name_version); + printk(KERN_CONT "\n"); dump_stack(); if (!graph_lock()) { @@ -1071,7 +1071,7 @@ print_circular_bug_entry(struct lock_list *target, int depth) return 0; printk("\n-> #%u", depth); print_lock_name(target->class); - printk(":\n"); + printk(KERN_CONT ":\n"); print_stack_trace(&target->trace, 6); return 0; @@ -1102,11 +1102,11 @@ print_circular_lock_scenario(struct held_lock *src, if (parent != source) { printk("Chain exists of:\n "); __print_lock_name(source); - printk(" --> "); + printk(KERN_CONT " --> "); __print_lock_name(parent); - printk(" --> "); + printk(KERN_CONT " --> "); __print_lock_name(target); - printk("\n\n"); + printk(KERN_CONT "\n\n"); } printk(" Possible unsafe locking scenario:\n\n"); @@ -1114,16 +1114,16 @@ print_circular_lock_scenario(struct held_lock *src, printk(" ---- ----\n"); printk(" lock("); __print_lock_name(target); - printk(");\n"); + printk(KERN_CONT ");\n"); printk(" lock("); __print_lock_name(parent); - printk(");\n"); + printk(KERN_CONT ");\n"); printk(" lock("); __print_lock_name(target); - printk(");\n"); + printk(KERN_CONT ");\n"); printk(" lock("); __print_lock_name(source); - printk(");\n"); + printk(KERN_CONT ");\n"); printk("\n *** DEADLOCK ***\n\n"); } @@ -1359,22 +1359,22 @@ static void print_lock_class_header(struct lock_class *class, int depth) printk("%*s->", depth, ""); print_lock_name(class); - printk(" ops: %lu", class->ops); - printk(" {\n"); + printk(KERN_CONT " ops: %lu", class->ops); + printk(KERN_CONT " {\n"); for (bit = 0; bit < LOCK_USAGE_STATES; bit++) { if (class->usage_mask & (1 << bit)) { int len = depth; 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); } } printk("%*s }\n", depth, ""); - printk("%*s ... key at: ",depth,""); - print_ip_sym((unsigned long)class->key); + printk("%*s ... key at: [<%p>] %pS\n", + depth, "", class->key, class->key); } /* @@ -1437,11 +1437,11 @@ print_irq_lock_scenario(struct lock_list *safe_entry, if (middle_class != unsafe_class) { printk("Chain exists of:\n "); __print_lock_name(safe_class); - printk(" --> "); + printk(KERN_CONT " --> "); __print_lock_name(middle_class); - printk(" --> "); + printk(KERN_CONT " --> "); __print_lock_name(unsafe_class); - printk("\n\n"); + printk(KERN_CONT "\n\n"); } printk(" Possible interrupt unsafe locking scenario:\n\n"); @@ -1449,18 +1449,18 @@ print_irq_lock_scenario(struct lock_list *safe_entry, printk(" ---- ----\n"); printk(" lock("); __print_lock_name(unsafe_class); - printk(");\n"); + printk(KERN_CONT ");\n"); printk(" local_irq_disable();\n"); printk(" lock("); __print_lock_name(safe_class); - printk(");\n"); + printk(KERN_CONT ");\n"); printk(" lock("); __print_lock_name(middle_class); - printk(");\n"); + printk(KERN_CONT ");\n"); printk(" \n"); printk(" lock("); __print_lock_name(safe_class); - printk(");\n"); + printk(KERN_CONT ");\n"); printk("\n *** DEADLOCK ***\n\n"); } @@ -1497,9 +1497,9 @@ print_bad_irq_dependency(struct task_struct *curr, print_lock(prev); printk("which would create a new lock dependency:\n"); print_lock_name(hlock_class(prev)); - printk(" ->"); + printk(KERN_CONT " ->"); print_lock_name(hlock_class(next)); - printk("\n"); + printk(KERN_CONT "\n"); printk("\nbut this new dependency connects a %s-irq-safe lock:\n", irqclass); @@ -1521,8 +1521,7 @@ print_bad_irq_dependency(struct task_struct *curr, lockdep_print_held_locks(curr); - printk("\nthe dependencies between %s-irq-safe lock", irqclass); - printk(" and the holding lock:\n"); + printk("\nthe dependencies between %s-irq-safe lock and the holding lock:\n", irqclass); if (!save_trace(&prev_root->trace)) return 0; print_shortest_lock_dependencies(backwards_entry, prev_root); @@ -1694,10 +1693,10 @@ print_deadlock_scenario(struct held_lock *nxt, printk(" ----\n"); printk(" lock("); __print_lock_name(prev); - printk(");\n"); + printk(KERN_CONT ");\n"); printk(" lock("); __print_lock_name(next); - printk(");\n"); + printk(KERN_CONT ");\n"); printk("\n *** DEADLOCK ***\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, graph_unlock(); printk("\n new dependency: "); print_lock_name(hlock_class(prev)); - printk(" => "); + printk(KERN_CONT " => "); print_lock_name(hlock_class(next)); - printk("\n"); + printk(KERN_CONT "\n"); dump_stack(); return graph_lock(); } @@ -2343,11 +2342,11 @@ print_usage_bug_scenario(struct held_lock *lock) printk(" ----\n"); printk(" lock("); __print_lock_name(class); - printk(");\n"); + printk(KERN_CONT ");\n"); printk(" \n"); printk(" lock("); __print_lock_name(class); - printk(");\n"); + printk(KERN_CONT ");\n"); printk("\n *** DEADLOCK ***\n\n"); } @@ -2522,14 +2521,18 @@ check_usage_backwards(struct task_struct *curr, struct held_lock *this, void print_irqtrace_events(struct task_struct *curr) { printk("irq event stamp: %u\n", curr->irq_events); - printk("hardirqs last enabled at (%u): ", curr->hardirq_enable_event); - print_ip_sym(curr->hardirq_enable_ip); - printk("hardirqs last disabled at (%u): ", curr->hardirq_disable_event); - print_ip_sym(curr->hardirq_disable_ip); - printk("softirqs last enabled at (%u): ", curr->softirq_enable_event); - print_ip_sym(curr->softirq_enable_ip); - printk("softirqs last disabled at (%u): ", curr->softirq_disable_event); - print_ip_sym(curr->softirq_disable_ip); + printk("hardirqs last enabled at (%u): [<%p>] %pS\n", + curr->hardirq_enable_event, (void *)curr->hardirq_enable_ip, + (void *)curr->hardirq_enable_ip); + printk("hardirqs last disabled at (%u): [<%p>] %pS\n", + curr->hardirq_disable_event, (void *)curr->hardirq_disable_ip, + (void *)curr->hardirq_disable_ip); + printk("softirqs last enabled at (%u): [<%p>] %pS\n", + 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) @@ -3235,8 +3238,8 @@ static int __lock_acquire(struct lockdep_map *lock, unsigned int subclass, if (very_verbose(class)) { printk("\nacquire class [%p] %s", class->key, class->name); if (class->name_version > 1) - printk("#%d", class->name_version); - printk("\n"); + printk(KERN_CONT "#%d", class->name_version); + printk(KERN_CONT "\n"); dump_stack(); } @@ -3378,7 +3381,7 @@ print_unlock_imbalance_bug(struct task_struct *curr, struct lockdep_map *lock, printk("%s/%d is trying to release lock (", curr->comm, task_pid_nr(curr)); print_lockdep_cache(lock); - printk(") at:\n"); + printk(KERN_CONT ") at:\n"); print_ip_sym(ip); printk("but there are no more locks to release!\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, printk("%s/%d is trying to contend lock (", curr->comm, task_pid_nr(curr)); print_lockdep_cache(lock); - printk(") at:\n"); + printk(KERN_CONT ") at:\n"); print_ip_sym(ip); printk("but there are no locks held!\n"); printk("\nother info that might help us debug this:\n"); -- 2.8.0.rc3.226.g39d4020