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. This flag is deprecated. ffx log dump
220    /// should be used instead. This is now a subcommand.
221    /// This switch will eventually be removed.
222    #[argh(switch, hidden_help)]
223    pub dump: bool,
224
225    /// filter for a string in either the message, component or url.
226    /// May be repeated.
227    #[argh(option)]
228    pub filter: Vec<String>,
229
230    /// DEPRECATED: use --component
231    #[argh(option)]
232    pub moniker: Vec<String>,
233
234    /// fuzzy search for a component by moniker or url.
235    /// May be repeated.
236    #[argh(option)]
237    pub component: Vec<String>,
238
239    /// exclude a string in either the message, component or url.
240    /// May be repeated.
241    #[argh(option)]
242    pub exclude: Vec<String>,
243
244    /// filter for only logs with a given tag. May be repeated.
245    #[argh(option)]
246    pub tag: Vec<String>,
247
248    /// exclude logs with a given tag. May be repeated.
249    #[argh(option)]
250    pub exclude_tags: Vec<String>,
251
252    /// set the minimum severity. Accepted values (from lower to higher) are: trace, debug, info,
253    /// warn (or warning), error, fatal. This field is case insensitive.
254    #[argh(option, default = "Severity::Info")]
255    pub severity: Severity,
256
257    /// outputs only kernel logs, unless combined with --component.
258    #[argh(switch)]
259    pub kernel: bool,
260
261    /// show only logs after a certain time (exclusive)
262    #[argh(option, from_str_fn(parse_time))]
263    pub since: Option<DetailedDateTime>,
264
265    /// show only logs after a certain time (as a boot
266    /// timestamp: seconds from the target's boot time).
267    #[argh(option, from_str_fn(parse_seconds_string_as_duration))]
268    pub since_boot: Option<Duration>,
269
270    /// show only logs until a certain time (exclusive)
271    #[argh(option, from_str_fn(parse_time))]
272    pub until: Option<DetailedDateTime>,
273
274    /// show only logs until a certain time (as a a boot
275    /// timestamp: seconds since the target's boot time).
276    #[argh(option, from_str_fn(parse_seconds_string_as_duration))]
277    pub until_boot: Option<Duration>,
278
279    /// hide the tag field from output (does not exclude any log messages)
280    #[argh(switch)]
281    pub hide_tags: bool,
282
283    /// hide the file and line number field from output (does not exclude any log messages)
284    #[argh(switch)]
285    pub hide_file: bool,
286
287    /// disable coloring logs according to severity.
288    /// Note that you can permanently disable this with
289    /// `ffx config set log_cmd.color false`
290    #[argh(switch)]
291    pub no_color: bool,
292
293    /// if enabled, text filtering options are case-sensitive
294    /// this applies to --filter, --exclude, --tag, and --exclude-tag.
295    #[argh(switch)]
296    pub case_sensitive: bool,
297
298    /// shows process-id and thread-id in log output
299    #[argh(switch)]
300    pub show_metadata: bool,
301
302    /// shows the full moniker in log output. By default this is false and only the last segment
303    /// of the moniker is printed.
304    #[argh(switch)]
305    pub show_full_moniker: bool,
306
307    /// if enabled, prefer using the component URL for the component name over the moniker.
308    #[argh(switch)]
309    pub prefer_url_component_name: bool,
310
311    /// if enabled, do not prefer using the component URL for the component name over the moniker.
312    #[argh(switch)]
313    pub noprefer_url_component_name: bool,
314
315    /// hide the moniker field from output (does not exclude any log messages)
316    #[argh(switch)]
317    pub hide_moniker: bool,
318
319    /// how to display log timestamps.
320    /// Options are "utc", "local", or "boot" (i.e. nanos since target boot).
321    /// Default is boot.
322    #[argh(option, default = "TimeFormat::Boot")]
323    pub clock: TimeFormat,
324
325    /// configure symbolization options. Valid options are:
326    /// - pretty (default): pretty concise symbolization
327    /// - off: disables all symbolization
328    /// - classic: traditional, non-prettified symbolization
329    #[cfg(not(target_os = "fuchsia"))]
330    #[argh(option, default = "SymbolizeMode::Pretty")]
331    pub symbolize: SymbolizeMode,
332
333    /// configure the log settings on the target device for components matching
334    /// the given selector. This modifies the minimum log severity level emitted
335    /// by components during the logging session.
336    /// Specify using the format <component-selector>#<log-level>, with level
337    /// as one of FATAL|ERROR|WARN|INFO|DEBUG|TRACE.
338    /// May be repeated and it's also possible to pass multiple comma-separated
339    /// strings per invocation.
340    /// Cannot be used in conjunction with --set-severity-persist.
341    #[argh(option, from_str_fn(log_interest_selector))]
342    pub set_severity: Vec<OneOrMany<LogInterestSelector>>,
343
344    /// filters by pid
345    #[argh(option)]
346    pub pid: Option<u64>,
347
348    /// filters by tid
349    #[argh(option)]
350    pub tid: Option<u64>,
351
352    /// if enabled, selectors will be passed directly to Archivist without any filtering.
353    /// If disabled and no matching components are found, the user will be prompted to
354    /// either enable this or be given a list of selectors to choose from.
355    /// This applies to both --set-severity and --set-severity-persist.
356    #[argh(switch)]
357    pub force_set_severity: bool,
358
359    /// enables structured JSON logs.
360    #[cfg(target_os = "fuchsia")]
361    #[argh(switch)]
362    pub json: bool,
363
364    /// disable automatic reconnect
365    #[cfg(not(target_os = "fuchsia"))]
366    #[argh(switch)]
367    pub disable_reconnect: bool,
368}
369
370impl Default for LogCommand {
371    fn default() -> Self {
372        LogCommand {
373            filter: vec![],
374            moniker: vec![],
375            component: vec![],
376            exclude: vec![],
377            tag: vec![],
378            exclude_tags: vec![],
379            hide_tags: false,
380            hide_file: false,
381            clock: TimeFormat::Boot,
382            no_color: false,
383            kernel: false,
384            severity: Severity::Info,
385            show_metadata: false,
386            force_set_severity: false,
387            since: None,
388            since_boot: None,
389            until: None,
390            case_sensitive: false,
391            until_boot: None,
392            sub_command: None,
393            dump: false,
394            set_severity: vec![],
395            show_full_moniker: false,
396            prefer_url_component_name: false,
397            noprefer_url_component_name: false,
398            hide_moniker: false,
399            pid: None,
400            tid: None,
401            #[cfg(target_os = "fuchsia")]
402            json: false,
403            #[cfg(not(target_os = "fuchsia"))]
404            disable_reconnect: false,
405            #[cfg(not(target_os = "fuchsia"))]
406            symbolize: SymbolizeMode::Pretty,
407        }
408    }
409}
410
411/// Result returned from processing logs
412#[derive(PartialEq, Debug)]
413pub enum LogProcessingResult {
414    /// The caller should exit
415    Exit,
416    /// The caller should continue processing logs
417    Continue,
418}
419
420impl FromStr for SymbolizeMode {
421    type Err = anyhow::Error;
422
423    fn from_str(s: &str) -> Result<Self, Self::Err> {
424        let s = s.to_lowercase();
425        match s.as_str() {
426            "off" => Ok(SymbolizeMode::Off),
427            "pretty" => Ok(SymbolizeMode::Pretty),
428            "classic" => Ok(SymbolizeMode::Classic),
429            other => Err(format_err!("invalid symbolize flag: {}", other)),
430        }
431    }
432}
433
434#[derive(Error, Debug)]
435pub enum LogError {
436    #[error(transparent)]
437    UnknownError(#[from] anyhow::Error),
438    #[error("No boot timestamp")]
439    NoBootTimestamp,
440    #[error(transparent)]
441    IOError(#[from] std::io::Error),
442    #[error("Cannot use dump with --since now")]
443    DumpWithSinceNow,
444    #[error("No symbolizer configuration provided")]
445    NoSymbolizerConfig,
446    #[error(transparent)]
447    FfxError(#[from] FfxError),
448    #[error(transparent)]
449    Utf8Error(#[from] FromUtf8Error),
450    #[error(transparent)]
451    FidlError(#[from] fidl::Error),
452    #[error(transparent)]
453    FormatterError(#[from] FormatterError),
454    #[error("Deprecated flag: `{flag}`, use: `{new_flag}`")]
455    DeprecatedFlag { flag: &'static str, new_flag: &'static str },
456    #[error("Fuzzy matching failed due to too many matches, please re-try with one of these:\n{0}")]
457    FuzzyMatchTooManyMatches(String),
458    #[error("No running components were found matching {0}")]
459    SearchParameterNotFound(String),
460}
461
462impl LogError {
463    fn too_many_fuzzy_matches(matches: impl Iterator<Item = String>) -> Self {
464        let mut result = String::new();
465        for component in matches {
466            result.push_str(&component);
467            result.push('\n');
468        }
469
470        Self::FuzzyMatchTooManyMatches(result)
471    }
472
473    pub fn is_broken_pipe(&self) -> bool {
474        match self {
475            LogError::IOError(error) => error.kind() == std::io::ErrorKind::BrokenPipe,
476            LogError::FormatterError(formatter_error) => formatter_error.is_broken_pipe(),
477            LogError::UnknownError(err) => {
478                if let Some(writer_err) = err.downcast_ref::<writer::Error>() {
479                    writer_err.is_broken_pipe()
480                } else if let Some(io_err) = err.downcast_ref::<std::io::Error>() {
481                    io_err.kind() == std::io::ErrorKind::BrokenPipe
482                } else {
483                    false
484                }
485            }
486
487            LogError::NoBootTimestamp
488            | LogError::DumpWithSinceNow
489            | LogError::NoSymbolizerConfig
490            | LogError::FfxError(_)
491            | LogError::Utf8Error(_)
492            | LogError::FidlError(_)
493            | LogError::DeprecatedFlag { .. }
494            | LogError::FuzzyMatchTooManyMatches(_)
495            | LogError::SearchParameterNotFound(_) => false,
496        }
497    }
498}
499
500/// Trait used to get available instances given a moniker query.
501#[async_trait::async_trait(?Send)]
502pub trait InstanceGetter {
503    async fn get_monikers_from_query(&self, query: &str) -> Result<Vec<Moniker>, LogError>;
504}
505
506#[async_trait::async_trait(?Send)]
507impl InstanceGetter for RealmQueryProxy {
508    async fn get_monikers_from_query(&self, query: &str) -> Result<Vec<Moniker>, LogError> {
509        Ok(get_instances_from_query(query, self)
510            .await?
511            .into_iter()
512            .map(|value| value.moniker)
513            .collect())
514    }
515}
516
517impl LogCommand {
518    async fn map_interest_selectors<'a>(
519        realm_query: &impl InstanceGetter,
520        interest_selectors: impl Iterator<Item = &'a LogInterestSelector>,
521    ) -> Result<impl Iterator<Item = Cow<'a, LogInterestSelector>>, LogError> {
522        let selectors = Self::get_selectors_and_monikers(interest_selectors);
523        let mut translated_selectors = vec![];
524        for (moniker, selector) in selectors {
525            // Attempt to translate to a single instance
526            let instances = realm_query.get_monikers_from_query(moniker.as_str()).await?;
527            // If exactly one match, perform rewrite
528            if instances.len() == 1 {
529                let mut translated_selector = selector.clone();
530                translated_selector.selector = instances[0].clone().into_component_selector();
531                translated_selectors.push((Cow::Owned(translated_selector), instances));
532            } else {
533                translated_selectors.push((Cow::Borrowed(selector), instances));
534            }
535        }
536        if translated_selectors.iter().any(|(_, matches)| matches.len() > 1) {
537            let mut err_output = vec![];
538            writeln!(
539                &mut err_output,
540                "WARN: One or more of your selectors appears to be ambiguous"
541            )?;
542            writeln!(&mut err_output, "and may not match any components on your system.\n")?;
543            writeln!(
544                &mut err_output,
545                "If this is unintentional you can explicitly match using the"
546            )?;
547            writeln!(&mut err_output, "following command:\n")?;
548            writeln!(&mut err_output, "ffx log \\")?;
549            let mut output = vec![];
550            for (oselector, instances) in translated_selectors {
551                for selector in instances {
552                    writeln!(
553                        output,
554                        "\t--set-severity {}#{} \\",
555                        sanitize_moniker_for_selectors(selector.to_string().as_str())
556                            .replace("\\", "\\\\"),
557                        format!("{:?}", oselector.interest.min_severity.unwrap()).to_uppercase()
558                    )?;
559                }
560            }
561            // Intentionally ignored, removes the newline, space, and \
562            let _ = output.pop();
563            let _ = output.pop();
564            let _ = output.pop();
565
566            writeln!(&mut err_output, "{}", String::from_utf8(output).unwrap())?;
567            writeln!(&mut err_output, "\nIf this is intentional, you can disable this with")?;
568            writeln!(&mut err_output, "ffx log --force-set-severity.")?;
569
570            ffx_bail!("{}", String::from_utf8(err_output)?);
571        }
572        Ok(translated_selectors.into_iter().map(|(selector, _)| selector))
573    }
574
575    pub fn validate_cmd_flags_with_warnings(&mut self) -> Result<Vec<&'static str>, LogError> {
576        let mut warnings = vec![];
577
578        if !self.moniker.is_empty() {
579            warnings.push("WARNING: --moniker is deprecated, use --component instead");
580            if self.component.is_empty() {
581                self.component = std::mem::take(&mut self.moniker);
582            } else {
583                warnings.push("WARNING: ignoring --moniker arguments in favor of --component");
584            }
585        }
586
587        Ok(warnings)
588    }
589
590    /// Sets interest based on configured selectors.
591    /// If a single ambiguous match is found, the monikers in the selectors
592    /// are automatically re-written.
593    pub async fn maybe_set_interest(
594        &self,
595        log_settings_client: &LogSettingsProxy,
596        realm_query: &impl InstanceGetter,
597    ) -> Result<(), LogError> {
598        let (set_severity, force_set_severity, persist) =
599            if let Some(LogSubCommand::SetSeverity(options)) = &self.sub_command {
600                // No other argument can exist in conjunction with SetSeverity
601                let default_cmd = LogCommand {
602                    sub_command: Some(LogSubCommand::SetSeverity(options.clone())),
603                    ..Default::default()
604                };
605                if &default_cmd != self {
606                    ffx_bail!("Cannot combine set-severity with other options.");
607                }
608                (&options.interest_selector, options.force, !options.no_persist)
609            } else {
610                (&self.set_severity, self.force_set_severity, false)
611            };
612
613        if persist || !set_severity.is_empty() {
614            let selectors = if force_set_severity {
615                set_severity.clone().into_iter().flatten().collect::<Vec<_>>()
616            } else {
617                let new_selectors =
618                    Self::map_interest_selectors(realm_query, set_severity.iter().flatten())
619                        .await?
620                        .map(|s| s.into_owned())
621                        .collect::<Vec<_>>();
622                if new_selectors.is_empty() {
623                    set_severity.clone().into_iter().flatten().collect::<Vec<_>>()
624                } else {
625                    new_selectors
626                }
627            };
628            log_settings_client
629                .set_component_interest(
630                    &flex_fuchsia_diagnostics::LogSettingsSetComponentInterestRequest {
631                        selectors: Some(selectors),
632                        persist: Some(persist),
633                        ..Default::default()
634                    },
635                )
636                .await?;
637        }
638
639        Ok(())
640    }
641
642    fn get_selectors_and_monikers<'a>(
643        interest_selectors: impl Iterator<Item = &'a LogInterestSelector>,
644    ) -> Vec<(String, &'a LogInterestSelector)> {
645        let mut selectors = vec![];
646        for selector in interest_selectors {
647            let segments = selector.selector.moniker_segments.as_ref().unwrap();
648            let mut full_moniker = String::new();
649            for segment in segments {
650                match segment {
651                    flex_fuchsia_diagnostics::StringSelector::ExactMatch(segment) => {
652                        if full_moniker.is_empty() {
653                            full_moniker.push_str(segment);
654                        } else {
655                            full_moniker.push('/');
656                            full_moniker.push_str(segment);
657                        }
658                    }
659                    _ => {
660                        // If the user passed a non-exact match we assume they
661                        // know what they're doing and skip this logic.
662                        return vec![];
663                    }
664                }
665            }
666            selectors.push((full_moniker, selector));
667        }
668        selectors
669    }
670}
671
672impl TopLevelCommand for LogCommand {}
673
674fn log_interest_selector(s: &str) -> Result<OneOrMany<LogInterestSelector>, String> {
675    if s.contains(",") {
676        let many: Result<Vec<LogInterestSelector>, String> = s
677            .split(",")
678            .map(|value| selectors::parse_log_interest_selector(value).map_err(|e| e.to_string()))
679            .collect();
680        Ok(OneOrMany::Many(many?))
681    } else {
682        Ok(OneOrMany::One(selectors::parse_log_interest_selector(s).map_err(|s| s.to_string())?))
683    }
684}
685
686#[cfg(test)]
687mod test {
688    use super::*;
689    use assert_matches::assert_matches;
690    use async_trait::async_trait;
691    use fidl::endpoints::create_proxy;
692    use flex_fuchsia_diagnostics::{LogSettingsMarker, LogSettingsRequest};
693    use futures_util::StreamExt;
694    use futures_util::future::Either;
695    use futures_util::stream::FuturesUnordered;
696    use selectors::parse_log_interest_selector;
697
698    #[derive(Default)]
699    struct FakeInstanceGetter {
700        output: Vec<Moniker>,
701        expected_selector: Option<String>,
702    }
703
704    #[async_trait(?Send)]
705    impl InstanceGetter for FakeInstanceGetter {
706        async fn get_monikers_from_query(&self, query: &str) -> Result<Vec<Moniker>, LogError> {
707            if let Some(expected) = &self.expected_selector {
708                assert_eq!(expected, query);
709            }
710            Ok(self.output.clone())
711        }
712    }
713
714    #[fuchsia::test]
715    async fn test_symbolize_mode_from_str() {
716        assert_matches!(SymbolizeMode::from_str("off"), Ok(value) if value == SymbolizeMode::Off);
717        assert_matches!(
718            SymbolizeMode::from_str("pretty"),
719            Ok(value) if value == SymbolizeMode::Pretty
720        );
721        assert_matches!(
722            SymbolizeMode::from_str("classic"),
723            Ok(value) if value == SymbolizeMode::Classic
724        );
725    }
726
727    #[fuchsia::test]
728    async fn maybe_set_interest_errors_additional_arguments_passed_to_set_interest() {
729        let (settings_proxy, settings_server) = create_proxy::<LogSettingsMarker>();
730        let getter = FakeInstanceGetter {
731            expected_selector: Some("ambiguous_selector".into()),
732            output: vec![
733                Moniker::try_from("core/some/ambiguous_selector:thing/test").unwrap(),
734                Moniker::try_from("core/other/ambiguous_selector:thing/test").unwrap(),
735            ],
736        };
737        // Main should return an error
738
739        let cmd = LogCommand {
740            sub_command: Some(LogSubCommand::SetSeverity(SetSeverityCommand {
741                interest_selector: vec![OneOrMany::One(
742                    parse_log_interest_selector("ambiguous_selector#INFO").unwrap(),
743                )],
744                force: false,
745                no_persist: false,
746            })),
747            hide_file: true,
748            ..LogCommand::default()
749        };
750        let mut set_interest_result = None;
751
752        let mut scheduler = FuturesUnordered::new();
753        scheduler.push(Either::Left(async {
754            set_interest_result = Some(cmd.maybe_set_interest(&settings_proxy, &getter).await);
755            drop(settings_proxy);
756        }));
757        scheduler.push(Either::Right(async {
758            let request = settings_server.into_stream().next().await;
759            // The channel should be closed without sending any requests.
760            assert_matches!(request, None);
761        }));
762        while scheduler.next().await.is_some() {}
763        drop(scheduler);
764
765        let error = format!("{}", set_interest_result.unwrap().unwrap_err());
766
767        const EXPECTED_INTEREST_ERROR: &str = "Cannot combine set-severity with other options.";
768        assert_eq!(error, EXPECTED_INTEREST_ERROR);
769    }
770
771    #[fuchsia::test]
772    async fn maybe_set_interest_errors_if_ambiguous_selector() {
773        let (settings_proxy, settings_server) = create_proxy::<LogSettingsMarker>();
774        let getter = FakeInstanceGetter {
775            expected_selector: Some("ambiguous_selector".into()),
776            output: vec![
777                Moniker::try_from("core/some/ambiguous_selector:thing/test").unwrap(),
778                Moniker::try_from("core/other/ambiguous_selector:thing/test").unwrap(),
779            ],
780        };
781        // Main should return an error
782
783        let cmd = LogCommand {
784            sub_command: Some(LogSubCommand::Dump(DumpCommand {})),
785            set_severity: vec![OneOrMany::One(
786                parse_log_interest_selector("ambiguous_selector#INFO").unwrap(),
787            )],
788            ..LogCommand::default()
789        };
790        let mut set_interest_result = None;
791
792        let mut scheduler = FuturesUnordered::new();
793        scheduler.push(Either::Left(async {
794            set_interest_result = Some(cmd.maybe_set_interest(&settings_proxy, &getter).await);
795            drop(settings_proxy);
796        }));
797        scheduler.push(Either::Right(async {
798            let request = settings_server.into_stream().next().await;
799            // The channel should be closed without sending any requests.
800            assert_matches!(request, None);
801        }));
802        while scheduler.next().await.is_some() {}
803        drop(scheduler);
804
805        let error = format!("{}", set_interest_result.unwrap().unwrap_err());
806
807        const EXPECTED_INTEREST_ERROR: &str = r#"WARN: One or more of your selectors appears to be ambiguous
808and may not match any components on your system.
809
810If this is unintentional you can explicitly match using the
811following command:
812
813ffx log \
814	--set-severity core/some/ambiguous_selector\\:thing/test#INFO \
815	--set-severity core/other/ambiguous_selector\\:thing/test#INFO
816
817If this is intentional, you can disable this with
818ffx log --force-set-severity.
819"#;
820        assert_eq!(error, EXPECTED_INTEREST_ERROR);
821    }
822
823    #[fuchsia::test]
824    async fn logger_translates_selector_if_one_match() {
825        let cmd = LogCommand {
826            sub_command: Some(LogSubCommand::Dump(DumpCommand {})),
827            set_severity: vec![OneOrMany::One(
828                parse_log_interest_selector("ambiguous_selector#INFO").unwrap(),
829            )],
830            ..LogCommand::default()
831        };
832        let mut set_interest_result = None;
833        let getter = FakeInstanceGetter {
834            expected_selector: Some("ambiguous_selector".into()),
835            output: vec![Moniker::try_from("core/some/ambiguous_selector").unwrap()],
836        };
837        let mut scheduler = FuturesUnordered::new();
838        let (settings_proxy, settings_server) = create_proxy::<LogSettingsMarker>();
839        scheduler.push(Either::Left(async {
840            set_interest_result = Some(cmd.maybe_set_interest(&settings_proxy, &getter).await);
841            drop(settings_proxy);
842        }));
843        scheduler.push(Either::Right(async {
844            let request = settings_server.into_stream().next().await;
845            let (payload, responder) = assert_matches!(
846                request,
847                Some(Ok(LogSettingsRequest::SetComponentInterest { payload, responder })) =>
848                (payload, responder)
849            );
850            responder.send().unwrap();
851            assert_eq!(
852                payload.selectors,
853                Some(vec![
854                    parse_log_interest_selector("core/some/ambiguous_selector#INFO").unwrap()
855                ])
856            );
857        }));
858        while scheduler.next().await.is_some() {}
859        drop(scheduler);
860        assert_matches!(set_interest_result, Some(Ok(())));
861    }
862
863    #[fuchsia::test]
864    async fn logger_uses_specified_selectors_if_no_results_returned() {
865        let cmd = LogCommand {
866            sub_command: Some(LogSubCommand::Dump(DumpCommand {})),
867            set_severity: vec![OneOrMany::One(
868                parse_log_interest_selector("core/something/a:b/elements:main/otherstuff:*#DEBUG")
869                    .unwrap(),
870            )],
871            ..LogCommand::default()
872        };
873        let mut set_interest_result = None;
874        let getter = FakeInstanceGetter {
875            expected_selector: Some("core/something/a:b/elements:main/otherstuff:*#DEBUG".into()),
876            output: vec![],
877        };
878        let scheduler = FuturesUnordered::new();
879        let (settings_proxy, settings_server) = create_proxy::<LogSettingsMarker>();
880        scheduler.push(Either::Left(async {
881            set_interest_result = Some(cmd.maybe_set_interest(&settings_proxy, &getter).await);
882            drop(settings_proxy);
883        }));
884        scheduler.push(Either::Right(async {
885            let request = settings_server.into_stream().next().await;
886            let (payload, responder) = assert_matches!(
887                request,
888                Some(Ok(LogSettingsRequest::SetComponentInterest { payload, responder })) =>
889                (payload, responder)
890            );
891            responder.send().unwrap();
892            assert_eq!(
893                payload.selectors,
894                Some(vec![
895                    parse_log_interest_selector(
896                        "core/something/a:b/elements:main/otherstuff:*#DEBUG"
897                    )
898                    .unwrap()
899                ])
900            );
901        }));
902        scheduler.map(|_| Ok(())).forward(futures::sink::drain()).await.unwrap();
903        assert_matches!(set_interest_result, Some(Ok(())));
904    }
905
906    #[fuchsia::test]
907    async fn logger_prints_ignores_ambiguity_if_force_set_severity_is_used() {
908        let cmd = LogCommand {
909            sub_command: Some(LogSubCommand::SetSeverity(SetSeverityCommand {
910                no_persist: true,
911                interest_selector: vec![OneOrMany::One(
912                    parse_log_interest_selector("ambiguous_selector#INFO").unwrap(),
913                )],
914                force: true,
915            })),
916            ..LogCommand::default()
917        };
918        let getter = FakeInstanceGetter {
919            expected_selector: Some("ambiguous_selector".into()),
920            output: vec![
921                Moniker::try_from("core/some/ambiguous_selector:thing/test").unwrap(),
922                Moniker::try_from("core/other/ambiguous_selector:thing/test").unwrap(),
923            ],
924        };
925        let mut set_interest_result = None;
926        let mut scheduler = FuturesUnordered::new();
927        let (settings_proxy, settings_server) = create_proxy::<LogSettingsMarker>();
928        scheduler.push(Either::Left(async {
929            set_interest_result = Some(cmd.maybe_set_interest(&settings_proxy, &getter).await);
930            drop(settings_proxy);
931        }));
932        scheduler.push(Either::Right(async {
933            let request = settings_server.into_stream().next().await;
934            let (payload, responder) = assert_matches!(
935                request,
936                Some(Ok(LogSettingsRequest::SetComponentInterest { payload, responder })) =>
937                (payload, responder)
938            );
939            responder.send().unwrap();
940            assert_eq!(
941                payload.selectors,
942                Some(vec![parse_log_interest_selector("ambiguous_selector#INFO").unwrap()])
943            );
944        }));
945        while scheduler.next().await.is_some() {}
946        drop(scheduler);
947        assert_matches!(set_interest_result, Some(Ok(())));
948    }
949
950    #[fuchsia::test]
951    async fn logger_prints_ignores_ambiguity_if_force_set_severity_is_used_persistent() {
952        let cmd = LogCommand {
953            sub_command: Some(LogSubCommand::SetSeverity(SetSeverityCommand {
954                no_persist: false,
955                interest_selector: vec![log_socket_stream::OneOrMany::One(
956                    parse_log_interest_selector("ambiguous_selector#INFO").unwrap(),
957                )],
958                force: true,
959            })),
960            ..LogCommand::default()
961        };
962        let getter = FakeInstanceGetter {
963            expected_selector: Some("ambiguous_selector".into()),
964            output: vec![
965                Moniker::try_from("core/some/ambiguous_selector:thing/test").unwrap(),
966                Moniker::try_from("core/other/ambiguous_selector:thing/test").unwrap(),
967            ],
968        };
969        let mut set_interest_result = None;
970        let mut scheduler = FuturesUnordered::new();
971        let (settings_proxy, settings_server) = create_proxy::<LogSettingsMarker>();
972        scheduler.push(Either::Left(async {
973            set_interest_result = Some(cmd.maybe_set_interest(&settings_proxy, &getter).await);
974            drop(settings_proxy);
975        }));
976        scheduler.push(Either::Right(async {
977            let request = settings_server.into_stream().next().await;
978            let (payload, responder) = assert_matches!(
979                request,
980                Some(Ok(LogSettingsRequest::SetComponentInterest { payload, responder })) =>
981                (payload, responder)
982            );
983            responder.send().unwrap();
984            assert_eq!(
985                payload.selectors,
986                Some(vec![parse_log_interest_selector("ambiguous_selector#INFO").unwrap()])
987            );
988            assert_eq!(payload.persist, Some(true));
989        }));
990        while scheduler.next().await.is_some() {}
991        drop(scheduler);
992        assert_matches!(set_interest_result, Some(Ok(())));
993    }
994
995    #[fuchsia::test]
996    async fn logger_prints_ignores_ambiguity_if_machine_output_is_used() {
997        let cmd = LogCommand {
998            sub_command: Some(LogSubCommand::Dump(DumpCommand {})),
999            set_severity: vec![OneOrMany::One(
1000                parse_log_interest_selector("ambiguous_selector#INFO").unwrap(),
1001            )],
1002            force_set_severity: true,
1003            ..LogCommand::default()
1004        };
1005        let getter = FakeInstanceGetter {
1006            expected_selector: Some("ambiguous_selector".into()),
1007            output: vec![
1008                Moniker::try_from("core/some/collection:thing/test").unwrap(),
1009                Moniker::try_from("core/other/collection:thing/test").unwrap(),
1010            ],
1011        };
1012        let mut set_interest_result = None;
1013        let mut scheduler = FuturesUnordered::new();
1014        let (settings_proxy, settings_server) = create_proxy::<LogSettingsMarker>();
1015        scheduler.push(Either::Left(async {
1016            set_interest_result = Some(cmd.maybe_set_interest(&settings_proxy, &getter).await);
1017            drop(settings_proxy);
1018        }));
1019        scheduler.push(Either::Right(async {
1020            let request = settings_server.into_stream().next().await;
1021            let (payload, responder) = assert_matches!(
1022                request,
1023                Some(Ok(LogSettingsRequest::SetComponentInterest { payload, responder })) =>
1024                (payload, responder)
1025            );
1026            responder.send().unwrap();
1027            assert_eq!(
1028                payload.selectors,
1029                Some(vec![parse_log_interest_selector("ambiguous_selector#INFO").unwrap()])
1030            );
1031        }));
1032        while scheduler.next().await.is_some() {}
1033        drop(scheduler);
1034        assert_matches!(set_interest_result, Some(Ok(())));
1035    }
1036    #[test]
1037    fn test_parse_selector() {
1038        assert_eq!(
1039            log_interest_selector("core/audio#DEBUG").unwrap(),
1040            OneOrMany::One(parse_log_interest_selector("core/audio#DEBUG").unwrap())
1041        );
1042    }
1043
1044    #[test]
1045    fn test_parse_selector_with_commas() {
1046        assert_eq!(
1047            log_interest_selector("core/audio#DEBUG,bootstrap/archivist#TRACE").unwrap(),
1048            OneOrMany::Many(vec![
1049                parse_log_interest_selector("core/audio#DEBUG").unwrap(),
1050                parse_log_interest_selector("bootstrap/archivist#TRACE").unwrap()
1051            ])
1052        );
1053    }
1054
1055    #[test]
1056    fn test_parse_time() {
1057        assert!(parse_time("now").unwrap().is_now);
1058        let date_string = "04/20/2020";
1059        let res = parse_time(date_string).unwrap();
1060        assert!(!res.is_now);
1061        assert_eq!(
1062            res.date_naive(),
1063            parse_date_string(date_string, Local::now(), Dialect::Us).unwrap().date_naive()
1064        );
1065    }
1066
1067    #[test]
1068    fn test_log_error_is_broken_pipe() {
1069        assert!(
1070            LogError::IOError(std::io::Error::new(std::io::ErrorKind::BrokenPipe, "broken pipe"))
1071                .is_broken_pipe()
1072        );
1073        assert!(
1074            LogError::UnknownError(anyhow::Error::new(std::io::Error::new(
1075                std::io::ErrorKind::BrokenPipe,
1076                "broken pipe"
1077            )))
1078            .is_broken_pipe()
1079        );
1080        assert!(!LogError::IOError(std::io::Error::other("other")).is_broken_pipe());
1081        assert!(!LogError::NoBootTimestamp.is_broken_pipe());
1082    }
1083}
log_command/lib.rs

log_command/
lib.rs
