2017-03-16 05:57:44

by Andrei Vagin

Subject: linux-next: tty: BUG: spinlock bad magic on CPU#0, init/1

Hello,

We run CRIU tests for linux-next and here is a new bug in the kernel log

[ 2.431229] Freeing unused kernel memory: 1356K
[ 2.436371] Freeing unused kernel memory: 168K
[ 2.522236] BUG: spinlock bad magic on CPU#0, init/1
[ 2.527487] lock: 0xffff94915477fd88, .magic: 00000000, .owner:
<none>/-1, .owner_cpu: -1
[ 2.537257] CPU: 0 PID: 1 Comm: init Not tainted 4.11.0-rc1-next-20170310 #1
[ 2.541136] Hardware name: Google Google Compute Engine/Google
Compute Engine, BIOS Google 01/01/2011
[ 2.541136] Call Trace:
[ 2.541136] dump_stack+0x85/0xc9
[ 2.541136] spin_bug+0xa6/0xad
[ 2.541136] do_raw_spin_lock+0x66/0xa0
[ 2.541136] _raw_spin_lock+0x40/0x50
[ 2.541136] ? check_tty_count+0x27/0xe0
[ 2.541136] check_tty_count+0x27/0xe0
[ 2.541136] tty_release+0x64/0x620
[ 2.541136] __fput+0xfa/0x230
[ 2.541136] ____fput+0xe/0x10
[ 2.541136] task_work_run+0x83/0xc0
[ 2.541136] exit_to_usermode_loop+0x64/0x9a
[ 2.541136] syscall_return_slowpath+0xa9/0xe0
[ 2.541136] entry_SYSCALL_64_fastpath+0xc0/0xc2
[ 2.541136] RIP: 0033:0x7fb953f58e10
[ 2.541136] RSP: 002b:00007fff3d276ba8 EFLAGS: 00000246 ORIG_RAX:
0000000000000003
[ 2.541136] RAX: 0000000000000000 RBX: 00005610f1867710 RCX: 00007fb953f58e10
[ 2.541136] RDX: fffffffffffffe80 RSI: 0000000000000001 RDI: 0000000000000002
[ 2.541136] RBP: 0000000000000000 R08: 00005610f165786e R09: 00005610f21bef90
[ 2.541136] R10: 000000000000000a R11: 0000000000000246 R12: 0000000000000001
[ 2.541136] R13: 00005610f1867674 R14: 00005610f1867678 R15: 0000000000000001
[ 2.748104] tsc: Refined TSC clocksource calibration: 2299.999 MHz

All logs are here:
https://s3.amazonaws.com/archive.travis-ci.org/jobs/211615735/log.txt

Thanks,
Andrei

2017-03-31 13:21:40

by Greg Kroah-Hartman

Subject: Re: linux-next: tty: BUG: spinlock bad magic on CPU#0, init/1

On Wed, Mar 15, 2017 at 10:57:14PM -0700, Andrei Vagin wrote:
> Hello,
>
> We run CRIU tests for linux-next and here is a new bug in the kernel log
>
> [ 2.431229] Freeing unused kernel memory: 1356K
> [ 2.436371] Freeing unused kernel memory: 168K
> [ 2.522236] BUG: spinlock bad magic on CPU#0, init/1
> [ 2.527487] lock: 0xffff94915477fd88, .magic: 00000000, .owner:
> <none>/-1, .owner_cpu: -1
> [ 2.537257] CPU: 0 PID: 1 Comm: init Not tainted 4.11.0-rc1-next-20170310 #1
> [ 2.541136] Hardware name: Google Google Compute Engine/Google
> Compute Engine, BIOS Google 01/01/2011
> [ 2.541136] Call Trace:
> [ 2.541136] dump_stack+0x85/0xc9
> [ 2.541136] spin_bug+0xa6/0xad
> [ 2.541136] do_raw_spin_lock+0x66/0xa0
> [ 2.541136] _raw_spin_lock+0x40/0x50
> [ 2.541136] ? check_tty_count+0x27/0xe0
> [ 2.541136] check_tty_count+0x27/0xe0
> [ 2.541136] tty_release+0x64/0x620
> [ 2.541136] __fput+0xfa/0x230
> [ 2.541136] ____fput+0xe/0x10
> [ 2.541136] task_work_run+0x83/0xc0
> [ 2.541136] exit_to_usermode_loop+0x64/0x9a
> [ 2.541136] syscall_return_slowpath+0xa9/0xe0
> [ 2.541136] entry_SYSCALL_64_fastpath+0xc0/0xc2
> [ 2.541136] RIP: 0033:0x7fb953f58e10
> [ 2.541136] RSP: 002b:00007fff3d276ba8 EFLAGS: 00000246 ORIG_RAX:
> 0000000000000003
> [ 2.541136] RAX: 0000000000000000 RBX: 00005610f1867710 RCX: 00007fb953f58e10
> [ 2.541136] RDX: fffffffffffffe80 RSI: 0000000000000001 RDI: 0000000000000002
> [ 2.541136] RBP: 0000000000000000 R08: 00005610f165786e R09: 00005610f21bef90
> [ 2.541136] R10: 000000000000000a R11: 0000000000000246 R12: 0000000000000001
> [ 2.541136] R13: 00005610f1867674 R14: 00005610f1867678 R15: 0000000000000001
> [ 2.748104] tsc: Refined TSC clocksource calibration: 2299.999 MHz
>
> All logs are here:
> https://s3.amazonaws.com/archive.travis-ci.org/jobs/211615735/log.txt

