[PATCH] usb: raw_gadget: Add debug logs to a troubleshoot a double-free bug in raw_release.

[PATCH] usb: raw_gadget: Add debug logs to a troubleshoot a double-free bug in raw_release.

[Chang Yu]

syzkaller reported a double free bug
(https://syzkaller.appspot.com/bug?extid=3e563d99e70973c0755c) in
raw_release.

From the stack traces it looks like either raw_release was invoked
twice or there were some between kref_get in raw_ioctl_run and
kref_put raw_release. But these should not be possible. We need
more logs to understand the cause.

Make raw_release and raw_ioctl_run report the ref count before
and after get/put to help debug this.

Signed-off-by: Chang Yu <marcus.yu.56@gmail.com>
Reported-by: syzbot+3e563d99e70973c0755c@syzkaller.appspotmail.com
Link: https://syzkaller.appspot.com/bug?extid=3e563d99e70973c0755c
---
 drivers/usb/gadget/legacy/raw_gadget.c | 14 ++++++++++++++
 1 file changed, 14 insertions(+)

diff --git a/drivers/usb/gadget/legacy/raw_gadget.c b/drivers/usb/gadget/legacy/raw_gadget.c
index 112fd18d8c99..ac4e319c743f 100644
--- a/drivers/usb/gadget/legacy/raw_gadget.c
+++ b/drivers/usb/gadget/legacy/raw_gadget.c
@@ -194,6 +194,8 @@ static struct raw_dev *dev_new(void)
 		return NULL;
 	/* Matches kref_put() in raw_release(). */
 	kref_init(&dev->count);
+	dev_dbg(dev->dev, "%s kref count initialized: %d\n",
+		__func__, kref_read(&dev->count));
 	spin_lock_init(&dev->lock);
 	init_completion(&dev->ep0_done);
 	raw_event_queue_init(&dev->queue);
@@ -464,13 +466,21 @@ static int raw_release(struct inode *inode, struct file *fd)
 			dev_err(dev->dev,
 				"usb_gadget_unregister_driver() failed with %d\n",
 				ret);
+		dev_dbg(dev->dev, "%s kref count before unregister driver put: %d\n",
+				__func__, kref_read(&dev->count));
 		/* Matches kref_get() in raw_ioctl_run(). */
 		kref_put(&dev->count, dev_free);
+		dev_dbg(dev->dev, "%s kref count after unregister driver put: %d\n",
+				__func__, kref_read(&dev->count));
 	}
 
 out_put:
+	dev_dbg(dev->dev, "%s kref count before final put: %d\n",
+			__func__, kref_read(&dev->count));
 	/* Matches dev_new() in raw_open(). */
 	kref_put(&dev->count, dev_free);
+	dev_dbg(dev->dev, "%s kref count after final put: %d\n",
+			__func__, kref_read(&dev->count));
 	return ret;
 }
 
@@ -603,8 +613,12 @@ static int raw_ioctl_run(struct raw_dev *dev, unsigned long value)
 	}
 	dev->gadget_registered = true;
 	dev->state = STATE_DEV_RUNNING;
+	dev_dbg(dev->dev, "%s kref count before get: %d\n",
+			__func__, kref_read(&dev->count));
 	/* Matches kref_put() in raw_release(). */
 	kref_get(&dev->count);
+	dev_dbg(dev->dev, "%s kref count after get: %d\n",
+			__func__, kref_read(&dev->count));
 
 out_unlock:
 	spin_unlock_irqrestore(&dev->lock, flags);
-- 
2.47.0

Re: [PATCH] usb: raw_gadget: Add debug logs to a troubleshoot a double-free bug in raw_release.

[Andrey Konovalov]

