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

[Frode Isaksen <fisaksen@baylibre.com>]

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@meta.com>
>>
>> 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@meta.com>
>> ---
>> 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