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

wlan_telemetry/processors/
toggle_events.rs
