[PATCH v2 0/5] binder: extended error and logging enhancements

[PATCH v2 0/5] binder: extended error and logging enhancements

[Carlos Llamas]

This is a followup from [1], in which a split of commits was suggested
by Greg. Additionally, the following changes were removed and not
included in this v2 version:

  - dropped the binder_transaction_log_entry->strerr[] logic
  - dropped the binder_transaction_error() do-it-all function
  - dropped the re-work of current binder_user_error() messages

[1] https://lore.kernel.org/r/20220421042040.759068-1-cmllamas@google.com/

Carlos Llamas (5):
  binder: add failed transaction logging info
  binder: add BINDER_GET_EXTENDED_ERROR ioctl
  binderfs: add extended_error feature entry
  binder: convert logging macros into functions
  binder: additional transaction error logs

 drivers/android/binder.c                      | 153 ++++++++++++++++--
 drivers/android/binder_internal.h             |   3 +
 drivers/android/binderfs.c                    |   8 +
 include/uapi/linux/android/binder.h           |  16 ++
 .../filesystems/binderfs/binderfs_test.c      |   1 +
 5 files changed, 165 insertions(+), 16 deletions(-)


base-commit: 8013d1d3d2e33236dee13a133fba49ad55045e79
-- 
2.36.0.464.gb9c8b46e94-goog

[PATCH v2 1/5] binder: add failed transaction logging info

[Carlos Llamas]

Make sure we log relevant information about failed transactions such as
the target proc/thread, call type and transaction id. These details are
particularly important when debugging userspace issues.

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

diff --git a/drivers/android/binder.c b/drivers/android/binder.c
index 8351c5638880..f0885baa53a1 100644
--- a/drivers/android/binder.c
+++ b/drivers/android/binder.c
@@ -3459,8 +3459,12 @@ static void binder_transaction(struct binder_proc *proc,
 	}
 
 	binder_debug(BINDER_DEBUG_FAILED_TRANSACTION,
-		     "%d:%d transaction failed %d/%d, size %lld-%lld line %d\n",
-		     proc->pid, thread->pid, return_error, return_error_param,
+		     "%d:%d transaction %s to %d:%d failed %d/%d/%d, size %lld-%lld line %d\n",
+		     proc->pid, thread->pid, reply ? "reply" :
+		     (tr->flags & TF_ONE_WAY ? "async" : "call"),
+		     target_proc ? target_proc->pid : 0,
+		     target_thread ? target_thread->pid : 0,
+		     t_debug_id, return_error, return_error_param,
 		     (u64)tr->data_size, (u64)tr->offsets_size,
 		     return_error_line);
 
-- 
2.36.0.464.gb9c8b46e94-goog

Re: [PATCH v2 1/5] binder: add failed transaction logging info

[Todd Kjos]

On Fri, Apr 29, 2022 at 4:56 PM Carlos Llamas <cmllamas@google.com> wrote:
>
> Make sure we log relevant information about failed transactions such as
> the target proc/thread, call type and transaction id. These details are
> particularly important when debugging userspace issues.
>
> Signed-off-by: Carlos Llamas <cmllamas@google.com>

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

> ---
>  drivers/android/binder.c | 8 ++++++--
>  1 file changed, 6 insertions(+), 2 deletions(-)
>
> diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> index 8351c5638880..f0885baa53a1 100644
> --- a/drivers/android/binder.c
> +++ b/drivers/android/binder.c
> @@ -3459,8 +3459,12 @@ static void binder_transaction(struct binder_proc *proc,
>         }
>
>         binder_debug(BINDER_DEBUG_FAILED_TRANSACTION,
> -                    "%d:%d transaction failed %d/%d, size %lld-%lld line %d\n",
> -                    proc->pid, thread->pid, return_error, return_error_param,
> +                    "%d:%d transaction %s to %d:%d failed %d/%d/%d, size %lld-%lld line %d\n",
> +                    proc->pid, thread->pid, reply ? "reply" :
> +                    (tr->flags & TF_ONE_WAY ? "async" : "call"),
> +                    target_proc ? target_proc->pid : 0,
> +                    target_thread ? target_thread->pid : 0,
> +                    t_debug_id, return_error, return_error_param,
>                      (u64)tr->data_size, (u64)tr->offsets_size,
>                      return_error_line);
>
> --
> 2.36.0.464.gb9c8b46e94-goog
>

Re: [PATCH v2 1/5] binder: add failed transaction logging info

[Christian Brauner]

On Fri, Apr 29, 2022 at 11:56:40PM +0000, Carlos Llamas wrote:
> Make sure we log relevant information about failed transactions such as
> the target proc/thread, call type and transaction id. These details are
> particularly important when debugging userspace issues.
> 
> Signed-off-by: Carlos Llamas <cmllamas@google.com>
> ---

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

[PATCH v2 2/5] binder: add BINDER_GET_EXTENDED_ERROR ioctl

[Carlos Llamas]

Provide a userspace mechanism to pull precise error information upon
failed operations. Extending the current error codes returned by the
interfaces allows userspace to better determine the course of action.
This could be for instance, retrying a failed transaction at a later
point and thus offloading the error handling from the driver.

Signed-off-by: Carlos Llamas <cmllamas@google.com>
---
 drivers/android/binder.c            | 60 +++++++++++++++++++++++++++++
 drivers/android/binder_internal.h   |  3 ++
 include/uapi/linux/android/binder.h | 16 ++++++++
 3 files changed, 79 insertions(+)

