[wlan][sme] Switch to inspect_log macro
Also log the `disconnect` case, which wasn't done previously.
Test: connect to local network and do a dump manually
Change-Id: I4f0447e58bb4e57333f680f9b3a8a88e19741675
diff --git a/src/connectivity/wlan/lib/sme/src/client/inspect.rs b/src/connectivity/wlan/lib/sme/src/client/inspect.rs
index 50b4cf5..b7127a1 100644
--- a/src/connectivity/wlan/lib/sme/src/client/inspect.rs
+++ b/src/connectivity/wlan/lib/sme/src/client/inspect.rs
@@ -2,16 +2,13 @@
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
-use fidl_fuchsia_inspect as fidl_inspect;
-use std::fmt::Display;
use wlan_inspect::nodes::{BoundedListNode, NodeExt, SharedNodePtr};
-use wlan_rsn::rsna::SecAssocUpdate;
/// These limits are set to capture roughly 5 to 10 recent connection attempts. An average
/// successful connection attempt would generate about 5 state events and 7 supplicant events (this
/// number may be different in error cases).
const STATE_EVENTS_LIMIT: usize = 50;
-const SUPPLICANT_EVENTS_LIMIT: usize = 50;
+const RSN_EVENTS_LIMIT: usize = 50;
/// Limit set to capture roughly join scans for 10 recent connection attempts.
const JOIN_SCAN_EVENTS_LIMIT: usize = 10;
@@ -20,9 +17,9 @@
pub struct SmeNode {
/// Inspection node to log recent state transitions, or cases where an event would that would
/// normally cause a state transition doesn't due to an error.
- states: BoundedListNode,
+ pub states: BoundedListNode,
/// Inspection node to log EAPOL frames processed by supplicant and its output.
- supplicant_events: BoundedListNode,
+ pub rsn_events: BoundedListNode,
/// Inspection node to log recent join scan results.
pub join_scan_events: BoundedListNode,
}
@@ -31,60 +28,9 @@
pub fn new(node: SharedNodePtr) -> Self {
let mut node = node.lock();
let states = BoundedListNode::new(node.create_child("states"), STATE_EVENTS_LIMIT);
- let supplicant_events =
- BoundedListNode::new(node.create_child("supplicant_events"), SUPPLICANT_EVENTS_LIMIT);
+ let rsn_events = BoundedListNode::new(node.create_child("rsn_events"), RSN_EVENTS_LIMIT);
let join_scan_events =
BoundedListNode::new(node.create_child("join_scan_events"), JOIN_SCAN_EVENTS_LIMIT);
- Self { states, supplicant_events, join_scan_events }
+ Self { states, rsn_events, join_scan_events }
}
-
- pub fn log_state_change<F, T, C>(&mut self, from: F, to: T, cause: Option<C>)
- where
- F: Display,
- T: Display,
- C: Display,
- {
- let msg = match cause {
- None => format!("{} -> {}", from, to),
- Some(cause) => format!("{} -> {} (why={})", from, to, cause),
- };
- let node = self.states.request_entry();
- node.lock().set_time().insert_str("msg", msg);
- }
-
- pub fn log_eapol_frame(
- &mut self,
- eapol_pdu: Vec<u8>,
- transmit_direction: TransmitDirection,
- ) -> SharedNodePtr {
- let key = match transmit_direction {
- TransmitDirection::Rx => "rx_eapol_frame",
- TransmitDirection::Tx => "tx_eapol_frame",
- };
- let node = self.supplicant_events.request_entry();
- node.lock().set_time().add_property(fidl_inspect::Property {
- key: key.to_string(),
- value: fidl_inspect::PropertyValue::Bytes(eapol_pdu),
- });
- node
- }
-
- pub fn log_supplicant_update(&mut self, update: &SecAssocUpdate) {
- match update {
- SecAssocUpdate::TxEapolKeyFrame(_) => (), // log separately
- SecAssocUpdate::Key(key) => {
- let node = self.supplicant_events.request_entry();
- node.lock().set_time().insert_str("derived_key", key.name());
- }
- SecAssocUpdate::Status(status) => {
- let node = self.supplicant_events.request_entry();
- node.lock().set_time().insert_debug("rsna_status", status);
- }
- }
- }
-}
-
-pub enum TransmitDirection {
- Rx,
- Tx,
}
diff --git a/src/connectivity/wlan/lib/sme/src/client/mod.rs b/src/connectivity/wlan/lib/sme/src/client/mod.rs
index 5329156..124fba5 100644
--- a/src/connectivity/wlan/lib/sme/src/client/mod.rs
+++ b/src/connectivity/wlan/lib/sme/src/client/mod.rs
@@ -209,7 +209,7 @@
}
pub fn on_disconnect_command(&mut self) {
- self.state = self.state.take().map(|state| state.disconnect(&self.context));
+ self.state = self.state.take().map(|state| state.disconnect(&mut self.context));
}
pub fn on_scan_command(
diff --git a/src/connectivity/wlan/lib/sme/src/client/state.rs b/src/connectivity/wlan/lib/sme/src/client/state.rs
index 5abf13c..5d4974b 100644
--- a/src/connectivity/wlan/lib/sme/src/client/state.rs
+++ b/src/connectivity/wlan/lib/sme/src/client/state.rs
@@ -5,7 +5,7 @@
use fidl_fuchsia_wlan_mlme::{self as fidl_mlme, BssDescription, MlmeEvent};
use log::{error, warn};
use wlan_common::RadioConfig;
-use wlan_inspect::nodes::NodeExt;
+use wlan_inspect::{inspect_log, log::InspectBytes};
use wlan_rsn::key::exchange::Key;
use wlan_rsn::rsna::{self, SecAssocStatus, SecAssocUpdate};
@@ -15,7 +15,6 @@
use crate::client::{
event::{self, Event},
- inspect::TransmitDirection,
report_connect_finished, Context,
};
use crate::clone_utils::clone_bss_desc;
@@ -331,7 +330,11 @@
};
if start_state != new_state.state_name() || state_change_msg.is_some() {
- context.inspect.log_state_change(start_state, new_state.state_name(), state_change_msg);
+ inspect_log!(context.inspect.states, {
+ from: start_state,
+ to: new_state.state_name(),
+ ctx: state_change_msg,
+ });
}
new_state
}
@@ -416,7 +419,11 @@
};
if start_state != new_state.state_name() || state_change_msg.is_some() {
- context.inspect.log_state_change(start_state, new_state.state_name(), state_change_msg);
+ inspect_log!(context.inspect.states, {
+ from: start_state,
+ to: new_state.state_name(),
+ ctx: state_change_msg,
+ });
}
new_state
}
@@ -442,11 +449,16 @@
context.info_sink.send(InfoEvent::AssociationStarted { att_id: context.att_id });
let msg = connect_cmd_inspect_summary(&cmd);
- context.inspect.log_state_change(start_state, JOINING_STATE, Some(msg));
+ inspect_log!(context.inspect.states, from: start_state, to: JOINING_STATE, ctx: msg);
State::Joining { cmd }
}
- pub fn disconnect(self, context: &Context) -> Self {
+ pub fn disconnect(self, context: &mut Context) -> Self {
+ inspect_log!(context.inspect.states, {
+ from: self.state_name(),
+ to: IDLE_STATE,
+ ctx: "disconnect command",
+ });
self.disconnect_internal(context);
State::Idle
}
@@ -540,12 +552,12 @@
) -> RsnaStatus {
let mic_size = rsna.negotiated_rsne.mic_size;
let eapol_pdu = &ind.data[..];
- let node = context.inspect.log_eapol_frame(eapol_pdu.to_vec(), TransmitDirection::Rx);
+ inspect_log!(context.inspect.rsn_events, rx_eapol_frame: InspectBytes(&eapol_pdu));
let eapol_frame = match eapol::key_frame_from_bytes(eapol_pdu, mic_size).to_full_result() {
Ok(key_frame) => eapol::Frame::Key(key_frame),
Err(e) => {
error!("received invalid EAPOL Key frame: {:?}", e);
- node.lock().insert_debug("parse_error", e);
+ inspect_log!(context.inspect.rsn_events, parse_eapol_error: format!("{:?}", e));
return RsnaStatus::Unchanged;
}
};
@@ -554,7 +566,7 @@
match rsna.supplicant.on_eapol_frame(&mut update_sink, &eapol_frame) {
Err(e) => {
error!("error processing EAPOL key frame: {}", e);
- node.lock().insert_debug("processing_error", e);
+ inspect_log!(context.inspect.rsn_events, process_eapol_error: format!("{:?}", e));
return RsnaStatus::Unchanged;
}
Ok(_) if update_sink.is_empty() => return RsnaStatus::Unchanged,
@@ -565,7 +577,6 @@
let sta_addr = ind.dst_addr;
let mut new_resp_timeout = None;
for update in update_sink {
- context.inspect.log_supplicant_update(&update);
match update {
// ESS Security Association requests to send an EAPOL frame.
// Forward EAPOL frame to MLME.
@@ -574,21 +585,27 @@
}
// ESS Security Association derived a new key.
// Configure key in MLME.
- SecAssocUpdate::Key(key) => send_keys(&context.mlme_sink, bssid, key),
+ SecAssocUpdate::Key(key) => {
+ inspect_log!(context.inspect.rsn_events, derived_key: key.name());
+ send_keys(&context.mlme_sink, bssid, key)
+ },
// Received a status update.
// TODO(hahnr): Rework this part.
// As of now, we depend on the fact that the status is always the last update.
// However, this fact is not clear from the API.
// We should fix the API and make this more explicit.
// Then we should rework this part.
- SecAssocUpdate::Status(status) => match status {
- // ESS Security Association was successfully established. Link is now up.
- SecAssocStatus::EssSaEstablished => return RsnaStatus::Established,
- // TODO(hahnr): The API should not expose whether or not the connection failed
- // because of bad credentials as it allows callers to reason about location
- // information since the network was apparently found.
- SecAssocStatus::WrongPassword => {
- return RsnaStatus::Failed(ConnectResult::BadCredentials);
+ SecAssocUpdate::Status(status) => {
+ inspect_log!(context.inspect.rsn_events, rsna_status: format!("{:?}", status));
+ match status {
+ // ESS Security Association was successfully established. Link is now up.
+ SecAssocStatus::EssSaEstablished => return RsnaStatus::Established,
+ // TODO(hahnr): The API should not expose whether or not the connection failed
+ // because of bad credentials as it allows callers to reason about location
+ // information since the network was apparently found.
+ SecAssocStatus::WrongPassword => {
+ return RsnaStatus::Failed(ConnectResult::BadCredentials);
+ }
}
},
}
@@ -613,7 +630,7 @@
let mut buf = Vec::with_capacity(frame.len());
frame.as_bytes(false, &mut buf);
- context.inspect.log_eapol_frame(buf.to_vec(), TransmitDirection::Tx);
+ inspect_log!(context.inspect.rsn_events, tx_eapol_frame: InspectBytes(&buf));
context.mlme_sink.send(MlmeRequest::Eapol(fidl_mlme::EapolRequest {
src_addr: sta_addr,
dst_addr: bssid,
@@ -1123,7 +1140,7 @@
#[test]
fn disconnect_while_idle() {
let mut h = TestHelper::new();
- let new_state = idle_state().disconnect(&h.context);
+ let new_state = idle_state().disconnect(&mut h.context);
assert_idle(new_state);
// Expect no messages to the MLME
assert!(h.mlme_stream.try_next().is_err());
@@ -1131,20 +1148,20 @@
#[test]
fn disconnect_while_joining() {
- let h = TestHelper::new();
+ let mut h = TestHelper::new();
let (cmd, receiver) = connect_command_one();
let state = joining_state(cmd);
- let state = state.disconnect(&h.context);
+ let state = state.disconnect(&mut h.context);
expect_result(receiver, ConnectResult::Canceled);
assert_idle(state);
}
#[test]
fn disconnect_while_authenticating() {
- let h = TestHelper::new();
+ let mut h = TestHelper::new();
let (cmd, receiver) = connect_command_one();
let state = authenticating_state(cmd);
- let state = state.disconnect(&h.context);
+ let state = state.disconnect(&mut h.context);
expect_result(receiver, ConnectResult::Canceled);
assert_idle(state);
}
@@ -1154,7 +1171,7 @@
let mut h = TestHelper::new();
let (cmd, receiver) = connect_command_one();
let state = associating_state(cmd);
- let state = state.disconnect(&h.context);
+ let state = state.disconnect(&mut h.context);
let state = exchange_deauth(state, &mut h);
expect_result(receiver, ConnectResult::Canceled);
assert_idle(state);
@@ -1164,7 +1181,7 @@
fn disconnect_while_link_up() {
let mut h = TestHelper::new();
let state = link_up_state(connect_command_one().0.bss);
- let state = state.disconnect(&h.context);
+ let state = state.disconnect(&mut h.context);
let state = exchange_deauth(state, &mut h);
assert_idle(state);
}
@@ -1178,7 +1195,7 @@
let state = state.connect(connect_command_one().0, &mut h.context);
assert_eq!(h.context.att_id, 1);
- let state = state.disconnect(&h.context);
+ let state = state.disconnect(&mut h.context);
assert_eq!(h.context.att_id, 1);
let state = state.connect(connect_command_two().0, &mut h.context);
