Re: [PATCH] binder: do not crash on bad transaction in binder_thread_release()

[Frode Isaksen]

On 4/1/25 5:03 AM, Carlos Llamas wrote:
> On Mon, Mar 31, 2025 at 05:24:14PM +0200, Frode Isaksen wrote:
> > From: Frode Isaksen <frode@xxxxxxxx>
> >
> > Instead of calling BUG(), set the binder_thread to NULL,
> Yeap, not crashing the kernel is a good idea.
>
> > as is done in other parts of the code.
> > Log if it is a bad transaction (other than in or out).
> > The BUG in binder_thread_release() was preceded by
> > these warning logs:
> > binder: 1198:1217 got reply transaction with bad transaction stack,
> >   transaction 49693 has target 1198:0
> So tid 1217 is sending a reply to an incoming sync transaction. However,
> its transaction_stack shows that t->to_thread is NULL. I have no idea
> how can this be possible. When the transaction was picked up by 1217,
> its info was recorded in its transaction_stack as such:
>
> 	if (cmd != BR_REPLY && !(t->flags & TF_ONE_WAY)) {
> 		binder_inner_proc_lock(thread->proc);
> 		t->to_parent = thread->transaction_stack;
> 		t->to_thread = thread;            <----- HERE
> 		thread->transaction_stack = t;
> 		binder_inner_proc_unlock(thread->proc);
> 	}
>
> I don't understand how 't->to_thread' later becomes NULL, maybe memory
> corruption?
>
> > binder: 1198:1217 transaction failed 29201/-71, size 4-0 line 3065
> > ...
> > binder: release 954:1333 transaction 49693 out, still active
> > ...
> > binder: release 1198:1217 transaction 49693 out, still active
> > kernel BUG at drivers/android/binder.c:5070!
> >
> > Signed-off-by: Frode Isaksen <frode@xxxxxxxx>
> > ---
> > This bug was discovered, tested and fixed (no more crashes seen) on Meta Quest 3 device.
> Do you have a way to reproduce this? It sounds like there is something
> else going wrong before and we probably want to fix that.

I was never able to reproduce this locally and it happens very seldom.

As you can see in the log, there was a "bad transaction" 17 secs before 
the crash.
<6>[   13.664167] binder: 1198:1217 got reply transaction with bad 
transaction stack, transaction 49693 has target 1198:0
<6>[   13.664174] binder: 1198:1217 transaction failed 29201/-71, size 
4-0 line 3065
...
<6>[   40.793299] binder: release 954:1333 transaction 49693 out, still 
active
...
<6>[   41.624171] binder: release 1198:1217 transaction 49693 out, still 
active
<6>[   41.624197] ------------[ cut here ]------------
<2>[   41.624198] kernel BUG at drivers/android/binder.c:5070!

> >   drivers/android/binder.c | 5 +++--
> >   1 file changed, 3 insertions(+), 2 deletions(-)
> >
> > diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> > index 76052006bd87..c21d7806e42b 100644
> > --- a/drivers/android/binder.c
> > +++ b/drivers/android/binder.c
> > @@ -5302,7 +5302,8 @@ static int binder_thread_release(struct binder_proc *proc,
> >   			     "release %d:%d transaction %d %s, still active\n",
> >   			      proc->pid, thread->pid,
> >   			     t->debug_id,
> > -			     (t->to_thread == thread) ? "in" : "out");
> > +			     (t->to_thread == thread) ? "in" :
> > +			     (t->from == thread) ? "out" : "bad");
> >   
> >   		if (t->to_thread == thread) {
> >   			thread->proc->outstanding_txns--;
> > @@ -5317,7 +5318,7 @@ static int binder_thread_release(struct binder_proc *proc,
> >   			t->from = NULL;
> >   			t = t->from_parent;
> >   		} else
> > -			BUG();
> > +			t = NULL;
> Dropping BUG() is nice but this could use en error message.

The binder_debug() will log it as "bad" transaction instead of "out", so 
there will be a trace of this happening.

Thanks,

Frode

> >   		spin_unlock(&last_t->lock);
> >   		if (t)
> >   			spin_lock(&t->lock);
> > --
> > 2.49.0
> Regards,
> --
> Carlos Llamas