diff mbox series

[v2,5/5] binder: additional transaction error logs

Message ID 20220429235644.697372-6-cmllamas@google.com (mailing list archive)
State Accepted
Commit a15dac8b228677daf8ad7f9855d38734ffa0e7d9
Headers show
Series binder: extended error and logging enhancements | expand

Commit Message

Carlos Llamas April 29, 2022, 11:56 p.m. UTC 
Log readable and specific error messages whenever a transaction failure
happens. This will ensure better context is given to regular users about
these unique error cases, without having to decode a cryptic log.

Signed-off-by: Carlos Llamas <cmllamas@google.com>
---
 drivers/android/binder.c | 48 ++++++++++++++++++++++++++++++++++++----
 1 file changed, 44 insertions(+), 4 deletions(-)

Comments

Todd Kjos May 2, 2022, 3:29 p.m. UTC | #1 
On Fri, Apr 29, 2022 at 4:57 PM 'Carlos Llamas' via kernel-team
<kernel-team@android.com> wrote:
>
> Log readable and specific error messages whenever a transaction failure
> happens. This will ensure better context is given to regular users about
> these unique error cases, without having to decode a cryptic log.
>
> Signed-off-by: Carlos Llamas <cmllamas@google.com>

Acked-by: Todd Kjos <tkjos@google.com>

