log_command/
lib.rs

1// Copyright 2023 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 anyhow::format_err;
6use argh::{ArgsInfo, FromArgs, TopLevelCommand};
7use chrono::{DateTime, Local, Utc};
8use chrono_english::{Dialect, parse_date_string};
9#[cfg(not(feature = "fdomain"))]
10use component_debug::query::get_instances_from_query;
11#[cfg(feature = "fdomain")]
12use component_debug_fdomain::query::get_instances_from_query;
13use diagnostics_data::Severity;
14use errors::{FfxError, ffx_bail};
15use flex_fuchsia_diagnostics::{LogInterestSelector, LogSettingsProxy};
16use flex_fuchsia_sys2::RealmQueryProxy;
17pub use log_socket_stream::OneOrMany;
18use moniker::Moniker;
19use selectors::{SelectorExt, sanitize_moniker_for_selectors};
20use std::borrow::Cow;
21use std::io::Write;
22use std::ops::Deref;
23use std::str::FromStr;
24use std::string::FromUtf8Error;
25use std::time::Duration;
26use thiserror::Error;
27mod filter;
28mod log_formatter;
29mod log_socket_stream;
30pub use log_formatter::{
31    BootTimeAccessor, DefaultLogFormatter, FormatterError, LogData, LogEntry, Symbolize,
32    TIMESTAMP_FORMAT, Timestamp, WriterContainer, dump_logs_from_socket,
33};
34pub use log_socket_stream::{JsonDeserializeError, LogsDataStream};
35
36// Subcommand for ffx log (either watch or dump).
37#[derive(ArgsInfo, FromArgs, Clone, PartialEq, Debug)]
38#[argh(subcommand)]
39pub enum LogSubCommand {
40    Watch(WatchCommand),
41    Dump(DumpCommand),
42    SetSeverity(SetSeverityCommand),
43}
44
45#[derive(ArgsInfo, FromArgs, Clone, PartialEq, Debug, Default)]
46/// Sets the severity, but doesn't view any logs.
47#[argh(subcommand, name = "set-severity")]
48pub struct SetSeverityCommand {
49    /// if true, doesn't persist the interest setting
50    /// and blocks forever, keeping the connection open.
51    /// Interest settings will be reset when the command exits.
52    #[argh(switch)]
53    pub no_persist: bool,
54
55    /// if enabled, selectors will be passed directly to Archivist without any filtering.
56    /// If disabled and no matching components are found, the user will be prompted to
57    /// either enable this or be given a list of selectors to choose from.
58    #[argh(switch)]
59    pub force: bool,
60
61    /// configure the log settings on the target device for components matching
62    /// the given selector. This modifies the minimum log severity level emitted
63    /// by components during the logging session.
64    /// Specify using the format <component-selector>#<log-level>, with level
65    /// as one of FATAL|ERROR|WARN|INFO|DEBUG|TRACE.
66    /// May be repeated.
67    #[argh(positional, from_str_fn(log_interest_selector))]
68    pub interest_selector: Vec<OneOrMany<LogInterestSelector>>,
69}
70
71#[derive(ArgsInfo, FromArgs, Clone, PartialEq, Debug)]
72/// Watches for and prints logs from a target. Default if no sub-command is specified.
73#[argh(subcommand, name = "watch")]
74pub struct WatchCommand {}
75
76#[derive(ArgsInfo, FromArgs, Clone, PartialEq, Debug)]
77/// Dumps all log from a given target's session.
78#[argh(subcommand, name = "dump")]
79pub struct DumpCommand {}
80
81pub fn parse_time(value: &str) -> Result<DetailedDateTime, String> {
82    parse_date_string(value, Local::now(), Dialect::Us)
83        .map(|time| DetailedDateTime { time, is_now: value == "now" })
84        .map_err(|e| format!("invalid date string: {e}"))
85}
86
87/// Parses a time string that defaults to UTC. The time returned will be in the local time zone.
88pub fn parse_utc_time(value: &str) -> Result<DetailedDateTime, String> {
89    parse_date_string(value, Utc::now(), Dialect::Us)
90        .map(|time| DetailedDateTime { time: time.into(), is_now: value == "now" })
91        .map_err(|e| format!("invalid date string: {e}"))
92}
93
94/// Parses a duration from a string. The input is in seconds
95/// and the output is a Rust duration.
96pub fn parse_seconds_string_as_duration(value: &str) -> Result<Duration, String> {
97    Ok(Duration::from_secs(
98        value.parse().map_err(|e| format!("value '{value}' is not a number: {e}"))?,
99    ))
100}
101
102// Time format for displaying logs
103#[derive(Clone, Debug, PartialEq)]
104pub enum TimeFormat {
105    // UTC time
106    Utc,
107    // Local time
108    Local,
109    // Boot time
110    Boot,
111}
112
113impl std::str::FromStr for TimeFormat {
114    type Err = String;
115
116    fn from_str(s: &str) -> Result<Self, Self::Err> {
117        let lower = s.to_ascii_lowercase();
118        match lower.as_str() {
119            "local" => Ok(TimeFormat::Local),
120            "utc" => Ok(TimeFormat::Utc),
121            "boot" => Ok(TimeFormat::Boot),
122            _ => Err(format!("'{s}' is not a valid value: must be one of 'local', 'utc', 'boot'")),
123        }
124    }
125}
126
127/// Date/time structure containing a "now"
128/// field, set if it should be interpreted as the
129/// current time (used to call Subscribe instead of SnapshotThenSubscribe).
130#[derive(PartialEq, Clone, Debug)]
131pub struct DetailedDateTime {
132    /// The absolute timestamp as specified by the user
133    /// or the current timestamp if 'now' is specified.
134    pub time: DateTime<Local>,
135    /// Whether or not the DateTime was "now".
136    /// If the DateTime is "now", logs will be collected in subscribe
137    /// mode, instead of SnapshotThenSubscribe.
138    pub is_now: bool,
139}
140
141impl Deref for DetailedDateTime {
142    type Target = DateTime<Local>;
143
144    fn deref(&self) -> &Self::Target {
145        &self.time
146    }
147}
148
149#[derive(Clone, PartialEq, Debug)]
150pub enum SymbolizeMode {
151    /// Disable all symbolization
152    Off,
153    /// Use prettified symbolization
154    Pretty,
155    /// Use classic (non-prettified) symbolization
156    Classic,
157}
158
159impl SymbolizeMode {
160    pub fn is_prettification_disabled(&self) -> bool {
161        matches!(self, SymbolizeMode::Classic)
162    }
163
164    pub fn is_symbolize_disabled(&self) -> bool {
165        matches!(self, SymbolizeMode::Off)
166    }
167}
168
169#[derive(ArgsInfo, FromArgs, Clone, Debug, PartialEq)]
170#[argh(
171    subcommand,
172    name = "log",
173    description = "Display logs from a target device",
174    note = "Logs are retrieve from the target at the moment this command is called.
175
176You may see some additional information attached to the log line:
177
178- `dropped=N`: this means that N logs attributed to the component were dropped when the component
179  wrote to the log socket. This can happen when archivist cannot keep up with the rate of logs being
180  emitted by the component and the component filled the log socket buffer in the kernel.
181
182- `rolled=N`: this means that N logs rolled out from the archivist buffer and ffx never saw them.
183  This can happen when more logs are being ingested by the archivist across all components and the
184  ffx couldn't retrieve them fast enough.
185
186Symbolization is performed in the background using the symbolizer host tool. You can pass
187additional arguments to the symbolizer tool (for example, to add a remote symbol server) using:
188  $ ffx config set proactive_log.symbolize.extra_args \"--symbol-server gs://some-url/path --symbol-server gs://some-other-url/path ...\"
189
190To learn more about configuring the log viewer, visit https://fuchsia.dev/fuchsia-src/development/tools/ffx/commands/log",
191    example = "\
192Dump the most recent logs and stream new ones as they happen:
193  $ ffx log
194
195Stream new logs starting from the current time, filtering for severity of at least \"WARN\":
196  $ ffx log --severity warn --since now
197
198Stream logs where the source moniker, component url and message do not include \"sys\":
199  $ ffx log --exclude sys
200
201Stream ERROR logs with source moniker, component url or message containing either
202\"netstack\" or \"remote-control.cm\", but not containing \"sys\":
203  $ ffx log --severity error --filter netstack --filter remote-control.cm --exclude sys
204
205Dump all available logs where the source moniker, component url, or message contains
206\"remote-control\":
207  $ ffx log --filter remote-control dump
208
209Dump all logs from the last 30 minutes logged before 5 minutes ago:
210  $ ffx log --since \"30m ago\" --until \"5m ago\" dump
211
212Enable DEBUG logs from the \"core/audio\" component while logs are streaming:
213  $ ffx log --set-severity core/audio#DEBUG"
214)]
215pub struct LogCommand {
216    #[argh(subcommand)]
217    pub sub_command: Option<LogSubCommand>,
218
219    /// dumps all logs and exits.
220    #[argh(switch)]
221    pub dump: bool,
222
223    /// filter for a string in either the message, component or url.
224    /// May be repeated.
225    #[argh(option)]
226    pub filter: Vec<String>,
227
228    /// DEPRECATED: use --component
229    #[argh(option)]
230    pub moniker: Vec<String>,
231
232    /// fuzzy search for a component by moniker or url.
233    /// May be repeated.
234    #[argh(option)]
235    pub component: Vec<String>,
236
237    /// exclude a string in either the message, component or url.
238    /// May be repeated.
239    #[argh(option)]
240    pub exclude: Vec<String>,
241
242    /// filter for only logs with a given tag. May be repeated.
243    #[argh(option)]
244    pub tag: Vec<String>,
245
246    /// exclude logs with a given tag. May be repeated.
247    #[argh(option)]
248    pub exclude_tags: Vec<String>,
249
250    /// set the minimum severity. Accepted values (from lower to higher) are: trace, debug, info,
251    /// warn (or warning), error, fatal. This field is case insensitive.
252    #[argh(option, default = "Severity::Info")]
253    pub severity: Severity,
254
255    /// outputs only kernel logs, unless combined with --component.
256    #[argh(switch)]
257    pub kernel: bool,
258
259    /// show only logs after a certain time (exclusive)
260    #[argh(option, from_str_fn(parse_time))]
261    pub since: Option<DetailedDateTime>,
262
263    /// show only logs after a certain time (as a boot
264    /// timestamp: seconds from the target's boot time).
265    #[argh(option, from_str_fn(parse_seconds_string_as_duration))]
266    pub since_boot: Option<Duration>,
267
268    /// show only logs until a certain time (exclusive)
269    #[argh(option, from_str_fn(parse_time))]
270    pub until: Option<DetailedDateTime>,
271
272    /// show only logs until a certain time (as a a boot
273    /// timestamp: seconds since the target's boot time).
274    #[argh(option, from_str_fn(parse_seconds_string_as_duration))]
275    pub until_boot: Option<Duration>,
276
277    /// hide the tag field from output (does not exclude any log messages)
278    #[argh(switch)]
279    pub hide_tags: bool,
280
281    /// hide the file and line number field from output (does not exclude any log messages)
282    #[argh(switch)]
283    pub hide_file: bool,
284
285    /// disable coloring logs according to severity.
286    /// Note that you can permanently disable this with
287    /// `ffx config set log_cmd.color false`
288    #[argh(switch)]
289    pub no_color: bool,
290
291    /// if enabled, text filtering options are case-sensitive
292    /// this applies to --filter, --exclude, --tag, and --exclude-tag.
293    #[argh(switch)]
294    pub case_sensitive: bool,
295
296    /// shows process-id and thread-id in log output
297    #[argh(switch)]
298    pub show_metadata: bool,
299
300    /// shows the full moniker in log output. By default this is false and only the last segment
301    /// of the moniker is printed.
302    #[argh(switch)]
303    pub show_full_moniker: bool,
304
305    /// if enabled, prefer using the component URL for the component name over the moniker.
306    #[argh(switch)]
307    pub prefer_url_component_name: bool,
308
309    /// if enabled, do not prefer using the component URL for the component name over the moniker.
310    #[argh(switch)]
311    pub noprefer_url_component_name: bool,
312
313    /// hide the moniker field from output (does not exclude any log messages)
314    #[argh(switch)]
315    pub hide_moniker: bool,
316
317    /// how to display log timestamps.
318    /// Options are "utc", "local", or "boot" (i.e. nanos since target boot).
319    /// Default is boot.
320    #[argh(option, default = "TimeFormat::Boot")]
321    pub clock: TimeFormat,
322
323    /// configure symbolization options. Valid options are:
324    /// - pretty (default): pretty concise symbolization
325    /// - off: disables all symbolization
326    /// - classic: traditional, non-prettified symbolization
327    #[cfg(not(target_os = "fuchsia"))]
328    #[argh(option, default = "SymbolizeMode::Pretty")]
329    pub symbolize: SymbolizeMode,
330
331    /// configure the log settings on the target device for components matching
332    /// the given selector. This modifies the minimum log severity level emitted
333    /// by components during the logging session.
334    /// Specify using the format <component-selector>#<log-level>, with level
335    /// as one of FATAL|ERROR|WARN|INFO|DEBUG|TRACE.
336    /// May be repeated and it's also possible to pass multiple comma-separated
337    /// strings per invocation.
338    /// Cannot be used in conjunction with --set-severity-persist.
339    #[argh(option, from_str_fn(log_interest_selector))]
340    pub set_severity: Vec<OneOrMany<LogInterestSelector>>,
341
342    /// filters by pid
343    #[argh(option)]
344    pub pid: Option<u64>,
345
346    /// filters by tid
347    #[argh(option)]
348    pub tid: Option<u64>,
349
350    /// if enabled, selectors will be passed directly to Archivist without any filtering.
351    /// If disabled and no matching components are found, the user will be prompted to
352    /// either enable this or be given a list of selectors to choose from.
353    /// This applies to both --set-severity and --set-severity-persist.
354    #[argh(switch)]
355    pub force_set_severity: bool,
356
357    /// enables structured JSON logs.
358    #[cfg(target_os = "fuchsia")]
359    #[argh(switch)]
360    pub json: bool,
361
362    /// disable automatic reconnect
363    #[cfg(not(target_os = "fuchsia"))]
364    #[argh(switch)]
365    pub disable_reconnect: bool,
366}
367
368impl Default for LogCommand {
369    fn default() -> Self {
370        LogCommand {
371            filter: vec![],
372            moniker: vec![],
373            component: vec![],
374            exclude: vec![],
375            tag: vec![],
376            exclude_tags: vec![],
377            hide_tags: false,
378            hide_file: false,
379            clock: TimeFormat::Boot,
380            no_color: false,
381            kernel: false,
382            severity: Severity::Info,
383            show_metadata: false,
384            force_set_severity: false,
385            since: None,
386            since_boot: None,
387            until: None,
388            case_sensitive: false,
389            until_boot: None,
390            sub_command: None,
391            dump: false,
392            set_severity: vec![],
393            show_full_moniker: false,
394            prefer_url_component_name: false,
395            noprefer_url_component_name: false,
396            hide_moniker: false,
397            pid: None,
398            tid: None,
399            #[cfg(target_os = "fuchsia")]
400            json: false,
401            #[cfg(not(target_os = "fuchsia"))]
402            disable_reconnect: false,
403            #[cfg(not(target_os = "fuchsia"))]
404            symbolize: SymbolizeMode::Pretty,
405        }
406    }
407}
408
409/// Result returned from processing logs
410#[derive(PartialEq, Debug)]
411pub enum LogProcessingResult {
412    /// The caller should exit
413    Exit,
414    /// The caller should continue processing logs
415    Continue,
416}
417
418impl FromStr for SymbolizeMode {
419    type Err = anyhow::Error;
420
421    fn from_str(s: &str) -> Result<Self, Self::Err> {
422        let s = s.to_lowercase();
423        match s.as_str() {
424            "off" => Ok(SymbolizeMode::Off),
425            "pretty" => Ok(SymbolizeMode::Pretty),
426            "classic" => Ok(SymbolizeMode::Classic),
427            other => Err(format_err!("invalid symbolize flag: {}", other)),
428        }
429    }
430}
431
432#[derive(Error, Debug)]
433pub enum LogError {
434    #[error(transparent)]
435    UnknownError(#[from] anyhow::Error),
436    #[error("No boot timestamp")]
437    NoBootTimestamp,
438    #[error(transparent)]
439    IOError(#[from] std::io::Error),
440    #[error("Cannot use dump with --since now")]
441    DumpWithSinceNow,
442    #[error("No symbolizer configuration provided")]
443    NoSymbolizerConfig,
444    #[error(transparent)]
445    FfxError(#[from] FfxError),
446    #[error(transparent)]
447    Utf8Error(#[from] FromUtf8Error),
448    #[error(transparent)]
449    FidlError(#[from] fidl::Error),
450    #[error(transparent)]
451    FormatterError(#[from] FormatterError),
452    #[error("Deprecated flag: `{flag}`, use: `{new_flag}`")]
453    DeprecatedFlag { flag: &'static str, new_flag: &'static str },
454    #[error("Fuzzy matching failed due to too many matches, please re-try with one of these:\n{0}")]
455    FuzzyMatchTooManyMatches(String),
456    #[error("No running components were found matching {0}")]
457    SearchParameterNotFound(String),
458}
459
460impl LogError {
461    fn too_many_fuzzy_matches(matches: impl Iterator<Item = String>) -> Self {
462        let mut result = String::new();
463        for component in matches {
464            result.push_str(&component);
465            result.push('\n');
466        }
467
468        Self::FuzzyMatchTooManyMatches(result)
469    }
470
471    pub fn is_broken_pipe(&self) -> bool {
472        match self {
473            LogError::IOError(error) => error.kind() == std::io::ErrorKind::BrokenPipe,
474            LogError::FormatterError(formatter_error) => formatter_error.is_broken_pipe(),
475            LogError::UnknownError(err) => {
476                if let Some(writer_err) = err.downcast_ref::<writer::Error>() {
477                    writer_err.is_broken_pipe()
478                } else if let Some(io_err) = err.downcast_ref::<std::io::Error>() {
479                    io_err.kind() == std::io::ErrorKind::BrokenPipe
480                } else {
481                    false
482                }
483            }
484
485            LogError::NoBootTimestamp
486            | LogError::DumpWithSinceNow
487            | LogError::NoSymbolizerConfig
488            | LogError::FfxError(_)
489            | LogError::Utf8Error(_)
490            | LogError::FidlError(_)
491            | LogError::DeprecatedFlag { .. }
492            | LogError::FuzzyMatchTooManyMatches(_)
493            | LogError::SearchParameterNotFound(_) => false,
494        }
495    }
496}
497
498/// Trait used to get available instances given a moniker query.
499#[async_trait::async_trait(?Send)]
500pub trait InstanceGetter {
501    async fn get_monikers_from_query(&self, query: &str) -> Result<Vec<Moniker>, LogError>;
502}
503
504#[async_trait::async_trait(?Send)]
505impl InstanceGetter for RealmQueryProxy {
506    async fn get_monikers_from_query(&self, query: &str) -> Result<Vec<Moniker>, LogError> {
507        Ok(get_instances_from_query(query, self)
508            .await?
509            .into_iter()
510            .map(|value| value.moniker)
511            .collect())
512    }
513}
514
515impl LogCommand {
516    async fn map_interest_selectors<'a>(
517        realm_query: &impl InstanceGetter,
518        interest_selectors: impl Iterator<Item = &'a LogInterestSelector>,
519    ) -> Result<impl Iterator<Item = Cow<'a, LogInterestSelector>>, LogError> {
520        let selectors = Self::get_selectors_and_monikers(interest_selectors);
521        let mut translated_selectors = vec![];
522        for (moniker, selector) in selectors {
523            // Attempt to translate to a single instance
524            let instances = realm_query.get_monikers_from_query(moniker.as_str()).await?;
525            // If exactly one match, perform rewrite
526            if instances.len() == 1 {
527                let mut translated_selector = selector.clone();
528                translated_selector.selector = instances[0].clone().into_component_selector();
529                translated_selectors.push((Cow::Owned(translated_selector), instances));
530            } else {
531                translated_selectors.push((Cow::Borrowed(selector), instances));
532            }
533        }
534        if translated_selectors.iter().any(|(_, matches)| matches.len() > 1) {
535            let mut err_output = vec![];
536            writeln!(
537                &mut err_output,
538                "WARN: One or more of your selectors appears to be ambiguous"
539            )?;
540            writeln!(&mut err_output, "and may not match any components on your system.\n")?;
541            writeln!(
542                &mut err_output,
543                "If this is unintentional you can explicitly match using the"
544            )?;
545            writeln!(&mut err_output, "following command:\n")?;
546            writeln!(&mut err_output, "ffx log \\")?;
547            let mut output = vec![];
548            for (oselector, instances) in translated_selectors {
549                for selector in instances {
550                    writeln!(
551                        output,
552                        "\t--set-severity {}#{} \\",
553                        sanitize_moniker_for_selectors(selector.to_string().as_str())
554                            .replace("\\", "\\\\"),
555                        format!("{:?}", oselector.interest.min_severity.unwrap()).to_uppercase()
556                    )?;
557                }
558            }
559            // Intentionally ignored, removes the newline, space, and \
560            let _ = output.pop();
561            let _ = output.pop();
562            let _ = output.pop();
563
564            writeln!(&mut err_output, "{}", String::from_utf8(output).unwrap())?;
565            writeln!(&mut err_output, "\nIf this is intentional, you can disable this with")?;
566            writeln!(&mut err_output, "ffx log --force-set-severity.")?;
567
568            ffx_bail!("{}", String::from_utf8(err_output)?);
569        }
570        Ok(translated_selectors.into_iter().map(|(selector, _)| selector))
571    }
572
573    pub fn validate_cmd_flags_with_warnings(&mut self) -> Result<Vec<&'static str>, LogError> {
574        let mut warnings = vec![];
575
576        if !self.moniker.is_empty() {
577            warnings.push("WARNING: --moniker is deprecated, use --component instead");
578            if self.component.is_empty() {
579                self.component = std::mem::take(&mut self.moniker);
580            } else {
581                warnings.push("WARNING: ignoring --moniker arguments in favor of --component");
582            }
583        }
584
585        Ok(warnings)
586    }
587
588    /// Sets interest based on configured selectors.
589    /// If a single ambiguous match is found, the monikers in the selectors
590    /// are automatically re-written.
591    pub async fn maybe_set_interest(
592        &self,
593        log_settings_client: &LogSettingsProxy,
594        realm_query: &impl InstanceGetter,
595    ) -> Result<(), LogError> {
596        let (set_severity, force_set_severity, persist) =
597            if let Some(LogSubCommand::SetSeverity(options)) = &self.sub_command {
598                // No other argument can exist in conjunction with SetSeverity
599                let default_cmd = LogCommand {
600                    sub_command: Some(LogSubCommand::SetSeverity(options.clone())),
601                    ..Default::default()
602                };
603                if &default_cmd != self {
604                    ffx_bail!("Cannot combine set-severity with other options.");
605                }
606                (&options.interest_selector, options.force, !options.no_persist)
607            } else {
608                (&self.set_severity, self.force_set_severity, false)
609            };
610
611        if persist || !set_severity.is_empty() {
612            let selectors = if force_set_severity {
613                set_severity.clone().into_iter().flatten().collect::<Vec<_>>()
614            } else {
615                let new_selectors =
616                    Self::map_interest_selectors(realm_query, set_severity.iter().flatten())
617                        .await?
618                        .map(|s| s.into_owned())
619                        .collect::<Vec<_>>();
620                if new_selectors.is_empty() {
621                    set_severity.clone().into_iter().flatten().collect::<Vec<_>>()
622                } else {
623                    new_selectors
624                }
625            };
626            log_settings_client
627                .set_component_interest(
628                    &flex_fuchsia_diagnostics::LogSettingsSetComponentInterestRequest {
629                        selectors: Some(selectors),
630                        persist: Some(persist),
631                        ..Default::default()
632                    },
633                )
634                .await?;
635        }
636
637        Ok(())
638    }
639
640    fn get_selectors_and_monikers<'a>(
641        interest_selectors: impl Iterator<Item = &'a LogInterestSelector>,
642    ) -> Vec<(String, &'a LogInterestSelector)> {
643        let mut selectors = vec![];
644        for selector in interest_selectors {
645            let segments = selector.selector.moniker_segments.as_ref().unwrap();
646            let mut full_moniker = String::new();
647            for segment in segments {
648                match segment {
649                    flex_fuchsia_diagnostics::StringSelector::ExactMatch(segment) => {
650                        if full_moniker.is_empty() {
651                            full_moniker.push_str(segment);
652                        } else {
653                            full_moniker.push('/');
654                            full_moniker.push_str(segment);
655                        }
656                    }
657                    _ => {
658                        // If the user passed a non-exact match we assume they
659                        // know what they're doing and skip this logic.
660                        return vec![];
661                    }
662                }
663            }
664            selectors.push((full_moniker, selector));
665        }
666        selectors
667    }
668}
669
670impl TopLevelCommand for LogCommand {}
671
672fn log_interest_selector(s: &str) -> Result<OneOrMany<LogInterestSelector>, String> {
673    if s.contains(",") {
674        let many: Result<Vec<LogInterestSelector>, String> = s
675            .split(",")
676            .map(|value| selectors::parse_log_interest_selector(value).map_err(|e| e.to_string()))
677            .collect();
678        Ok(OneOrMany::Many(many?))
679    } else {
680        Ok(OneOrMany::One(selectors::parse_log_interest_selector(s).map_err(|s| s.to_string())?))
681    }
682}
683
684#[cfg(test)]
685mod test {
686    use super::*;
687    use assert_matches::assert_matches;
688    use async_trait::async_trait;
689    use fidl::endpoints::create_proxy;
690    use flex_fuchsia_diagnostics::{LogSettingsMarker, LogSettingsRequest};
691    use futures_util::StreamExt;
692    use futures_util::future::Either;
693    use futures_util::stream::FuturesUnordered;
694    use selectors::parse_log_interest_selector;
695
696    #[derive(Default)]
697    struct FakeInstanceGetter {
698        output: Vec<Moniker>,
699        expected_selector: Option<String>,
700    }
701
702    #[async_trait(?Send)]
703    impl InstanceGetter for FakeInstanceGetter {
704        async fn get_monikers_from_query(&self, query: &str) -> Result<Vec<Moniker>, LogError> {
705            if let Some(expected) = &self.expected_selector {
706                assert_eq!(expected, query);
707            }
708            Ok(self.output.clone())
709        }
710    }
711
712    #[fuchsia::test]
713    async fn test_symbolize_mode_from_str() {
714        assert_matches!(SymbolizeMode::from_str("off"), Ok(value) if value == SymbolizeMode::Off);
715        assert_matches!(
716            SymbolizeMode::from_str("pretty"),
717            Ok(value) if value == SymbolizeMode::Pretty
718        );
719        assert_matches!(
720            SymbolizeMode::from_str("classic"),
721            Ok(value) if value == SymbolizeMode::Classic
722        );
723    }
724
725    #[fuchsia::test]
726    async fn maybe_set_interest_errors_additional_arguments_passed_to_set_interest() {
727        let (settings_proxy, settings_server) = create_proxy::<LogSettingsMarker>();
728        let getter = FakeInstanceGetter {
729            expected_selector: Some("ambiguous_selector".into()),
730            output: vec![
731                Moniker::try_from("core/some/ambiguous_selector:thing/test").unwrap(),
732                Moniker::try_from("core/other/ambiguous_selector:thing/test").unwrap(),
733            ],
734        };
735        // Main should return an error
736
737        let cmd = LogCommand {
738            sub_command: Some(LogSubCommand::SetSeverity(SetSeverityCommand {
739                interest_selector: vec![OneOrMany::One(
740                    parse_log_interest_selector("ambiguous_selector#INFO").unwrap(),
741                )],
742                force: false,
743                no_persist: false,
744            })),
745            hide_file: true,
746            ..LogCommand::default()
747        };
748        let mut set_interest_result = None;
749
750        let mut scheduler = FuturesUnordered::new();
751        scheduler.push(Either::Left(async {
752            set_interest_result = Some(cmd.maybe_set_interest(&settings_proxy, &getter).await);
753            drop(settings_proxy);
754        }));
755        scheduler.push(Either::Right(async {
756            let request = settings_server.into_stream().next().await;
757            // The channel should be closed without sending any requests.
758            assert_matches!(request, None);
759        }));
760        while scheduler.next().await.is_some() {}
761        drop(scheduler);
762
763        let error = format!("{}", set_interest_result.unwrap().unwrap_err());
764
765        const EXPECTED_INTEREST_ERROR: &str = "Cannot combine set-severity with other options.";
766        assert_eq!(error, EXPECTED_INTEREST_ERROR);
767    }
768
769    #[fuchsia::test]
770    async fn maybe_set_interest_errors_if_ambiguous_selector() {
771        let (settings_proxy, settings_server) = create_proxy::<LogSettingsMarker>();
772        let getter = FakeInstanceGetter {
773            expected_selector: Some("ambiguous_selector".into()),
774            output: vec![
775                Moniker::try_from("core/some/ambiguous_selector:thing/test").unwrap(),
776                Moniker::try_from("core/other/ambiguous_selector:thing/test").unwrap(),
777            ],
778        };
779        // Main should return an error
780
781        let cmd = LogCommand {
782            sub_command: Some(LogSubCommand::Dump(DumpCommand {})),
783            set_severity: vec![OneOrMany::One(
784                parse_log_interest_selector("ambiguous_selector#INFO").unwrap(),
785            )],
786            ..LogCommand::default()
787        };
788        let mut set_interest_result = None;
789
790        let mut scheduler = FuturesUnordered::new();
791        scheduler.push(Either::Left(async {
792            set_interest_result = Some(cmd.maybe_set_interest(&settings_proxy, &getter).await);
793            drop(settings_proxy);
794        }));
795        scheduler.push(Either::Right(async {
796            let request = settings_server.into_stream().next().await;
797            // The channel should be closed without sending any requests.
798            assert_matches!(request, None);
799        }));
800        while scheduler.next().await.is_some() {}
801        drop(scheduler);
802
803        let error = format!("{}", set_interest_result.unwrap().unwrap_err());
804
805        const EXPECTED_INTEREST_ERROR: &str = r#"WARN: One or more of your selectors appears to be ambiguous
806and may not match any components on your system.
807
808If this is unintentional you can explicitly match using the
809following command:
810
811ffx log \
812	--set-severity core/some/ambiguous_selector\\:thing/test#INFO \
813	--set-severity core/other/ambiguous_selector\\:thing/test#INFO
814
815If this is intentional, you can disable this with
816ffx log --force-set-severity.
817"#;
818        assert_eq!(error, EXPECTED_INTEREST_ERROR);
819    }
820
821    #[fuchsia::test]
822    async fn logger_translates_selector_if_one_match() {
823        let cmd = LogCommand {
824            sub_command: Some(LogSubCommand::Dump(DumpCommand {})),
825            set_severity: vec![OneOrMany::One(
826                parse_log_interest_selector("ambiguous_selector#INFO").unwrap(),
827            )],
828            ..LogCommand::default()
829        };
830        let mut set_interest_result = None;
831        let getter = FakeInstanceGetter {
832            expected_selector: Some("ambiguous_selector".into()),
833            output: vec![Moniker::try_from("core/some/ambiguous_selector").unwrap()],
834        };
835        let mut scheduler = FuturesUnordered::new();
836        let (settings_proxy, settings_server) = create_proxy::<LogSettingsMarker>();
837        scheduler.push(Either::Left(async {
838            set_interest_result = Some(cmd.maybe_set_interest(&settings_proxy, &getter).await);
839            drop(settings_proxy);
840        }));
841        scheduler.push(Either::Right(async {
842            let request = settings_server.into_stream().next().await;
843            let (payload, responder) = assert_matches!(
844                request,
845                Some(Ok(LogSettingsRequest::SetComponentInterest { payload, responder })) =>
846                (payload, responder)
847            );
848            responder.send().unwrap();
849            assert_eq!(
850                payload.selectors,
851                Some(vec![
852                    parse_log_interest_selector("core/some/ambiguous_selector#INFO").unwrap()
853                ])
854            );
855        }));
856        while scheduler.next().await.is_some() {}
857        drop(scheduler);
858        assert_matches!(set_interest_result, Some(Ok(())));
859    }
860
861    #[fuchsia::test]
862    async fn logger_uses_specified_selectors_if_no_results_returned() {
863        let cmd = LogCommand {
864            sub_command: Some(LogSubCommand::Dump(DumpCommand {})),
865            set_severity: vec![OneOrMany::One(
866                parse_log_interest_selector("core/something/a:b/elements:main/otherstuff:*#DEBUG")
867                    .unwrap(),
868            )],
869            ..LogCommand::default()
870        };
871        let mut set_interest_result = None;
872        let getter = FakeInstanceGetter {
873            expected_selector: Some("core/something/a:b/elements:main/otherstuff:*#DEBUG".into()),
874            output: vec![],
875        };
876        let scheduler = FuturesUnordered::new();
877        let (settings_proxy, settings_server) = create_proxy::<LogSettingsMarker>();
878        scheduler.push(Either::Left(async {
879            set_interest_result = Some(cmd.maybe_set_interest(&settings_proxy, &getter).await);
880            drop(settings_proxy);
881        }));
882        scheduler.push(Either::Right(async {
883            let request = settings_server.into_stream().next().await;
884            let (payload, responder) = assert_matches!(
885                request,
886                Some(Ok(LogSettingsRequest::SetComponentInterest { payload, responder })) =>
887                (payload, responder)
888            );
889            responder.send().unwrap();
890            assert_eq!(
891                payload.selectors,
892                Some(vec![
893                    parse_log_interest_selector(
894                        "core/something/a:b/elements:main/otherstuff:*#DEBUG"
895                    )
896                    .unwrap()
897                ])
898            );
899        }));
900        scheduler.map(|_| Ok(())).forward(futures::sink::drain()).await.unwrap();
901        assert_matches!(set_interest_result, Some(Ok(())));
902    }
903
904    #[fuchsia::test]
905    async fn logger_prints_ignores_ambiguity_if_force_set_severity_is_used() {
906        let cmd = LogCommand {
907            sub_command: Some(LogSubCommand::SetSeverity(SetSeverityCommand {
908                no_persist: true,
909                interest_selector: vec![OneOrMany::One(
910                    parse_log_interest_selector("ambiguous_selector#INFO").unwrap(),
911                )],
912                force: true,
913            })),
914            ..LogCommand::default()
915        };
916        let getter = FakeInstanceGetter {
917            expected_selector: Some("ambiguous_selector".into()),
918            output: vec![
919                Moniker::try_from("core/some/ambiguous_selector:thing/test").unwrap(),
920                Moniker::try_from("core/other/ambiguous_selector:thing/test").unwrap(),
921            ],
922        };
923        let mut set_interest_result = None;
924        let mut scheduler = FuturesUnordered::new();
925        let (settings_proxy, settings_server) = create_proxy::<LogSettingsMarker>();
926        scheduler.push(Either::Left(async {
927            set_interest_result = Some(cmd.maybe_set_interest(&settings_proxy, &getter).await);
928            drop(settings_proxy);
929        }));
930        scheduler.push(Either::Right(async {
931            let request = settings_server.into_stream().next().await;
932            let (payload, responder) = assert_matches!(
933                request,
934                Some(Ok(LogSettingsRequest::SetComponentInterest { payload, responder })) =>
935                (payload, responder)
936            );
937            responder.send().unwrap();
938            assert_eq!(
939                payload.selectors,
940                Some(vec![parse_log_interest_selector("ambiguous_selector#INFO").unwrap()])
941            );
942        }));
943        while scheduler.next().await.is_some() {}
944        drop(scheduler);
945        assert_matches!(set_interest_result, Some(Ok(())));
946    }
947
948    #[fuchsia::test]
949    async fn logger_prints_ignores_ambiguity_if_force_set_severity_is_used_persistent() {
950        let cmd = LogCommand {
951            sub_command: Some(LogSubCommand::SetSeverity(SetSeverityCommand {
952                no_persist: false,
953                interest_selector: vec![log_socket_stream::OneOrMany::One(
954                    parse_log_interest_selector("ambiguous_selector#INFO").unwrap(),
955                )],
956                force: true,
957            })),
958            ..LogCommand::default()
959        };
960        let getter = FakeInstanceGetter {
961            expected_selector: Some("ambiguous_selector".into()),
962            output: vec![
963                Moniker::try_from("core/some/ambiguous_selector:thing/test").unwrap(),
964                Moniker::try_from("core/other/ambiguous_selector:thing/test").unwrap(),
965            ],
966        };
967        let mut set_interest_result = None;
968        let mut scheduler = FuturesUnordered::new();
969        let (settings_proxy, settings_server) = create_proxy::<LogSettingsMarker>();
970        scheduler.push(Either::Left(async {
971            set_interest_result = Some(cmd.maybe_set_interest(&settings_proxy, &getter).await);
972            drop(settings_proxy);
973        }));
974        scheduler.push(Either::Right(async {
975            let request = settings_server.into_stream().next().await;
976            let (payload, responder) = assert_matches!(
977                request,
978                Some(Ok(LogSettingsRequest::SetComponentInterest { payload, responder })) =>
979                (payload, responder)
980            );
981            responder.send().unwrap();
982            assert_eq!(
983                payload.selectors,
984                Some(vec![parse_log_interest_selector("ambiguous_selector#INFO").unwrap()])
985            );
986            assert_eq!(payload.persist, Some(true));
987        }));
988        while scheduler.next().await.is_some() {}
989        drop(scheduler);
990        assert_matches!(set_interest_result, Some(Ok(())));
991    }
992
993    #[fuchsia::test]
994    async fn logger_prints_ignores_ambiguity_if_machine_output_is_used() {
995        let cmd = LogCommand {
996            sub_command: Some(LogSubCommand::Dump(DumpCommand {})),
997            set_severity: vec![OneOrMany::One(
998                parse_log_interest_selector("ambiguous_selector#INFO").unwrap(),
999            )],
1000            force_set_severity: true,
1001            ..LogCommand::default()
1002        };
1003        let getter = FakeInstanceGetter {
1004            expected_selector: Some("ambiguous_selector".into()),
1005            output: vec![
1006                Moniker::try_from("core/some/collection:thing/test").unwrap(),
1007                Moniker::try_from("core/other/collection:thing/test").unwrap(),
1008            ],
1009        };
1010        let mut set_interest_result = None;
1011        let mut scheduler = FuturesUnordered::new();
1012        let (settings_proxy, settings_server) = create_proxy::<LogSettingsMarker>();
1013        scheduler.push(Either::Left(async {
1014            set_interest_result = Some(cmd.maybe_set_interest(&settings_proxy, &getter).await);
1015            drop(settings_proxy);
1016        }));
1017        scheduler.push(Either::Right(async {
1018            let request = settings_server.into_stream().next().await;
1019            let (payload, responder) = assert_matches!(
1020                request,
1021                Some(Ok(LogSettingsRequest::SetComponentInterest { payload, responder })) =>
1022                (payload, responder)
1023            );
1024            responder.send().unwrap();
1025            assert_eq!(
1026                payload.selectors,
1027                Some(vec![parse_log_interest_selector("ambiguous_selector#INFO").unwrap()])
1028            );
1029        }));
1030        while scheduler.next().await.is_some() {}
1031        drop(scheduler);
1032        assert_matches!(set_interest_result, Some(Ok(())));
1033    }
1034    #[test]
1035    fn test_parse_selector() {
1036        assert_eq!(
1037            log_interest_selector("core/audio#DEBUG").unwrap(),
1038            OneOrMany::One(parse_log_interest_selector("core/audio#DEBUG").unwrap())
1039        );
1040    }
1041
1042    #[test]
1043    fn test_parse_selector_with_commas() {
1044        assert_eq!(
1045            log_interest_selector("core/audio#DEBUG,bootstrap/archivist#TRACE").unwrap(),
1046            OneOrMany::Many(vec![
1047                parse_log_interest_selector("core/audio#DEBUG").unwrap(),
1048                parse_log_interest_selector("bootstrap/archivist#TRACE").unwrap()
1049            ])
1050        );
1051    }
1052
1053    #[test]
1054    fn test_parse_time() {
1055        assert!(parse_time("now").unwrap().is_now);
1056        let date_string = "04/20/2020";
1057        let res = parse_time(date_string).unwrap();
1058        assert!(!res.is_now);
1059        assert_eq!(
1060            res.date_naive(),
1061            parse_date_string(date_string, Local::now(), Dialect::Us).unwrap().date_naive()
1062        );
1063    }
1064
1065    #[test]
1066    fn test_log_error_is_broken_pipe() {
1067        assert!(
1068            LogError::IOError(std::io::Error::new(std::io::ErrorKind::BrokenPipe, "broken pipe"))
1069                .is_broken_pipe()
1070        );
1071        assert!(
1072            LogError::UnknownError(anyhow::Error::new(std::io::Error::new(
1073                std::io::ErrorKind::BrokenPipe,
1074                "broken pipe"
1075            )))
1076            .is_broken_pipe()
1077        );
1078        assert!(!LogError::IOError(std::io::Error::other("other")).is_broken_pipe());
1079        assert!(!LogError::NoBootTimestamp.is_broken_pipe());
1080    }
1081}
log_command/lib.rs

log_command/
lib.rs
