Re: WARNING in tracepoint_probe_unregister

[Dmitry Vyukov]

On Sun, Nov 5, 2017 at 4:47 PM, Jens Axboe <axboe@xxxxxxxxx> wrote:
> On 11/05/2017 01:09 AM, Dmitry Vyukov wrote:
>> On Sun, Nov 5, 2017 at 11:05 AM, syzbot
>> <bot+f00b2fc1cf284703bf4107c0ea565aafd9b536d0@xxxxxxxxxxxxxxxxxxxxxxxxx>
>> wrote:
>>> Hello,
>>>
>>> syzkaller hit the following crash on
>>> 36ef71cae353f88fd6e095e2aaa3e5953af1685d
>>> git://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git/master
>>> compiler: gcc (GCC) 7.1.1 20170620
>>> .config is attached
>>> Raw console output is attached.
>>> C reproducer is attached
>>> syzkaller reproducer is attached. See https://goo.gl/kgGztJ
>>> for information about syzkaller reproducers
>>>
>>>
>>> WARNING: CPU: 1 PID: 2992 at kernel/tracepoint.c:243 tracepoint_remove_func
>>> kernel/tracepoint.c:243 [inline]
>>> WARNING: CPU: 1 PID: 2992 at kernel/tracepoint.c:243
>>> tracepoint_probe_unregister+0x6b3/0x870 kernel/tracepoint.c:324
>>> Kernel panic - not syncing: panic_on_warn set ...
>>>
>>> CPU: 1 PID: 2992 Comm: syzkaller812809 Not tainted 4.14.0-rc5-next-20171018+
>>> #8
>>> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
>>> Call Trace:
>>>  __dump_stack lib/dump_stack.c:16 [inline]
>>>  dump_stack+0x194/0x257 lib/dump_stack.c:52
>>>  panic+0x1e4/0x41c kernel/panic.c:183
>>>  __warn+0x1c4/0x1e0 kernel/panic.c:546
>>>  report_bug+0x211/0x2d0 lib/bug.c:183
>>>  fixup_bug+0x40/0x90 arch/x86/kernel/traps.c:177
>>>  do_trap_no_signal arch/x86/kernel/traps.c:211 [inline]
>>>  do_trap+0x260/0x390 arch/x86/kernel/traps.c:260
>>>  do_error_trap+0x120/0x390 arch/x86/kernel/traps.c:297
>>>  do_invalid_op+0x1b/0x20 arch/x86/kernel/traps.c:310
>>>  invalid_op+0x18/0x20 arch/x86/entry/entry_64.S:905
>>> RIP: 0010:tracepoint_remove_func kernel/tracepoint.c:243 [inline]
>>> RIP: 0010:tracepoint_probe_unregister+0x6b3/0x870 kernel/tracepoint.c:324
>>> RSP: 0018:ffff8800397df890 EFLAGS: 00010293
>>> RAX: ffff88003982e8c0 RBX: 00000000fffffffe RCX: ffffffff81710233
>>> RDX: 0000000000000000 RSI: ffffffff85b679c0 RDI: 0000000000000282
>>> RBP: ffff8800397df9a8 R08: 0000000000000001 R09: 1ffff100072fbe6e
>>> R10: ffff8800397df880 R11: 0000000000000001 R12: ffffffff8175b5e0
>>> R13: dffffc0000000000 R14: 0000000000000000 R15: ffff8800397df980
>>>  unregister_trace_block_rq_remap include/trace/events/block.h:602 [inline]
>>>  blk_unregister_tracepoints+0x1e/0x160 kernel/trace/blktrace.c:1079
>>>  blk_trace_cleanup+0x28/0x30 kernel/trace/blktrace.c:336
>>>  blk_trace_remove+0x55/0x80 kernel/trace/blktrace.c:348
>>>  sg_ioctl+0x5eb/0x2d90 drivers/scsi/sg.c:1098
>>>  vfs_ioctl fs/ioctl.c:45 [inline]
>>>  do_vfs_ioctl+0x1b1/0x1520 fs/ioctl.c:685
>>>  SYSC_ioctl fs/ioctl.c:700 [inline]
>>>  SyS_ioctl+0x8f/0xc0 fs/ioctl.c:691
>>>  entry_SYSCALL_64_fastpath+0x1f/0xbe
>>> RIP: 0033:0x4396a9
>>> RSP: 002b:00007ffd4d3facb8 EFLAGS: 00000206 ORIG_RAX: 0000000000000010
>>> RAX: ffffffffffffffda RBX: 00000000006ccac0 RCX: 00000000004396a9
>>> RDX: 000000002002d000 RSI: 4000000000001276 RDI: 0000000000000004
>>> RBP: 0000000000000082 R08: 00000000000000fe R09: 0000000000000000
>>> R10: 0000000000000000 R11: 0000000000000206 R12: 0000000000000038
>>> R13: ffffffffffffffff R14: 0000000000401eb0 R15: 0000000000000000
>>> Dumping ftrace buffer:
>>>    (ftrace buffer empty)
>>> Kernel Offset: disabled
>>> Rebooting in 86400 seconds..
>>
>>
>> Jens, this has the same root cause as "WARNING in
>> tracepoint_probe_register_prio":
>> https://groups.google.com/forum/#!msg/syzkaller-bugs/9IolqTA_NUk/LgLFZ6hQAQAJ
>> right?
>
> Yep, it is - can/did you check the patch I sent out yesterday for this?
> Here it is again.