> ---
>  drivers/android/binder.c | 48 ++++++++++++++++++++++++++++++++++++----
>  1 file changed, 44 insertions(+), 4 deletions(-)
>
> diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> index bfb21e258427..d7c5e2dde270 100644
> --- a/drivers/android/binder.c
> +++ b/drivers/android/binder.c
> @@ -147,6 +147,9 @@ static __printf(2, 3) void binder_debug(int mask, const char *format, ...)
>         }
>  }
>
> +#define binder_txn_error(x...) \
> +       binder_debug(BINDER_DEBUG_FAILED_TRANSACTION, x)
> +
>  static __printf(1, 2) void binder_user_error(const char *format, ...)
>  {
>         struct va_format vaf;
> @@ -2823,6 +2826,8 @@ static void binder_transaction(struct binder_proc *proc,
>                 if (target_thread == NULL) {
>                         /* annotation for sparse */
>                         __release(&target_thread->proc->inner_lock);
> +                       binder_txn_error("%d:%d reply target not found\n",
> +                               thread->pid, proc->pid);
>                         return_error = BR_DEAD_REPLY;
>                         return_error_line = __LINE__;
>                         goto err_dead_binder;
> @@ -2888,6 +2893,8 @@ static void binder_transaction(struct binder_proc *proc,
>                         }
>                 }
>                 if (!target_node) {
> +                       binder_txn_error("%d:%d cannot find target node\n",
> +                               thread->pid, proc->pid);
>                         /*
>                          * return_error is set above
>                          */
> @@ -2897,6 +2904,8 @@ static void binder_transaction(struct binder_proc *proc,
>                 }
>                 e->to_node = target_node->debug_id;
>                 if (WARN_ON(proc == target_proc)) {
> +                       binder_txn_error("%d:%d self transactions not allowed\n",
> +                               thread->pid, proc->pid);
>                         return_error = BR_FAILED_REPLY;
>                         return_error_param = -EINVAL;
>                         return_error_line = __LINE__;
> @@ -2904,6 +2913,8 @@ static void binder_transaction(struct binder_proc *proc,
>                 }
>                 if (security_binder_transaction(proc->cred,
>                                                 target_proc->cred) < 0) {
> +                       binder_txn_error("%d:%d transaction credentials failed\n",
> +                               thread->pid, proc->pid);
>                         return_error = BR_FAILED_REPLY;
>                         return_error_param = -EPERM;
>                         return_error_line = __LINE__;
> @@ -2975,6 +2986,8 @@ static void binder_transaction(struct binder_proc *proc,
>         /* TODO: reuse incoming transaction for reply */
>         t = kzalloc(sizeof(*t), GFP_KERNEL);
>         if (t == NULL) {
> +               binder_txn_error("%d:%d cannot allocate transaction\n",
> +                       thread->pid, proc->pid);
>                 return_error = BR_FAILED_REPLY;
>                 return_error_param = -ENOMEM;
>                 return_error_line = __LINE__;
> @@ -2986,6 +2999,8 @@ static void binder_transaction(struct binder_proc *proc,
>
>         tcomplete = kzalloc(sizeof(*tcomplete), GFP_KERNEL);
>         if (tcomplete == NULL) {
> +               binder_txn_error("%d:%d cannot allocate work for transaction\n",
> +                       thread->pid, proc->pid);
>                 return_error = BR_FAILED_REPLY;
>                 return_error_param = -ENOMEM;
>                 return_error_line = __LINE__;
> @@ -3032,6 +3047,8 @@ static void binder_transaction(struct binder_proc *proc,
>                 security_cred_getsecid(proc->cred, &secid);
>                 ret = security_secid_to_secctx(secid, &secctx, &secctx_sz);
>                 if (ret) {
> +                       binder_txn_error("%d:%d failed to get security context\n",
> +                               thread->pid, proc->pid);
>                         return_error = BR_FAILED_REPLY;
>                         return_error_param = ret;
>                         return_error_line = __LINE__;
> @@ -3040,7 +3057,8 @@ static void binder_transaction(struct binder_proc *proc,
>                 added_size = ALIGN(secctx_sz, sizeof(u64));
>                 extra_buffers_size += added_size;
>                 if (extra_buffers_size < added_size) {
> -                       /* integer overflow of extra_buffers_size */
> +                       binder_txn_error("%d:%d integer overflow of extra_buffers_size\n",
> +                               thread->pid, proc->pid);
>                         return_error = BR_FAILED_REPLY;
>                         return_error_param = -EINVAL;
>                         return_error_line = __LINE__;
> @@ -3054,9 +3072,15 @@ static void binder_transaction(struct binder_proc *proc,
>                 tr->offsets_size, extra_buffers_size,
>                 !reply && (t->flags & TF_ONE_WAY), current->tgid);
>         if (IS_ERR(t->buffer)) {
> -               /*
> -                * -ESRCH indicates VMA cleared. The target is dying.
> -                */
> +               char *s;
> +
> +               ret = PTR_ERR(t->buffer);
> +               s = (ret == -ESRCH) ? ": vma cleared, target dead or dying"
> +                       : (ret == -ENOSPC) ? ": no space left"
> +                       : (ret == -ENOMEM) ? ": memory allocation failed"
> +                       : "";
> +               binder_txn_error("cannot allocate buffer%s", s);
> +
>                 return_error_param = PTR_ERR(t->buffer);
>                 return_error = return_error_param == -ESRCH ?
>                         BR_DEAD_REPLY : BR_FAILED_REPLY;
> @@ -3139,6 +3163,8 @@ static void binder_transaction(struct binder_proc *proc,
>                                                   t->buffer,
>                                                   buffer_offset,
>                                                   sizeof(object_offset))) {
> +                       binder_txn_error("%d:%d copy offset from buffer failed\n",
> +                               thread->pid, proc->pid);
>                         return_error = BR_FAILED_REPLY;
>                         return_error_param = -EINVAL;
>                         return_error_line = __LINE__;
> @@ -3197,6 +3223,8 @@ static void binder_transaction(struct binder_proc *proc,
>                                                         t->buffer,
>                                                         object_offset,
>                                                         fp, sizeof(*fp))) {
> +                               binder_txn_error("%d:%d translate binder failed\n",
> +                                       thread->pid, proc->pid);
>                                 return_error = BR_FAILED_REPLY;
>                                 return_error_param = ret;
>                                 return_error_line = __LINE__;
> @@ -3214,6 +3242,8 @@ static void binder_transaction(struct binder_proc *proc,
>                                                         t->buffer,
>                                                         object_offset,
>                                                         fp, sizeof(*fp))) {
> +                               binder_txn_error("%d:%d translate handle failed\n",
> +                                       thread->pid, proc->pid);
>                                 return_error = BR_FAILED_REPLY;
>                                 return_error_param = ret;
>                                 return_error_line = __LINE__;
> @@ -3234,6 +3264,8 @@ static void binder_transaction(struct binder_proc *proc,
>                                                         t->buffer,
>                                                         object_offset,
>                                                         fp, sizeof(*fp))) {
> +                               binder_txn_error("%d:%d translate fd failed\n",
> +                                       thread->pid, proc->pid);
>                                 return_error = BR_FAILED_REPLY;
>                                 return_error_param = ret;
>                                 return_error_line = __LINE__;
> @@ -3303,6 +3335,8 @@ static void binder_transaction(struct binder_proc *proc,
>                                                                   object_offset,
>                                                                   fda, sizeof(*fda));
>                         if (ret) {
> +                               binder_txn_error("%d:%d translate fd array failed\n",
> +                                       thread->pid, proc->pid);
>                                 return_error = BR_FAILED_REPLY;
>                                 return_error_param = ret > 0 ? -EINVAL : ret;
>                                 return_error_line = __LINE__;
> @@ -3330,6 +3364,8 @@ static void binder_transaction(struct binder_proc *proc,
>                                 (const void __user *)(uintptr_t)bp->buffer,
>                                 bp->length);
>                         if (ret) {
> +                               binder_txn_error("%d:%d deferred copy failed\n",
> +                                       thread->pid, proc->pid);
>                                 return_error = BR_FAILED_REPLY;
>                                 return_error_param = ret;
>                                 return_error_line = __LINE__;
> @@ -3353,6 +3389,8 @@ static void binder_transaction(struct binder_proc *proc,
>                                                         t->buffer,
>                                                         object_offset,
>                                                         bp, sizeof(*bp))) {
> +                               binder_txn_error("%d:%d failed to fixup parent\n",
> +                                       thread->pid, proc->pid);
>                                 return_error = BR_FAILED_REPLY;
>                                 return_error_param = ret;
>                                 return_error_line = __LINE__;
> @@ -3460,6 +3498,8 @@ static void binder_transaction(struct binder_proc *proc,
>         return;
>
>  err_dead_proc_or_thread:
> +       binder_txn_error("%d:%d dead process or thread\n",
> +               thread->pid, proc->pid);
>         return_error_line = __LINE__;
>         binder_dequeue_work(proc, tcomplete);
>  err_translate_failed:
> --
> 2.36.0.464.gb9c8b46e94-goog
>
> --
> To unsubscribe from this group and stop receiving emails from it, send an email to kernel-team+unsubscribe@android.com.
>
Christian Brauner May 9, 2022, 10:06 a.m. UTC | #2 
On Fri, Apr 29, 2022 at 11:56:44PM +0000, Carlos Llamas wrote:
> Log readable and specific error messages whenever a transaction failure
> happens. This will ensure better context is given to regular users about
> these unique error cases, without having to decode a cryptic log.
> 
> Signed-off-by: Carlos Llamas <cmllamas@google.com>
> ---

Looks good to me,
Acked-by: Christian Brauner (Microsoft) <brauner@kernel.org>
diff mbox series

Patch

diff --git a/drivers/android/binder.c b/drivers/android/binder.c
index bfb21e258427..d7c5e2dde270 100644
--- a/drivers/android/binder.c
+++ b/drivers/android/binder.c
@@ -147,6 +147,9 @@  static __printf(2, 3) void binder_debug(int mask, const char *format, ...)
 	}
 }
 
+#define binder_txn_error(x...) \
+	binder_debug(BINDER_DEBUG_FAILED_TRANSACTION, x)
+
 static __printf(1, 2) void binder_user_error(const char *format, ...)
 {
 	struct va_format vaf;
@@ -2823,6 +2826,8 @@  static void binder_transaction(struct binder_proc *proc,
 		if (target_thread == NULL) {
 			/* annotation for sparse */
 			__release(&target_thread->proc->inner_lock);
+			binder_txn_error("%d:%d reply target not found\n",
+				thread->pid, proc->pid);
 			return_error = BR_DEAD_REPLY;
 			return_error_line = __LINE__;
 			goto err_dead_binder;
@@ -2888,6 +2893,8 @@  static void binder_transaction(struct binder_proc *proc,
 			}
 		}
 		if (!target_node) {
+			binder_txn_error("%d:%d cannot find target node\n",
+				thread->pid, proc->pid);
 			/*
 			 * return_error is set above
 			 */
@@ -2897,6 +2904,8 @@  static void binder_transaction(struct binder_proc *proc,
 		}
 		e->to_node = target_node->debug_id;
 		if (WARN_ON(proc == target_proc)) {
+			binder_txn_error("%d:%d self transactions not allowed\n",
+				thread->pid, proc->pid);
 			return_error = BR_FAILED_REPLY;
 			return_error_param = -EINVAL;
 			return_error_line = __LINE__;
@@ -2904,6 +2913,8 @@  static void binder_transaction(struct binder_proc *proc,
 		}
 		if (security_binder_transaction(proc->cred,
 						target_proc->cred) < 0) {
+			binder_txn_error("%d:%d transaction credentials failed\n",
+				thread->pid, proc->pid);
 			return_error = BR_FAILED_REPLY;
 			return_error_param = -EPERM;
 			return_error_line = __LINE__;
@@ -2975,6 +2986,8 @@  static void binder_transaction(struct binder_proc *proc,
 	/* TODO: reuse incoming transaction for reply */
 	t = kzalloc(sizeof(*t), GFP_KERNEL);
 	if (t == NULL) {
+		binder_txn_error("%d:%d cannot allocate transaction\n",
+			thread->pid, proc->pid);
 		return_error = BR_FAILED_REPLY;
 		return_error_param = -ENOMEM;
 		return_error_line = __LINE__;
@@ -2986,6 +2999,8 @@  static void binder_transaction(struct binder_proc *proc,
 
 	tcomplete = kzalloc(sizeof(*tcomplete), GFP_KERNEL);
 	if (tcomplete == NULL) {
+		binder_txn_error("%d:%d cannot allocate work for transaction\n",
+			thread->pid, proc->pid);
 		return_error = BR_FAILED_REPLY;
 		return_error_param = -ENOMEM;
 		return_error_line = __LINE__;
@@ -3032,6 +3047,8 @@  static void binder_transaction(struct binder_proc *proc,
 		security_cred_getsecid(proc->cred, &secid);
 		ret = security_secid_to_secctx(secid, &secctx, &secctx_sz);
 		if (ret) {
+			binder_txn_error("%d:%d failed to get security context\n",
+				thread->pid, proc->pid);
 			return_error = BR_FAILED_REPLY;
 			return_error_param = ret;
 			return_error_line = __LINE__;
@@ -3040,7 +3057,8 @@  static void binder_transaction(struct binder_proc *proc,
 		added_size = ALIGN(secctx_sz, sizeof(u64));
 		extra_buffers_size += added_size;
 		if (extra_buffers_size < added_size) {
-			/* integer overflow of extra_buffers_size */
+			binder_txn_error("%d:%d integer overflow of extra_buffers_size\n",
+				thread->pid, proc->pid);
 			return_error = BR_FAILED_REPLY;
 			return_error_param = -EINVAL;
 			return_error_line = __LINE__;
@@ -3054,9 +3072,15 @@  static void binder_transaction(struct binder_proc *proc,
 		tr->offsets_size, extra_buffers_size,
 		!reply && (t->flags & TF_ONE_WAY), current->tgid);
 	if (IS_ERR(t->buffer)) {
-		/*
-		 * -ESRCH indicates VMA cleared. The target is dying.
-		 */
+		char *s;
+
+		ret = PTR_ERR(t->buffer);
+		s = (ret == -ESRCH) ? ": vma cleared, target dead or dying"
+			: (ret == -ENOSPC) ? ": no space left"
+			: (ret == -ENOMEM) ? ": memory allocation failed"
+			: "";
+		binder_txn_error("cannot allocate buffer%s", s);
+
 		return_error_param = PTR_ERR(t->buffer);
 		return_error = return_error_param == -ESRCH ?
 			BR_DEAD_REPLY : BR_FAILED_REPLY;
@@ -3139,6 +3163,8 @@  static void binder_transaction(struct binder_proc *proc,
 						  t->buffer,
 						  buffer_offset,
 						  sizeof(object_offset))) {
+			binder_txn_error("%d:%d copy offset from buffer failed\n",
+				thread->pid, proc->pid);
 			return_error = BR_FAILED_REPLY;
 			return_error_param = -EINVAL;
 			return_error_line = __LINE__;
@@ -3197,6 +3223,8 @@  static void binder_transaction(struct binder_proc *proc,
 							t->buffer,
 							object_offset,
 							fp, sizeof(*fp))) {
+				binder_txn_error("%d:%d translate binder failed\n",
+					thread->pid, proc->pid);
 				return_error = BR_FAILED_REPLY;
 				return_error_param = ret;
 				return_error_line = __LINE__;
@@ -3214,6 +3242,8 @@  static void binder_transaction(struct binder_proc *proc,
 							t->buffer,
 							object_offset,
 							fp, sizeof(*fp))) {
+				binder_txn_error("%d:%d translate handle failed\n",
+					thread->pid, proc->pid);
 				return_error = BR_FAILED_REPLY;
 				return_error_param = ret;
 				return_error_line = __LINE__;
@@ -3234,6 +3264,8 @@  static void binder_transaction(struct binder_proc *proc,
 							t->buffer,
 							object_offset,
 							fp, sizeof(*fp))) {
+				binder_txn_error("%d:%d translate fd failed\n",
+					thread->pid, proc->pid);
 				return_error = BR_FAILED_REPLY;
 				return_error_param = ret;
 				return_error_line = __LINE__;
@@ -3303,6 +3335,8 @@  static void binder_transaction(struct binder_proc *proc,
 								  object_offset,
 								  fda, sizeof(*fda));
 			if (ret) {
+				binder_txn_error("%d:%d translate fd array failed\n",
+					thread->pid, proc->pid);
 				return_error = BR_FAILED_REPLY;
 				return_error_param = ret > 0 ? -EINVAL : ret;
 				return_error_line = __LINE__;
@@ -3330,6 +3364,8 @@  static void binder_transaction(struct binder_proc *proc,
 				(const void __user *)(uintptr_t)bp->buffer,
 				bp->length);
 			if (ret) {
+				binder_txn_error("%d:%d deferred copy failed\n",
+					thread->pid, proc->pid);
 				return_error = BR_FAILED_REPLY;
 				return_error_param = ret;
 				return_error_line = __LINE__;
@@ -3353,6 +3389,8 @@  static void binder_transaction(struct binder_proc *proc,
 							t->buffer,
 							object_offset,
 							bp, sizeof(*bp))) {
+				binder_txn_error("%d:%d failed to fixup parent\n",
+					thread->pid, proc->pid);
 				return_error = BR_FAILED_REPLY;
 				return_error_param = ret;
 				return_error_line = __LINE__;
@@ -3460,6 +3498,8 @@  static void binder_transaction(struct binder_proc *proc,
 	return;
 
 err_dead_proc_or_thread:
+	binder_txn_error("%d:%d dead process or thread\n",
+		thread->pid, proc->pid);
 	return_error_line = __LINE__;
 	binder_dequeue_work(proc, tcomplete);
 err_translate_failed: