floss: Revise logging for Virtual/RealHciIndex (a3e963c1) · Commits · e / os / android_packages_modules_Bluetooth

system/gd/rust/linux/mgmt/src/bluetooth_manager.rs

+5 −5

Original line number	Diff line number	Diff line
		@@ -85,7 +85,7 @@ impl IBluetoothManager for BluetoothManager {
		warn!("Starting {}", hci);

		if !config_util::modify_hci_n_enabled(hci, true) {
		error!("Config is not successfully modified");
		error!("{}: Config is not successfully modified", hci);
		}

		// Store that this adapter is meant to be started in state machine.
		@@ -93,12 +93,12 @@ impl IBluetoothManager for BluetoothManager {

		// Ignore the request if adapter is already enabled or not present.
		if self.is_adapter_enabled(hci) {
		warn!("Adapter {} is already enabled.", hci);
		warn!("{} is already enabled.", hci);
		return;
		}

		if !self.is_adapter_present(hci) {
		warn!("Adapter {} is not present.", hci);
		warn!("{} is not present.", hci);
		return;
		}

		@@ -110,7 +110,7 @@ impl IBluetoothManager for BluetoothManager {
		warn!("Stopping {}", hci);

		if !config_util::modify_hci_n_enabled(hci, false) {
		error!("Config is not successfully modified");
		error!("{}: Config is not successfully modified", hci);
		}

		// Store that this adapter is meant to be stopped in state machine.
		@@ -118,7 +118,7 @@ impl IBluetoothManager for BluetoothManager {

		// Ignore the request if adapter is already disabled.
		if !self.is_adapter_enabled(hci) {
		warn!("Adapter {} is already stopped", hci);
		warn!("{} is already stopped", hci);
		return;
		}

system/gd/rust/linux/mgmt/src/config_util.rs

+7 −6

Original line number	Diff line number	Diff line
		@@ -78,7 +78,7 @@ pub fn is_hci_n_enabled(hci: VirtualHciIndex) -> bool {
		fn is_hci_n_enabled_internal(config: String, hci: VirtualHciIndex) -> Option<bool> {
		serde_json::from_str::<Value>(config.as_str())
		.ok()?
		.get(format!("hci{}", hci))?
		.get(format!("hci{}", hci.to_i32()))?
		.as_object()?
		.get("enabled")?
		.as_bool()
		@@ -111,7 +111,7 @@ fn modify_hci_n_enabled_internal(
		hci: VirtualHciIndex,
		enabled: bool,
		) -> Option<String> {
		let hci_str = format!("hci{}", hci);
		let hci_str = format!("hci{}", hci.to_i32());
		let mut o = serde_json::from_str::<Value>(config.as_str()).ok()?;
		match o.get_mut(hci_str.clone()) {
		Some(section) => {
		@@ -164,16 +164,17 @@ fn list_hci_devices_string() -> Vec<String> {

		/// Check whether a certain hci device exists in sysfs.
		pub fn check_hci_device_exists(hci: RealHciIndex) -> bool {
		Path::new(format!("{}/hci{}", HCI_DEVICES_DIR, hci).as_str()).exists()
		Path::new(format!("{}/hci{}", HCI_DEVICES_DIR, hci.to_i32()).as_str()).exists()
		}

		/// Get the devpath for a given hci index. This gives a stable path that can be
		/// used to identify a device even as the hci index fluctuates.
		pub fn get_devpath_for_hci(hci: RealHciIndex) -> Option<String> {
		match std::fs::canonicalize(format!("{}/hci{}/device", HCI_DEVICES_DIR, hci).as_str()) {
		match std::fs::canonicalize(format!("{}/hci{}/device", HCI_DEVICES_DIR, hci.to_i32()).as_str())
		{
		Ok(p) => Some(p.into_os_string().into_string().ok()?),
		Err(e) => {
		log::debug!("Failed to get devpath for hci{} with error: {}", hci, e);
		log::debug!("Failed to get devpath for {} with error: {}", hci, e);
		None
		}
		}
		@@ -190,7 +191,7 @@ pub fn list_pid_files(pid_dir: &str) -> Vec<String> {

		/// Calls the reset sysfs entry for an hci device. Returns True if the write succeeds.
		pub fn reset_hci_device(hci: RealHciIndex) -> bool {
		let path = format!("/sys/class/bluetooth/hci{}/reset", hci);
		let path = format!("/sys/class/bluetooth/hci{}/reset", hci.to_i32());
		std::fs::write(path, "1").is_ok()
		}

system/gd/rust/linux/mgmt/src/state_machine.rs

+46 −39

Original line number	Diff line number	Diff line
		@@ -73,7 +73,7 @@ impl VirtualHciIndex {
		}
		impl Display for VirtualHciIndex {
		fn fmt(&self, f: &mut Formatter) -> std::fmt::Result {
		self.0.fmt(f)
		write!(f, "VirtHci{}", self.0)
		}
		}

		@@ -87,7 +87,7 @@ impl RealHciIndex {
		}
		impl Display for RealHciIndex {
		fn fmt(&self, f: &mut Formatter) -> std::fmt::Result {
		self.0.fmt(f)
		write!(f, "RealHci{}", self.0)
		}
		}

		@@ -433,6 +433,7 @@ fn configure_hci(hci_tx: mpsc::Sender<Message>) {
		}
		MgmtEvent::IndexAdded(hci) => {
		let hci = RealHciIndex(hci.into());
		debug!("IndexAdded: {}", hci);
		// We need devpath for an index or we don't use it.
		if let Some(d) = config_util::get_devpath_for_hci(hci) {
		let _ = hci_tx
		@@ -452,6 +453,7 @@ fn configure_hci(hci_tx: mpsc::Sender<Message>) {
		}
		MgmtEvent::IndexRemoved(hci) => {
		let hci = RealHciIndex(hci.into());
		debug!("IndexRemoved: {}", hci);
		let devpath =
		config_util::get_devpath_for_hci(hci).unwrap_or(String::new());
		// Only send presence removed if the device is removed
		@@ -719,7 +721,7 @@ pub async fn mainloop(

		// All actions and the resulting state changes should be logged for debugging.
		info!(
		"[hci{}]: Action={:?}, Previous State({:?}), Next State({:?})",
		"{}: Action={:?}, Previous State({:?}), Next State({:?})",
		hci, adapter_action, prev_state, next_state
		);

		@@ -747,7 +749,7 @@ pub async fn mainloop(
		.expect("invalid pid file")
		.parse::<i32>()
		.unwrap_or(0);
		debug!("Sending bluetooth started action for pid={}, hci={}", pid, hci);
		debug!("Sending bluetooth started action for {}, pid={}", hci, pid);
		let _ = context
		.tx
		.send_timeout(
		@@ -759,15 +761,15 @@ pub async fn mainloop(
		.await
		.unwrap();
		let handle = tokio::spawn(async move {
		debug!("[hci{}]: Spawned process monitor", hci);
		debug!("{}: Spawned process monitor", hci);
		loop {
		tokio::time::sleep(PID_RUNNING_CHECK_PERIOD).await;
		// Check if process exists by sending kill -0.
		match nix::sys::signal::kill(Pid::from_raw(pid), None) {
		Err(nix::errno::Errno::ESRCH) => {
		warn!("[hci{}]: Process died; Removing PID file", hci);
		warn!("{}: Process died; Removing PID file", hci);
		if let Err(e) = std::fs::remove_file(path) {
		warn!("[hci{}]: Failed to remove: {}", hci, e);
		warn!("{}: Failed to remove: {}", hci, e);
		}
		break;
		}
		@@ -777,7 +779,7 @@ pub async fn mainloop(
		// or unsupported signal number.
		// EPERM: The process does not have permission to send
		// the signal to any receiving process.
		error!("[hci{}]: Failed to send signal: {}", hci, e);
		error!("{}: Failed to send signal: {}", hci, e);
		break;
		}
		_ => {}
		@@ -792,7 +794,7 @@ pub async fn mainloop(
		.insert(fname.clone(), handle)
		{
		Some(handle) => {
		warn!("[hci{}]: Aborting old handler", hci);
		warn!("{}: Aborting old handler", hci);
		handle.abort();
		}
		None => {}
		@@ -803,7 +805,7 @@ pub async fn mainloop(
		}
		(inotify::EventMask::DELETE, Some(fname)) => {
		if let Some(hci) = get_hci_index_from_pid_path(&fname) {
		debug!("Sending bluetooth stopped action for hci={}", hci);
		debug!("Sending bluetooth stopped action for {}", hci);
		context
		.tx
		.send_timeout(
		@@ -817,7 +819,7 @@ pub async fn mainloop(
		match context.state_machine.process_monitor.lock().unwrap().remove(fname) {
		Some(handle) => handle.abort(),
		None => {
		warn!("[hci{}]: Process exited but process monitor not found", hci)
		warn!("{}: Process exited but process monitor not found", hci)
		}
		}
		}
		@@ -833,7 +835,7 @@ pub async fn mainloop(
		// Handle command timeouts
		Message::CommandTimeout(hci) => {
		debug!(
		"Expired action on hci{:?} state{:?}",
		"{}: Expired action, state={:?}",
		hci,
		context.state_machine.get_process_state(hci)
		);
		@@ -901,7 +903,7 @@ impl NativeInvoker {
		impl ProcessManager for NativeInvoker {
		fn start(&mut self, virtual_hci: VirtualHciIndex, real_hci: RealHciIndex) {
		let new_process = Command::new("/usr/bin/btadapterd")
		.arg(format!("INDEX={} HCI={}", virtual_hci, real_hci))
		.arg(format!("INDEX={} HCI={}", virtual_hci.to_i32(), real_hci.to_i32()))
		.stdout(Stdio::piped())
		.spawn()
		.expect("cannot open");
		@@ -935,8 +937,8 @@ impl ProcessManager for UpstartInvoker {
		.args(&[
		"start",
		"btadapterd",
		format!("INDEX={}", virtual_hci).as_str(),
		format!("HCI={}", real_hci).as_str(),
		format!("INDEX={}", virtual_hci.to_i32()).as_str(),
		format!("HCI={}", real_hci.to_i32()).as_str(),
		])
		.output()
		{
		@@ -949,8 +951,8 @@ impl ProcessManager for UpstartInvoker {
		.args(&[
		"stop",
		"btadapterd",
		format!("INDEX={}", virtual_hci).as_str(),
		format!("HCI={}", real_hci).as_str(),
		format!("INDEX={}", virtual_hci.to_i32()).as_str(),
		format!("HCI={}", real_hci.to_i32()).as_str(),
		])
		.output()
		{
		@@ -970,14 +972,22 @@ impl SystemdInvoker {
		impl ProcessManager for SystemdInvoker {
		fn start(&mut self, virtual_hci: VirtualHciIndex, real_hci: RealHciIndex) {
		Command::new("systemctl")
		.args(&["restart", format!("btadapterd@{}_{}.service", virtual_hci, real_hci).as_str()])
		.args(&[
		"restart",
		format!("btadapterd@{}_{}.service", virtual_hci.to_i32(), real_hci.to_i32())
		.as_str(),
		])
		.output()
		.expect("failed to start bluetooth");
		}

		fn stop(&mut self, virtual_hci: VirtualHciIndex, real_hci: RealHciIndex) {
		Command::new("systemctl")
		.args(&["stop", format!("btadapterd@{}_{}.service", virtual_hci, real_hci).as_str()])
		.args(&[
		"stop",
		format!("btadapterd@{}_{}.service", virtual_hci.to_i32(), real_hci.to_i32())
		.as_str(),
		])
		.output()
		.expect("failed to stop bluetooth");
		}
		@@ -1259,7 +1269,7 @@ impl StateMachineInternal {
		/// as we expect this device to disappear and reappear.
		fn reset_hci(&mut self, hci: RealHciIndex) {
		if !config_util::reset_hci_device(hci) {
		error!("Attempted reset recovery of hci{} and failed.", hci.to_i32());
		error!("Attempted reset recovery of {} and failed.", hci);
		}
		}

		@@ -1322,7 +1332,7 @@ impl StateMachineInternal {
		/// Returns an action to reset or cancel timer if we are stopping bluetooth process.
		pub fn action_stop_bluetooth(&mut self, hci: VirtualHciIndex) -> CommandTimeoutAction {
		if !self.is_known(hci) {
		warn!("Attempting to stop unknown hci{}", hci.to_i32());
		warn!("Attempting to stop unknown device {}", hci);
		return CommandTimeoutAction::DoNothing;
		}

		@@ -1346,7 +1356,7 @@ impl StateMachineInternal {
		/// Returns an action to reset timer if we are restarting bluetooth process
		pub fn action_restart_bluetooth(&mut self, hci: VirtualHciIndex) -> CommandTimeoutAction {
		if !self.is_known(hci) {
		warn!("Attempting to restart unknown hci{}", hci);
		warn!("Attempting to restart unknown device {}", hci);
		return CommandTimeoutAction::DoNothing;
		}

		@@ -1361,7 +1371,7 @@ impl StateMachineInternal {
		CommandTimeoutAction::ResetTimer
		}
		ProcessState::TurningOn => {
		debug!("hci{} is already starting.", hci);
		debug!("{} is already starting.", hci);
		CommandTimeoutAction::DoNothing
		}
		_ => CommandTimeoutAction::DoNothing,
		@@ -1376,7 +1386,7 @@ impl StateMachineInternal {
		hci: VirtualHciIndex,
		) -> CommandTimeoutAction {
		if !self.is_known(hci) {
		warn!("Unknown hci{} is started; capturing that process", hci.to_i32());
		warn!("Unknown device {} is started; capturing that process", hci);
		self.modify_state(hci, \|s: &mut AdapterState\| s.state = ProcessState::Off);
		}

		@@ -1406,7 +1416,7 @@ impl StateMachineInternal {
		CommandTimeoutAction::CancelTimer
		}
		ProcessState::Restarting => {
		debug!("hci{} restarting", hci.to_i32());
		debug!("{} restarting", hci);
		self.modify_state(hci, \|s: &mut AdapterState\| s.state = ProcessState::TurningOn);
		self.process_manager.start(hci, self.get_real_hci_by_virtual_id(hci));
		CommandTimeoutAction::ResetTimer
		@@ -1420,9 +1430,8 @@ impl StateMachineInternal {
		// of retrying a start.
		if restart_count >= RESET_ON_RESTART_COUNT {
		warn!(
		"hci{} stopped unexpectedly. After {} restarts, trying a reset recovery.",
		hci.to_i32(),
		restart_count
		"{} stopped unexpectedly. After {} restarts, trying a reset recovery.",
		hci, restart_count
		);
		// Reset the restart count since we're attempting a reset now.
		self.modify_state(hci, \|s: &mut AdapterState\| {
		@@ -1436,8 +1445,8 @@ impl StateMachineInternal {
		CommandTimeoutAction::CancelTimer
		} else {
		warn!(
		"hci{} stopped unexpectedly, try restarting (attempt #{})",
		hci.to_i32(),
		"{} stopped unexpectedly, try restarting (attempt #{})",
		hci,
		restart_count + 1
		);
		self.modify_state(hci, \|s: &mut AdapterState\| {
		@@ -1450,10 +1459,8 @@ impl StateMachineInternal {
		}
		ProcessState::On \| ProcessState::TurningOn \| ProcessState::Off => {
		warn!(
		"hci{} stopped unexpectedly from {:?}. Adapter present? {}",
		hci.to_i32(),
		state,
		present
		"{} stopped unexpectedly from {:?}. Adapter present? {}",
		hci, state, present
		);
		self.modify_state(hci, \|s: &mut AdapterState\| s.state = ProcessState::Off);
		CommandTimeoutAction::CancelTimer
		@@ -1477,7 +1484,7 @@ impl StateMachineInternal {
		// If Floss is not enabled, just send \|Stop\| to process manager and end the state
		// machine actions.
		ProcessState::TurningOn if !floss_enabled => {
		warn!("Timed out turning on but floss is disabled: {}", hci);
		warn!("{}: Timed out turning on but floss is disabled", hci);
		self.modify_state(hci, \|s: &mut AdapterState\| s.state = ProcessState::Off);
		self.process_manager.stop(hci, self.get_real_hci_by_virtual_id(hci));
		StateMachineTimeoutActions::Noop
		@@ -1492,8 +1499,8 @@ impl StateMachineInternal {
		// of retrying a start.
		if restart_count >= RESET_ON_RESTART_COUNT {
		warn!(
		"hci{} timed out while starting (present={}). After {} restarts, trying a reset recovery.",
		hci.to_i32(), present, restart_count
		"{} timed out while starting (present={}). After {} restarts, trying a reset recovery.",
		hci, present, restart_count
		);
		// Reset the restart count since we're attempting a reset now.
		self.modify_state(hci, \|s: &mut AdapterState\| {
		@@ -1507,8 +1514,8 @@ impl StateMachineInternal {
		StateMachineTimeoutActions::Noop
		} else {
		warn!(
		"hci{} timed out while starting (present={}), try restarting (attempt #{})",
		hci.to_i32(),
		"{} timed out while starting (present={}), try restarting (attempt #{})",
		hci,
		present,
		restart_count + 1
		);