wlan_telemetry/processors/
toggle_events.rs

1// Copyright 2024 The Fuchsia Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
5use crate::util::cobalt_logger::log_cobalt_batch;
6use fidl_fuchsia_metrics::{MetricEvent, MetricEventPayload};
7use fuchsia_inspect::Node as InspectNode;
8use fuchsia_inspect_contrib::inspect_log;
9use fuchsia_inspect_contrib::nodes::BoundedListNode;
10use std::cmp::max;
11use {
12    fidl_fuchsia_power_battery as fidl_battery, fuchsia_async as fasync,
13    wlan_legacy_metrics_registry as metrics, zx,
14};
15
16pub const INSPECT_TOGGLE_EVENTS_LIMIT: usize = 20;
17const TIME_QUICK_TOGGLE_WIFI: zx::BootDuration = zx::BootDuration::from_seconds(5);
18
19#[derive(Debug, PartialEq)]
20pub enum ClientConnectionsToggleEvent {
21    Enabled,
22    Disabled,
23}
24
25pub struct ToggleLogger {
26    toggle_inspect_node: BoundedListNode,
27    cobalt_proxy: fidl_fuchsia_metrics::MetricEventLoggerProxy,
28    /// This is None until telemetry is notified of an off or on event, since these metrics don't
29    /// currently need to know the starting state.
30    current_state: Option<ClientConnectionsToggleEvent>,
31    /// The last time wlan was toggled on
32    time_started: Option<fasync::BootInstant>,
33    /// The last time wlan was toggled off, or None if it hasn't been. Used to determine if WLAN
34    /// was turned on right after being turned off.
35    time_stopped: Option<fasync::BootInstant>,
36    /// When the device was last on battery. This is not populated on init and when the device is
37    /// on charger.
38    on_battery_since: Option<fasync::BootInstant>,
39}
40
41impl ToggleLogger {
42    pub fn new(
43        cobalt_proxy: fidl_fuchsia_metrics::MetricEventLoggerProxy,
44        inspect_node: &InspectNode,
45    ) -> Self {
46        // Initialize inspect children
47        let toggle_events = inspect_node.create_child("client_connections_toggle_events");
48        let toggle_inspect_node = BoundedListNode::new(toggle_events, INSPECT_TOGGLE_EVENTS_LIMIT);
49        let current_state = None;
50        let time_started = None;
51        let time_stopped = None;
52        let on_battery_since = None;
53
54        Self {
55            toggle_inspect_node,
56            cobalt_proxy,
57            current_state,
58            time_started,
59            time_stopped,
60            on_battery_since,
61        }
62    }
63
64    pub async fn handle_toggle_event(&mut self, event_type: ClientConnectionsToggleEvent) {
65        // This inspect macro logs the time as well
66        inspect_log!(self.toggle_inspect_node, {
67            event_type: std::format!("{:?}", event_type)
68        });
69
70        let mut metric_events = vec![];
71        let now = fasync::BootInstant::now();
72        match &event_type {
73            ClientConnectionsToggleEvent::Enabled => {
74                // Log an occurrence if the client connection was not already enabled
75                if self.current_state != Some(ClientConnectionsToggleEvent::Enabled) {
76                    self.time_started = Some(now);
77
78                    metric_events.push(MetricEvent {
79                        metric_id: metrics::CLIENT_CONNECTION_ENABLED_OCCURRENCE_METRIC_ID,
80                        event_codes: vec![],
81                        payload: MetricEventPayload::Count(1),
82                    });
83                }
84
85                // If connections were just disabled before this, log a metric for the quick wifi
86                // restart.
87                if self.current_state == Some(ClientConnectionsToggleEvent::Disabled)
88                    && let Some(time_stopped) = self.time_stopped
89                    && now - time_stopped < TIME_QUICK_TOGGLE_WIFI
90                {
91                    metric_events.push(MetricEvent {
92                        metric_id: metrics::CLIENT_CONNECTIONS_STOP_AND_START_METRIC_ID,
93                        event_codes: vec![],
94                        payload: MetricEventPayload::Count(1),
95                    });
96                }
97            }
98            ClientConnectionsToggleEvent::Disabled => {
99                // Only change the time and log duration if connections were not already disabled.
100                if self.current_state == Some(ClientConnectionsToggleEvent::Enabled) {
101                    self.time_stopped = Some(now);
102
103                    if let Some(time_started) = self.time_started {
104                        let duration = now - time_started;
105                        metric_events.push(MetricEvent {
106                            metric_id: metrics::CLIENT_CONNECTION_ENABLED_DURATION_METRIC_ID,
107                            event_codes: vec![],
108                            payload: MetricEventPayload::IntegerValue(duration.into_millis()),
109                        });
110
111                        // If `on_battery_since` is `Some`, it indicates that we have been
112                        // on battery, as otherwise this Option would be cleared out in
113                        // `handle_battery_charge_status`
114                        //
115                        // Here we only handle the transition from connection-enabled +
116                        // on-battery state -> connection disabled. The other case
117                        // where we transition to on charger is handled in
118                        // `handle_battery_charge_status`
119                        if let Some(on_battery_since) = self.on_battery_since {
120                            // Get the max of `time_started` and `on_battery_since` as it was
121                            // when connection is enabled *and* device is on battery
122                            let duration = now - max(time_started, on_battery_since);
123                            metric_events.push(MetricEvent {
124                                metric_id: metrics::CLIENT_CONNECTION_ENABLED_DURATION_ON_BATTERY_METRIC_ID,
125                                event_codes: vec![],
126                                payload: MetricEventPayload::IntegerValue(duration.into_millis()),
127                            });
128                        }
129                    }
130                }
131            }
132        }
133        self.current_state = Some(event_type);
134
135        log_cobalt_batch!(self.cobalt_proxy, &metric_events, "handle_toggle_events");
136    }
137
138    pub async fn handle_battery_charge_status(
139        &mut self,
140        charge_status: fidl_battery::ChargeStatus,
141    ) {
142        let mut metric_events = vec![];
143        let now = fasync::BootInstant::now();
144        let on_battery_now = matches!(charge_status, fidl_battery::ChargeStatus::Discharging);
145
146        match (self.on_battery_since, on_battery_now) {
147            (None, true) => self.on_battery_since = Some(now),
148            (Some(on_battery_since), false) => {
149                let _on_battery_since = self.on_battery_since.take();
150                // Here we only handle the transition from connection-enabled *and*
151                // on-battery state -> on-charger state. The other case
152                // where we transition to connection disabled is handled in
153                // `handle_toggle_event`
154                if let Some(ClientConnectionsToggleEvent::Enabled) = self.current_state
155                    && let Some(time_started) = self.time_started
156                {
157                    // Get the max of `time_started` and `on_battery_since` as it was
158                    // when connection is enabled *and* device is on battery
159                    let duration = now - max(time_started, on_battery_since);
160                    metric_events.push(MetricEvent {
161                        metric_id: metrics::CLIENT_CONNECTION_ENABLED_DURATION_ON_BATTERY_METRIC_ID,
162                        event_codes: vec![],
163                        payload: MetricEventPayload::IntegerValue(duration.into_millis()),
164                    });
165                }
166            }
167            _ => (),
168        }
169
170        log_cobalt_batch!(self.cobalt_proxy, &metric_events, "handle_battery_charge_status");
171    }
172}
173
174#[cfg(test)]
175mod tests {
176    use super::*;
177    use crate::testing::{TestHelper, setup_test};
178    use assert_matches::assert_matches;
179    use diagnostics_assertions::{AnyNumericProperty, assert_data_tree};
180    use futures::task::Poll;
181    use std::pin::pin;
182
183    #[fuchsia::test]
184    fn test_toggle_is_recorded_to_inspect() {
185        let mut test_helper = setup_test();
186        let node = test_helper.create_inspect_node("wlan_mock_node");
187        let mut toggle_logger = ToggleLogger::new(test_helper.cobalt_proxy.clone(), &node);
188
189        let event = ClientConnectionsToggleEvent::Enabled;
190        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
191
192        let event = ClientConnectionsToggleEvent::Disabled;
193        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
194
195        let event = ClientConnectionsToggleEvent::Enabled;
196        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
197
198        assert_data_tree!(@executor test_helper.exec, test_helper.inspector, root: contains {
199            wlan_mock_node: {
200                client_connections_toggle_events: {
201                    "0": {
202                        "event_type": "Enabled",
203                        "@time": AnyNumericProperty
204                    },
205                    "1": {
206                        "event_type": "Disabled",
207                        "@time": AnyNumericProperty
208                    },
209                    "2": {
210                        "event_type": "Enabled",
211                        "@time": AnyNumericProperty
212                    },
213                }
214            }
215        });
216    }
217
218    // Uses the test helper to run toggle_logger.handle_toggle_event so that any cobalt metrics sent
219    // will be acked and not block anything. It expects no response from the handle_toggle_event.
220    fn run_handle_toggle_event(
221        test_helper: &mut TestHelper,
222        toggle_logger: &mut ToggleLogger,
223        event: ClientConnectionsToggleEvent,
224    ) {
225        let mut test_fut = pin!(toggle_logger.handle_toggle_event(event));
226        assert_eq!(
227            test_helper.run_until_stalled_drain_cobalt_events(&mut test_fut),
228            Poll::Ready(())
229        );
230    }
231
232    fn run_handle_battery_charge_status(
233        test_helper: &mut TestHelper,
234        toggle_logger: &mut ToggleLogger,
235        charge_status: fidl_battery::ChargeStatus,
236    ) {
237        let mut test_fut = pin!(toggle_logger.handle_battery_charge_status(charge_status));
238        assert_eq!(
239            test_helper.run_until_stalled_drain_cobalt_events(&mut test_fut),
240            Poll::Ready(())
241        );
242    }
243
244    #[fuchsia::test]
245    fn test_quick_toggle_metric_is_recorded() {
246        let mut test_helper = setup_test();
247        let inspect_node = test_helper.create_inspect_node("test_stats");
248        let mut toggle_logger = ToggleLogger::new(test_helper.cobalt_proxy.clone(), &inspect_node);
249
250        // Start with client connections enabled.
251        let mut test_time = fasync::MonotonicInstant::from_nanos(123);
252        let event = ClientConnectionsToggleEvent::Enabled;
253        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
254
255        // Stop client connections and quickly start them again.
256        test_time += fasync::MonotonicDuration::from_minutes(40);
257        test_helper.exec.set_fake_time(test_time);
258        let event = ClientConnectionsToggleEvent::Disabled;
259        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
260
261        test_time += fasync::MonotonicDuration::from_seconds(1);
262        test_helper.exec.set_fake_time(test_time);
263        let event = ClientConnectionsToggleEvent::Enabled;
264        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
265
266        // Check that a metric is logged for the quick stop and start.
267        let logged_metrics =
268            test_helper.get_logged_metrics(metrics::CLIENT_CONNECTIONS_STOP_AND_START_METRIC_ID);
269        assert_matches!(&logged_metrics[..], [metric] => {
270            let expected_metric = fidl_fuchsia_metrics::MetricEvent {
271                metric_id: metrics::CLIENT_CONNECTIONS_STOP_AND_START_METRIC_ID,
272                event_codes: vec![],
273                payload: fidl_fuchsia_metrics::MetricEventPayload::Count(1),
274            };
275            assert_eq!(metric, &expected_metric);
276        });
277    }
278
279    #[fuchsia::test]
280    fn test_quick_toggle_no_metric_is_recorded_if_not_quick() {
281        let mut test_helper = setup_test();
282        let inspect_node = test_helper.create_inspect_node("test_stats");
283        let mut toggle_logger = ToggleLogger::new(test_helper.cobalt_proxy.clone(), &inspect_node);
284
285        // Start with client connections enabled.
286        let mut test_time = fasync::MonotonicInstant::from_nanos(123);
287        let event = ClientConnectionsToggleEvent::Enabled;
288        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
289
290        // Stop client connections and a while later start them again.
291        test_time += fasync::MonotonicDuration::from_minutes(20);
292        test_helper.exec.set_fake_time(test_time);
293        let event = ClientConnectionsToggleEvent::Disabled;
294        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
295
296        test_time += fasync::MonotonicDuration::from_minutes(30);
297        test_helper.exec.set_fake_time(test_time);
298        let event = ClientConnectionsToggleEvent::Enabled;
299        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
300
301        // Check that no metric is logged for quick toggles since there was a while between the
302        // stop and start.
303        let logged_metrics =
304            test_helper.get_logged_metrics(metrics::CLIENT_CONNECTIONS_STOP_AND_START_METRIC_ID);
305        assert!(logged_metrics.is_empty());
306    }
307
308    #[fuchsia::test]
309    fn test_quick_toggle_metric_second_disable_doesnt_update_time() {
310        // Verify that if two consecutive disables happen, only the first is used to determine
311        // quick toggles since the following ones don't change the state.
312        let mut test_helper = setup_test();
313        let inspect_node = test_helper.create_inspect_node("test_stats");
314        let mut toggle_logger = ToggleLogger::new(test_helper.cobalt_proxy.clone(), &inspect_node);
315
316        // Start with client connections enabled.
317        let mut test_time = fasync::MonotonicInstant::from_nanos(123);
318        let event = ClientConnectionsToggleEvent::Enabled;
319        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
320
321        // Stop client connections and a while later stop them again.
322        test_time += fasync::MonotonicDuration::from_minutes(40);
323        test_helper.exec.set_fake_time(test_time);
324        let event = ClientConnectionsToggleEvent::Disabled;
325        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
326
327        test_time += fasync::MonotonicDuration::from_minutes(30);
328        test_helper.exec.set_fake_time(test_time);
329        let event = ClientConnectionsToggleEvent::Disabled;
330        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
331
332        // Start client connections right after the last disable message.
333        test_time += fasync::MonotonicDuration::from_seconds(1);
334        test_helper.exec.set_fake_time(test_time);
335        let event = ClientConnectionsToggleEvent::Enabled;
336        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
337
338        // Check that no metric is logged since the enable message came a while after the first
339        // disable message.
340        let logged_metrics =
341            test_helper.get_logged_metrics(metrics::CLIENT_CONNECTIONS_STOP_AND_START_METRIC_ID);
342        assert!(logged_metrics.is_empty());
343    }
344
345    #[fuchsia::test]
346    fn test_log_client_connection_enabled() {
347        let mut test_helper = setup_test();
348        let inspect_node = test_helper.create_inspect_node("test_stats");
349        let mut toggle_logger = ToggleLogger::new(test_helper.cobalt_proxy.clone(), &inspect_node);
350
351        // Start with client connections enabled.
352        test_helper.exec.set_fake_time(fasync::MonotonicInstant::from_nanos(10_000_000));
353        let event = ClientConnectionsToggleEvent::Enabled;
354        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
355
356        let metrics =
357            test_helper.get_logged_metrics(metrics::CLIENT_CONNECTION_ENABLED_OCCURRENCE_METRIC_ID);
358        assert_eq!(metrics.len(), 1);
359        assert_eq!(metrics[0].payload, MetricEventPayload::Count(1));
360
361        // Send enabled event again. This should not log any metric because the device was not
362        // in a disabled state
363        test_helper.clear_cobalt_events();
364        test_helper.exec.set_fake_time(fasync::MonotonicInstant::from_nanos(50_000_000));
365        let event = ClientConnectionsToggleEvent::Enabled;
366        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
367
368        let metrics =
369            test_helper.get_logged_metrics(metrics::CLIENT_CONNECTION_ENABLED_OCCURRENCE_METRIC_ID);
370        assert!(metrics.is_empty());
371
372        // Send disabled event. This should log the duration between now and when the
373        // first enabled event was sent.
374        test_helper.clear_cobalt_events();
375        test_helper.exec.set_fake_time(fasync::MonotonicInstant::from_nanos(100_000_000));
376        let event = ClientConnectionsToggleEvent::Disabled;
377        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
378
379        let metrics =
380            test_helper.get_logged_metrics(metrics::CLIENT_CONNECTION_ENABLED_DURATION_METRIC_ID);
381        assert_eq!(metrics.len(), 1);
382        assert_eq!(metrics[0].payload, MetricEventPayload::IntegerValue(90));
383        let metrics = test_helper
384            .get_logged_metrics(metrics::CLIENT_CONNECTION_ENABLED_DURATION_ON_BATTERY_METRIC_ID);
385        assert!(metrics.is_empty());
386    }
387
388    #[fuchsia::test]
389    fn test_log_client_connection_enabled_duration_on_battery_with_reenable() {
390        let mut test_helper = setup_test();
391        let inspect_node = test_helper.create_inspect_node("test_stats");
392        let mut toggle_logger = ToggleLogger::new(test_helper.cobalt_proxy.clone(), &inspect_node);
393
394        // Start with client connections enabled.
395        test_helper.exec.set_fake_time(fasync::MonotonicInstant::from_nanos(10_000_000));
396        let event = ClientConnectionsToggleEvent::Enabled;
397        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
398
399        // Set on battery
400        test_helper.exec.set_fake_time(fasync::MonotonicInstant::from_nanos(30_000_000));
401        let charge_status = fidl_battery::ChargeStatus::Discharging;
402        run_handle_battery_charge_status(&mut test_helper, &mut toggle_logger, charge_status);
403
404        // Send disabled event. This should log the duration between now and when the client
405        // connections enabled AND device is on battery
406        test_helper.exec.set_fake_time(fasync::MonotonicInstant::from_nanos(100_000_000));
407        let event = ClientConnectionsToggleEvent::Disabled;
408        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
409
410        let metrics = test_helper
411            .get_logged_metrics(metrics::CLIENT_CONNECTION_ENABLED_DURATION_ON_BATTERY_METRIC_ID);
412        assert_eq!(metrics.len(), 1);
413        assert_eq!(metrics[0].payload, MetricEventPayload::IntegerValue(70));
414
415        test_helper.clear_cobalt_events();
416        // Send client connections enabled and disabled events again.
417        test_helper.exec.set_fake_time(fasync::MonotonicInstant::from_nanos(110_000_000));
418        let event = ClientConnectionsToggleEvent::Enabled;
419        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
420        test_helper.exec.set_fake_time(fasync::MonotonicInstant::from_nanos(150_000_000));
421        let event = ClientConnectionsToggleEvent::Disabled;
422        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
423
424        // Verify that only the duration since the second enabled event is logged.
425        let metrics = test_helper
426            .get_logged_metrics(metrics::CLIENT_CONNECTION_ENABLED_DURATION_ON_BATTERY_METRIC_ID);
427        assert_eq!(metrics.len(), 1);
428        assert_eq!(metrics[0].payload, MetricEventPayload::IntegerValue(40));
429    }
430
431    #[fuchsia::test]
432    fn test_log_client_connection_enabled_duration_on_battery_with_repeated_battery_change() {
433        let mut test_helper = setup_test();
434        let inspect_node = test_helper.create_inspect_node("test_stats");
435        let mut toggle_logger = ToggleLogger::new(test_helper.cobalt_proxy.clone(), &inspect_node);
436
437        // Start with client connections enabled.
438        test_helper.exec.set_fake_time(fasync::MonotonicInstant::from_nanos(10_000_000));
439        let event = ClientConnectionsToggleEvent::Enabled;
440        run_handle_toggle_event(&mut test_helper, &mut toggle_logger, event);
441
442        // Set on battery
443        test_helper.exec.set_fake_time(fasync::MonotonicInstant::from_nanos(30_000_000));
444        let charge_status = fidl_battery::ChargeStatus::Discharging;
445        run_handle_battery_charge_status(&mut test_helper, &mut toggle_logger, charge_status);
446
447        // Set on charger. This should log the duration between now and when the client
448        // connection is enabled *and* device is on battery
449        test_helper.exec.set_fake_time(fasync::MonotonicInstant::from_nanos(100_000_000));
450        let charge_status = fidl_battery::ChargeStatus::Charging;
451        run_handle_battery_charge_status(&mut test_helper, &mut toggle_logger, charge_status);
452
453        let metrics = test_helper
454            .get_logged_metrics(metrics::CLIENT_CONNECTION_ENABLED_DURATION_ON_BATTERY_METRIC_ID);
455        assert_eq!(metrics.len(), 1);
456        assert_eq!(metrics[0].payload, MetricEventPayload::IntegerValue(70));
457
458        test_helper.clear_cobalt_events();
459        // Set on battery and then on charger again.
460        test_helper.exec.set_fake_time(fasync::MonotonicInstant::from_nanos(110_000_000));
461        let charge_status = fidl_battery::ChargeStatus::Discharging;
462        run_handle_battery_charge_status(&mut test_helper, &mut toggle_logger, charge_status);
463        test_helper.exec.set_fake_time(fasync::MonotonicInstant::from_nanos(150_000_000));
464        let charge_status = fidl_battery::ChargeStatus::Charging;
465        run_handle_battery_charge_status(&mut test_helper, &mut toggle_logger, charge_status);
466
467        // Verify that only the duration since the second enabled event is logged.
468        let metrics = test_helper
469            .get_logged_metrics(metrics::CLIENT_CONNECTION_ENABLED_DURATION_ON_BATTERY_METRIC_ID);
470        assert_eq!(metrics.len(), 1);
471        assert_eq!(metrics[0].payload, MetricEventPayload::IntegerValue(40));
472    }
473}
wlan_telemetry/processors/toggle_events.rs

wlan_telemetry/processors/
toggle_events.rs
