Re: [PATCH v2 tip/core/rcu 02/11] lockdep: Use "WARNING" tag on lockdep splats

["Paul E. McKenney" <paulmck@linux.vnet.ibm.com>]

On Wed, Apr 19, 2017 at 08:00:22AM -0700, Josh Triplett wrote:
> On Mon, Apr 17, 2017 at 04:28:49PM -0700, Paul E. McKenney wrote:
> > This commit changes lockdep splats to begin lines with "WARNING" and
> > to use pr_warn() instead of printk().  This change eases scripted
> > analysis of kernel console output.
> > 
> > Reported-by: Dmitry Vyukov <dvyukov@google.com>
> > Reported-by: Ingo Molnar <mingo@kernel.org>
> > Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> > Acked-by: Dmitry Vyukov <dvyukov@google.com>
> 
> Reviewed-by: Josh Triplett <josh@joshtriplett.org>

Thank you!

> Any reason not to change the adjacent calls to printk (without a
> priority) to pr_warn?

There was some discussion of changing them all throughout the file,
not sure where we left that.

							Thanx, Paul

> >  kernel/locking/lockdep.c       | 86 +++++++++++++++++++++---------------------
> >  kernel/locking/rtmutex-debug.c |  9 +++--
> >  2 files changed, 48 insertions(+), 47 deletions(-)
> > 
> > diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
> > index a95e5d1f4a9c..e9d4f85b290c 100644
> > --- a/kernel/locking/lockdep.c
> > +++ b/kernel/locking/lockdep.c
> > @@ -1144,10 +1144,10 @@ print_circular_bug_header(struct lock_list *entry, unsigned int depth,
> >  		return 0;
> >  
> >  	printk("\n");
> > -	printk("======================================================\n");
> > -	printk("[ INFO: possible circular locking dependency detected ]\n");
> > +	pr_warn("======================================================\n");
> > +	pr_warn("WARNING: possible circular locking dependency detected\n");
> >  	print_kernel_ident();
> > -	printk("-------------------------------------------------------\n");
> > +	pr_warn("------------------------------------------------------\n");
> >  	printk("%s/%d is trying to acquire lock:\n",
> >  		curr->comm, task_pid_nr(curr));
> >  	print_lock(check_src);
> > @@ -1482,11 +1482,11 @@ print_bad_irq_dependency(struct task_struct *curr,
> >  		return 0;
> >  
> >  	printk("\n");
> > -	printk("======================================================\n");
> > -	printk("[ INFO: %s-safe -> %s-unsafe lock order detected ]\n",
> > +	pr_warn("=====================================================\n");
> > +	pr_warn("WARNING: %s-safe -> %s-unsafe lock order detected\n",
> >  		irqclass, irqclass);
> >  	print_kernel_ident();
> > -	printk("------------------------------------------------------\n");
> > +	pr_warn("-----------------------------------------------------\n");
> >  	printk("%s/%d [HC%u[%lu]:SC%u[%lu]:HE%u:SE%u] is trying to acquire:\n",
> >  		curr->comm, task_pid_nr(curr),
> >  		curr->hardirq_context, hardirq_count() >> HARDIRQ_SHIFT,
> > @@ -1711,10 +1711,10 @@ print_deadlock_bug(struct task_struct *curr, struct held_lock *prev,
> >  		return 0;
> >  
> >  	printk("\n");
> > -	printk("=============================================\n");
> > -	printk("[ INFO: possible recursive locking detected ]\n");
> > +	pr_warn("============================================\n");
> > +	pr_warn("WARNING: possible recursive locking detected\n");
> >  	print_kernel_ident();
> > -	printk("---------------------------------------------\n");
> > +	pr_warn("--------------------------------------------\n");
> >  	printk("%s/%d is trying to acquire lock:\n",
> >  		curr->comm, task_pid_nr(curr));
> >  	print_lock(next);
> > @@ -2061,10 +2061,10 @@ static void print_collision(struct task_struct *curr,
> >  			struct lock_chain *chain)
> >  {
> >  	printk("\n");
> > -	printk("======================\n");
> > -	printk("[chain_key collision ]\n");
> > +	pr_warn("============================\n");
> > +	pr_warn("WARNING: chain_key collision\n");
> >  	print_kernel_ident();
> > -	printk("----------------------\n");
> > +	pr_warn("----------------------------\n");
> >  	printk("%s/%d: ", current->comm, task_pid_nr(current));
> >  	printk("Hash chain already cached but the contents don't match!\n");
> >  
> > @@ -2360,10 +2360,10 @@ print_usage_bug(struct task_struct *curr, struct held_lock *this,
> >  		return 0;
> >  
> >  	printk("\n");
> > -	printk("=================================\n");
> > -	printk("[ INFO: inconsistent lock state ]\n");
> > +	pr_warn("================================\n");
> > +	pr_warn("WARNING: inconsistent lock state\n");
> >  	print_kernel_ident();
> > -	printk("---------------------------------\n");
> > +	pr_warn("--------------------------------\n");
> >  
> >  	printk("inconsistent {%s} -> {%s} usage.\n",
> >  		usage_str[prev_bit], usage_str[new_bit]);
> > @@ -2425,10 +2425,10 @@ print_irq_inversion_bug(struct task_struct *curr,
> >  		return 0;
> >  
> >  	printk("\n");
> > -	printk("=========================================================\n");
> > -	printk("[ INFO: possible irq lock inversion dependency detected ]\n");
> > +	pr_warn("========================================================\n");
> > +	pr_warn("WARNING: possible irq lock inversion dependency detected\n");
> >  	print_kernel_ident();
> > -	printk("---------------------------------------------------------\n");
> > +	pr_warn("--------------------------------------------------------\n");
> >  	printk("%s/%d just changed the state of lock:\n",
> >  		curr->comm, task_pid_nr(curr));
> >  	print_lock(this);
> > @@ -3170,10 +3170,10 @@ print_lock_nested_lock_not_held(struct task_struct *curr,
> >  		return 0;
> >  
> >  	printk("\n");
> > -	printk("==================================\n");
> > -	printk("[ BUG: Nested lock was not taken ]\n");
> > +	pr_warn("==================================\n");
> > +	pr_warn("WARNING: Nested lock was not taken\n");
> >  	print_kernel_ident();
> > -	printk("----------------------------------\n");
> > +	pr_warn("----------------------------------\n");
> >  
> >  	printk("%s/%d is trying to lock:\n", curr->comm, task_pid_nr(curr));
> >  	print_lock(hlock);
> > @@ -3383,10 +3383,10 @@ print_unlock_imbalance_bug(struct task_struct *curr, struct lockdep_map *lock,
> >  		return 0;
> >  
> >  	printk("\n");
> > -	printk("=====================================\n");
> > -	printk("[ BUG: bad unlock balance detected! ]\n");
> > +	pr_warn("=====================================\n");
> > +	pr_warn("WARNING: bad unlock balance detected!\n");
> >  	print_kernel_ident();
> > -	printk("-------------------------------------\n");
> > +	pr_warn("-------------------------------------\n");
> >  	printk("%s/%d is trying to release lock (",
> >  		curr->comm, task_pid_nr(curr));
> >  	print_lockdep_cache(lock);
> > @@ -3880,10 +3880,10 @@ print_lock_contention_bug(struct task_struct *curr, struct lockdep_map *lock,
> >  		return 0;
> >  
> >  	printk("\n");
> > -	printk("=================================\n");
> > -	printk("[ BUG: bad contention detected! ]\n");
> > +	pr_warn("=================================\n");
> > +	pr_warn("WARNING: bad contention detected!\n");
> >  	print_kernel_ident();
> > -	printk("---------------------------------\n");
> > +	pr_warn("---------------------------------\n");
> >  	printk("%s/%d is trying to contend lock (",
> >  		curr->comm, task_pid_nr(curr));
> >  	print_lockdep_cache(lock);
> > @@ -4244,10 +4244,10 @@ print_freed_lock_bug(struct task_struct *curr, const void *mem_from,
> >  		return;
> >  
> >  	printk("\n");
> > -	printk("=========================\n");
> > -	printk("[ BUG: held lock freed! ]\n");
> > +	pr_warn("=========================\n");
> > +	pr_warn("WARNING: held lock freed!\n");
> >  	print_kernel_ident();
> > -	printk("-------------------------\n");
> > +	pr_warn("-------------------------\n");
> >  	printk("%s/%d is freeing memory %p-%p, with a lock still held there!\n",
> >  		curr->comm, task_pid_nr(curr), mem_from, mem_to-1);
> >  	print_lock(hlock);
> > @@ -4302,11 +4302,11 @@ static void print_held_locks_bug(void)
> >  		return;
> >  
> >  	printk("\n");
> > -	printk("=====================================\n");
> > -	printk("[ BUG: %s/%d still has locks held! ]\n",
> > +	pr_warn("====================================\n");
> > +	pr_warn("WARNING: %s/%d still has locks held!\n",
> >  	       current->comm, task_pid_nr(current));
> >  	print_kernel_ident();
> > -	printk("-------------------------------------\n");
> > +	pr_warn("------------------------------------\n");
> >  	lockdep_print_held_locks(current);
> >  	printk("\nstack backtrace:\n");
> >  	dump_stack();
> > @@ -4371,7 +4371,7 @@ void debug_show_all_locks(void)
> >  	} while_each_thread(g, p);
> >  
> >  	printk("\n");
> > -	printk("=============================================\n\n");
> > +	pr_warn("=============================================\n\n");
> >  
> >  	if (unlock)
> >  		read_unlock(&tasklist_lock);
> > @@ -4401,10 +4401,10 @@ asmlinkage __visible void lockdep_sys_exit(void)
> >  		if (!debug_locks_off())
> >  			return;
> >  		printk("\n");
> > -		printk("================================================\n");
> > -		printk("[ BUG: lock held when returning to user space! ]\n");
> > +		pr_warn("================================================\n");
> > +		pr_warn("WARNING: lock held when returning to user space!\n");
> >  		print_kernel_ident();
> > -		printk("------------------------------------------------\n");
> > +		pr_warn("------------------------------------------------\n");
> >  		printk("%s/%d is leaving the kernel with locks still held!\n",
> >  				curr->comm, curr->pid);
> >  		lockdep_print_held_locks(curr);
> > @@ -4421,13 +4421,13 @@ void lockdep_rcu_suspicious(const char *file, const int line, const char *s)
> >  #endif /* #ifdef CONFIG_PROVE_RCU_REPEATEDLY */
> >  	/* Note: the following can be executed concurrently, so be careful. */
> >  	printk("\n");
> > -	pr_err("===============================\n");
> > -	pr_err("[ ERR: suspicious RCU usage.  ]\n");
> > +	pr_warn("=============================\n");
> > +	pr_warn("WARNING: suspicious RCU usage\n");
> >  	print_kernel_ident();
> > -	pr_err("-------------------------------\n");
> > -	pr_err("%s:%d %s!\n", file, line, s);
> > -	pr_err("\nother info that might help us debug this:\n\n");
> > -	pr_err("\n%srcu_scheduler_active = %d, debug_locks = %d\n",
> > +	pr_warn("-----------------------------\n");
> > +	printk("%s:%d %s!\n", file, line, s);
> > +	printk("\nother info that might help us debug this:\n\n");
> > +	printk("\n%srcu_scheduler_active = %d, debug_locks = %d\n",
> >  	       !rcu_lockdep_current_cpu_online()
> >  			? "RCU used illegally from offline CPU!\n"
> >  			: !rcu_is_watching()
> > diff --git a/kernel/locking/rtmutex-debug.c b/kernel/locking/rtmutex-debug.c
> > index 97ee9df32e0f..db4f55211b04 100644
> > --- a/kernel/locking/rtmutex-debug.c
> > +++ b/kernel/locking/rtmutex-debug.c
> > @@ -102,10 +102,11 @@ void debug_rt_mutex_print_deadlock(struct rt_mutex_waiter *waiter)
> >  		return;
> >  	}
> >  
> > -	printk("\n============================================\n");
> > -	printk(  "[ BUG: circular locking deadlock detected! ]\n");
> > -	printk("%s\n", print_tainted());
> > -	printk(  "--------------------------------------------\n");
> > +	pr_warn("\n");
> > +	pr_warn("============================================\n");
> > +	pr_warn("WARNING: circular locking deadlock detected!\n");
> > +	pr_warn("%s\n", print_tainted());
> > +	pr_warn("--------------------------------------------\n");
> >  	printk("%s/%d is deadlocking current task %s/%d\n\n",
> >  	       task->comm, task_pid_nr(task),
> >  	       current->comm, task_pid_nr(current));
> > -- 
> > 2.5.2
> > 
>