Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2)

[Eric Biggers <ebiggers@kernel.org>]

On Wed, Jul 10, 2019 at 07:19:55AM -0700, Bart Van Assche wrote:
> On 7/9/19 10:30 PM, Eric Biggers wrote:
> > [Moved most people to Bcc; syzbot added way too many random people to this.]
> > 
> > Hi Bart,
> > 
> > On Sat, Mar 30, 2019 at 07:17:09PM -0700, Bart Van Assche wrote:
> > > On 3/30/19 2:58 PM, syzbot wrote:
> > > > syzbot has bisected this bug to:
> > > > 
> > > > commit 669de8bda87b92ab9a2fc663b3f5743c2ad1ae9f
> > > > Author: Bart Van Assche <bvanassche@acm.org>
> > > > Date:   Thu Feb 14 23:00:54 2019 +0000
> > > > 
> > > >       kernel/workqueue: Use dynamic lockdep keys for workqueues
> > > > 
> > > > bisection log:  https://syzkaller.appspot.com/x/bisect.txt?x=17f1bacd200000
> > > > start commit:   0e40da3e Merge tag 'kbuild-fixes-v5.1' of
> > > > git://git.kernel..
> > > > git tree:       upstream
> > > > final crash:    https://syzkaller.appspot.com/x/report.txt?x=1409bacd200000
> > > > console output: https://syzkaller.appspot.com/x/log.txt?x=1009bacd200000
> > > > kernel config:  https://syzkaller.appspot.com/x/.config?x=8dcdce25ea72bedf
> > > > dashboard link:
> > > > https://syzkaller.appspot.com/bug?extid=6f39a9deb697359fe520
> > > > syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=10e1bacd200000
> > > > C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=1120fe0f200000
> > > > 
> > > > Reported-by: syzbot+6f39a9deb697359fe520@syzkaller.appspotmail.com
> > > > Fixes: 669de8bda87b ("kernel/workqueue: Use dynamic lockdep keys for
> > > > workqueues")
> > > > 
> > > > For information about bisection process see:
> > > > https://goo.gl/tpsmEJ#bisection
> > > 
> > > Hi Dmitry,
> > > 
> > > This bisection result doesn't make sense to me. As one can see, the message
> > > "BUG: MAX_STACK_TRACE_ENTRIES too low!" does not occur in the console output
> > > the above console output URL points at.
> > > 
> > > Bart.
> > 
> > This is still happening on mainline, and I think this bisection result is
> > probably correct.  syzbot did start hitting something different at the very end
> > of the bisection ("WARNING: CPU: 0 PID: 9153 at kernel/locking/lockdep.c:747")
> > but that seems to be just because your commit had a lot of bugs in it, which had
> > to be fixed by later commits.  In particular, the WARNING seems to have been
> > fixed by commit 28d49e282665e ("locking/lockdep: Shrink struct lock_class_key").
> > 
> > What seems to still be happening is that the dynamic lockdep keys which you
> > added make it possible for an unbounded number of entries to be added to the
> > fixed length stack_trace[] array in kernel/locking/lockdep.c.  Hence the "BUG:
> > MAX_STACK_TRACE_ENTRIES too low!".
> > 
> > Am I understanding it correctly?  How did you intend this to work?
> 
> The last two paragraphs do not make sense to me. My changes do not increase
> the number of stack traces that get recorded by the lockdep code.
> 
> Bart.
> 

Interesting.  How do we explain that repeatedly allocating and freeing a
workqueue is causing the number of lockdep stack trace entries to grow without
bound, though?

This can be reproduced with the following (which I simplified from the C
reproducer that syzbot generated and used for its bisection):

	#include <fcntl.h>
	#include <unistd.h>

	int main()
	{
		for (;;) {
			int fd = open("/dev/infiniband/rdma_cm", O_RDWR);

			close(fd);
		}
	}

The workqueue is allocated in ucma_open() and freed in ucma_close().  If I run
'grep stack-trace /proc/lockdep_stats' while reproducer is running, I can see
the number is growing continuously until it hits the limit.

There is also a reproducer using io_uring instead of rdma_cm
(https://syzkaller.appspot.com/text?tag=ReproC&x=16483bf8600000).
In both cases the workqueue is associated with a file descriptor; the workqueue
is allocated and freed as the file descriptor is opened and closed.

Anyone have any ideas?

- Eric