fs/coda oops bisected to (925b9cd1b8) "locking/rwsem: Make owner store task pointer of last owning reader"

fs/coda oops bisected to (925b9cd1b8) "locking/rwsem: Make owner store task pointer of last owning reader"

[Jan Harkes]

I was testing Coda on the 5.1-rc2 kernel and noticed that when I run a
binary out of /coda, the binary would never exit and the system would
detect a soft lockup. I narrowed it down to a very simple reproducible
case of running a statically linked executable (busybox) from /coda with
the cwd outside of Coda, so the only Coda file reference is from the
executable itself.

I knew I definitely had never seen this problem with the stable kernel
on Ubuntu xenial (4.4) so I bisected between v4.4 and v5.1-rc2 and ended
up at

    # first bad commit: [925b9cd1b89a94b7124d128c80dfc48f78a63098]
    # locking/rwsem: Make owner store task pointer of last owning reader

When I revert this particular commit on 5.1-rc2, I am not able to
reproduce the problem anymore.

The puzzling thing to me is that a lot of that particular patch touches
codepaths that are not even enabled in the kernels that I run, because I
do not have CONFIG_RWSEM_DEBUG enabled.

    $ grep RWSEM .config
    CONFIG_RWSEM_XCHGADD_ALGORITHM=y
    CONFIG_RWSEM_SPIN_ON_OWNER=y
    # CONFIG_DEBUG_RWSEMS is not set

And this patch is for rwsem, while my soft lockup is on a spinlock.
So either I have a race in fs/coda that got somehow uncovered by this
patch, or something else is going on here but I have not been able to
figure it out.

Jan



Here is the Oops that reliably triggers on any kernel after 925b9cd1b8
when I execute a binary from /coda. It repeats a second time 28 seconds
later and another 5 seconds later is followed by "rcu_sched
self-detected stall on CPU" which I include as well.


[   64.145934] watchdog: BUG: soft lockup - CPU#4 stuck for 22s! [busybox:1814]
[   64.145938] Modules linked in: snd_hda_codec_generic snd_hda_intel snd_hda_codec snd_hda_core snd_pcm kvm_intel kvm irqbypass crct10dif_pclmul snd_hwdep crc32_pclmul ghash_clmulni_intel snd_seq snd_timer aesni_intel joydev snd_seq_device aes_x86_64 crypto_simd cryptd glue_helper snd input_leds soundcore serio_raw i2c_piix4 mac_hid parport_pc ppdev lp parport coda hid_generic usbhid hid qxl drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm drm psmouse pata_acpi floppy
[   64.145958] CPU: 4 PID: 1814 Comm: busybox Not tainted 4.19.0-rc3+ #18
[   64.145959] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[   64.145964] RIP: 0010:native_queued_spin_lock_slowpath+0x21/0x1c0
[   64.145965] Code: 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 0f 1f 44 00 00 ba 01 00 00 00 8b 07 85 c0 75 0a f0 0f b1 17 85 c0 75 f2 f3 c3 f3 90 <eb> ec 81 fe 00 01 00 00 0f 84 25 01 00 00 81 e6 00 ff ff ff 75 44
[   64.145966] RSP: 0018:ffffbab781dabdf0 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
[   64.145967] RAX: 00000000ffff9491 RBX: ffff949179f30c00 RCX: 0000000000000000
[   64.145967] RDX: 0000000000000001 RSI: 00000000ffff9491 RDI: ffff9490777dca04
[   64.145968] RBP: ffff9490777dca08 R08: 0000000000025f80 R09: ffffffffc01db0ed
[   64.145968] R10: ffffbab781dabe30 R11: 0000000000000001 R12: ffff949176c2a220
[   64.145969] R13: ffff9490777dca04 R14: ffff94917950edc8 R15: ffff9490777dca08
[   64.145970] FS:  0000000001957880(0000) GS:ffff94917bb00000(0000) knlGS:0000000000000000
[   64.145970] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   64.145971] CR2: 0000000000415c20 CR3: 000000007720a001 CR4: 0000000000160ee0
[   64.145974] Call Trace:
[   64.145979]  _raw_spin_lock+0x1d/0x20
[   64.145982]  coda_release+0x66/0xd0 [coda]
[   64.145986]  __fput+0xe2/0x210
[   64.145989]  task_work_run+0x86/0xa0
[   64.145990]  do_exit+0x2d7/0xb30
[   64.145994]  ? handle_mm_fault+0xfa/0x200
[   64.145995]  do_group_exit+0x3a/0xa0
[   64.145996]  __x64_sys_exit_group+0x14/0x20
[   64.145998]  do_syscall_64+0x55/0x100
[   64.145999]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   64.146001] RIP: 0033:0x453988
[   64.146005] Code: Bad RIP value.
[   64.146005] RSP: 002b:00007ffcd39246a8 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
[   64.146006] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 0000000000453988
[   64.146007] RDX: 0000000000000000 RSI: 000000000000003c RDI: 0000000000000000
[   64.146007] RBP: 00000000005a79b0 R08: 00000000000000e7 R09: ffffffffffffffe0
[   64.146008] R10: 0000000000000022 R11: 0000000000000246 R12: 0000000000000001
[   64.146008] R13: 00000000007c1640 R14: 00000000005a0fc1 R15: 0000000000000000
...
[   97.001204] rcu: INFO: rcu_sched self-detected stall on CPU
[   97.001211] rcu: 	4-....: (14997 ticks this GP) idle=916/1/0x4000000000000002 softirq=2901/2901 fqs=6623 
[   97.001211] rcu: 	 (t=15000 jiffies g=3281 q=10605)
[   97.001213] NMI backtrace for cpu 4
[   97.001215] CPU: 4 PID: 1814 Comm: busybox Tainted: G             L    4.19.0-rc3+ #18
[   97.001216] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[   97.001216] Call Trace:
[   97.001219]  <IRQ>
[   97.001223]  dump_stack+0x5c/0x7b
[   97.001236]  nmi_cpu_backtrace+0x8a/0x90
[   97.001239]  ? lapic_can_unplug_cpu+0xa0/0xa0
[   97.001240]  nmi_trigger_cpumask_backtrace+0xfb/0x130
[   97.001242]  rcu_dump_cpu_stacks+0x89/0xb9
[   97.001244]  rcu_check_callbacks+0x60f/0x770
[   97.001255]  ? tick_sched_do_timer+0x60/0x60
[   97.001257]  update_process_times+0x28/0x50
[   97.001258]  tick_sched_handle+0x22/0x60
[   97.001259]  tick_sched_timer+0x37/0x70
[   97.001261]  __hrtimer_run_queues+0xfc/0x270
[   97.001262]  hrtimer_interrupt+0x122/0x270
[   97.001264]  smp_apic_timer_interrupt+0x6a/0x140
[   97.001265]  apic_timer_interrupt+0xf/0x20
[   97.001266]  </IRQ>
[   97.001269] RIP: 0010:native_queued_spin_lock_slowpath+0x21/0x1c0
[   97.001270] Code: 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 0f 1f 44 00 00 ba 01 00 00 00 8b 07 85 c0 75 0a f0 0f b1 17 85 c0 75 f2 f3 c3 f3 90 <eb> ec 81 fe 00 01 00 00 0f 84 25 01 00 00 81 e6 00 ff ff ff 75 44
[   97.001270] RSP: 0018:ffffbab781dabdf0 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
[   97.001271] RAX: 00000000ffff9491 RBX: ffff949179f30c00 RCX: 0000000000000000
[   97.001272] RDX: 0000000000000001 RSI: 00000000ffff9491 RDI: ffff9490777dca04
[   97.001272] RBP: ffff9490777dca08 R08: 0000000000025f80 R09: ffffffffc01db0ed
[   97.001273] R10: ffffbab781dabe30 R11: 0000000000000001 R12: ffff949176c2a220
[   97.001273] R13: ffff9490777dca04 R14: ffff94917950edc8 R15: ffff9490777dca08
[   97.001277]  ? venus_close+0x9d/0xd0 [coda]
[   97.001280]  _raw_spin_lock+0x1d/0x20
[   97.001281]  coda_release+0x66/0xd0 [coda]
[   97.001285]  __fput+0xe2/0x210
[   97.001287]  task_work_run+0x86/0xa0
[   97.001289]  do_exit+0x2d7/0xb30
[   97.001292]  ? handle_mm_fault+0xfa/0x200
[   97.001293]  do_group_exit+0x3a/0xa0
[   97.001294]  __x64_sys_exit_group+0x14/0x20
[   97.001296]  do_syscall_64+0x55/0x100
[   97.001298]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   97.001299] RIP: 0033:0x453988
[   97.001302] Code: Bad RIP value.
[   97.001302] RSP: 002b:00007ffcd39246a8 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
[   97.001303] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 0000000000453988
[   97.001304] RDX: 0000000000000000 RSI: 000000000000003c RDI: 0000000000000000
[   97.001304] RBP: 00000000005a79b0 R08: 00000000000000e7 R09: ffffffffffffffe0
[   97.001305] R10: 0000000000000022 R11: 0000000000000246 R12: 0000000000000001
[   97.001305] R13: 00000000007c1640 R14: 00000000005a0fc1 R15: 0000000000000000

