* [PATCH v2 0/3] rust_binder: error line numbers and failed_transaction_log
@ 2026-09-30 13:56 Alice Ryhl
2026-09-30 13:56 ` [PATCH v2 1/3] rust_binder: never return 0 from next_debug_id Alice Ryhl
` (2 more replies)
0 siblings, 3 replies; 6+ messages in thread
From: Alice Ryhl @ 2026-09-30 13:56 UTC (permalink / raw)
To: Greg Kroah-Hartman, Carlos Llamas
Cc: Miguel Ojeda, Boqun Feng, Gary Guo, Björn Roy Baron,
Benno Lossin, Andreas Hindborg, Trevor Gross, Danilo Krummrich,
Daniel Almeida, Tamir Duberstein, Alexandre Courbot,
Onur Özkan, linux-kernel, rust-for-linux, Alice Ryhl
When diagnosing Binder issues, it's useful to know what the most recent
failed transactions are, so include a transaction log with this content
matching the C Binder transaction log.
While we're at it, improve the line number information emitted by Rust
Binder using #[track_caller].
Signed-off-by: Alice Ryhl <aliceryhl@google.com>
---
Changes in v2:
- Retry on 0 in next_debug_id() so 0 is never returned on wrap-around.
- Handle debug_id wrap-around in TransactionLog::add using wrapping_sub.
- Link to v1: https://lore.kernel.org/r/20260930-binder-transaction-log-v1-0-3d832fb30388@google.com
---
Alice Ryhl (3):
rust_binder: never return 0 from next_debug_id
rust_binder: track caller location in BinderError
rust_binder: add transaction_log and failed_transaction_log
drivers/android/binder/context.rs | 8 +-
drivers/android/binder/error.rs | 39 +++++
drivers/android/binder/process.rs | 5 +-
drivers/android/binder/rust_binder_internal.h | 1 +
drivers/android/binder/rust_binder_main.rs | 31 +++-
drivers/android/binder/rust_binderfs.c | 19 +++
drivers/android/binder/thread.rs | 12 +-
drivers/android/binder/transaction.rs | 197 +++++++++++++++++++++++++-
8 files changed, 302 insertions(+), 10 deletions(-)
---
base-commit: 72d3fcf802c45d00b300f25b848a93c3a2bd7c7e
change-id: 20260930-binder-transaction-log-94989f47b142
Best regards,
--
Alice Ryhl <aliceryhl@google.com>
^ permalink raw reply [flat|nested] 6+ messages in thread* [PATCH v2 1/3] rust_binder: never return 0 from next_debug_id 2026-09-30 13:56 [PATCH v2 0/3] rust_binder: error line numbers and failed_transaction_log Alice Ryhl @ 2026-09-30 13:56 ` Alice Ryhl 2026-09-30 13:56 ` [PATCH v2 2/3] rust_binder: track caller location in BinderError Alice Ryhl 2026-09-30 13:56 ` [PATCH v2 3/3] rust_binder: add transaction_log and failed_transaction_log Alice Ryhl 2 siblings, 0 replies; 6+ messages in thread From: Alice Ryhl @ 2026-09-30 13:56 UTC (permalink / raw) To: Greg Kroah-Hartman, Carlos Llamas Cc: Miguel Ojeda, Boqun Feng, Gary Guo, Björn Roy Baron, Benno Lossin, Andreas Hindborg, Trevor Gross, Danilo Krummrich, Daniel Almeida, Tamir Duberstein, Alexandre Courbot, Onur Özkan, linux-kernel, rust-for-linux, Alice Ryhl Retry if fetch_add returns 0 in next_debug_id() so that valid debug IDs start at 1 and 0 is never assigned, even if NEXT_DEBUG_ID wraps around. This allows 0 to be used as a sentinel for an absent or uninitialized debug_id (such as in TransactionInfo::to_node_debug_id and in transaction log entries). Assisted-by: LLM Signed-off-by: Alice Ryhl <aliceryhl@google.com> --- drivers/android/binder/rust_binder_main.rs | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/drivers/android/binder/rust_binder_main.rs b/drivers/android/binder/rust_binder_main.rs index 955c4c348f73..bd26ef96fefb 100644 --- a/drivers/android/binder/rust_binder_main.rs +++ b/drivers/android/binder/rust_binder_main.rs @@ -98,7 +98,12 @@ fn default() -> Self { fn next_debug_id() -> usize { static NEXT_DEBUG_ID: Atomic<usize> = Atomic::new(0); - NEXT_DEBUG_ID.fetch_add(1, Relaxed) + loop { + let id = NEXT_DEBUG_ID.fetch_add(1, Relaxed); + if id != 0 { + return id; + } + } } /// Provides a single place to write Binder return values via the -- 2.56.0.rc1.315.gc6ed9934b7-goog ^ permalink raw reply [flat|nested] 6+ messages in thread
* [PATCH v2 2/3] rust_binder: track caller location in BinderError 2026-09-30 13:56 [PATCH v2 0/3] rust_binder: error line numbers and failed_transaction_log Alice Ryhl 2026-09-30 13:56 ` [PATCH v2 1/3] rust_binder: never return 0 from next_debug_id Alice Ryhl @ 2026-09-30 13:56 ` Alice Ryhl 2026-09-30 13:56 ` [PATCH v2 3/3] rust_binder: add transaction_log and failed_transaction_log Alice Ryhl 2 siblings, 0 replies; 6+ messages in thread From: Alice Ryhl @ 2026-09-30 13:56 UTC (permalink / raw) To: Greg Kroah-Hartman, Carlos Llamas Cc: Miguel Ojeda, Boqun Feng, Gary Guo, Björn Roy Baron, Benno Lossin, Andreas Hindborg, Trevor Gross, Danilo Krummrich, Daniel Almeida, Tamir Duberstein, Alexandre Courbot, Onur Özkan, linux-kernel, rust-for-linux, Alice Ryhl Record the caller's location in BinderError using #[track_caller] and a new ErrorLocation wrapper around &'static Location<'static> across all BinderError constructors and From implementations. ErrorLocation implements Display by stripping the directory prefix so locations are formatted as filename.rs:line (e.g. process.rs:422). In Context::get_manager_node and Process::buffer_alloc, avoid passing BinderError::new_dead() or BinderError::from() as function pointers to Option::ok_or_else() and Result::map_err() so that #[track_caller] captures the call site in rust_binder correctly. Include the error location in the FailedTransaction debug print and prepare for recording it in the binder transaction log. Example output: rust_binder: 840:4583 transaction async to 7656:0 failed ESRCH, code 1 size 428-16 line thread.rs:711 Assisted-by: LLM Signed-off-by: Alice Ryhl <aliceryhl@google.com> --- drivers/android/binder/context.rs | 8 ++++---- drivers/android/binder/error.rs | 39 +++++++++++++++++++++++++++++++++++++++ drivers/android/binder/process.rs | 5 ++++- drivers/android/binder/thread.rs | 5 +++-- 4 files changed, 50 insertions(+), 7 deletions(-) diff --git a/drivers/android/binder/context.rs b/drivers/android/binder/context.rs index ddddb66b3557..bcc97ddaacd7 100644 --- a/drivers/android/binder/context.rs +++ b/drivers/android/binder/context.rs @@ -134,13 +134,13 @@ pub(crate) fn unset_manager_node(&self) { } pub(crate) fn get_manager_node(&self, strong: bool) -> Result<NodeRef, BinderError> { - self.manager + Ok(self + .manager .lock() .node .as_ref() - .ok_or_else(BinderError::new_dead)? - .clone(strong) - .map_err(BinderError::from) + .ok_or_else(|| BinderError::new_dead())? + .clone(strong)?) } pub(crate) fn for_each_proc<F>(&self, mut func: F) diff --git a/drivers/android/binder/error.rs b/drivers/android/binder/error.rs index 1296072c35d9..41b07d687b30 100644 --- a/drivers/android/binder/error.rs +++ b/drivers/android/binder/error.rs @@ -2,6 +2,7 @@ // Copyright (C) 2025 Google LLC. +use core::panic::Location; use kernel::fmt; use kernel::prelude::*; @@ -9,32 +10,65 @@ pub(crate) type BinderResult<T = ()> = core::result::Result<T, BinderError>; +/// Wraps a `&'static Location` to format it as `filename.rs:line` without the directory prefix. +#[derive(Copy, Clone)] +#[repr(transparent)] +pub(crate) struct ErrorLocation(&'static Location<'static>); + +// SAFETY: `ErrorLocation` is `repr(transparent)` over a shared reference, which is part of the +// option layout optimization guarantee, so all zeroes is a valid representation for `None`. +unsafe impl pin_init::ZeroableOption for ErrorLocation {} + +impl ErrorLocation { + #[track_caller] + pub(crate) const fn caller() -> Self { + Self(Location::caller()) + } +} + +impl fmt::Display for ErrorLocation { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let file = match self.0.file().rsplit_once('/') { + Some((_, file)) => file, + None => self.0.file(), + }; + write!(f, "{}:{}", file, self.0.line()) + } +} + /// An error that will be returned to userspace via the `BINDER_WRITE_READ` ioctl rather than via /// errno. pub(crate) struct BinderError { pub(crate) reply: u32, pub(crate) source: Option<Error>, + pub(crate) line: ErrorLocation, } impl BinderError { + #[track_caller] pub(crate) fn new_dead() -> Self { Self { reply: BR_DEAD_REPLY, source: None, + line: ErrorLocation::caller(), } } + #[track_caller] pub(crate) fn new_frozen() -> Self { Self { reply: BR_FROZEN_REPLY, source: None, + line: ErrorLocation::caller(), } } + #[track_caller] pub(crate) fn new_frozen_oneway() -> Self { Self { reply: BR_TRANSACTION_PENDING_FROZEN, source: None, + line: ErrorLocation::caller(), } } @@ -46,25 +80,30 @@ pub(crate) fn is_dead(&self) -> bool { /// Convert an errno into a `BinderError` and store the errno used to construct it. The errno /// should be stored as the thread's extended error when given to userspace. impl From<Error> for BinderError { + #[track_caller] fn from(source: Error) -> Self { Self { reply: BR_FAILED_REPLY, source: Some(source), + line: ErrorLocation::caller(), } } } impl From<kernel::fs::file::BadFdError> for BinderError { + #[track_caller] fn from(source: kernel::fs::file::BadFdError) -> Self { BinderError::from(Error::from(source)) } } impl From<kernel::alloc::AllocError> for BinderError { + #[track_caller] fn from(_: kernel::alloc::AllocError) -> Self { Self { reply: BR_FAILED_REPLY, source: Some(ENOMEM), + line: ErrorLocation::caller(), } } } diff --git a/drivers/android/binder/process.rs b/drivers/android/binder/process.rs index 5372bfbd93b3..dcf6ba4bc71b 100644 --- a/drivers/android/binder/process.rs +++ b/drivers/android/binder/process.rs @@ -1066,7 +1066,10 @@ pub(crate) fn buffer_alloc( let (new_alloc, addr) = loop { let mut inner = self.inner.lock(); - let mapping = inner.mapping.as_mut().ok_or_else(BinderError::new_dead)?; + let mapping = inner + .mapping + .as_mut() + .ok_or_else(|| BinderError::new_dead())?; let alloc_request = match mapping.alloc.reserve_new(reserve_new_args)? { ReserveNew::Success(new_alloc) => break (new_alloc, mapping.address), ReserveNew::NeedAlloc(request) => request, diff --git a/drivers/android/binder/thread.rs b/drivers/android/binder/thread.rs index 18a14aa8a835..0891a36e9cbd 100644 --- a/drivers/android/binder/thread.rs +++ b/drivers/android/binder/thread.rs @@ -1310,7 +1310,7 @@ fn transaction(self: &Arc<Self>, cmd: u32, reader: &mut UserSliceReader) -> Resu binder_debug!( FailedTransaction, - "transaction {} to {}:{} failed {:?}, code {} size {}-{}", + "transaction {} to {}:{} failed {:?}, code {} size {}-{} line {}", if info.is_reply { "reply" } else if info.is_oneway() { @@ -1323,7 +1323,8 @@ fn transaction(self: &Arc<Self>, cmd: u32, reader: &mut UserSliceReader) -> Resu err, info.code, info.data_size, - info.offsets_size + info.offsets_size, + err.line ); } } -- 2.56.0.rc1.315.gc6ed9934b7-goog ^ permalink raw reply [flat|nested] 6+ messages in thread
* [PATCH v2 3/3] rust_binder: add transaction_log and failed_transaction_log 2026-09-30 13:56 [PATCH v2 0/3] rust_binder: error line numbers and failed_transaction_log Alice Ryhl 2026-09-30 13:56 ` [PATCH v2 1/3] rust_binder: never return 0 from next_debug_id Alice Ryhl 2026-09-30 13:56 ` [PATCH v2 2/3] rust_binder: track caller location in BinderError Alice Ryhl @ 2026-09-30 13:56 ` Alice Ryhl 2026-10-01 12:34 ` Greg Kroah-Hartman 2 siblings, 1 reply; 6+ messages in thread From: Alice Ryhl @ 2026-09-30 13:56 UTC (permalink / raw) To: Greg Kroah-Hartman, Carlos Llamas Cc: Miguel Ojeda, Boqun Feng, Gary Guo, Björn Roy Baron, Benno Lossin, Andreas Hindborg, Trevor Gross, Danilo Krummrich, Daniel Almeida, Tamir Duberstein, Alexandre Courbot, Onur Özkan, linux-kernel, rust-for-linux, Alice Ryhl Implement the binder_logs/transaction_log and binder_logs/failed_transaction_log binderfs files in Rust Binder, matching the circular 32-entry transaction logs in C Binder. Example output from /dev/binderfs/binder_logs/transaction_log: 261251: call from 6157:6171 to 391:0 context binder node 170 handle 34 size 256:0 ret 0/0 l=0 261254: async from 606:783 to 669:0 context binder node 2048 handle 2 size 144:0 ret 0/0 l=0 261255: reply from 391:552 to 6157:6171 context binder node 0 handle -1 size 2436:8 ret 0/0 l=0 Example output from /dev/binderfs/binder_logs/failed_transaction_log: 194556: async from 6646:6853 to 7452:0 context binder node 177682 handle 450 size 160:0 ret 29189/0 l=process.rs:1081 194846: reply from 6646:6775 to 7452:7544 context binder node 0 handle -1 size 8:0 ret 29201/0 l=process.rs:1081 201573: call from 7771:7793 to 6646:0 context binder node 198883 handle 28 size 0:0 ret 29189/0 l=process.rs:1081 Unlike C Binder, which writes to log entries without a lock using memory barriers (smp_wmb/smp_rmb) and a debug_id_done field, each TransactionLog uses an atomic index cursor with 32 cacheline-aligned SpinLock<TransactionLogEntry> slots initialized in BinderModule::init via SetOnce<_>. Using a SpinLock per slot avoids data races (such as tearing when the ring buffer wraps around while an entry is being printed) without requiring atomic accesses for every field, and has very low risk of contention: concurrent transactions are spread across 32 separate cacheline-aligned locks, each lock is only held briefly for a fixed-size copy, and two writers only contend on a slot if 32 transactions occur before a single copy completes. Assisted-by: LLM Signed-off-by: Alice Ryhl <aliceryhl@google.com> --- drivers/android/binder/rust_binder_internal.h | 1 + drivers/android/binder/rust_binder_main.rs | 24 ++++ drivers/android/binder/rust_binderfs.c | 19 +++ drivers/android/binder/thread.rs | 7 + drivers/android/binder/transaction.rs | 197 +++++++++++++++++++++++++- 5 files changed, 246 insertions(+), 2 deletions(-) diff --git a/drivers/android/binder/rust_binder_internal.h b/drivers/android/binder/rust_binder_internal.h index 78288fe7964d..50a50df14c77 100644 --- a/drivers/android/binder/rust_binder_internal.h +++ b/drivers/android/binder/rust_binder_internal.h @@ -44,6 +44,7 @@ struct binder_device { int rust_binder_stats_show(struct seq_file *m, void *unused); int rust_binder_state_show(struct seq_file *m, void *unused); int rust_binder_transactions_show(struct seq_file *m, void *unused); +int rust_binder_transaction_log_show(struct seq_file *m, void *unused); int rust_binder_proc_show(struct seq_file *m, void *pid); extern const struct file_operations rust_binder_fops; diff --git a/drivers/android/binder/rust_binder_main.rs b/drivers/android/binder/rust_binder_main.rs index bd26ef96fefb..dd168a932d7a 100644 --- a/drivers/android/binder/rust_binder_main.rs +++ b/drivers/android/binder/rust_binder_main.rs @@ -310,6 +310,9 @@ fn init(_module: &'static kernel::ThisModule) -> Result<Self> { // SAFETY: The module initializer never runs twice, so we only call this once. unsafe { crate::context::CONTEXTS.init() }; + crate::transaction::TRANSACTION_LOG.init()?; + crate::transaction::FAILED_TRANSACTION_LOG.init()?; + let netlink = crate::netlink::BINDER_NL_FAMILY.register()?; BINDER_SHRINKER.register(c"android-binder")?; @@ -550,6 +553,27 @@ unsafe impl<T> Sync for AssertSync<T> {} 0 } +/// # Safety +/// Only called by binderfs. +#[no_mangle] +unsafe extern "C" fn rust_binder_transaction_log_show( + ptr: *mut seq_file, + _: *mut kernel::ffi::c_void, +) -> kernel::ffi::c_int { + // SAFETY: Accessing the private field of `seq_file` is okay. + let is_failed = !unsafe { (*ptr).private }.is_null(); + // SAFETY: The caller ensures that the pointer is valid and exclusive for the duration in which + // this method is called. + let m = unsafe { SeqFile::from_raw(ptr) }; + let log = if is_failed { + &transaction::FAILED_TRANSACTION_LOG + } else { + &transaction::TRANSACTION_LOG + }; + log.debug_print(m); + 0 +} + fn rust_binder_transactions_show_impl(m: &SeqFile) -> Result<()> { seq_print!(m, "binder transactions:\n"); let contexts = context::get_all_contexts()?; diff --git a/drivers/android/binder/rust_binderfs.c b/drivers/android/binder/rust_binderfs.c index 300cc65562d1..ef83d5a502af 100644 --- a/drivers/android/binder/rust_binderfs.c +++ b/drivers/android/binder/rust_binderfs.c @@ -46,6 +46,7 @@ DEFINE_SHOW_ATTRIBUTE(rust_binder_stats); DEFINE_SHOW_ATTRIBUTE(rust_binder_state); DEFINE_SHOW_ATTRIBUTE(rust_binder_transactions); +DEFINE_SHOW_ATTRIBUTE(rust_binder_transaction_log); DEFINE_SHOW_ATTRIBUTE(rust_binder_proc); char *rust_binder_devices_param = CONFIG_ANDROID_BINDER_DEVICES; @@ -603,6 +604,24 @@ static int init_binder_logs(struct super_block *sb) goto out; } + dentry = rust_binderfs_create_file(binder_logs_root_dir, + "transaction_log", + &rust_binder_transaction_log_fops, + (void *)0); + if (IS_ERR(dentry)) { + ret = PTR_ERR(dentry); + goto out; + } + + dentry = rust_binderfs_create_file(binder_logs_root_dir, + "failed_transaction_log", + &rust_binder_transaction_log_fops, + (void *)1); + if (IS_ERR(dentry)) { + ret = PTR_ERR(dentry); + goto out; + } + proc_log_dir = binderfs_create_dir(binder_logs_root_dir, "proc"); if (IS_ERR(proc_log_dir)) { ret = PTR_ERR(proc_log_dir); diff --git a/drivers/android/binder/thread.rs b/drivers/android/binder/thread.rs index 0891a36e9cbd..875daaef5f53 100644 --- a/drivers/android/binder/thread.rs +++ b/drivers/android/binder/thread.rs @@ -1299,6 +1299,7 @@ fn transaction(self: &Arc<Self>, cmd: u32, reader: &mut UserSliceReader) -> Resu self.push_return_work(err.reply); if err.reply != BR_TRANSACTION_COMPLETE { info.reply = err.reply; + info.error_line = Some(err.line); if let Some(source) = &err.source { info.errno = source.to_errno(); @@ -1330,6 +1331,8 @@ fn transaction(self: &Arc<Self>, cmd: u32, reader: &mut UserSliceReader) -> Resu } } + info.write_log(&self.process.ctx); + if info.oneway_spam_suspect { // If this is both a oneway spam suspect and a failure, we report it twice. This is // useful in case the transaction failed with BR_TRANSACTION_PENDING_FROZEN. @@ -1345,6 +1348,7 @@ fn transaction(self: &Arc<Self>, cmd: u32, reader: &mut UserSliceReader) -> Resu fn transaction_inner(self: &Arc<Self>, info: &mut TransactionInfo) -> BinderResult { let node_ref = self.process.get_transaction_node(info.target_handle)?; info.to_pid = node_ref.node.owner.task.pid(); + info.to_node_debug_id = node_ref.node.debug_id; security::binder_transaction(&self.process.cred, &node_ref.node.owner.cred)?; // TODO: We need to ensure that there isn't a pending transaction in the work queue. How // could this happen? @@ -1431,6 +1435,8 @@ fn reply_inner(self: &Arc<Self>, info: &mut TransactionInfo) -> BinderResult { orig.from .deliver_reply(Err(BR_FAILED_REPLY), &orig, Some(ee)); info.reply = BR_FAILED_REPLY; + info.errno = param; + info.error_line = Some(err.line); err.reply = BR_TRANSACTION_COMPLETE; err }); @@ -1441,6 +1447,7 @@ fn reply_inner(self: &Arc<Self>, info: &mut TransactionInfo) -> BinderResult { fn oneway_transaction_inner(self: &Arc<Self>, info: &mut TransactionInfo) -> BinderResult { let node_ref = self.process.get_transaction_node(info.target_handle)?; info.to_pid = node_ref.node.owner.task.pid(); + info.to_node_debug_id = node_ref.node.debug_id; security::binder_transaction(&self.process.cred, &node_ref.node.owner.cred)?; let transaction = Transaction::new(node_ref, None, self, info)?; let code = if self.process.is_oneway_spam_detection_enabled() && info.oneway_spam_suspect { diff --git a/drivers/android/binder/transaction.rs b/drivers/android/binder/transaction.rs index 245f1556b5db..693644ef0b70 100644 --- a/drivers/android/binder/transaction.rs +++ b/drivers/android/binder/transaction.rs @@ -7,8 +7,9 @@ prelude::*, seq_file::SeqFile, seq_print, + str::BStr, sync::atomic::{ordering::Relaxed, Atomic}, - sync::{Arc, SpinLock}, + sync::{Arc, SetOnce, SpinLock}, task::{Kuid, Pid}, time::{Instant, Monotonic}, types::ScopeGuard, @@ -18,7 +19,7 @@ use crate::{ allocation::{Allocation, TranslatedFds}, defs::*, - error::{BinderError, BinderResult}, + error::{BinderError, BinderResult, ErrorLocation}, netlink::Report, node::{Node, NodeRef}, process::{Process, ProcessInner}, @@ -54,12 +55,195 @@ pub(crate) fn is_oneway(self) -> bool { } } +const LOG_SIZE: usize = 32; + +pub(crate) static TRANSACTION_LOG: TransactionLog = TransactionLog::new(); +pub(crate) static FAILED_TRANSACTION_LOG: TransactionLog = TransactionLog::new(); + +#[derive(Copy, Clone)] +enum CallType { + Call, + Async, + Reply, +} + +#[derive(Copy, Clone)] +pub(crate) struct TransactionLogEntry { + debug_id: usize, + call_type: CallType, + from_proc: Pid, + from_thread: Pid, + // The kernel ignores `target.handle` on replies (where `libbinder` passes `-1` / `0xffffffff`), + // and C Binder stores and prints this field as a signed `int` (`%d`). + target_handle: i32, + to_proc: Pid, + to_thread: Pid, + to_node: usize, + data_size: usize, + offsets_size: usize, + return_error_line: Option<ErrorLocation>, + return_error: u32, + return_error_param: i32, + context_name: [u8; 16], +} + +impl TransactionLogEntry { + const fn empty() -> Self { + Self { + debug_id: 0, + call_type: CallType::Call, + from_proc: 0, + from_thread: 0, + target_handle: 0, + to_proc: 0, + to_thread: 0, + to_node: 0, + data_size: 0, + offsets_size: 0, + return_error_line: None, + return_error: 0, + return_error_param: 0, + context_name: [0; 16], + } + } + + fn new(info: &TransactionInfo, ctx: &crate::Context) -> Self { + let call_type = if info.is_reply { + CallType::Reply + } else if info.is_oneway() { + CallType::Async + } else { + CallType::Call + }; + let name_bytes = ctx.name.to_bytes(); + let mut context_name = [0u8; 16]; + let len = usize::min(name_bytes.len(), context_name.len()); + context_name[..len].copy_from_slice(&name_bytes[..len]); + + let failed = info.reply != 0 && info.reply != BR_TRANSACTION_PENDING_FROZEN; + Self { + debug_id: info.debug_id, + call_type, + from_proc: info.from_pid, + from_thread: info.from_tid, + target_handle: info.target_handle as i32, + to_proc: info.to_pid, + to_thread: info.to_tid, + to_node: info.to_node_debug_id, + data_size: info.data_size, + offsets_size: info.offsets_size, + return_error_line: if failed { info.error_line } else { None }, + return_error: if failed { info.reply } else { 0 }, + return_error_param: if failed { info.errno } else { 0 }, + context_name, + } + } +} + +#[pin_data] +#[repr(align(64))] +struct TransactionLogSlot { + #[pin] + entry: SpinLock<TransactionLogEntry>, +} + +pub(crate) struct TransactionLog { + cur: Atomic<usize>, + entries: SetOnce<Pin<KBox<[TransactionLogSlot; LOG_SIZE]>>>, +} + +impl TransactionLog { + const fn new() -> Self { + Self { + cur: Atomic::new(0), + entries: SetOnce::new(), + } + } + + pub(crate) fn init(&self) -> Result<()> { + let entries = KBox::pin_init( + pin_init::pin_init_array_from_fn(|_| { + pin_init!(TransactionLogSlot { + entry <- kernel::new_spinlock!( + TransactionLogEntry::empty(), + "TransactionLog::entries" + ), + }) + }), + GFP_KERNEL, + )?; + self.entries.populate(entries); + Ok(()) + } + + fn add(&self, entry: &TransactionLogEntry) { + let Some(entries) = self.entries.as_ref() else { + return; + }; + let idx = self.cur.fetch_add(1, Relaxed) % LOG_SIZE; + let mut slot = entries[idx].entry.lock(); + // Avoid overwriting a newer entry if the ring buffer wraps around between `fetch_add` and + // acquiring the lock. + // CAST: Overflowing behavior of this cast is intentional to handle `debug_id` wrap-around. + let diff = slot.debug_id.wrapping_sub(entry.debug_id) as isize; + if slot.debug_id == 0 || diff < 0 { + *slot = *entry; + } + } + + pub(crate) fn debug_print(&self, m: &SeqFile) { + let Some(entries) = self.entries.as_ref() else { + return; + }; + let cur = self.cur.load(Relaxed); + for i in 0..LOG_SIZE { + let idx = cur.wrapping_add(i) % LOG_SIZE; + let entry = *entries[idx].entry.lock(); + if entry.debug_id == 0 { + continue; + } + let call_type = match entry.call_type { + CallType::Call => "call ", + CallType::Async => "async", + CallType::Reply => "reply", + }; + let ctx_name = match CStr::from_bytes_until_nul(&entry.context_name) { + Ok(cstr) => BStr::from_bytes(cstr.to_bytes()), + Err(_) => BStr::from_bytes(&entry.context_name), + }; + let return_error_line: &dyn kernel::fmt::Display = match &entry.return_error_line { + Some(line) => line, + None => &0, + }; + seq_print!( + m, + "{}: {} from {}:{} to {}:{} context {} node {} handle {} size {}:{} ret {}/{} l={}\n", + entry.debug_id, + call_type, + entry.from_proc, + entry.from_thread, + entry.to_proc, + entry.to_thread, + ctx_name, + entry.to_node, + entry.target_handle, + entry.data_size, + entry.offsets_size, + entry.return_error, + entry.return_error_param, + return_error_line, + ); + } + } +} + #[derive(Zeroable)] pub(crate) struct TransactionInfo { pub(crate) from_pid: Pid, pub(crate) from_tid: Pid, pub(crate) to_pid: Pid, pub(crate) to_tid: Pid, + pub(crate) to_node_debug_id: usize, pub(crate) code: u32, pub(crate) flags: TransactionFlags, pub(crate) data_ptr: UserPtr, @@ -70,6 +254,7 @@ pub(crate) struct TransactionInfo { pub(crate) target_handle: u32, pub(crate) errno: i32, pub(crate) reply: u32, + pub(crate) error_line: Option<ErrorLocation>, pub(crate) oneway_spam_suspect: bool, pub(crate) is_reply: bool, pub(crate) debug_id: usize, @@ -81,6 +266,14 @@ pub(crate) fn is_oneway(&self) -> bool { self.flags.is_oneway() } + pub(crate) fn write_log(&self, ctx: &crate::Context) { + let entry = TransactionLogEntry::new(self, ctx); + TRANSACTION_LOG.add(&entry); + if self.reply != 0 && self.reply != BR_TRANSACTION_PENDING_FROZEN { + FAILED_TRANSACTION_LOG.add(&entry); + } + } + pub(crate) fn report_netlink(&self, reply: u32, ctx: &crate::Context) { if let Err(err) = self.report_netlink_inner(reply, ctx) { pr_warn!( -- 2.56.0.rc1.315.gc6ed9934b7-goog ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH v2 3/3] rust_binder: add transaction_log and failed_transaction_log 2026-09-30 13:56 ` [PATCH v2 3/3] rust_binder: add transaction_log and failed_transaction_log Alice Ryhl @ 2026-10-01 12:34 ` Greg Kroah-Hartman 2026-10-01 14:11 ` [PATCH v2 3/3 rebased] " Alice Ryhl 0 siblings, 1 reply; 6+ messages in thread From: Greg Kroah-Hartman @ 2026-10-01 12:34 UTC (permalink / raw) To: Alice Ryhl Cc: Carlos Llamas, Miguel Ojeda, Boqun Feng, Gary Guo, Björn Roy Baron, Benno Lossin, Andreas Hindborg, Trevor Gross, Danilo Krummrich, Daniel Almeida, Tamir Duberstein, Alexandre Courbot, Onur Özkan, linux-kernel, rust-for-linux On Wed, Sep 30, 2026 at 01:56:38PM +0000, Alice Ryhl wrote: > Implement the binder_logs/transaction_log and > binder_logs/failed_transaction_log binderfs files in Rust Binder, > matching the circular 32-entry transaction logs in C Binder. > > Example output from /dev/binderfs/binder_logs/transaction_log: > > 261251: call from 6157:6171 to 391:0 context binder node 170 handle 34 size 256:0 ret 0/0 l=0 > 261254: async from 606:783 to 669:0 context binder node 2048 handle 2 size 144:0 ret 0/0 l=0 > 261255: reply from 391:552 to 6157:6171 context binder node 0 handle -1 size 2436:8 ret 0/0 l=0 > > Example output from /dev/binderfs/binder_logs/failed_transaction_log: > > 194556: async from 6646:6853 to 7452:0 context binder node 177682 handle 450 size 160:0 ret 29189/0 l=process.rs:1081 > 194846: reply from 6646:6775 to 7452:7544 context binder node 0 handle -1 size 8:0 ret 29201/0 l=process.rs:1081 > 201573: call from 7771:7793 to 6646:0 context binder node 198883 handle 28 size 0:0 ret 29189/0 l=process.rs:1081 > > Unlike C Binder, which writes to log entries without a lock using memory > barriers (smp_wmb/smp_rmb) and a debug_id_done field, each > TransactionLog uses an atomic index cursor with 32 cacheline-aligned > SpinLock<TransactionLogEntry> slots initialized in BinderModule::init > via SetOnce<_>. Using a SpinLock per slot avoids data races (such as > tearing when the ring buffer wraps around while an entry is being > printed) without requiring atomic accesses for every field, and has very > low risk of contention: concurrent transactions are spread across 32 > separate cacheline-aligned locks, each lock is only held briefly for a > fixed-size copy, and two writers only contend on a slot if 32 > transactions occur before a single copy completes. > > Assisted-by: LLM > Signed-off-by: Alice Ryhl <aliceryhl@google.com> > --- > drivers/android/binder/rust_binder_internal.h | 1 + > drivers/android/binder/rust_binder_main.rs | 24 ++++ > drivers/android/binder/rust_binderfs.c | 19 +++ > drivers/android/binder/thread.rs | 7 + > drivers/android/binder/transaction.rs | 197 +++++++++++++++++++++++++- > 5 files changed, 246 insertions(+), 2 deletions(-) > > diff --git a/drivers/android/binder/rust_binder_internal.h b/drivers/android/binder/rust_binder_internal.h > index 78288fe7964d..50a50df14c77 100644 > --- a/drivers/android/binder/rust_binder_internal.h > +++ b/drivers/android/binder/rust_binder_internal.h > @@ -44,6 +44,7 @@ struct binder_device { > int rust_binder_stats_show(struct seq_file *m, void *unused); > int rust_binder_state_show(struct seq_file *m, void *unused); > int rust_binder_transactions_show(struct seq_file *m, void *unused); > +int rust_binder_transaction_log_show(struct seq_file *m, void *unused); > int rust_binder_proc_show(struct seq_file *m, void *pid); > > extern const struct file_operations rust_binder_fops; > diff --git a/drivers/android/binder/rust_binder_main.rs b/drivers/android/binder/rust_binder_main.rs > index bd26ef96fefb..dd168a932d7a 100644 > --- a/drivers/android/binder/rust_binder_main.rs > +++ b/drivers/android/binder/rust_binder_main.rs > @@ -310,6 +310,9 @@ fn init(_module: &'static kernel::ThisModule) -> Result<Self> { > // SAFETY: The module initializer never runs twice, so we only call this once. > unsafe { crate::context::CONTEXTS.init() }; > > + crate::transaction::TRANSACTION_LOG.init()?; > + crate::transaction::FAILED_TRANSACTION_LOG.init()?; > + > let netlink = crate::netlink::BINDER_NL_FAMILY.register()?; > BINDER_SHRINKER.register(c"android-binder")?; > > @@ -550,6 +553,27 @@ unsafe impl<T> Sync for AssertSync<T> {} > 0 > } > > +/// # Safety > +/// Only called by binderfs. > +#[no_mangle] > +unsafe extern "C" fn rust_binder_transaction_log_show( > + ptr: *mut seq_file, > + _: *mut kernel::ffi::c_void, > +) -> kernel::ffi::c_int { > + // SAFETY: Accessing the private field of `seq_file` is okay. > + let is_failed = !unsafe { (*ptr).private }.is_null(); > + // SAFETY: The caller ensures that the pointer is valid and exclusive for the duration in which > + // this method is called. > + let m = unsafe { SeqFile::from_raw(ptr) }; > + let log = if is_failed { > + &transaction::FAILED_TRANSACTION_LOG > + } else { > + &transaction::TRANSACTION_LOG > + }; > + log.debug_print(m); > + 0 > +} > + > fn rust_binder_transactions_show_impl(m: &SeqFile) -> Result<()> { > seq_print!(m, "binder transactions:\n"); > let contexts = context::get_all_contexts()?; > diff --git a/drivers/android/binder/rust_binderfs.c b/drivers/android/binder/rust_binderfs.c > index 300cc65562d1..ef83d5a502af 100644 > --- a/drivers/android/binder/rust_binderfs.c > +++ b/drivers/android/binder/rust_binderfs.c > @@ -46,6 +46,7 @@ > DEFINE_SHOW_ATTRIBUTE(rust_binder_stats); > DEFINE_SHOW_ATTRIBUTE(rust_binder_state); > DEFINE_SHOW_ATTRIBUTE(rust_binder_transactions); > +DEFINE_SHOW_ATTRIBUTE(rust_binder_transaction_log); > DEFINE_SHOW_ATTRIBUTE(rust_binder_proc); > > char *rust_binder_devices_param = CONFIG_ANDROID_BINDER_DEVICES; > @@ -603,6 +604,24 @@ static int init_binder_logs(struct super_block *sb) > goto out; > } > > + dentry = rust_binderfs_create_file(binder_logs_root_dir, > + "transaction_log", > + &rust_binder_transaction_log_fops, > + (void *)0); > + if (IS_ERR(dentry)) { > + ret = PTR_ERR(dentry); > + goto out; > + } > + > + dentry = rust_binderfs_create_file(binder_logs_root_dir, > + "failed_transaction_log", > + &rust_binder_transaction_log_fops, > + (void *)1); > + if (IS_ERR(dentry)) { > + ret = PTR_ERR(dentry); > + goto out; > + } > + > proc_log_dir = binderfs_create_dir(binder_logs_root_dir, "proc"); > if (IS_ERR(proc_log_dir)) { > ret = PTR_ERR(proc_log_dir); > diff --git a/drivers/android/binder/thread.rs b/drivers/android/binder/thread.rs > index 0891a36e9cbd..875daaef5f53 100644 > --- a/drivers/android/binder/thread.rs > +++ b/drivers/android/binder/thread.rs > @@ -1299,6 +1299,7 @@ fn transaction(self: &Arc<Self>, cmd: u32, reader: &mut UserSliceReader) -> Resu > self.push_return_work(err.reply); > if err.reply != BR_TRANSACTION_COMPLETE { > info.reply = err.reply; > + info.error_line = Some(err.line); > if let Some(source) = &err.source { > info.errno = source.to_errno(); > > @@ -1330,6 +1331,8 @@ fn transaction(self: &Arc<Self>, cmd: u32, reader: &mut UserSliceReader) -> Resu > } > } > > + info.write_log(&self.process.ctx); > + > if info.oneway_spam_suspect { > // If this is both a oneway spam suspect and a failure, we report it twice. This is > // useful in case the transaction failed with BR_TRANSACTION_PENDING_FROZEN. > @@ -1345,6 +1348,7 @@ fn transaction(self: &Arc<Self>, cmd: u32, reader: &mut UserSliceReader) -> Resu > fn transaction_inner(self: &Arc<Self>, info: &mut TransactionInfo) -> BinderResult { > let node_ref = self.process.get_transaction_node(info.target_handle)?; > info.to_pid = node_ref.node.owner.task.pid(); > + info.to_node_debug_id = node_ref.node.debug_id; > security::binder_transaction(&self.process.cred, &node_ref.node.owner.cred)?; > // TODO: We need to ensure that there isn't a pending transaction in the work queue. How > // could this happen? > @@ -1431,6 +1435,8 @@ fn reply_inner(self: &Arc<Self>, info: &mut TransactionInfo) -> BinderResult { > orig.from > .deliver_reply(Err(BR_FAILED_REPLY), &orig, Some(ee)); > info.reply = BR_FAILED_REPLY; > + info.errno = param; > + info.error_line = Some(err.line); > err.reply = BR_TRANSACTION_COMPLETE; > err > }); > @@ -1441,6 +1447,7 @@ fn reply_inner(self: &Arc<Self>, info: &mut TransactionInfo) -> BinderResult { > fn oneway_transaction_inner(self: &Arc<Self>, info: &mut TransactionInfo) -> BinderResult { > let node_ref = self.process.get_transaction_node(info.target_handle)?; > info.to_pid = node_ref.node.owner.task.pid(); > + info.to_node_debug_id = node_ref.node.debug_id; > security::binder_transaction(&self.process.cred, &node_ref.node.owner.cred)?; > let transaction = Transaction::new(node_ref, None, self, info)?; > let code = if self.process.is_oneway_spam_detection_enabled() && info.oneway_spam_suspect { > diff --git a/drivers/android/binder/transaction.rs b/drivers/android/binder/transaction.rs > index 245f1556b5db..693644ef0b70 100644 > --- a/drivers/android/binder/transaction.rs > +++ b/drivers/android/binder/transaction.rs > @@ -7,8 +7,9 @@ > prelude::*, > seq_file::SeqFile, > seq_print, > + str::BStr, > sync::atomic::{ordering::Relaxed, Atomic}, > - sync::{Arc, SpinLock}, > + sync::{Arc, SetOnce, SpinLock}, > task::{Kuid, Pid}, > time::{Instant, Monotonic}, > types::ScopeGuard, > @@ -18,7 +19,7 @@ > use crate::{ > allocation::{Allocation, TranslatedFds}, > defs::*, > - error::{BinderError, BinderResult}, > + error::{BinderError, BinderResult, ErrorLocation}, > netlink::Report, > node::{Node, NodeRef}, > process::{Process, ProcessInner}, > @@ -54,12 +55,195 @@ pub(crate) fn is_oneway(self) -> bool { > } > } > > +const LOG_SIZE: usize = 32; > + > +pub(crate) static TRANSACTION_LOG: TransactionLog = TransactionLog::new(); > +pub(crate) static FAILED_TRANSACTION_LOG: TransactionLog = TransactionLog::new(); > + > +#[derive(Copy, Clone)] > +enum CallType { > + Call, > + Async, > + Reply, > +} > + > +#[derive(Copy, Clone)] > +pub(crate) struct TransactionLogEntry { > + debug_id: usize, > + call_type: CallType, > + from_proc: Pid, > + from_thread: Pid, > + // The kernel ignores `target.handle` on replies (where `libbinder` passes `-1` / `0xffffffff`), > + // and C Binder stores and prints this field as a signed `int` (`%d`). > + target_handle: i32, > + to_proc: Pid, > + to_thread: Pid, > + to_node: usize, > + data_size: usize, > + offsets_size: usize, > + return_error_line: Option<ErrorLocation>, > + return_error: u32, > + return_error_param: i32, > + context_name: [u8; 16], > +} > + > +impl TransactionLogEntry { > + const fn empty() -> Self { > + Self { > + debug_id: 0, > + call_type: CallType::Call, > + from_proc: 0, > + from_thread: 0, > + target_handle: 0, > + to_proc: 0, > + to_thread: 0, > + to_node: 0, > + data_size: 0, > + offsets_size: 0, > + return_error_line: None, > + return_error: 0, > + return_error_param: 0, > + context_name: [0; 16], > + } > + } > + > + fn new(info: &TransactionInfo, ctx: &crate::Context) -> Self { > + let call_type = if info.is_reply { > + CallType::Reply > + } else if info.is_oneway() { > + CallType::Async > + } else { > + CallType::Call > + }; > + let name_bytes = ctx.name.to_bytes(); > + let mut context_name = [0u8; 16]; > + let len = usize::min(name_bytes.len(), context_name.len()); > + context_name[..len].copy_from_slice(&name_bytes[..len]); > + > + let failed = info.reply != 0 && info.reply != BR_TRANSACTION_PENDING_FROZEN; > + Self { > + debug_id: info.debug_id, > + call_type, > + from_proc: info.from_pid, > + from_thread: info.from_tid, > + target_handle: info.target_handle as i32, > + to_proc: info.to_pid, > + to_thread: info.to_tid, > + to_node: info.to_node_debug_id, > + data_size: info.data_size, > + offsets_size: info.offsets_size, > + return_error_line: if failed { info.error_line } else { None }, > + return_error: if failed { info.reply } else { 0 }, > + return_error_param: if failed { info.errno } else { 0 }, > + context_name, > + } > + } > +} > + > +#[pin_data] > +#[repr(align(64))] > +struct TransactionLogSlot { > + #[pin] > + entry: SpinLock<TransactionLogEntry>, > +} > + > +pub(crate) struct TransactionLog { > + cur: Atomic<usize>, > + entries: SetOnce<Pin<KBox<[TransactionLogSlot; LOG_SIZE]>>>, > +} > + > +impl TransactionLog { > + const fn new() -> Self { > + Self { > + cur: Atomic::new(0), > + entries: SetOnce::new(), > + } > + } > + > + pub(crate) fn init(&self) -> Result<()> { > + let entries = KBox::pin_init( > + pin_init::pin_init_array_from_fn(|_| { > + pin_init!(TransactionLogSlot { > + entry <- kernel::new_spinlock!( > + TransactionLogEntry::empty(), > + "TransactionLog::entries" > + ), > + }) > + }), > + GFP_KERNEL, > + )?; > + self.entries.populate(entries); > + Ok(()) > + } > + > + fn add(&self, entry: &TransactionLogEntry) { > + let Some(entries) = self.entries.as_ref() else { > + return; > + }; > + let idx = self.cur.fetch_add(1, Relaxed) % LOG_SIZE; > + let mut slot = entries[idx].entry.lock(); > + // Avoid overwriting a newer entry if the ring buffer wraps around between `fetch_add` and > + // acquiring the lock. > + // CAST: Overflowing behavior of this cast is intentional to handle `debug_id` wrap-around. > + let diff = slot.debug_id.wrapping_sub(entry.debug_id) as isize; > + if slot.debug_id == 0 || diff < 0 { > + *slot = *entry; > + } > + } > + > + pub(crate) fn debug_print(&self, m: &SeqFile) { > + let Some(entries) = self.entries.as_ref() else { > + return; > + }; > + let cur = self.cur.load(Relaxed); > + for i in 0..LOG_SIZE { > + let idx = cur.wrapping_add(i) % LOG_SIZE; > + let entry = *entries[idx].entry.lock(); > + if entry.debug_id == 0 { > + continue; > + } > + let call_type = match entry.call_type { > + CallType::Call => "call ", > + CallType::Async => "async", > + CallType::Reply => "reply", > + }; > + let ctx_name = match CStr::from_bytes_until_nul(&entry.context_name) { > + Ok(cstr) => BStr::from_bytes(cstr.to_bytes()), > + Err(_) => BStr::from_bytes(&entry.context_name), > + }; > + let return_error_line: &dyn kernel::fmt::Display = match &entry.return_error_line { > + Some(line) => line, > + None => &0, > + }; > + seq_print!( > + m, > + "{}: {} from {}:{} to {}:{} context {} node {} handle {} size {}:{} ret {}/{} l={}\n", > + entry.debug_id, > + call_type, > + entry.from_proc, > + entry.from_thread, > + entry.to_proc, > + entry.to_thread, > + ctx_name, > + entry.to_node, > + entry.target_handle, > + entry.data_size, > + entry.offsets_size, > + entry.return_error, > + entry.return_error_param, > + return_error_line, > + ); > + } > + } > +} > + > #[derive(Zeroable)] > pub(crate) struct TransactionInfo { > pub(crate) from_pid: Pid, > pub(crate) from_tid: Pid, > pub(crate) to_pid: Pid, > pub(crate) to_tid: Pid, > + pub(crate) to_node_debug_id: usize, > pub(crate) code: u32, > pub(crate) flags: TransactionFlags, > pub(crate) data_ptr: UserPtr, > @@ -70,6 +254,7 @@ pub(crate) struct TransactionInfo { > pub(crate) target_handle: u32, > pub(crate) errno: i32, > pub(crate) reply: u32, > + pub(crate) error_line: Option<ErrorLocation>, > pub(crate) oneway_spam_suspect: bool, > pub(crate) is_reply: bool, > pub(crate) debug_id: usize, > @@ -81,6 +266,14 @@ pub(crate) fn is_oneway(&self) -> bool { > self.flags.is_oneway() > } > > + pub(crate) fn write_log(&self, ctx: &crate::Context) { > + let entry = TransactionLogEntry::new(self, ctx); > + TRANSACTION_LOG.add(&entry); > + if self.reply != 0 && self.reply != BR_TRANSACTION_PENDING_FROZEN { > + FAILED_TRANSACTION_LOG.add(&entry); > + } > + } > + > pub(crate) fn report_netlink(&self, reply: u32, ctx: &crate::Context) { > if let Err(err) = self.report_netlink_inner(reply, ctx) { > pr_warn!( > > -- > 2.56.0.rc1.315.gc6ed9934b7-goog > This patch did not apply to the char-misc-testing branch :( ^ permalink raw reply [flat|nested] 6+ messages in thread
* [PATCH v2 3/3 rebased] rust_binder: add transaction_log and failed_transaction_log 2026-10-01 12:34 ` Greg Kroah-Hartman @ 2026-10-01 14:11 ` Alice Ryhl 0 siblings, 0 replies; 6+ messages in thread From: Alice Ryhl @ 2026-10-01 14:11 UTC (permalink / raw) To: gregkh Cc: a.hindborg, acourbot, aliceryhl, bjorn3_gh, boqun, cmllamas, dakr, daniel.almeida, gary, linux-kernel, lossin, ojeda, rust-for-linux, tamird, tmgross, work Implement the binder_logs/transaction_log and binder_logs/failed_transaction_log binderfs files in Rust Binder, matching the circular 32-entry transaction logs in C Binder. Example output from /dev/binderfs/binder_logs/transaction_log: 261251: call from 6157:6171 to 391:0 context binder node 170 handle 34 size 256:0 ret 0/0 l=0 261254: async from 606:783 to 669:0 context binder node 2048 handle 2 size 144:0 ret 0/0 l=0 261255: reply from 391:552 to 6157:6171 context binder node 0 handle -1 size 2436:8 ret 0/0 l=0 Example output from /dev/binderfs/binder_logs/failed_transaction_log: 194556: async from 6646:6853 to 7452:0 context binder node 177682 handle 450 size 160:0 ret 29189/0 l=process.rs:1081 194846: reply from 6646:6775 to 7452:7544 context binder node 0 handle -1 size 8:0 ret 29201/0 l=process.rs:1081 201573: call from 7771:7793 to 6646:0 context binder node 198883 handle 28 size 0:0 ret 29189/0 l=process.rs:1081 Unlike C Binder, which writes to log entries without a lock using memory barriers (smp_wmb/smp_rmb) and a debug_id_done field, each TransactionLog uses an atomic index cursor with 32 cacheline-aligned SpinLock<TransactionLogEntry> slots initialized in BinderModule::init via SetOnce<_>. Using a SpinLock per slot avoids data races (such as tearing when the ring buffer wraps around while an entry is being printed) without requiring atomic accesses for every field, and has very low risk of contention: concurrent transactions are spread across 32 separate cacheline-aligned locks, each lock is only held briefly for a fixed-size copy, and two writers only contend on a slot if 32 transactions occur before a single copy completes. Assisted-by: LLM Signed-off-by: Alice Ryhl <aliceryhl@google.com> --- Changes in v3: minor conflict resolution drivers/android/binder/rust_binder_internal.h | 1 + drivers/android/binder/rust_binder_main.rs | 24 +++ drivers/android/binder/rust_binderfs.c | 19 ++ drivers/android/binder/thread.rs | 7 + drivers/android/binder/transaction.rs | 197 +++++++++++++++++- 5 files changed, 246 insertions(+), 2 deletions(-) diff --git a/drivers/android/binder/rust_binder_internal.h b/drivers/android/binder/rust_binder_internal.h index 78288fe7964d..50a50df14c77 100644 --- a/drivers/android/binder/rust_binder_internal.h +++ b/drivers/android/binder/rust_binder_internal.h @@ -44,6 +44,7 @@ struct binder_device { int rust_binder_stats_show(struct seq_file *m, void *unused); int rust_binder_state_show(struct seq_file *m, void *unused); int rust_binder_transactions_show(struct seq_file *m, void *unused); +int rust_binder_transaction_log_show(struct seq_file *m, void *unused); int rust_binder_proc_show(struct seq_file *m, void *pid); extern const struct file_operations rust_binder_fops; diff --git a/drivers/android/binder/rust_binder_main.rs b/drivers/android/binder/rust_binder_main.rs index 89add66c0483..56c786475237 100644 --- a/drivers/android/binder/rust_binder_main.rs +++ b/drivers/android/binder/rust_binder_main.rs @@ -310,6 +310,9 @@ fn init(_module: &'static kernel::ThisModule) -> Result<Self> { // SAFETY: The module initializer never runs twice, so we only call this once. unsafe { crate::context::CONTEXTS.init() }; + crate::transaction::TRANSACTION_LOG.init()?; + crate::transaction::FAILED_TRANSACTION_LOG.init()?; + let netlink = crate::netlink::BINDER_NL_FAMILY.register()?; BINDER_SHRINKER.register(c"android-binder")?; @@ -550,6 +553,27 @@ unsafe impl<T> Sync for AssertSync<T> {} 0 } +/// # Safety +/// Only called by binderfs. +#[no_mangle] +unsafe extern "C" fn rust_binder_transaction_log_show( + ptr: *mut seq_file, + _: *mut kernel::ffi::c_void, +) -> kernel::ffi::c_int { + // SAFETY: Accessing the private field of `seq_file` is okay. + let is_failed = !unsafe { (*ptr).private }.is_null(); + // SAFETY: The caller ensures that the pointer is valid and exclusive for the duration in which + // this method is called. + let m = unsafe { SeqFile::from_raw(ptr) }; + let log = if is_failed { + &transaction::FAILED_TRANSACTION_LOG + } else { + &transaction::TRANSACTION_LOG + }; + log.debug_print(m); + 0 +} + fn rust_binder_transactions_show_impl(m: &SeqFile) -> Result { seq_print!(m, "binder transactions:\n"); let contexts = context::get_all_contexts()?; diff --git a/drivers/android/binder/rust_binderfs.c b/drivers/android/binder/rust_binderfs.c index acc83a179f38..25dc54ab45e9 100644 --- a/drivers/android/binder/rust_binderfs.c +++ b/drivers/android/binder/rust_binderfs.c @@ -46,6 +46,7 @@ DEFINE_SHOW_ATTRIBUTE(rust_binder_stats); DEFINE_SHOW_ATTRIBUTE(rust_binder_state); DEFINE_SHOW_ATTRIBUTE(rust_binder_transactions); +DEFINE_SHOW_ATTRIBUTE(rust_binder_transaction_log); DEFINE_SHOW_ATTRIBUTE(rust_binder_proc); char *rust_binder_devices_param = CONFIG_ANDROID_BINDER_DEVICES; @@ -611,6 +612,24 @@ static int init_binder_logs(struct super_block *sb) goto out; } + dentry = rust_binderfs_create_file(binder_logs_root_dir, + "transaction_log", + &rust_binder_transaction_log_fops, + (void *)0); + if (IS_ERR(dentry)) { + ret = PTR_ERR(dentry); + goto out; + } + + dentry = rust_binderfs_create_file(binder_logs_root_dir, + "failed_transaction_log", + &rust_binder_transaction_log_fops, + (void *)1); + if (IS_ERR(dentry)) { + ret = PTR_ERR(dentry); + goto out; + } + proc_log_dir = binderfs_create_dir(binder_logs_root_dir, "proc"); if (IS_ERR(proc_log_dir)) { ret = PTR_ERR(proc_log_dir); diff --git a/drivers/android/binder/thread.rs b/drivers/android/binder/thread.rs index c91c885c1292..4df006b98ebf 100644 --- a/drivers/android/binder/thread.rs +++ b/drivers/android/binder/thread.rs @@ -1332,6 +1332,7 @@ fn transaction(self: &Arc<Self>, cmd: u32, reader: &mut UserSliceReader) -> Resu self.push_return_work(err.reply); if err.reply != BR_TRANSACTION_COMPLETE { info.reply = err.reply; + info.error_line = Some(err.line); if let Some(source) = &err.source { info.errno = source.to_errno(); @@ -1363,6 +1364,8 @@ fn transaction(self: &Arc<Self>, cmd: u32, reader: &mut UserSliceReader) -> Resu } } + info.write_log(&self.process.ctx); + if info.oneway_spam_suspect { // If this is both a oneway spam suspect and a failure, we report it twice. This is // useful in case the transaction failed with BR_TRANSACTION_PENDING_FROZEN. @@ -1378,6 +1381,7 @@ fn transaction(self: &Arc<Self>, cmd: u32, reader: &mut UserSliceReader) -> Resu fn transaction_inner(self: &Arc<Self>, info: &mut TransactionInfo) -> BinderResult { let node_ref = self.process.get_transaction_node(info.target_handle)?; info.to_pid = node_ref.node.owner.task.pid(); + info.to_node_debug_id = node_ref.node.debug_id; security::binder_transaction(&self.process.cred, &node_ref.node.owner.cred)?; // TODO: We need to ensure that there isn't a pending transaction in the work queue. How // could this happen? @@ -1472,6 +1476,8 @@ fn reply_inner(self: &Arc<Self>, info: &mut TransactionInfo) -> BinderResult { orig.from .deliver_reply(Err(BR_FAILED_REPLY), &orig, Some(ee)); info.reply = BR_FAILED_REPLY; + info.errno = param; + info.error_line = Some(err.line); err.reply = BR_TRANSACTION_COMPLETE; err }); @@ -1482,6 +1488,7 @@ fn reply_inner(self: &Arc<Self>, info: &mut TransactionInfo) -> BinderResult { fn oneway_transaction_inner(self: &Arc<Self>, info: &mut TransactionInfo) -> BinderResult { let node_ref = self.process.get_transaction_node(info.target_handle)?; info.to_pid = node_ref.node.owner.task.pid(); + info.to_node_debug_id = node_ref.node.debug_id; security::binder_transaction(&self.process.cred, &node_ref.node.owner.cred)?; let transaction = Transaction::new(node_ref, None, self, info)?; let code = if self.process.is_oneway_spam_detection_enabled() && info.oneway_spam_suspect { diff --git a/drivers/android/binder/transaction.rs b/drivers/android/binder/transaction.rs index e56272b00be4..e627522141b8 100644 --- a/drivers/android/binder/transaction.rs +++ b/drivers/android/binder/transaction.rs @@ -7,8 +7,9 @@ prelude::*, seq_file::SeqFile, seq_print, + str::BStr, sync::atomic::{ordering::Relaxed, Atomic}, - sync::{Arc, SpinLock}, + sync::{Arc, SetOnce, SpinLock}, task::{Kuid, Pid}, time::{Instant, Monotonic}, types::ScopeGuard, @@ -18,7 +19,7 @@ use crate::{ allocation::{Allocation, TranslatedFds}, defs::*, - error::{BinderError, BinderResult}, + error::{BinderError, BinderResult, ErrorLocation}, netlink::Report, node::{Node, NodeRef}, process::{Process, ProcessInner}, @@ -56,12 +57,195 @@ pub(crate) fn is_oneway(self) -> bool { } } +const LOG_SIZE: usize = 32; + +pub(crate) static TRANSACTION_LOG: TransactionLog = TransactionLog::new(); +pub(crate) static FAILED_TRANSACTION_LOG: TransactionLog = TransactionLog::new(); + +#[derive(Copy, Clone)] +enum CallType { + Call, + Async, + Reply, +} + +#[derive(Copy, Clone)] +pub(crate) struct TransactionLogEntry { + debug_id: usize, + call_type: CallType, + from_proc: Pid, + from_thread: Pid, + // The kernel ignores `target.handle` on replies (where `libbinder` passes `-1` / `0xffffffff`), + // and C Binder stores and prints this field as a signed `int` (`%d`). + target_handle: i32, + to_proc: Pid, + to_thread: Pid, + to_node: usize, + data_size: usize, + offsets_size: usize, + return_error_line: Option<ErrorLocation>, + return_error: u32, + return_error_param: i32, + context_name: [u8; 16], +} + +impl TransactionLogEntry { + const fn empty() -> Self { + Self { + debug_id: 0, + call_type: CallType::Call, + from_proc: 0, + from_thread: 0, + target_handle: 0, + to_proc: 0, + to_thread: 0, + to_node: 0, + data_size: 0, + offsets_size: 0, + return_error_line: None, + return_error: 0, + return_error_param: 0, + context_name: [0; 16], + } + } + + fn new(info: &TransactionInfo, ctx: &crate::Context) -> Self { + let call_type = if info.is_reply { + CallType::Reply + } else if info.is_oneway() { + CallType::Async + } else { + CallType::Call + }; + let name_bytes = ctx.name.to_bytes(); + let mut context_name = [0u8; 16]; + let len = usize::min(name_bytes.len(), context_name.len()); + context_name[..len].copy_from_slice(&name_bytes[..len]); + + let failed = info.reply != 0 && info.reply != BR_TRANSACTION_PENDING_FROZEN; + Self { + debug_id: info.debug_id, + call_type, + from_proc: info.from_pid, + from_thread: info.from_tid, + target_handle: info.target_handle as i32, + to_proc: info.to_pid, + to_thread: info.to_tid, + to_node: info.to_node_debug_id, + data_size: info.data_size, + offsets_size: info.offsets_size, + return_error_line: if failed { info.error_line } else { None }, + return_error: if failed { info.reply } else { 0 }, + return_error_param: if failed { info.errno } else { 0 }, + context_name, + } + } +} + +#[pin_data] +#[repr(align(64))] +struct TransactionLogSlot { + #[pin] + entry: SpinLock<TransactionLogEntry>, +} + +pub(crate) struct TransactionLog { + cur: Atomic<usize>, + entries: SetOnce<Pin<KBox<[TransactionLogSlot; LOG_SIZE]>>>, +} + +impl TransactionLog { + const fn new() -> Self { + Self { + cur: Atomic::new(0), + entries: SetOnce::new(), + } + } + + pub(crate) fn init(&self) -> Result { + let entries = KBox::pin_init( + pin_init::pin_init_array_from_fn(|_| { + pin_init!(TransactionLogSlot { + entry <- kernel::new_spinlock!( + TransactionLogEntry::empty(), + "TransactionLog::entries" + ), + }) + }), + GFP_KERNEL, + )?; + self.entries.populate(entries); + Ok(()) + } + + fn add(&self, entry: &TransactionLogEntry) { + let Some(entries) = self.entries.as_ref() else { + return; + }; + let idx = self.cur.fetch_add(1, Relaxed) % LOG_SIZE; + let mut slot = entries[idx].entry.lock(); + // Avoid overwriting a newer entry if the ring buffer wraps around between `fetch_add` and + // acquiring the lock. + // CAST: Overflowing behavior of this cast is intentional to handle `debug_id` wrap-around. + let diff = slot.debug_id.wrapping_sub(entry.debug_id) as isize; + if slot.debug_id == 0 || diff < 0 { + *slot = *entry; + } + } + + pub(crate) fn debug_print(&self, m: &SeqFile) { + let Some(entries) = self.entries.as_ref() else { + return; + }; + let cur = self.cur.load(Relaxed); + for i in 0..LOG_SIZE { + let idx = cur.wrapping_add(i) % LOG_SIZE; + let entry = *entries[idx].entry.lock(); + if entry.debug_id == 0 { + continue; + } + let call_type = match entry.call_type { + CallType::Call => "call ", + CallType::Async => "async", + CallType::Reply => "reply", + }; + let ctx_name = match CStr::from_bytes_until_nul(&entry.context_name) { + Ok(cstr) => BStr::from_bytes(cstr.to_bytes()), + Err(_) => BStr::from_bytes(&entry.context_name), + }; + let return_error_line: &dyn kernel::fmt::Display = match &entry.return_error_line { + Some(line) => line, + None => &0, + }; + seq_print!( + m, + "{}: {} from {}:{} to {}:{} context {} node {} handle {} size {}:{} ret {}/{} l={}\n", + entry.debug_id, + call_type, + entry.from_proc, + entry.from_thread, + entry.to_proc, + entry.to_thread, + ctx_name, + entry.to_node, + entry.target_handle, + entry.data_size, + entry.offsets_size, + entry.return_error, + entry.return_error_param, + return_error_line, + ); + } + } +} + #[derive(Zeroable)] pub(crate) struct TransactionInfo { pub(crate) from_pid: Pid, pub(crate) from_tid: Pid, pub(crate) to_pid: Pid, pub(crate) to_tid: Pid, + pub(crate) to_node_debug_id: usize, pub(crate) code: u32, pub(crate) flags: TransactionFlags, pub(crate) data_ptr: UserPtr, @@ -72,6 +256,7 @@ pub(crate) struct TransactionInfo { pub(crate) target_handle: u32, pub(crate) errno: i32, pub(crate) reply: u32, + pub(crate) error_line: Option<ErrorLocation>, pub(crate) oneway_spam_suspect: bool, pub(crate) is_reply: bool, pub(crate) debug_id: usize, @@ -83,6 +268,14 @@ pub(crate) fn is_oneway(&self) -> bool { self.flags.is_oneway() } + pub(crate) fn write_log(&self, ctx: &crate::Context) { + let entry = TransactionLogEntry::new(self, ctx); + TRANSACTION_LOG.add(&entry); + if self.reply != 0 && self.reply != BR_TRANSACTION_PENDING_FROZEN { + FAILED_TRANSACTION_LOG.add(&entry); + } + } + pub(crate) fn report_netlink(&self, reply: u32, ctx: &crate::Context) { if let Err(err) = self.report_netlink_inner(reply, ctx) { pr_warn!( -- 2.56.0.rc1.315.gc6ed9934b7-goog ^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2026-10-01 14:11 UTC | newest] Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2026-09-30 13:56 [PATCH v2 0/3] rust_binder: error line numbers and failed_transaction_log Alice Ryhl 2026-09-30 13:56 ` [PATCH v2 1/3] rust_binder: never return 0 from next_debug_id Alice Ryhl 2026-09-30 13:56 ` [PATCH v2 2/3] rust_binder: track caller location in BinderError Alice Ryhl 2026-09-30 13:56 ` [PATCH v2 3/3] rust_binder: add transaction_log and failed_transaction_log Alice Ryhl 2026-10-01 12:34 ` Greg Kroah-Hartman 2026-10-01 14:11 ` [PATCH v2 3/3 rebased] " Alice Ryhl
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox
all inboxes | Powered by JetHome®