On Wed, Nov 6, 2024 at 1:11 PM Chang Yu <marcus.yu.56@gmail.com> wrote:
>
> syzkaller reported a double free bug
> (https://syzkaller.appspot.com/bug?extid=3e563d99e70973c0755c) in
> raw_release.
>
> From the stack traces it looks like either raw_release was invoked
> twice or there were some between kref_get in raw_ioctl_run and
> kref_put raw_release. But these should not be possible. We need
> more logs to understand the cause.
>
> Make raw_release and raw_ioctl_run report the ref count before
> and after get/put to help debug this.
>
> Signed-off-by: Chang Yu <marcus.yu.56@gmail.com>
> Reported-by: syzbot+3e563d99e70973c0755c@syzkaller.appspotmail.com
> Link: https://syzkaller.appspot.com/bug?extid=3e563d99e70973c0755c
> ---
>  drivers/usb/gadget/legacy/raw_gadget.c | 14 ++++++++++++++
>  1 file changed, 14 insertions(+)
>
> diff --git a/drivers/usb/gadget/legacy/raw_gadget.c b/drivers/usb/gadget/legacy/raw_gadget.c
> index 112fd18d8c99..ac4e319c743f 100644
> --- a/drivers/usb/gadget/legacy/raw_gadget.c
> +++ b/drivers/usb/gadget/legacy/raw_gadget.c
> @@ -194,6 +194,8 @@ static struct raw_dev *dev_new(void)
>                 return NULL;
>         /* Matches kref_put() in raw_release(). */
>         kref_init(&dev->count);
> +       dev_dbg(dev->dev, "%s kref count initialized: %d\n",
> +               __func__, kref_read(&dev->count));
>         spin_lock_init(&dev->lock);
>         init_completion(&dev->ep0_done);
>         raw_event_queue_init(&dev->queue);
> @@ -464,13 +466,21 @@ static int raw_release(struct inode *inode, struct file *fd)
>                         dev_err(dev->dev,
>                                 "usb_gadget_unregister_driver() failed with %d\n",
>                                 ret);
> +               dev_dbg(dev->dev, "%s kref count before unregister driver put: %d\n",
> +                               __func__, kref_read(&dev->count));
>                 /* Matches kref_get() in raw_ioctl_run(). */
>                 kref_put(&dev->count, dev_free);
> +               dev_dbg(dev->dev, "%s kref count after unregister driver put: %d\n",
> +                               __func__, kref_read(&dev->count));
>         }
>
>  out_put:
> +       dev_dbg(dev->dev, "%s kref count before final put: %d\n",
> +                       __func__, kref_read(&dev->count));
>         /* Matches dev_new() in raw_open(). */
>         kref_put(&dev->count, dev_free);
> +       dev_dbg(dev->dev, "%s kref count after final put: %d\n",
> +                       __func__, kref_read(&dev->count));
>         return ret;
>  }
>
> @@ -603,8 +613,12 @@ static int raw_ioctl_run(struct raw_dev *dev, unsigned long value)
>         }
>         dev->gadget_registered = true;
>         dev->state = STATE_DEV_RUNNING;
> +       dev_dbg(dev->dev, "%s kref count before get: %d\n",
> +                       __func__, kref_read(&dev->count));
>         /* Matches kref_put() in raw_release(). */
>         kref_get(&dev->count);
> +       dev_dbg(dev->dev, "%s kref count after get: %d\n",
> +                       __func__, kref_read(&dev->count));
>
>  out_unlock:
>         spin_unlock_irqrestore(&dev->lock, flags);
> --
> 2.47.0
>

Hi Chang,

This patch looks very specific to the bug we're trying to debug - I
don't think it makes sense to apply it to the mainline.

What you can do instead is ask syzbot to run the reproducer it has
with this patch applied via the #syz test command.

Thank you!

Re: [PATCH] usb: raw_gadget: Add debug logs to a troubleshoot a double-free bug in raw_release.

[Chang Yu]

On Wed, Nov 06, 2024 at 01:35:27PM +0900, Andrey Konovalov wrote:
> On Wed, Nov 6, 2024 at 1:11 PM Chang Yu <marcus.yu.56@gmail.com> wrote:
> >
> > syzkaller reported a double free bug
> > (https://syzkaller.appspot.com/bug?extid=3e563d99e70973c0755c) in
> > raw_release.
> >
> > From the stack traces it looks like either raw_release was invoked
> > twice or there were some between kref_get in raw_ioctl_run and
> > kref_put raw_release. But these should not be possible. We need
> > more logs to understand the cause.
> >
> > Make raw_release and raw_ioctl_run report the ref count before
> > and after get/put to help debug this.
> >
> > Signed-off-by: Chang Yu <marcus.yu.56@gmail.com>
> > Reported-by: syzbot+3e563d99e70973c0755c@syzkaller.appspotmail.com
> > Link: https://syzkaller.appspot.com/bug?extid=3e563d99e70973c0755c
> > ---
> >  drivers/usb/gadget/legacy/raw_gadget.c | 14 ++++++++++++++
> >  1 file changed, 14 insertions(+)
> >
> > diff --git a/drivers/usb/gadget/legacy/raw_gadget.c b/drivers/usb/gadget/legacy/raw_gadget.c
> > index 112fd18d8c99..ac4e319c743f 100644
> > --- a/drivers/usb/gadget/legacy/raw_gadget.c
> > +++ b/drivers/usb/gadget/legacy/raw_gadget.c
> > @@ -194,6 +194,8 @@ static struct raw_dev *dev_new(void)
> >                 return NULL;
> >         /* Matches kref_put() in raw_release(). */
> >         kref_init(&dev->count);
> > +       dev_dbg(dev->dev, "%s kref count initialized: %d\n",
> > +               __func__, kref_read(&dev->count));
> >         spin_lock_init(&dev->lock);
> >         init_completion(&dev->ep0_done);
> >         raw_event_queue_init(&dev->queue);
> > @@ -464,13 +466,21 @@ static int raw_release(struct inode *inode, struct file *fd)
> >                         dev_err(dev->dev,
> >                                 "usb_gadget_unregister_driver() failed with %d\n",
> >                                 ret);
> > +               dev_dbg(dev->dev, "%s kref count before unregister driver put: %d\n",
> > +                               __func__, kref_read(&dev->count));
> >                 /* Matches kref_get() in raw_ioctl_run(). */
> >                 kref_put(&dev->count, dev_free);
> > +               dev_dbg(dev->dev, "%s kref count after unregister driver put: %d\n",
> > +                               __func__, kref_read(&dev->count));
> >         }
> >
> >  out_put:
> > +       dev_dbg(dev->dev, "%s kref count before final put: %d\n",
> > +                       __func__, kref_read(&dev->count));
> >         /* Matches dev_new() in raw_open(). */
> >         kref_put(&dev->count, dev_free);
> > +       dev_dbg(dev->dev, "%s kref count after final put: %d\n",
> > +                       __func__, kref_read(&dev->count));
> >         return ret;
> >  }
> >
> > @@ -603,8 +613,12 @@ static int raw_ioctl_run(struct raw_dev *dev, unsigned long value)
> >         }
> >         dev->gadget_registered = true;
> >         dev->state = STATE_DEV_RUNNING;
> > +       dev_dbg(dev->dev, "%s kref count before get: %d\n",
> > +                       __func__, kref_read(&dev->count));
> >         /* Matches kref_put() in raw_release(). */
> >         kref_get(&dev->count);
> > +       dev_dbg(dev->dev, "%s kref count after get: %d\n",
> > +                       __func__, kref_read(&dev->count));
> >
> >  out_unlock:
> >         spin_unlock_irqrestore(&dev->lock, flags);
> > --
> > 2.47.0
> >
> 
> Hi Chang,
> 
> This patch looks very specific to the bug we're trying to debug - I
> don't think it makes sense to apply it to the mainline.
> 
> What you can do instead is ask syzbot to run the reproducer it has
> with this patch applied via the #syz test command.
> 
> Thank you!
Thank you for the tips, Andrey. I will do that. My apologies for the
rookie mistake. I'm pretty new to kernel patching/debugging and I'm
still learning the correct way to do stuff.

Thank you again for your help!

Re: [PATCH] usb: raw_gadget: Add debug logs to a troubleshoot a double-free bug in raw_release.

[Greg KH]