Re: fs/coda oops bisected to (925b9cd1b8) "locking/rwsem: Make owner store task pointer of last owning reader"

[Waiman Long]

On 03/29/2019 12:10 PM, Jan Harkes wrote:
> I was testing Coda on the 5.1-rc2 kernel and noticed that when I run a
> binary out of /coda, the binary would never exit and the system would
> detect a soft lockup. I narrowed it down to a very simple reproducible
> case of running a statically linked executable (busybox) from /coda with
> the cwd outside of Coda, so the only Coda file reference is from the
> executable itself.
>
> I knew I definitely had never seen this problem with the stable kernel
> on Ubuntu xenial (4.4) so I bisected between v4.4 and v5.1-rc2 and ended
> up at
>
>     # first bad commit: [925b9cd1b89a94b7124d128c80dfc48f78a63098]
>     # locking/rwsem: Make owner store task pointer of last owning reader
>
> When I revert this particular commit on 5.1-rc2, I am not able to
> reproduce the problem anymore.
>
> The puzzling thing to me is that a lot of that particular patch touches
> codepaths that are not even enabled in the kernels that I run, because I
> do not have CONFIG_RWSEM_DEBUG enabled.
>
>     $ grep RWSEM .config
>     CONFIG_RWSEM_XCHGADD_ALGORITHM=y
>     CONFIG_RWSEM_SPIN_ON_OWNER=y
>     # CONFIG_DEBUG_RWSEMS is not set
>
> And this patch is for rwsem, while my soft lockup is on a spinlock.
> So either I have a race in fs/coda that got somehow uncovered by this
> patch, or something else is going on here but I have not been able to
> figure it out.
>
> Jan

Without CONFIG_DEBUG_RWSEMS, the only behavioral change of this patch is
to do an unconditional write of task_structure pointer into sem->owner
after acquiring the read lock in down_read(). Before this patch, it does
conditional write of 0x1 into sem->owner if it was not 0x1. The only
possible scenario that I can think of that can cause the soft lockup you
see is use-after-free of memory objects.

Cheers,
Longman