diff --git a/drivers/android/binder.c b/drivers/android/binder.c
index f0885baa53a1..b9df0c8a68d3 100644
--- a/drivers/android/binder.c
+++ b/drivers/android/binder.c
@@ -147,6 +147,13 @@ module_param_call(stop_on_user_error, binder_set_stop_on_user_error,
 			binder_stop_on_user_error = 2; \
 	} while (0)
 
+#define binder_set_extended_error(ee, _id, _command, _param) \
+	do { \
+		(ee)->id = _id; \
+		(ee)->command = _command; \
+		(ee)->param = _param; \
+	} while (0)
+
 #define to_flat_binder_object(hdr) \
 	container_of(hdr, struct flat_binder_object, hdr)
 
@@ -2697,6 +2704,24 @@ static struct binder_node *binder_get_node_refs_for_txn(
 	return target_node;
 }
 
+static void binder_set_txn_from_error(struct binder_transaction *t, int id,
+				      uint32_t command, int32_t param)
+{
+	struct binder_thread *from = binder_get_txn_from_and_acq_inner(t);
+
+	if (!from) {
+		/* annotation for sparse */
+		__release(&from->proc->inner_lock);
+		return;
+	}
+
+	/* don't override existing errors */
+	if (from->ee.command == BR_OK)
+		binder_set_extended_error(&from->ee, id, command, param);
+	binder_inner_proc_unlock(from->proc);
+	binder_thread_dec_tmpref(from);
+}
+
 static void binder_transaction(struct binder_proc *proc,
 			       struct binder_thread *thread,
 			       struct binder_transaction_data *tr, int reply,
@@ -2742,6 +2767,10 @@ static void binder_transaction(struct binder_proc *proc,
 	e->offsets_size = tr->offsets_size;
 	strscpy(e->context_name, proc->context->name, BINDERFS_MAX_NAME);
 
+	binder_inner_proc_lock(proc);
+	binder_set_extended_error(&thread->ee, t_debug_id, BR_OK, 0);
+	binder_inner_proc_unlock(proc);
+
 	if (reply) {
 		binder_inner_proc_lock(proc);
 		in_reply_to = thread->transaction_stack;
@@ -3487,10 +3516,16 @@ static void binder_transaction(struct binder_proc *proc,
 
 	BUG_ON(thread->return_error.cmd != BR_OK);
 	if (in_reply_to) {
+		binder_set_txn_from_error(in_reply_to, t_debug_id,
+				return_error, return_error_param);
 		thread->return_error.cmd = BR_TRANSACTION_COMPLETE;
 		binder_enqueue_thread_work(thread, &thread->return_error.work);
 		binder_send_failed_reply(in_reply_to, return_error);
 	} else {
+		binder_inner_proc_lock(proc);
+		binder_set_extended_error(&thread->ee, t_debug_id,
+				return_error, return_error_param);
+		binder_inner_proc_unlock(proc);
 		thread->return_error.cmd = return_error;
 		binder_enqueue_thread_work(thread, &thread->return_error.work);
 	}
@@ -4628,6 +4663,7 @@ static struct binder_thread *binder_get_thread_ilocked(
 	thread->return_error.cmd = BR_OK;
 	thread->reply_error.work.type = BINDER_WORK_RETURN_ERROR;
 	thread->reply_error.cmd = BR_OK;
+	thread->ee.command = BR_OK;
 	INIT_LIST_HEAD(&new_thread->waiting_thread_node);
 	return thread;
 }
@@ -5066,6 +5102,25 @@ static int binder_ioctl_get_freezer_info(
 	return 0;
 }
 
+static int binder_ioctl_get_extended_error(struct binder_thread *thread,
+					   void __user *ubuf)
+{
+	struct binder_extended_error *ee = &thread->ee;
+
+	binder_inner_proc_lock(thread->proc);
+	if (copy_to_user(ubuf, ee, sizeof(*ee))) {
+		binder_inner_proc_unlock(thread->proc);
+		return -EFAULT;
+	}
+
+	ee->id = 0;
+	ee->command = BR_OK;
+	ee->param = 0;
+	binder_inner_proc_unlock(thread->proc);
+
+	return 0;
+}
+
 static long binder_ioctl(struct file *filp, unsigned int cmd, unsigned long arg)
 {
 	int ret;
@@ -5274,6 +5329,11 @@ static long binder_ioctl(struct file *filp, unsigned int cmd, unsigned long arg)
 		binder_inner_proc_unlock(proc);
 		break;
 	}
+	case BINDER_GET_EXTENDED_ERROR:
+		ret = binder_ioctl_get_extended_error(thread, ubuf);
+		if (ret < 0)
+			goto err;
+		break;
 	default:
 		ret = -EINVAL;
 		goto err;
diff --git a/drivers/android/binder_internal.h b/drivers/android/binder_internal.h
index d6b6b8cb7346..7c366a854125 100644
--- a/drivers/android/binder_internal.h
+++ b/drivers/android/binder_internal.h
@@ -480,6 +480,8 @@ struct binder_proc {
  *                        (only accessed by this thread)
  * @reply_error:          transaction errors reported by target thread
  *                        (protected by @proc->inner_lock)
+ * @ee:                   extended error information from this thread
+ *                        (protected by @proc->inner_lock)
  * @wait:                 wait queue for thread work
  * @stats:                per-thread statistics
  *                        (atomics, no lock needed)
@@ -504,6 +506,7 @@ struct binder_thread {
 	bool process_todo;
 	struct binder_error return_error;
 	struct binder_error reply_error;
+	struct binder_extended_error ee;
 	wait_queue_head_t wait;
 	struct binder_stats stats;
 	atomic_t tmp_ref;
diff --git a/include/uapi/linux/android/binder.h b/include/uapi/linux/android/binder.h
index 11157fae8a8e..e6ee8cae303b 100644
--- a/include/uapi/linux/android/binder.h
+++ b/include/uapi/linux/android/binder.h
@@ -236,6 +236,21 @@ struct binder_frozen_status_info {
 	__u32            async_recv;
 };
 
+/* struct binder_extened_error - extended error information
+ * @id:		identifier for the failed operation
+ * @command:	command as defined by binder_driver_return_protocol
+ * @param:	parameter holding a negative errno value
+ *
+ * Used with BINDER_GET_EXTENDED_ERROR. This extends the error information
+ * returned by the driver upon a failed operation. Userspace can pull this
+ * data to properly handle specific error scenarios.
+ */
+struct binder_extended_error {
+	__u32	id;
+	__u32	command;
+	__s32	param;
+};
+
 #define BINDER_WRITE_READ		_IOWR('b', 1, struct binder_write_read)
 #define BINDER_SET_IDLE_TIMEOUT		_IOW('b', 3, __s64)
 #define BINDER_SET_MAX_THREADS		_IOW('b', 5, __u32)
@@ -249,6 +264,7 @@ struct binder_frozen_status_info {
 #define BINDER_FREEZE			_IOW('b', 14, struct binder_freeze_info)
 #define BINDER_GET_FROZEN_INFO		_IOWR('b', 15, struct binder_frozen_status_info)
 #define BINDER_ENABLE_ONEWAY_SPAM_DETECTION	_IOW('b', 16, __u32)
+#define BINDER_GET_EXTENDED_ERROR	_IOWR('b', 17, struct binder_extended_error)
 
 /*
  * NOTE: Two special error codes you should check for when calling
-- 
2.36.0.464.gb9c8b46e94-goog

Re: [PATCH v2 2/5] binder: add BINDER_GET_EXTENDED_ERROR ioctl

[Todd Kjos]

On Fri, Apr 29, 2022 at 4:56 PM Carlos Llamas <cmllamas@google.com> wrote:
>
> Provide a userspace mechanism to pull precise error information upon
> failed operations. Extending the current error codes returned by the
> interfaces allows userspace to better determine the course of action.
> This could be for instance, retrying a failed transaction at a later
> point and thus offloading the error handling from the driver.
>
> Signed-off-by: Carlos Llamas <cmllamas@google.com>

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

> ---
>  drivers/android/binder.c            | 60 +++++++++++++++++++++++++++++
>  drivers/android/binder_internal.h   |  3 ++
>  include/uapi/linux/android/binder.h | 16 ++++++++
>  3 files changed, 79 insertions(+)
>
> diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> index f0885baa53a1..b9df0c8a68d3 100644
> --- a/drivers/android/binder.c
> +++ b/drivers/android/binder.c
> @@ -147,6 +147,13 @@ module_param_call(stop_on_user_error, binder_set_stop_on_user_error,
>                         binder_stop_on_user_error = 2; \
>         } while (0)
>
> +#define binder_set_extended_error(ee, _id, _command, _param) \
> +       do { \
> +               (ee)->id = _id; \
> +               (ee)->command = _command; \
> +               (ee)->param = _param; \
> +       } while (0)
> +
>  #define to_flat_binder_object(hdr) \
>         container_of(hdr, struct flat_binder_object, hdr)
>
> @@ -2697,6 +2704,24 @@ static struct binder_node *binder_get_node_refs_for_txn(
>         return target_node;
>  }
>
> +static void binder_set_txn_from_error(struct binder_transaction *t, int id,
> +                                     uint32_t command, int32_t param)
> +{
> +       struct binder_thread *from = binder_get_txn_from_and_acq_inner(t);
> +
> +       if (!from) {
> +               /* annotation for sparse */
> +               __release(&from->proc->inner_lock);
> +               return;
> +       }
> +
> +       /* don't override existing errors */
> +       if (from->ee.command == BR_OK)
> +               binder_set_extended_error(&from->ee, id, command, param);
> +       binder_inner_proc_unlock(from->proc);
> +       binder_thread_dec_tmpref(from);
> +}
> +
>  static void binder_transaction(struct binder_proc *proc,
>                                struct binder_thread *thread,
>                                struct binder_transaction_data *tr, int reply,
> @@ -2742,6 +2767,10 @@ static void binder_transaction(struct binder_proc *proc,
>         e->offsets_size = tr->offsets_size;
>         strscpy(e->context_name, proc->context->name, BINDERFS_MAX_NAME);
>
> +       binder_inner_proc_lock(proc);
> +       binder_set_extended_error(&thread->ee, t_debug_id, BR_OK, 0);
> +       binder_inner_proc_unlock(proc);
> +
>         if (reply) {
>                 binder_inner_proc_lock(proc);
>                 in_reply_to = thread->transaction_stack;
> @@ -3487,10 +3516,16 @@ static void binder_transaction(struct binder_proc *proc,
>
>         BUG_ON(thread->return_error.cmd != BR_OK);
>         if (in_reply_to) {
> +               binder_set_txn_from_error(in_reply_to, t_debug_id,
> +                               return_error, return_error_param);
>                 thread->return_error.cmd = BR_TRANSACTION_COMPLETE;
>                 binder_enqueue_thread_work(thread, &thread->return_error.work);
>                 binder_send_failed_reply(in_reply_to, return_error);
>         } else {
> +               binder_inner_proc_lock(proc);
> +               binder_set_extended_error(&thread->ee, t_debug_id,
> +                               return_error, return_error_param);
> +               binder_inner_proc_unlock(proc);
>                 thread->return_error.cmd = return_error;
>                 binder_enqueue_thread_work(thread, &thread->return_error.work);
>         }
> @@ -4628,6 +4663,7 @@ static struct binder_thread *binder_get_thread_ilocked(
>         thread->return_error.cmd = BR_OK;
>         thread->reply_error.work.type = BINDER_WORK_RETURN_ERROR;
>         thread->reply_error.cmd = BR_OK;
> +       thread->ee.command = BR_OK;
>         INIT_LIST_HEAD(&new_thread->waiting_thread_node);
>         return thread;
>  }
> @@ -5066,6 +5102,25 @@ static int binder_ioctl_get_freezer_info(
>         return 0;
>  }
>
> +static int binder_ioctl_get_extended_error(struct binder_thread *thread,
> +                                          void __user *ubuf)
> +{
> +       struct binder_extended_error *ee = &thread->ee;
> +
> +       binder_inner_proc_lock(thread->proc);
> +       if (copy_to_user(ubuf, ee, sizeof(*ee))) {
> +               binder_inner_proc_unlock(thread->proc);
> +               return -EFAULT;
> +       }
> +
> +       ee->id = 0;
> +       ee->command = BR_OK;
> +       ee->param = 0;
> +       binder_inner_proc_unlock(thread->proc);
> +
> +       return 0;
> +}
> +
>  static long binder_ioctl(struct file *filp, unsigned int cmd, unsigned long arg)
>  {
>         int ret;
> @@ -5274,6 +5329,11 @@ static long binder_ioctl(struct file *filp, unsigned int cmd, unsigned long arg)
>                 binder_inner_proc_unlock(proc);
>                 break;
>         }
> +       case BINDER_GET_EXTENDED_ERROR:
> +               ret = binder_ioctl_get_extended_error(thread, ubuf);
> +               if (ret < 0)
> +                       goto err;
> +               break;
>         default:
>                 ret = -EINVAL;
>                 goto err;
> diff --git a/drivers/android/binder_internal.h b/drivers/android/binder_internal.h
> index d6b6b8cb7346..7c366a854125 100644
> --- a/drivers/android/binder_internal.h
> +++ b/drivers/android/binder_internal.h
> @@ -480,6 +480,8 @@ struct binder_proc {
>   *                        (only accessed by this thread)
>   * @reply_error:          transaction errors reported by target thread
>   *                        (protected by @proc->inner_lock)
> + * @ee:                   extended error information from this thread
> + *                        (protected by @proc->inner_lock)
>   * @wait:                 wait queue for thread work
>   * @stats:                per-thread statistics
>   *                        (atomics, no lock needed)
> @@ -504,6 +506,7 @@ struct binder_thread {
>         bool process_todo;
>         struct binder_error return_error;
>         struct binder_error reply_error;
> +       struct binder_extended_error ee;
>         wait_queue_head_t wait;
>         struct binder_stats stats;
>         atomic_t tmp_ref;
> diff --git a/include/uapi/linux/android/binder.h b/include/uapi/linux/android/binder.h
> index 11157fae8a8e..e6ee8cae303b 100644
> --- a/include/uapi/linux/android/binder.h
> +++ b/include/uapi/linux/android/binder.h
> @@ -236,6 +236,21 @@ struct binder_frozen_status_info {
>         __u32            async_recv;
>  };
>
> +/* struct binder_extened_error - extended error information
> + * @id:                identifier for the failed operation
> + * @command:   command as defined by binder_driver_return_protocol
> + * @param:     parameter holding a negative errno value
> + *
> + * Used with BINDER_GET_EXTENDED_ERROR. This extends the error information
> + * returned by the driver upon a failed operation. Userspace can pull this
> + * data to properly handle specific error scenarios.
> + */
> +struct binder_extended_error {
> +       __u32   id;
> +       __u32   command;
> +       __s32   param;
> +};
> +
>  #define BINDER_WRITE_READ              _IOWR('b', 1, struct binder_write_read)
>  #define BINDER_SET_IDLE_TIMEOUT                _IOW('b', 3, __s64)
>  #define BINDER_SET_MAX_THREADS         _IOW('b', 5, __u32)
> @@ -249,6 +264,7 @@ struct binder_frozen_status_info {
>  #define BINDER_FREEZE                  _IOW('b', 14, struct binder_freeze_info)
>  #define BINDER_GET_FROZEN_INFO         _IOWR('b', 15, struct binder_frozen_status_info)
>  #define BINDER_ENABLE_ONEWAY_SPAM_DETECTION    _IOW('b', 16, __u32)
> +#define BINDER_GET_EXTENDED_ERROR      _IOWR('b', 17, struct binder_extended_error)
>
>  /*
>   * NOTE: Two special error codes you should check for when calling
> --
> 2.36.0.464.gb9c8b46e94-goog
>

Re: [PATCH v2 2/5] binder: add BINDER_GET_EXTENDED_ERROR ioctl

[Christian Brauner]

On Fri, Apr 29, 2022 at 11:56:41PM +0000, Carlos Llamas wrote:
> Provide a userspace mechanism to pull precise error information upon
> failed operations. Extending the current error codes returned by the
> interfaces allows userspace to better determine the course of action.
> This could be for instance, retrying a failed transaction at a later
> point and thus offloading the error handling from the driver.
> 
> Signed-off-by: Carlos Llamas <cmllamas@google.com>
> ---

One comment below otherwise looks good to me,
Acked-by: Christian Brauner (Microsoft) <brauner@kernel.org>

>  drivers/android/binder.c            | 60 +++++++++++++++++++++++++++++
>  drivers/android/binder_internal.h   |  3 ++
>  include/uapi/linux/android/binder.h | 16 ++++++++
>  3 files changed, 79 insertions(+)
> 
> diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> index f0885baa53a1..b9df0c8a68d3 100644
> --- a/drivers/android/binder.c
> +++ b/drivers/android/binder.c
> @@ -147,6 +147,13 @@ module_param_call(stop_on_user_error, binder_set_stop_on_user_error,
>  			binder_stop_on_user_error = 2; \
>  	} while (0)
>  
> +#define binder_set_extended_error(ee, _id, _command, _param) \
> +	do { \
> +		(ee)->id = _id; \
> +		(ee)->command = _command; \
> +		(ee)->param = _param; \
> +	} while (0)
> +
>  #define to_flat_binder_object(hdr) \
>  	container_of(hdr, struct flat_binder_object, hdr)
>  
> @@ -2697,6 +2704,24 @@ static struct binder_node *binder_get_node_refs_for_txn(
>  	return target_node;
>  }
>  
> +static void binder_set_txn_from_error(struct binder_transaction *t, int id,
> +				      uint32_t command, int32_t param)
> +{
> +	struct binder_thread *from = binder_get_txn_from_and_acq_inner(t);
> +
> +	if (!from) {
> +		/* annotation for sparse */
> +		__release(&from->proc->inner_lock);
> +		return;
> +	}
> +
> +	/* don't override existing errors */
> +	if (from->ee.command == BR_OK)
> +		binder_set_extended_error(&from->ee, id, command, param);
> +	binder_inner_proc_unlock(from->proc);
> +	binder_thread_dec_tmpref(from);
> +}
> +
>  static void binder_transaction(struct binder_proc *proc,
>  			       struct binder_thread *thread,
>  			       struct binder_transaction_data *tr, int reply,
> @@ -2742,6 +2767,10 @@ static void binder_transaction(struct binder_proc *proc,
>  	e->offsets_size = tr->offsets_size;
>  	strscpy(e->context_name, proc->context->name, BINDERFS_MAX_NAME);
>  
> +	binder_inner_proc_lock(proc);
> +	binder_set_extended_error(&thread->ee, t_debug_id, BR_OK, 0);
> +	binder_inner_proc_unlock(proc);
> +
>  	if (reply) {
>  		binder_inner_proc_lock(proc);
>  		in_reply_to = thread->transaction_stack;
> @@ -3487,10 +3516,16 @@ static void binder_transaction(struct binder_proc *proc,
>  
>  	BUG_ON(thread->return_error.cmd != BR_OK);
>  	if (in_reply_to) {
> +		binder_set_txn_from_error(in_reply_to, t_debug_id,
> +				return_error, return_error_param);
>  		thread->return_error.cmd = BR_TRANSACTION_COMPLETE;
>  		binder_enqueue_thread_work(thread, &thread->return_error.work);
>  		binder_send_failed_reply(in_reply_to, return_error);
>  	} else {
> +		binder_inner_proc_lock(proc);
> +		binder_set_extended_error(&thread->ee, t_debug_id,
> +				return_error, return_error_param);
> +		binder_inner_proc_unlock(proc);
>  		thread->return_error.cmd = return_error;
>  		binder_enqueue_thread_work(thread, &thread->return_error.work);
>  	}
> @@ -4628,6 +4663,7 @@ static struct binder_thread *binder_get_thread_ilocked(
>  	thread->return_error.cmd = BR_OK;
>  	thread->reply_error.work.type = BINDER_WORK_RETURN_ERROR;
>  	thread->reply_error.cmd = BR_OK;
> +	thread->ee.command = BR_OK;
>  	INIT_LIST_HEAD(&new_thread->waiting_thread_node);
>  	return thread;
>  }
> @@ -5066,6 +5102,25 @@ static int binder_ioctl_get_freezer_info(
>  	return 0;
>  }
>  
> +static int binder_ioctl_get_extended_error(struct binder_thread *thread,
> +					   void __user *ubuf)
> +{
> +	struct binder_extended_error *ee = &thread->ee;
> +
> +	binder_inner_proc_lock(thread->proc);
> +	if (copy_to_user(ubuf, ee, sizeof(*ee))) {
> +		binder_inner_proc_unlock(thread->proc);
> +		return -EFAULT;
> +	}
> +
> +	ee->id = 0;
> +	ee->command = BR_OK;
> +	ee->param = 0;
> +	binder_inner_proc_unlock(thread->proc);
> +
> +	return 0;
> +}

Fwiw, could be:

static int binder_ioctl_get_extended_error(struct binder_thread *thread,
					   void __user *ubuf)
{
	int ret;
	struct binder_extended_error *ee = &thread->ee;

	binder_inner_proc_lock(thread->proc);
	if (copy_to_user(ubuf, ee, sizeof(*ee))) {
		ret = -EFAULT;
	} else {
		ee->id = 0;
		ee->command = BR_OK;
		ee->param = 0;
	}
	binder_inner_proc_unlock(thread->proc);

	return ret;
}

> +
>  static long binder_ioctl(struct file *filp, unsigned int cmd, unsigned long arg)
>  {
>  	int ret;
> @@ -5274,6 +5329,11 @@ static long binder_ioctl(struct file *filp, unsigned int cmd, unsigned long arg)
>  		binder_inner_proc_unlock(proc);
>  		break;
>  	}
> +	case BINDER_GET_EXTENDED_ERROR:
> +		ret = binder_ioctl_get_extended_error(thread, ubuf);
> +		if (ret < 0)
> +			goto err;
> +		break;
>  	default:
>  		ret = -EINVAL;
>  		goto err;
> diff --git a/drivers/android/binder_internal.h b/drivers/android/binder_internal.h
> index d6b6b8cb7346..7c366a854125 100644
> --- a/drivers/android/binder_internal.h
> +++ b/drivers/android/binder_internal.h
> @@ -480,6 +480,8 @@ struct binder_proc {
>   *                        (only accessed by this thread)
>   * @reply_error:          transaction errors reported by target thread
>   *                        (protected by @proc->inner_lock)
> + * @ee:                   extended error information from this thread
> + *                        (protected by @proc->inner_lock)
>   * @wait:                 wait queue for thread work
>   * @stats:                per-thread statistics
>   *                        (atomics, no lock needed)
> @@ -504,6 +506,7 @@ struct binder_thread {
>  	bool process_todo;
>  	struct binder_error return_error;
>  	struct binder_error reply_error;
> +	struct binder_extended_error ee;
>  	wait_queue_head_t wait;
>  	struct binder_stats stats;
>  	atomic_t tmp_ref;
> diff --git a/include/uapi/linux/android/binder.h b/include/uapi/linux/android/binder.h
> index 11157fae8a8e..e6ee8cae303b 100644
> --- a/include/uapi/linux/android/binder.h
> +++ b/include/uapi/linux/android/binder.h
> @@ -236,6 +236,21 @@ struct binder_frozen_status_info {
>  	__u32            async_recv;
>  };
>  
> +/* struct binder_extened_error - extended error information
> + * @id:		identifier for the failed operation
> + * @command:	command as defined by binder_driver_return_protocol
> + * @param:	parameter holding a negative errno value
> + *
> + * Used with BINDER_GET_EXTENDED_ERROR. This extends the error information
> + * returned by the driver upon a failed operation. Userspace can pull this
> + * data to properly handle specific error scenarios.
> + */
> +struct binder_extended_error {
> +	__u32	id;
> +	__u32	command;
> +	__s32	param;
> +};
> +
>  #define BINDER_WRITE_READ		_IOWR('b', 1, struct binder_write_read)
>  #define BINDER_SET_IDLE_TIMEOUT		_IOW('b', 3, __s64)
>  #define BINDER_SET_MAX_THREADS		_IOW('b', 5, __u32)
> @@ -249,6 +264,7 @@ struct binder_frozen_status_info {
>  #define BINDER_FREEZE			_IOW('b', 14, struct binder_freeze_info)
>  #define BINDER_GET_FROZEN_INFO		_IOWR('b', 15, struct binder_frozen_status_info)
>  #define BINDER_ENABLE_ONEWAY_SPAM_DETECTION	_IOW('b', 16, __u32)
> +#define BINDER_GET_EXTENDED_ERROR	_IOWR('b', 17, struct binder_extended_error)
>  
>  /*
>   * NOTE: Two special error codes you should check for when calling
> -- 
> 2.36.0.464.gb9c8b46e94-goog
> 

[PATCH v2 3/5] binderfs: add extended_error feature entry

[Carlos Llamas]

Add extended_error to the binderfs feature list, to help userspace
determine whether the BINDER_GET_EXTENDED_ERROR ioctl is supported by
the binder driver.

Signed-off-by: Carlos Llamas <cmllamas@google.com>
---
 drivers/android/binderfs.c                                | 8 ++++++++
 .../selftests/filesystems/binderfs/binderfs_test.c        | 1 +
 2 files changed, 9 insertions(+)

diff --git a/drivers/android/binderfs.c b/drivers/android/binderfs.c
index e3605cdd4335..6c5e94f6cb3a 100644
--- a/drivers/android/binderfs.c
+++ b/drivers/android/binderfs.c
@@ -60,6 +60,7 @@ enum binderfs_stats_mode {
 
 struct binder_features {
 	bool oneway_spam_detection;
+	bool extended_error;
 };
 
 static const struct constant_table binderfs_param_stats[] = {
@@ -75,6 +76,7 @@ static const struct fs_parameter_spec binderfs_fs_parameters[] = {
 
 static struct binder_features binder_features = {
 	.oneway_spam_detection = true,
+	.extended_error = true,
 };
 
 static inline struct binderfs_info *BINDERFS_SB(const struct super_block *sb)
@@ -615,6 +617,12 @@ static int init_binder_features(struct super_block *sb)
 	if (IS_ERR(dentry))
 		return PTR_ERR(dentry);
 
+	dentry = binderfs_create_file(dir, "extended_error",
+				      &binder_features_fops,
+				      &binder_features.extended_error);
+	if (IS_ERR(dentry))
+		return PTR_ERR(dentry);
+
 	return 0;
 }
 
diff --git a/tools/testing/selftests/filesystems/binderfs/binderfs_test.c b/tools/testing/selftests/filesystems/binderfs/binderfs_test.c
index 0315955ff0f4..9409bb136d95 100644
--- a/tools/testing/selftests/filesystems/binderfs/binderfs_test.c
+++ b/tools/testing/selftests/filesystems/binderfs/binderfs_test.c
@@ -64,6 +64,7 @@ static int __do_binderfs_test(struct __test_metadata *_metadata)
 		device_path[sizeof(P_tmpdir "/binderfs_XXXXXX/") + BINDERFS_MAX_NAME];
 	static const char * const binder_features[] = {
 		"oneway_spam_detection",
+		"extended_error",
 	};
 
 	change_mountns(_metadata);
-- 
2.36.0.464.gb9c8b46e94-goog

Re: [PATCH v2 3/5] binderfs: add extended_error feature entry

[Todd Kjos]

On Fri, Apr 29, 2022 at 4:57 PM Carlos Llamas <cmllamas@google.com> wrote:
>
> Add extended_error to the binderfs feature list, to help userspace
> determine whether the BINDER_GET_EXTENDED_ERROR ioctl is supported by
> the binder driver.
>
> Signed-off-by: Carlos Llamas <cmllamas@google.com>

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

> ---
>  drivers/android/binderfs.c                                | 8 ++++++++
>  .../selftests/filesystems/binderfs/binderfs_test.c        | 1 +
>  2 files changed, 9 insertions(+)
>
> diff --git a/drivers/android/binderfs.c b/drivers/android/binderfs.c
> index e3605cdd4335..6c5e94f6cb3a 100644
> --- a/drivers/android/binderfs.c
> +++ b/drivers/android/binderfs.c
> @@ -60,6 +60,7 @@ enum binderfs_stats_mode {
>
>  struct binder_features {
>         bool oneway_spam_detection;
> +       bool extended_error;
>  };
>
>  static const struct constant_table binderfs_param_stats[] = {
> @@ -75,6 +76,7 @@ static const struct fs_parameter_spec binderfs_fs_parameters[] = {
>
>  static struct binder_features binder_features = {
>         .oneway_spam_detection = true,
> +       .extended_error = true,
>  };
>
>  static inline struct binderfs_info *BINDERFS_SB(const struct super_block *sb)
> @@ -615,6 +617,12 @@ static int init_binder_features(struct super_block *sb)
>         if (IS_ERR(dentry))
>                 return PTR_ERR(dentry);
>
> +       dentry = binderfs_create_file(dir, "extended_error",
> +                                     &binder_features_fops,
> +                                     &binder_features.extended_error);
> +       if (IS_ERR(dentry))
> +               return PTR_ERR(dentry);
> +
>         return 0;
>  }
>
> diff --git a/tools/testing/selftests/filesystems/binderfs/binderfs_test.c b/tools/testing/selftests/filesystems/binderfs/binderfs_test.c
> index 0315955ff0f4..9409bb136d95 100644
> --- a/tools/testing/selftests/filesystems/binderfs/binderfs_test.c
> +++ b/tools/testing/selftests/filesystems/binderfs/binderfs_test.c
> @@ -64,6 +64,7 @@ static int __do_binderfs_test(struct __test_metadata *_metadata)
>                 device_path[sizeof(P_tmpdir "/binderfs_XXXXXX/") + BINDERFS_MAX_NAME];
>         static const char * const binder_features[] = {
>                 "oneway_spam_detection",
> +               "extended_error",
>         };
>
>         change_mountns(_metadata);
> --
> 2.36.0.464.gb9c8b46e94-goog
>

Re: [PATCH v2 3/5] binderfs: add extended_error feature entry

[Christian Brauner]

On Fri, Apr 29, 2022 at 11:56:42PM +0000, Carlos Llamas wrote:
> Add extended_error to the binderfs feature list, to help userspace
> determine whether the BINDER_GET_EXTENDED_ERROR ioctl is supported by
> the binder driver.
> 
> Signed-off-by: Carlos Llamas <cmllamas@google.com>
> ---

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

[PATCH v2 4/5] binder: convert logging macros into functions

[Carlos Llamas]

Converting binder_debug() and binder_user_error() macros into functions
reduces the overall object size by 16936 bytes when cross-compiled with
aarch64-linux-gnu-gcc 11.2.0:

$ size drivers/android/binder.o.{old,new}
   text	   data	    bss	    dec	    hex	filename
  77935	   6168	  20264	 104367	  197af	drivers/android/binder.o.old
  65551	   1616	  20264	  87431	  15587	drivers/android/binder.o.new

This is particularly beneficial to functions binder_transaction() and
binder_thread_write() which repeatedly use these macros and are both
part of the critical path for all binder transactions.

$ nm --size vmlinux.{old,new} |grep ' binder_transaction$'
0000000000002f60 t binder_transaction
0000000000002358 t binder_transaction

$ nm --size vmlinux.{old,new} |grep binder_thread_write
0000000000001c54 t binder_thread_write
00000000000014a8 t binder_thread_write

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

diff --git a/drivers/android/binder.c b/drivers/android/binder.c
index b9df0c8a68d3..bfb21e258427 100644
--- a/drivers/android/binder.c
+++ b/drivers/android/binder.c
@@ -133,19 +133,36 @@ static int binder_set_stop_on_user_error(const char *val,
 module_param_call(stop_on_user_error, binder_set_stop_on_user_error,
 	param_get_int, &binder_stop_on_user_error, 0644);
 
-#define binder_debug(mask, x...) \
-	do { \
-		if (binder_debug_mask & mask) \
-			pr_info_ratelimited(x); \
-	} while (0)
+static __printf(2, 3) void binder_debug(int mask, const char *format, ...)
+{
+	struct va_format vaf;
+	va_list args;
 
-#define binder_user_error(x...) \
-	do { \
-		if (binder_debug_mask & BINDER_DEBUG_USER_ERROR) \
-			pr_info_ratelimited(x); \
-		if (binder_stop_on_user_error) \
-			binder_stop_on_user_error = 2; \
-	} while (0)
+	if (binder_debug_mask & mask) {
+		va_start(args, format);
+		vaf.va = &args;
+		vaf.fmt = format;
+		pr_info_ratelimited("%pV", &vaf);
+		va_end(args);
+	}
+}
+
+static __printf(1, 2) void binder_user_error(const char *format, ...)
+{
+	struct va_format vaf;
+	va_list args;
+
+	if (binder_debug_mask & BINDER_DEBUG_USER_ERROR) {
+		va_start(args, format);
+		vaf.va = &args;
+		vaf.fmt = format;
+		pr_info_ratelimited("%pV", &vaf);
+		va_end(args);
+	}
+
+	if (binder_stop_on_user_error)
+		binder_stop_on_user_error = 2;
+}
 
 #define binder_set_extended_error(ee, _id, _command, _param) \
 	do { \
-- 
2.36.0.464.gb9c8b46e94-goog

Re: [PATCH v2 4/5] binder: convert logging macros into functions

[Todd Kjos]

On Fri, Apr 29, 2022 at 4:57 PM Carlos Llamas <cmllamas@google.com> wrote:
>
> Converting binder_debug() and binder_user_error() macros into functions
> reduces the overall object size by 16936 bytes when cross-compiled with
> aarch64-linux-gnu-gcc 11.2.0:
>
> $ size drivers/android/binder.o.{old,new}
>    text    data     bss     dec     hex filename
>   77935    6168   20264  104367   197af drivers/android/binder.o.old
>   65551    1616   20264   87431   15587 drivers/android/binder.o.new
>
> This is particularly beneficial to functions binder_transaction() and
> binder_thread_write() which repeatedly use these macros and are both
> part of the critical path for all binder transactions.
>
> $ nm --size vmlinux.{old,new} |grep ' binder_transaction$'
> 0000000000002f60 t binder_transaction
> 0000000000002358 t binder_transaction
>
> $ nm --size vmlinux.{old,new} |grep binder_thread_write
> 0000000000001c54 t binder_thread_write
> 00000000000014a8 t binder_thread_write
>
> Signed-off-by: Carlos Llamas <cmllamas@google.com>

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

> ---
>  drivers/android/binder.c | 41 ++++++++++++++++++++++++++++------------
>  1 file changed, 29 insertions(+), 12 deletions(-)
>
> diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> index b9df0c8a68d3..bfb21e258427 100644
> --- a/drivers/android/binder.c
> +++ b/drivers/android/binder.c
> @@ -133,19 +133,36 @@ static int binder_set_stop_on_user_error(const char *val,
>  module_param_call(stop_on_user_error, binder_set_stop_on_user_error,
>         param_get_int, &binder_stop_on_user_error, 0644);
>
> -#define binder_debug(mask, x...) \
> -       do { \
> -               if (binder_debug_mask & mask) \
> -                       pr_info_ratelimited(x); \
> -       } while (0)
> +static __printf(2, 3) void binder_debug(int mask, const char *format, ...)
> +{
> +       struct va_format vaf;
> +       va_list args;
>
> -#define binder_user_error(x...) \
> -       do { \
> -               if (binder_debug_mask & BINDER_DEBUG_USER_ERROR) \
> -                       pr_info_ratelimited(x); \
> -               if (binder_stop_on_user_error) \
> -                       binder_stop_on_user_error = 2; \
> -       } while (0)
> +       if (binder_debug_mask & mask) {
> +               va_start(args, format);
> +               vaf.va = &args;
> +               vaf.fmt = format;
> +               pr_info_ratelimited("%pV", &vaf);
> +               va_end(args);
> +       }
> +}
> +
> +static __printf(1, 2) void binder_user_error(const char *format, ...)
> +{
> +       struct va_format vaf;
> +       va_list args;
> +
> +       if (binder_debug_mask & BINDER_DEBUG_USER_ERROR) {
> +               va_start(args, format);
> +               vaf.va = &args;
> +               vaf.fmt = format;
> +               pr_info_ratelimited("%pV", &vaf);
> +               va_end(args);
> +       }
> +
> +       if (binder_stop_on_user_error)
> +               binder_stop_on_user_error = 2;
> +}
>
>  #define binder_set_extended_error(ee, _id, _command, _param) \
>         do { \
> --
> 2.36.0.464.gb9c8b46e94-goog
>

Re: [PATCH v2 4/5] binder: convert logging macros into functions

[Christian Brauner]

On Fri, Apr 29, 2022 at 11:56:43PM +0000, Carlos Llamas wrote:
> Converting binder_debug() and binder_user_error() macros into functions
> reduces the overall object size by 16936 bytes when cross-compiled with
> aarch64-linux-gnu-gcc 11.2.0:
> 
> $ size drivers/android/binder.o.{old,new}
>    text	   data	    bss	    dec	    hex	filename
>   77935	   6168	  20264	 104367	  197af	drivers/android/binder.o.old
>   65551	   1616	  20264	  87431	  15587	drivers/android/binder.o.new
> 
> This is particularly beneficial to functions binder_transaction() and
> binder_thread_write() which repeatedly use these macros and are both
> part of the critical path for all binder transactions.
> 
> $ nm --size vmlinux.{old,new} |grep ' binder_transaction$'
> 0000000000002f60 t binder_transaction
> 0000000000002358 t binder_transaction
> 
> $ nm --size vmlinux.{old,new} |grep binder_thread_write
> 0000000000001c54 t binder_thread_write
> 00000000000014a8 t binder_thread_write
> 
> Signed-off-by: Carlos Llamas <cmllamas@google.com>
> ---

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

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

[Carlos Llamas]

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(-)

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

Re: [PATCH v2 5/5] binder: additional transaction error logs

[Todd Kjos]

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.
>

Re: [PATCH v2 5/5] binder: additional transaction error logs

[Christian Brauner]

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>