On Tue, Nov 05, 2024 at 08:11:47PM -0800, Chang Yu wrote:
> syzkaller reported a double free bug
> (https://syzkaller.appspot.com/bug?extid=3e563d99e70973c0755c) in
> raw_release.
> 
> >From the stack traces it looks like either raw_release was invoked
> twice or there were some between kref_get in raw_ioctl_run and
> kref_put raw_release. But these should not be possible. We need
> more logs to understand the cause.
> 
> Make raw_release and raw_ioctl_run report the ref count before
> and after get/put to help debug this.
> 
> Signed-off-by: Chang Yu <marcus.yu.56@gmail.com>
> Reported-by: syzbot+3e563d99e70973c0755c@syzkaller.appspotmail.com
> Link: https://syzkaller.appspot.com/bug?extid=3e563d99e70973c0755c
> ---
>  drivers/usb/gadget/legacy/raw_gadget.c | 14 ++++++++++++++
>  1 file changed, 14 insertions(+)
> 
> diff --git a/drivers/usb/gadget/legacy/raw_gadget.c b/drivers/usb/gadget/legacy/raw_gadget.c
> index 112fd18d8c99..ac4e319c743f 100644
> --- a/drivers/usb/gadget/legacy/raw_gadget.c
> +++ b/drivers/usb/gadget/legacy/raw_gadget.c
> @@ -194,6 +194,8 @@ static struct raw_dev *dev_new(void)
>  		return NULL;
>  	/* Matches kref_put() in raw_release(). */
>  	kref_init(&dev->count);
> +	dev_dbg(dev->dev, "%s kref count initialized: %d\n",
> +		__func__, kref_read(&dev->count));

Please note that you never need to add a __func__ to a dev_dbg() call,
as it is already present automatically for you.

thanks,

greg k-h

Re: [PATCH] usb: raw_gadget: Add debug logs to a troubleshoot a double-free bug in raw_release.

[Alan Stern]

On Wed, Nov 06, 2024 at 01:35:27PM +0900, Andrey Konovalov wrote:
> On Wed, Nov 6, 2024 at 1:11 PM Chang Yu <marcus.yu.56@gmail.com> wrote:
> >
> > syzkaller reported a double free bug
> > (https://syzkaller.appspot.com/bug?extid=3e563d99e70973c0755c) in
> > raw_release.
> >
> > From the stack traces it looks like either raw_release was invoked
> > twice or there were some between kref_get in raw_ioctl_run and
> > kref_put raw_release. But these should not be possible. We need
> > more logs to understand the cause.
> >
> > Make raw_release and raw_ioctl_run report the ref count before
> > and after get/put to help debug this.
> >
> > Signed-off-by: Chang Yu <marcus.yu.56@gmail.com>
> > Reported-by: syzbot+3e563d99e70973c0755c@syzkaller.appspotmail.com
> > Link: https://syzkaller.appspot.com/bug?extid=3e563d99e70973c0755c
> > ---
> >  drivers/usb/gadget/legacy/raw_gadget.c | 14 ++++++++++++++
> >  1 file changed, 14 insertions(+)
> >
> > diff --git a/drivers/usb/gadget/legacy/raw_gadget.c b/drivers/usb/gadget/legacy/raw_gadget.c
> > index 112fd18d8c99..ac4e319c743f 100644
> > --- a/drivers/usb/gadget/legacy/raw_gadget.c
> > +++ b/drivers/usb/gadget/legacy/raw_gadget.c
> > @@ -194,6 +194,8 @@ static struct raw_dev *dev_new(void)
> >                 return NULL;
> >         /* Matches kref_put() in raw_release(). */
> >         kref_init(&dev->count);
> > +       dev_dbg(dev->dev, "%s kref count initialized: %d\n",
> > +               __func__, kref_read(&dev->count));
> >         spin_lock_init(&dev->lock);
> >         init_completion(&dev->ep0_done);
> >         raw_event_queue_init(&dev->queue);
> > @@ -464,13 +466,21 @@ static int raw_release(struct inode *inode, struct file *fd)
> >                         dev_err(dev->dev,
> >                                 "usb_gadget_unregister_driver() failed with %d\n",
> >                                 ret);
> > +               dev_dbg(dev->dev, "%s kref count before unregister driver put: %d\n",
> > +                               __func__, kref_read(&dev->count));
> >                 /* Matches kref_get() in raw_ioctl_run(). */
> >                 kref_put(&dev->count, dev_free);
> > +               dev_dbg(dev->dev, "%s kref count after unregister driver put: %d\n",
> > +                               __func__, kref_read(&dev->count));
> >         }
> >
> >  out_put:
> > +       dev_dbg(dev->dev, "%s kref count before final put: %d\n",
> > +                       __func__, kref_read(&dev->count));
> >         /* Matches dev_new() in raw_open(). */
> >         kref_put(&dev->count, dev_free);
> > +       dev_dbg(dev->dev, "%s kref count after final put: %d\n",
> > +                       __func__, kref_read(&dev->count));
> >         return ret;
> >  }
> >
> > @@ -603,8 +613,12 @@ static int raw_ioctl_run(struct raw_dev *dev, unsigned long value)
> >         }
> >         dev->gadget_registered = true;
> >         dev->state = STATE_DEV_RUNNING;
> > +       dev_dbg(dev->dev, "%s kref count before get: %d\n",
> > +                       __func__, kref_read(&dev->count));
> >         /* Matches kref_put() in raw_release(). */
> >         kref_get(&dev->count);
> > +       dev_dbg(dev->dev, "%s kref count after get: %d\n",
> > +                       __func__, kref_read(&dev->count));
> >
> >  out_unlock:
> >         spin_unlock_irqrestore(&dev->lock, flags);
> > --
> > 2.47.0
> >
> 
> Hi Chang,
> 
> This patch looks very specific to the bug we're trying to debug - I
> don't think it makes sense to apply it to the mainline.
> 
> What you can do instead is ask syzbot to run the reproducer it has
> with this patch applied via the #syz test command.
> 
> Thank you!

In addition you should change your dev_dbg() calls to dev_info(), 
because dev_dbg() output will not show up in the syzbot console log.

Alan Stern