Any chance to narrow this down to a commit with 'git bisect'?

thanks,

greg k-h

2017-04-01 06:34:22

by Andrei Vagin

Subject: Re: linux-next: tty: BUG: spinlock bad magic on CPU#0, init/1

On Fri, Mar 31, 2017 at 03:19:48PM +0200, Greg Kroah-Hartman wrote:
> On Wed, Mar 15, 2017 at 10:57:14PM -0700, Andrei Vagin wrote:
> > Hello,
> >
> > We run CRIU tests for linux-next and here is a new bug in the kernel log
> >
> > [ 2.431229] Freeing unused kernel memory: 1356K
> > [ 2.436371] Freeing unused kernel memory: 168K
> > [ 2.522236] BUG: spinlock bad magic on CPU#0, init/1
> > [ 2.527487] lock: 0xffff94915477fd88, .magic: 00000000, .owner:
> > <none>/-1, .owner_cpu: -1
> > [ 2.537257] CPU: 0 PID: 1 Comm: init Not tainted 4.11.0-rc1-next-20170310 #1
> > [ 2.541136] Hardware name: Google Google Compute Engine/Google
> > Compute Engine, BIOS Google 01/01/2011
> > [ 2.541136] Call Trace:
> > [ 2.541136] dump_stack+0x85/0xc9
> > [ 2.541136] spin_bug+0xa6/0xad
> > [ 2.541136] do_raw_spin_lock+0x66/0xa0
> > [ 2.541136] _raw_spin_lock+0x40/0x50
> > [ 2.541136] ? check_tty_count+0x27/0xe0
> > [ 2.541136] check_tty_count+0x27/0xe0
> > [ 2.541136] tty_release+0x64/0x620
> > [ 2.541136] __fput+0xfa/0x230
> > [ 2.541136] ____fput+0xe/0x10
> > [ 2.541136] task_work_run+0x83/0xc0
> > [ 2.541136] exit_to_usermode_loop+0x64/0x9a
> > [ 2.541136] syscall_return_slowpath+0xa9/0xe0
> > [ 2.541136] entry_SYSCALL_64_fastpath+0xc0/0xc2
> > [ 2.541136] RIP: 0033:0x7fb953f58e10
> > [ 2.541136] RSP: 002b:00007fff3d276ba8 EFLAGS: 00000246 ORIG_RAX:
> > 0000000000000003
> > [ 2.541136] RAX: 0000000000000000 RBX: 00005610f1867710 RCX: 00007fb953f58e10
> > [ 2.541136] RDX: fffffffffffffe80 RSI: 0000000000000001 RDI: 0000000000000002
> > [ 2.541136] RBP: 0000000000000000 R08: 00005610f165786e R09: 00005610f21bef90
> > [ 2.541136] R10: 000000000000000a R11: 0000000000000246 R12: 0000000000000001
> > [ 2.541136] R13: 00005610f1867674 R14: 00005610f1867678 R15: 0000000000000001
> > [ 2.748104] tsc: Refined TSC clocksource calibration: 2299.999 MHz
> >
> > All logs are here:
> > https://s3.amazonaws.com/archive.travis-ci.org/jobs/211615735/log.txt
>
> Any chance to narrow this down to a commit with 'git bisect'?

We run CRIU tests once a day and have seen this issue only once. I don't
have a reproducer for this issue.

Thanks,
Andrei

>
> thanks,
>
> greg k-h