On Wed, Apr 13, 2022 at 10:59:22AM +0530, Mukesh Ojha wrote:
> Hi All,
>
> We are hitting one race due to which try_to_grab_pending() is stuck .
What kernel version are you using?
> In following scenario, while running (p1)dev_coredumpm() devcd device is
> added to
> the framework and uevent notification sent to userspace that result in the
> call to (p2) devcd_data_write()
> which eventually try to delete the queued timer which in the racy scenario
> timer is not queued yet.
> So, debug object report some warning and in the meantime timer is
> initialized and queued from p1 path.
> and from p2 path it gets overriden again timer->entry.pprev=NULL and
> try_to_grab_pending() stuck
> as del_timer() always return 0 as timer_pending() return false.
>
> P1 P2(X)
>
>
> ???? dev_coredumpm()
>
> ????????????????????????????????????????? Uevent notification sent to
> userspace
> ????????????????????????????????????????? for device addition
>
> ??????????? device_add() ========================>???????????????? Process X
> reads this uevents
> notification and do write call
> that results in call to
>
> devcd_data_write()
> mod_delayed_work()
> try_to_grab_pending()
> del_timer()
> debug_assert_init()
>
> ??????????? INIT_DELAYED_WORK
> ?????????????????? (&devcd->del_wk, devcd_del);
> ??????????? schedule_delayed_work(&devcd->del_wk,
> ?????????????????? DEVCD_TIMEOUT);
>
> debug_object_fixup()
> timer_fixup_assert_init()
> timer_setup()
> do_init_timer()?? ==> reinitialized the timer to timer->entry.pprev=NULL
>
> timer_pending()
> !hlist_unhashed_lockless(&timer->entry)
> !h->pprev
The above is confusing and not able to be understood due to the
formatting mess. Care to fix this up and resend?
thanks,
greg k-h
On Wed, 2022-04-13 at 07:34 +0200, Greg KH wrote:
> >
> > debug_object_fixup()
> >
Also, isn't that a debug path with a lot of prints or something?
johannes
On Wed, Apr 13, 2022 at 07:34:24AM +0200, Greg KH wrote:
> On Wed, Apr 13, 2022 at 10:59:22AM +0530, Mukesh Ojha wrote:
> > Hi All,
> >
> > We are hitting one race due to which try_to_grab_pending() is stuck .
>
> What kernel version are you using?
5.10
Sorry, for the formatting mess.
> > In following scenario, while running (p1)dev_coredumpm() devcd device is
> > added to
> > the framework and uevent notification sent to userspace that result in the
> > call to (p2) devcd_data_write()
> > which eventually try to delete the queued timer which in the racy scenario
> > timer is not queued yet.
> > So, debug object report some warning and in the meantime timer is
> > initialized and queued from p1 path.
> > and from p2 path it gets overriden again timer->entry.pprev=NULL and
> > try_to_grab_pending() stuck
p1 p2(X)
dev_coredump() uevent sent to userspace
device_add() =========================> userspace process X reads the uevents
writes to devcd fd which
results into writes to
devcd_data_write()
mod_delayed_work()
try_to_grab_pending()
del_timer()
debug_assert_init()
INIT_DELAYED_WORK
schedule_delayed_work
debug_object_fixup()
timer_fixup_assert_init()
timer_setup()
do_init_timer()?? ==> reinitialized the timer to timer->entry.pprev=NULL
timer_pending()
!hlist_unhashed_lockless(&timer->entry)
!h->pprev ==> del_timer checks and finds to be NULL
stuck in try_to_grab_pending
Thanks,Mukesh
>
>
> > In following scenario, while running (p1)dev_coredumpm() devcd device is
> > added to
> > the framework and uevent notification sent to userspace that result in the
> > call to (p2) devcd_data_write()
> > which eventually try to delete the queued timer which in the racy scenario
> > timer is not queued yet.
> > So, debug object report some warning and in the meantime timer is
> > initialized and queued from p1 path.
> > and from p2 path it gets overriden again timer->entry.pprev=NULL and
> > try_to_grab_pending() stuck
> > as del_timer() always return 0 as timer_pending() return false.
> >
> > P1 P2(X)
> >
> >
> > ???? dev_coredumpm()
> >
> > ????????????????????????????????????????? Uevent notification sent to
> > userspace
> > ????????????????????????????????????????? for device addition
> >
> > ??????????? device_add() ========================>???????????????? Process X
> > reads this uevents
> > notification and do write call
> > that results in call to
> >
> > devcd_data_write()
> > mod_delayed_work()
> > try_to_grab_pending()
> > del_timer()
> > debug_assert_init()
> >
> > ??????????? INIT_DELAYED_WORK
> > ?????????????????? (&devcd->del_wk, devcd_del);
> > ??????????? schedule_delayed_work(&devcd->del_wk,
> > ?????????????????? DEVCD_TIMEOUT);
> >
> > debug_object_fixup()
> > timer_fixup_assert_init()
> > timer_setup()
> > do_init_timer()?? ==> reinitialized the timer to timer->entry.pprev=NULL
> >
> > timer_pending()
> > !hlist_unhashed_lockless(&timer->entry)
> > !h->pprev
>
> The above is confusing and not able to be understood due to the
> formatting mess. Care to fix this up and resend?
>
> thanks,
>
> greg k-h
On Wed, Apr 13, 2022 at 03:46:39PM +0530, Mukesh Ojha wrote:
> On Wed, Apr 13, 2022 at 07:34:24AM +0200, Greg KH wrote:
> > On Wed, Apr 13, 2022 at 10:59:22AM +0530, Mukesh Ojha wrote:
> > > Hi All,
> > >
> > > We are hitting one race due to which try_to_grab_pending() is stuck .
> >
> > What kernel version are you using?
>
> 5.10
5.10.0 was released a very long time ago. Please use a more modern
kernel release :)
> Sorry, for the formatting mess.
>
> > > In following scenario, while running (p1)dev_coredumpm() devcd device is
> > > added to
> > > the framework and uevent notification sent to userspace that result in the
> > > call to (p2) devcd_data_write()
> > > which eventually try to delete the queued timer which in the racy scenario
> > > timer is not queued yet.
> > > So, debug object report some warning and in the meantime timer is
> > > initialized and queued from p1 path.
> > > and from p2 path it gets overriden again timer->entry.pprev=NULL and
> > > try_to_grab_pending() stuck
> p1 p2(X)
>
> dev_coredump() uevent sent to userspace
> device_add() =========================> userspace process X reads the uevents
> writes to devcd fd which
> results into writes to
>
> devcd_data_write()
> mod_delayed_work()
> try_to_grab_pending()
> del_timer()
> debug_assert_init()
> INIT_DELAYED_WORK
> schedule_delayed_work
> debug_object_fixup()
Why do you have object debugging enabled? That's going to take a LONG
time, and will find bugs in your code. Perhaps like this one?
What type of device is this? What bus? What driver?
And if you turn object debugging off, what happens?
thanks,
greg k-h
On Wed, Apr 13 2022 at 12:58, Greg KH wrote:
> On Wed, Apr 13, 2022 at 03:46:39PM +0530, Mukesh Ojha wrote:
>> p1 p2(X)
>>
>> dev_coredump() uevent sent to userspace
>> device_add() =========================> userspace process X reads the uevents
>> writes to devcd fd which
>> results into writes to
>>
>> devcd_data_write()
>> mod_delayed_work()
>> try_to_grab_pending()
>> del_timer()
>> debug_assert_init()
>> INIT_DELAYED_WORK
>> schedule_delayed_work
>> debug_object_fixup()
>
> Why do you have object debugging enabled? That's going to take a LONG
> time, and will find bugs in your code. Perhaps like this one?
It's not finding bugs in his code. It finds bug in the upstream
dev_coredump code.
> And if you turn object debugging off, what happens?
The debugobject splat goes away, but the problem persists.
device_add() -> uevent
Preemption or concurrency:
devcd_data_write()
mod_delayed_work(..., w, 0); <- Uninitialized.
The dev_coredump code exposes the device before it is fully initialized
and a write ending up in devcd_data_write() touches uninitialized work.
It does not help to move the initialization before device_add() as that
creates another problem:
INIT_DELAYED_WORK(w)
...
device_add() -> uevent
Preemption or concurrency:
devcd_data_write()
mod_delayed_work(..., w, 0); <- Schedules work immediately
work_queue_runs()
devcd_del(w)
device_del()
put_device() <- Drops the last reference
initialization continues...
So, yes this needs serialization of some sort.
Same problem vs. disabled_store().
Thanks,
tglx
On Thu, Apr 14, 2022 at 12:38:13PM +0200, Thomas Gleixner wrote:
> On Wed, Apr 13 2022 at 12:58, Greg KH wrote:
> > On Wed, Apr 13, 2022 at 03:46:39PM +0530, Mukesh Ojha wrote:
> >> p1 p2(X)
> >>
> >> dev_coredump() uevent sent to userspace
> >> device_add() =========================> userspace process X reads the uevents
> >> writes to devcd fd which
> >> results into writes to
> >>
> >> devcd_data_write()
> >> mod_delayed_work()
> >> try_to_grab_pending()
> >> del_timer()
> >> debug_assert_init()
> >> INIT_DELAYED_WORK
> >> schedule_delayed_work
> >> debug_object_fixup()
> >
> > Why do you have object debugging enabled? That's going to take a LONG
> > time, and will find bugs in your code. Perhaps like this one?
>
> It's not finding bugs in his code. It finds bug in the upstream
> dev_coredump code.
>
> > And if you turn object debugging off, what happens?
>
> The debugobject splat goes away, but the problem persists.
>
> device_add() -> uevent
>
> Preemption or concurrency:
>
> devcd_data_write()
> mod_delayed_work(..., w, 0); <- Uninitialized.
>
> The dev_coredump code exposes the device before it is fully initialized
> and a write ending up in devcd_data_write() touches uninitialized work.
>
> It does not help to move the initialization before device_add() as that
> creates another problem:
>
> INIT_DELAYED_WORK(w)
> ...
> device_add() -> uevent
>
> Preemption or concurrency:
>
> devcd_data_write()
> mod_delayed_work(..., w, 0); <- Schedules work immediately
>
> work_queue_runs()
> devcd_del(w)
> device_del()
> put_device() <- Drops the last reference
>
> initialization continues...
>
> So, yes this needs serialization of some sort.
Hi Thomas,
Thanks for understanding the problem.
Can the patch mentioned at below link helps with the first problem ?
https://lore.kernel.org/lkml/[email protected]/
>
> Same problem vs. disabled_store().
you mean, while userspace is reading the data and suddenly disable_store() done from
sysfs.
-Mukesh
>
> Thanks,
>
> tglx
On Thu, Apr 14 2022 at 16:50, Mukesh Ojha wrote:
> On Thu, Apr 14, 2022 at 12:38:13PM +0200, Thomas Gleixner wrote:
>> So, yes this needs serialization of some sort.
>
> Thanks for understanding the problem.
> Can the patch mentioned at below link helps with the first problem ?
>
> https://lore.kernel.org/lkml/[email protected]/
Something like that.
>> Same problem vs. disabled_store().
>
> you mean, while userspace is reading the data and suddenly disable_store() done from
> sysfs.
No, that's not a problem because the reader holds a reference, but it's
the same problem vs. initialization:
device_add()
disable_store()
devcd_free()
mod_delayed_work()
....
Thanks,
tglx