I re-run the attached reproducer and it does not trigger the warning
with the patch:

Tested-by: Dmitry Vyukov <dvyukov@xxxxxxxxxx>


> diff --git a/kernel/trace/blktrace.c b/kernel/trace/blktrace.c
> index 45a3928544ce..206e0e2ace53 100644
> --- a/kernel/trace/blktrace.c
> +++ b/kernel/trace/blktrace.c
> @@ -66,7 +66,8 @@ static struct tracer_flags blk_tracer_flags = {
>  };
>
>  /* Global reference count of probes */
> -static atomic_t blk_probes_ref = ATOMIC_INIT(0);
> +static DEFINE_MUTEX(blk_probe_mutex);
> +static int blk_probes_ref;
>
>  static void blk_register_tracepoints(void);
>  static void blk_unregister_tracepoints(void);
> @@ -329,14 +330,29 @@ static void blk_trace_free(struct blk_trace *bt)
>         kfree(bt);
>  }
>
> +static void get_probe_ref(void)
> +{
> +       mutex_lock(&blk_probe_mutex);
> +       if (++blk_probes_ref == 1)
> +               blk_register_tracepoints();
> +       mutex_unlock(&blk_probe_mutex);
> +}
> +
> +static void put_probe_ref(void)
> +{
> +       mutex_lock(&blk_probe_mutex);
> +       if (!--blk_probes_ref)
> +               blk_unregister_tracepoints();
> +       mutex_unlock(&blk_probe_mutex);
> +}
> +
>  static void blk_trace_cleanup(struct blk_trace *bt)
>  {
>         blk_trace_free(bt);
> -       if (atomic_dec_and_test(&blk_probes_ref))
> -               blk_unregister_tracepoints();
> +       put_probe_ref();
>  }
>
> -int blk_trace_remove(struct request_queue *q)
> +static int __blk_trace_remove(struct request_queue *q)
>  {
>         struct blk_trace *bt;
>
> @@ -349,6 +365,17 @@ int blk_trace_remove(struct request_queue *q)
>
>         return 0;
>  }
> +
> +int blk_trace_remove(struct request_queue *q)
> +{
> +       int ret;
> +
> +       mutex_lock(&q->blk_trace_mutex);
> +       ret = __blk_trace_remove(q);
> +       mutex_unlock(&q->blk_trace_mutex);
> +
> +       return ret;
> +}
>  EXPORT_SYMBOL_GPL(blk_trace_remove);
>
>  static ssize_t blk_dropped_read(struct file *filp, char __user *buffer,
> @@ -538,8 +565,7 @@ static int do_blk_trace_setup(struct request_queue *q, char *name, dev_t dev,
>         if (cmpxchg(&q->blk_trace, NULL, bt))
>                 goto err;
>
> -       if (atomic_inc_return(&blk_probes_ref) == 1)
> -               blk_register_tracepoints();
> +       get_probe_ref();
>
>         ret = 0;
>  err:
> @@ -550,9 +576,8 @@ static int do_blk_trace_setup(struct request_queue *q, char *name, dev_t dev,
>         return ret;
>  }
>
> -int blk_trace_setup(struct request_queue *q, char *name, dev_t dev,
> -                   struct block_device *bdev,
> -                   char __user *arg)
> +static int __blk_trace_setup(struct request_queue *q, char *name, dev_t dev,
> +                            struct block_device *bdev, char __user *arg)
>  {
>         struct blk_user_trace_setup buts;
>         int ret;
> @@ -571,6 +596,19 @@ int blk_trace_setup(struct request_queue *q, char *name, dev_t dev,
>         }
>         return 0;
>  }
> +
> +int blk_trace_setup(struct request_queue *q, char *name, dev_t dev,
> +                   struct block_device *bdev,
> +                   char __user *arg)
> +{
> +       int ret;
> +
> +       mutex_lock(&q->blk_trace_mutex);
> +       ret = __blk_trace_setup(q, name, dev, bdev, arg);
> +       mutex_unlock(&q->blk_trace_mutex);
> +
> +       return ret;
> +}
>  EXPORT_SYMBOL_GPL(blk_trace_setup);
>
>  #if defined(CONFIG_COMPAT) && defined(CONFIG_X86_64)
> @@ -607,7 +645,7 @@ static int compat_blk_trace_setup(struct request_queue *q, char *name,
>  }
>  #endif
>
> -int blk_trace_startstop(struct request_queue *q, int start)
> +static int __blk_trace_startstop(struct request_queue *q, int start)
>  {
>         int ret;
>         struct blk_trace *bt = q->blk_trace;
> @@ -646,6 +684,17 @@ int blk_trace_startstop(struct request_queue *q, int start)
>
>         return ret;
>  }
> +
> +int blk_trace_startstop(struct request_queue *q, int start)
> +{
> +       int ret;
> +
> +       mutex_lock(&q->blk_trace_mutex);
> +       ret = __blk_trace_startstop(q, start);
> +       mutex_unlock(&q->blk_trace_mutex);
> +
> +       return ret;
> +}
>  EXPORT_SYMBOL_GPL(blk_trace_startstop);
>
>  /*
> @@ -676,7 +725,7 @@ int blk_trace_ioctl(struct block_device *bdev, unsigned cmd, char __user *arg)
>         switch (cmd) {
>         case BLKTRACESETUP:
>                 bdevname(bdev, b);
> -               ret = blk_trace_setup(q, b, bdev->bd_dev, bdev, arg);
> +               ret = __blk_trace_setup(q, b, bdev->bd_dev, bdev, arg);
>                 break;
>  #if defined(CONFIG_COMPAT) && defined(CONFIG_X86_64)
>         case BLKTRACESETUP32:
> @@ -687,10 +736,10 @@ int blk_trace_ioctl(struct block_device *bdev, unsigned cmd, char __user *arg)
>         case BLKTRACESTART:
>                 start = 1;
>         case BLKTRACESTOP:
> -               ret = blk_trace_startstop(q, start);
> +               ret = __blk_trace_startstop(q, start);
>                 break;
>         case BLKTRACETEARDOWN:
> -               ret = blk_trace_remove(q);
> +               ret = __blk_trace_remove(q);
>                 break;
>         default:
>                 ret = -ENOTTY;
> @@ -708,10 +757,14 @@ int blk_trace_ioctl(struct block_device *bdev, unsigned cmd, char __user *arg)
>   **/
>  void blk_trace_shutdown(struct request_queue *q)
>  {
> +       mutex_lock(&q->blk_trace_mutex);
> +
>         if (q->blk_trace) {
> -               blk_trace_startstop(q, 0);
> -               blk_trace_remove(q);
> +               __blk_trace_startstop(q, 0);
> +               __blk_trace_remove(q);
>         }
> +
> +       mutex_unlock(&q->blk_trace_mutex);
>  }
>
>  #ifdef CONFIG_BLK_CGROUP
> @@ -1558,9 +1611,7 @@ static int blk_trace_remove_queue(struct request_queue *q)
>         if (bt == NULL)
>                 return -EINVAL;
>
> -       if (atomic_dec_and_test(&blk_probes_ref))
> -               blk_unregister_tracepoints();
> -
> +       put_probe_ref();
>         blk_trace_free(bt);
>         return 0;
>  }
> @@ -1591,8 +1642,7 @@ static int blk_trace_setup_queue(struct request_queue *q,
>         if (cmpxchg(&q->blk_trace, NULL, bt))
>                 goto free_bt;
>
> -       if (atomic_inc_return(&blk_probes_ref) == 1)
> -               blk_register_tracepoints();
> +       get_probe_ref();
>         return 0;
>
>  free_bt:
>
> --
> Jens Axboe
>