log_command/
log_formatter.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 crate::filter::LogFilterCriteria;
6use crate::log_socket_stream::{JsonDeserializeError, LogsDataStream};
7use crate::{
8    DetailedDateTime, InstanceGetter, LogCommand, LogError, LogProcessingResult, TimeFormat,
9};
10use anyhow::Result;
11use async_trait::async_trait;
12use diagnostics_data::{
13    Data, LogTextColor, LogTextDisplayOptions, LogTextPresenter, LogTimeDisplayFormat, Logs,
14    LogsData, LogsDataBuilder, LogsField, LogsProperty, Severity, Timezone,
15};
16use futures_util::future::Either;
17use futures_util::stream::FuturesUnordered;
18use futures_util::{select, StreamExt};
19use serde::{Deserialize, Serialize};
20use std::fmt::Display;
21use std::io::Write;
22use std::time::Duration;
23use thiserror::Error;
24use writer::ToolIO;
25
26pub use diagnostics_data::Timestamp;
27
28pub const TIMESTAMP_FORMAT: &str = "%Y-%m-%d %H:%M:%S.%3f";
29
30/// Type of an FFX event
31#[derive(Clone, Debug, Deserialize, PartialEq, Serialize)]
32pub enum EventType {
33    /// Overnet connection to logger started
34    LoggingStarted,
35    /// Overnet connection to logger lost
36    TargetDisconnected,
37}
38
39/// Type of data in a log entry
40#[derive(Clone, Debug, PartialEq, Serialize, Deserialize)]
41pub enum LogData {
42    /// A log entry from the target
43    TargetLog(LogsData),
44}
45
46impl LogData {
47    /// Gets the LogData as a target log.
48    pub fn as_target_log(&self) -> Option<&LogsData> {
49        match self {
50            LogData::TargetLog(log) => Some(log),
51        }
52    }
53
54    pub fn as_target_log_mut(&mut self) -> Option<&mut LogsData> {
55        match self {
56            LogData::TargetLog(log) => Some(log),
57        }
58    }
59}
60
61impl From<LogsData> for LogData {
62    fn from(data: LogsData) -> Self {
63        Self::TargetLog(data)
64    }
65}
66
67/// A log entry from either the host, target, or
68/// a symbolized log.
69#[derive(Clone, Debug, PartialEq, Serialize, Deserialize)]
70pub struct LogEntry {
71    /// The log
72    pub data: LogData,
73}
74
75impl LogEntry {
76    fn utc_timestamp(&self, boot_ts: Option<Timestamp>) -> Timestamp {
77        Timestamp::from_nanos(match &self.data {
78            LogData::TargetLog(data) => {
79                data.metadata.timestamp.into_nanos()
80                    + boot_ts.map(|value| value.into_nanos()).unwrap_or(0)
81            }
82        })
83    }
84}
85
86// Required if we want to use ffx's built-in I/O, but
87// this isn't really applicable to us because we have
88// custom formatting rules.
89impl Display for LogEntry {
90    fn fmt(&self, _f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
91        unreachable!("UNSUPPORTED -- This type cannot be formatted with std format.");
92    }
93}
94
95/// A trait for symbolizing log entries
96#[async_trait(?Send)]
97pub trait Symbolize {
98    /// Symbolizes a LogEntry and optionally produces a result.
99    /// The symbolizer may choose to discard the result.
100    /// This method may be called multiple times concurrently.
101    async fn symbolize(&self, entry: LogEntry) -> Option<LogEntry>;
102}
103
104async fn handle_value<S>(one: Data<Logs>, symbolizer: &S) -> Option<LogEntry>
105where
106    S: Symbolize + ?Sized,
107{
108    let entry = LogEntry { data: one.into() };
109    symbolizer.symbolize(entry).await
110}
111
112fn generate_timestamp_message(boot_timestamp: Timestamp) -> LogEntry {
113    LogEntry {
114        data: LogData::TargetLog(
115            LogsDataBuilder::new(diagnostics_data::BuilderArgs {
116                moniker: "ffx".try_into().unwrap(),
117                timestamp: Timestamp::from_nanos(0),
118                component_url: Some("ffx".into()),
119                severity: Severity::Info,
120            })
121            .set_message("Logging started")
122            .add_key(LogsProperty::String(
123                LogsField::Other("utc_time_now".into()),
124                chrono::Utc::now().to_rfc3339(),
125            ))
126            .add_key(LogsProperty::Int(
127                LogsField::Other("current_boot_timestamp".to_string()),
128                boot_timestamp.into_nanos(),
129            ))
130            .build(),
131        ),
132    }
133}
134
135/// Reads logs from a socket and formats them using the given formatter and symbolizer.
136pub async fn dump_logs_from_socket<F, S>(
137    socket: fuchsia_async::Socket,
138    formatter: &mut F,
139    symbolizer: &S,
140    include_timestamp: bool,
141) -> Result<LogProcessingResult, JsonDeserializeError>
142where
143    F: LogFormatter + BootTimeAccessor,
144    S: Symbolize + ?Sized,
145{
146    let mut decoder = Box::pin(LogsDataStream::new(socket).fuse());
147    let mut symbolize_pending = FuturesUnordered::new();
148    if include_timestamp && !formatter.is_utc_time_format() {
149        formatter.push_log(generate_timestamp_message(formatter.get_boot_timestamp())).await?;
150    }
151    while let Some(value) = select! {
152        res = decoder.next() => Some(Either::Left(res)),
153        res = symbolize_pending.next() => Some(Either::Right(res)),
154        complete => None,
155    } {
156        match value {
157            Either::Left(Some(log)) => {
158                symbolize_pending.push(handle_value(log, symbolizer));
159            }
160            Either::Right(Some(Some(symbolized))) => match formatter.push_log(symbolized).await? {
161                LogProcessingResult::Exit => {
162                    return Ok(LogProcessingResult::Exit);
163                }
164                LogProcessingResult::Continue => {}
165            },
166            _ => {}
167        }
168    }
169    Ok(LogProcessingResult::Continue)
170}
171
172pub trait BootTimeAccessor {
173    /// Sets the boot timestamp in nanoseconds since the Unix epoch.
174    fn set_boot_timestamp(&mut self, _boot_ts_nanos: Timestamp);
175
176    /// Returns the boot timestamp in nanoseconds since the Unix epoch.
177    fn get_boot_timestamp(&self) -> Timestamp;
178}
179
180/// Timestamp filter which is either either boot-based or UTC-based.
181#[derive(Clone, Debug)]
182pub struct DeviceOrLocalTimestamp {
183    /// Timestamp in boot time
184    pub timestamp: Timestamp,
185    /// True if this filter should be applied to boot time,
186    /// false if UTC time.
187    pub is_boot: bool,
188}
189
190impl DeviceOrLocalTimestamp {
191    /// Creates a DeviceOrLocalTimestamp from a real-time date/time or
192    /// a boot date/time. Returns None if both rtc and boot are None.
193    /// Returns None if the timestamp is "now".
194    pub fn new(
195        rtc: Option<&DetailedDateTime>,
196        boot: Option<&Duration>,
197    ) -> Option<DeviceOrLocalTimestamp> {
198        rtc.as_ref()
199            .filter(|value| !value.is_now)
200            .map(|value| DeviceOrLocalTimestamp {
201                timestamp: Timestamp::from_nanos(value.naive_utc().timestamp_nanos_opt().unwrap()),
202                is_boot: false,
203            })
204            .or_else(|| {
205                boot.map(|value| DeviceOrLocalTimestamp {
206                    timestamp: Timestamp::from_nanos(value.as_nanos() as i64),
207                    is_boot: true,
208                })
209            })
210    }
211}
212
213/// Log formatter options
214#[derive(Clone, Debug)]
215pub struct LogFormatterOptions {
216    /// Text display options
217    pub display: Option<LogTextDisplayOptions>,
218    /// Only display logs since the specified time.
219    pub since: Option<DeviceOrLocalTimestamp>,
220    /// Only display logs until the specified time.
221    pub until: Option<DeviceOrLocalTimestamp>,
222}
223
224impl Default for LogFormatterOptions {
225    fn default() -> Self {
226        LogFormatterOptions { display: Some(Default::default()), since: None, until: None }
227    }
228}
229
230/// Log formatter error
231#[derive(Error, Debug)]
232pub enum FormatterError {
233    /// An unknown error occurred
234    #[error(transparent)]
235    Other(#[from] anyhow::Error),
236    /// An IO error occurred
237    #[error(transparent)]
238    IO(#[from] std::io::Error),
239}
240
241/// Default formatter implementation
242pub struct DefaultLogFormatter<W>
243where
244    W: Write + ToolIO<OutputItem = LogEntry>,
245{
246    writer: W,
247    filters: LogFilterCriteria,
248    options: LogFormatterOptions,
249    boot_ts_nanos: Option<Timestamp>,
250}
251
252/// Converts from UTC time to boot time.
253fn utc_to_boot(boot_ts: Timestamp, utc: Timestamp) -> Timestamp {
254    Timestamp::from_nanos(utc.into_nanos() - boot_ts.into_nanos())
255}
256
257#[async_trait(?Send)]
258impl<W> LogFormatter for DefaultLogFormatter<W>
259where
260    W: Write + ToolIO<OutputItem = LogEntry>,
261{
262    async fn push_log(&mut self, log_entry: LogEntry) -> Result<LogProcessingResult, LogError> {
263        self.push_log_internal(log_entry, true).await
264    }
265
266    fn is_utc_time_format(&self) -> bool {
267        self.options.display.iter().any(|options| match options.time_format {
268            LogTimeDisplayFormat::Original => false,
269            LogTimeDisplayFormat::WallTime { tz, offset: _ } => tz == Timezone::Utc,
270        })
271    }
272}
273
274impl<W> BootTimeAccessor for DefaultLogFormatter<W>
275where
276    W: Write + ToolIO<OutputItem = LogEntry>,
277{
278    fn set_boot_timestamp(&mut self, boot_ts_nanos: Timestamp) {
279        if let Some(LogTextDisplayOptions {
280            time_format: LogTimeDisplayFormat::WallTime { ref mut offset, .. },
281            ..
282        }) = &mut self.options.display
283        {
284            *offset = boot_ts_nanos.into_nanos();
285        }
286        self.boot_ts_nanos = Some(boot_ts_nanos);
287    }
288    fn get_boot_timestamp(&self) -> Timestamp {
289        debug_assert!(self.boot_ts_nanos.is_some());
290        self.boot_ts_nanos.unwrap_or_else(|| Timestamp::from_nanos(0))
291    }
292}
293
294/// Object which contains a Writer that can be borrowed
295pub trait WriterContainer<W>
296where
297    W: Write + ToolIO<OutputItem = LogEntry>,
298{
299    fn writer(&mut self) -> &mut W;
300}
301
302impl<W> WriterContainer<W> for DefaultLogFormatter<W>
303where
304    W: Write + ToolIO<OutputItem = LogEntry>,
305{
306    fn writer(&mut self) -> &mut W {
307        &mut self.writer
308    }
309}
310
311impl<W> DefaultLogFormatter<W>
312where
313    W: Write + ToolIO<OutputItem = LogEntry>,
314{
315    /// Creates a new DefaultLogFormatter with the given writer and options.
316    pub fn new(filters: LogFilterCriteria, writer: W, options: LogFormatterOptions) -> Self {
317        Self { filters, writer, options, boot_ts_nanos: None }
318    }
319
320    pub async fn expand_monikers(&mut self, getter: &impl InstanceGetter) -> Result<(), LogError> {
321        self.filters.expand_monikers(getter).await
322    }
323
324    pub async fn push_unfiltered_log(
325        &mut self,
326        log_entry: LogEntry,
327    ) -> Result<LogProcessingResult, LogError> {
328        self.push_log_internal(log_entry, false).await
329    }
330
331    async fn push_log_internal(
332        &mut self,
333        log_entry: LogEntry,
334        enable_filters: bool,
335    ) -> Result<LogProcessingResult, LogError> {
336        if enable_filters {
337            if self.filter_by_timestamp(&log_entry, self.options.since.as_ref(), |a, b| a <= b) {
338                return Ok(LogProcessingResult::Continue);
339            }
340
341            if self.filter_by_timestamp(&log_entry, self.options.until.as_ref(), |a, b| a >= b) {
342                return Ok(LogProcessingResult::Exit);
343            }
344
345            if !self.filters.matches(&log_entry) {
346                return Ok(LogProcessingResult::Continue);
347            }
348        }
349        match self.options.display {
350            Some(text_options) => {
351                let mut options_for_this_line_only = self.options.clone();
352                options_for_this_line_only.display = Some(text_options);
353                if !enable_filters {
354                    // For host logs, don't apply the boot time offset
355                    // as this is with reference to the UTC timeline
356                    if let LogTimeDisplayFormat::WallTime { ref mut offset, .. } =
357                        options_for_this_line_only.display.as_mut().unwrap().time_format
358                    {
359                        // 1 nanosecond so that LogTimeDisplayFormat in diagnostics_data
360                        // knows that we have a valid UTC offset. It normally falls back if
361                        // the UTC offset is 0. It prints at millisecond precision so being
362                        // off by +1 nanosecond isn't an issue.
363                        *offset = 1;
364                    };
365                }
366                self.format_text_log(options_for_this_line_only, log_entry)?;
367            }
368            None => {
369                self.writer.item(&log_entry).map_err(|err| LogError::UnknownError(err.into()))?;
370            }
371        };
372
373        Ok(LogProcessingResult::Continue)
374    }
375
376    /// Creates a new DefaultLogFormatter from command-line arguments.
377    pub fn new_from_args(cmd: &LogCommand, writer: W) -> Self {
378        let is_json = writer.is_machine();
379        let formatter = DefaultLogFormatter::new(
380            LogFilterCriteria::from(cmd.clone()),
381            writer,
382            LogFormatterOptions {
383                display: if is_json {
384                    None
385                } else {
386                    Some(LogTextDisplayOptions {
387                        show_tags: !cmd.hide_tags,
388                        color: if cmd.no_color {
389                            LogTextColor::None
390                        } else {
391                            LogTextColor::BySeverity
392                        },
393                        show_metadata: cmd.show_metadata,
394                        time_format: match cmd.clock {
395                            TimeFormat::Boot => LogTimeDisplayFormat::Original,
396                            TimeFormat::Local => LogTimeDisplayFormat::WallTime {
397                                tz: Timezone::Local,
398                                // This will receive a correct value when logging actually starts,
399                                // see `set_boot_timestamp()` method on the log formatter.
400                                offset: 0,
401                            },
402                            TimeFormat::Utc => LogTimeDisplayFormat::WallTime {
403                                tz: Timezone::Utc,
404                                // This will receive a correct value when logging actually starts,
405                                // see `set_boot_timestamp()` method on the log formatter.
406                                offset: 0,
407                            },
408                        },
409                        show_file: !cmd.hide_file,
410                        show_full_moniker: cmd.show_full_moniker,
411                    })
412                },
413                since: DeviceOrLocalTimestamp::new(cmd.since.as_ref(), cmd.since_boot.as_ref()),
414                until: DeviceOrLocalTimestamp::new(cmd.until.as_ref(), cmd.until_boot.as_ref()),
415            },
416        );
417        formatter
418    }
419
420    fn filter_by_timestamp(
421        &self,
422        log_entry: &LogEntry,
423        timestamp: Option<&DeviceOrLocalTimestamp>,
424        callback: impl Fn(&Timestamp, &Timestamp) -> bool,
425    ) -> bool {
426        let Some(timestamp) = timestamp else {
427            return false;
428        };
429        if timestamp.is_boot {
430            callback(
431                &utc_to_boot(
432                    self.get_boot_timestamp(),
433                    log_entry.utc_timestamp(self.boot_ts_nanos),
434                ),
435                &timestamp.timestamp,
436            )
437        } else {
438            callback(&log_entry.utc_timestamp(self.boot_ts_nanos), &timestamp.timestamp)
439        }
440    }
441
442    // This function's arguments are copied to make lifetimes in push_log easier since borrowing
443    // &self would complicate spam highlighting.
444    fn format_text_log(
445        &mut self,
446        options: LogFormatterOptions,
447        log_entry: LogEntry,
448    ) -> Result<(), FormatterError> {
449        let text_options = match options.display {
450            Some(o) => o,
451            None => {
452                unreachable!("If we are here, we can only be formatting text");
453            }
454        };
455        match log_entry {
456            LogEntry { data: LogData::TargetLog(data), .. } => {
457                // TODO(https://fxbug.dev/42072442): Add support for log spam redaction and other
458                // features listed in the design doc.
459                writeln!(self.writer, "{}", LogTextPresenter::new(&data, text_options))?;
460            }
461        }
462        Ok(())
463    }
464}
465
466#[allow(dead_code)] // TODO(https://fxbug.dev/421409178)
467/// Symbolizer that does nothing.
468pub struct NoOpSymbolizer;
469
470#[async_trait(?Send)]
471impl Symbolize for NoOpSymbolizer {
472    async fn symbolize(&self, entry: LogEntry) -> Option<LogEntry> {
473        Some(entry)
474    }
475}
476
477/// Trait for formatting logs one at a time.
478#[async_trait(?Send)]
479pub trait LogFormatter {
480    /// Formats a log entry and writes it to the output.
481    async fn push_log(&mut self, log_entry: LogEntry) -> Result<LogProcessingResult, LogError>;
482
483    /// Returns true if the formatter is configured to output in UTC time format.
484    fn is_utc_time_format(&self) -> bool;
485}
486
487#[cfg(test)]
488mod test {
489    use crate::parse_time;
490    use assert_matches::assert_matches;
491    use diagnostics_data::{LogsDataBuilder, Severity};
492    use std::cell::Cell;
493    use writer::{Format, JsonWriter, TestBuffers};
494
495    use super::*;
496
497    const DEFAULT_TS_NANOS: u64 = 1615535969000000000;
498
499    struct FakeFormatter {
500        logs: Vec<LogEntry>,
501        boot_timestamp: Timestamp,
502        is_utc_time_format: bool,
503    }
504
505    impl FakeFormatter {
506        fn new() -> Self {
507            Self {
508                logs: Vec::new(),
509                boot_timestamp: Timestamp::from_nanos(0),
510                is_utc_time_format: false,
511            }
512        }
513    }
514
515    impl BootTimeAccessor for FakeFormatter {
516        fn set_boot_timestamp(&mut self, boot_ts_nanos: Timestamp) {
517            self.boot_timestamp = boot_ts_nanos;
518        }
519
520        fn get_boot_timestamp(&self) -> Timestamp {
521            self.boot_timestamp
522        }
523    }
524
525    #[async_trait(?Send)]
526    impl LogFormatter for FakeFormatter {
527        async fn push_log(&mut self, log_entry: LogEntry) -> Result<LogProcessingResult, LogError> {
528            self.logs.push(log_entry);
529            Ok(LogProcessingResult::Continue)
530        }
531
532        fn is_utc_time_format(&self) -> bool {
533            self.is_utc_time_format
534        }
535    }
536
537    /// Symbolizer that prints "Fuchsia".
538    pub struct FakeFuchsiaSymbolizer;
539
540    fn set_log_msg(entry: &mut LogEntry, msg: impl Into<String>) {
541        *entry.data.as_target_log_mut().unwrap().msg_mut().unwrap() = msg.into();
542    }
543
544    #[async_trait(?Send)]
545    impl Symbolize for FakeFuchsiaSymbolizer {
546        async fn symbolize(&self, mut entry: LogEntry) -> Option<LogEntry> {
547            set_log_msg(&mut entry, "Fuchsia");
548            Some(entry)
549        }
550    }
551
552    struct FakeSymbolizerCallback {
553        should_discard: Cell<bool>,
554    }
555
556    impl FakeSymbolizerCallback {
557        fn new() -> Self {
558            Self { should_discard: Cell::new(true) }
559        }
560    }
561
562    async fn dump_logs_from_socket<F, S>(
563        socket: fuchsia_async::Socket,
564        formatter: &mut F,
565        symbolizer: &S,
566    ) -> Result<LogProcessingResult, JsonDeserializeError>
567    where
568        F: LogFormatter + BootTimeAccessor,
569        S: Symbolize + ?Sized,
570    {
571        super::dump_logs_from_socket(socket, formatter, symbolizer, false).await
572    }
573
574    #[async_trait(?Send)]
575    impl Symbolize for FakeSymbolizerCallback {
576        async fn symbolize(&self, mut input: LogEntry) -> Option<LogEntry> {
577            self.should_discard.set(!self.should_discard.get());
578            if self.should_discard.get() {
579                None
580            } else {
581                set_log_msg(&mut input, "symbolized log");
582                Some(input)
583            }
584        }
585    }
586
587    #[fuchsia::test]
588    async fn test_boot_timestamp_setter() {
589        let buffers = TestBuffers::default();
590        let stdout = JsonWriter::<LogEntry>::new_test(None, &buffers);
591        let options = LogFormatterOptions {
592            display: Some(LogTextDisplayOptions {
593                time_format: LogTimeDisplayFormat::WallTime { tz: Timezone::Utc, offset: 0 },
594                ..Default::default()
595            }),
596            ..Default::default()
597        };
598        let mut formatter =
599            DefaultLogFormatter::new(LogFilterCriteria::default(), stdout, options.clone());
600        formatter.set_boot_timestamp(Timestamp::from_nanos(1234));
601        assert_eq!(formatter.get_boot_timestamp(), Timestamp::from_nanos(1234));
602
603        // Boot timestamp is supported when using JSON output (for filtering)
604        let buffers = TestBuffers::default();
605        let output = JsonWriter::<LogEntry>::new_test(None, &buffers);
606        let options = LogFormatterOptions { display: None, ..Default::default() };
607        let mut formatter = DefaultLogFormatter::new(LogFilterCriteria::default(), output, options);
608        formatter.set_boot_timestamp(Timestamp::from_nanos(1234));
609        assert_eq!(formatter.get_boot_timestamp(), Timestamp::from_nanos(1234));
610    }
611
612    #[fuchsia::test]
613    async fn test_format_single_message() {
614        let symbolizer = NoOpSymbolizer {};
615        let mut formatter = FakeFormatter::new();
616        let target_log = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
617            moniker: "ffx".try_into().unwrap(),
618            timestamp: Timestamp::from_nanos(0),
619            component_url: Some("ffx".into()),
620            severity: Severity::Info,
621        })
622        .set_message("Hello world!")
623        .build();
624        let (sender, receiver) = zx::Socket::create_stream();
625        sender
626            .write(serde_json::to_string(&target_log).unwrap().as_bytes())
627            .expect("failed to write target log");
628        drop(sender);
629        dump_logs_from_socket(
630            fuchsia_async::Socket::from_socket(receiver),
631            &mut formatter,
632            &symbolizer,
633        )
634        .await
635        .unwrap();
636        assert_eq!(formatter.logs, vec![LogEntry { data: LogData::TargetLog(target_log) }]);
637    }
638
639    #[fuchsia::test]
640    async fn test_format_utc_timestamp() {
641        let symbolizer = NoOpSymbolizer {};
642        let mut formatter = FakeFormatter::new();
643        formatter.set_boot_timestamp(Timestamp::from_nanos(DEFAULT_TS_NANOS as i64));
644        let (_, receiver) = zx::Socket::create_stream();
645        super::dump_logs_from_socket(
646            fuchsia_async::Socket::from_socket(receiver),
647            &mut formatter,
648            &symbolizer,
649            true,
650        )
651        .await
652        .unwrap();
653        let target_log = formatter.logs[0].data.as_target_log().unwrap();
654        let properties = target_log.payload_keys().unwrap();
655        assert_eq!(target_log.msg().unwrap(), "Logging started");
656
657        // Ensure the end has a valid timestamp
658        chrono::DateTime::parse_from_rfc3339(
659            properties.get_property("utc_time_now").unwrap().string().unwrap(),
660        )
661        .unwrap();
662        assert_eq!(
663            properties.get_property("current_boot_timestamp").unwrap().int().unwrap(),
664            DEFAULT_TS_NANOS as i64
665        );
666    }
667
668    #[fuchsia::test]
669    async fn test_format_utc_timestamp_does_not_print_if_utc_time() {
670        let symbolizer = NoOpSymbolizer {};
671        let mut formatter = FakeFormatter::new();
672        formatter.is_utc_time_format = true;
673        formatter.set_boot_timestamp(Timestamp::from_nanos(DEFAULT_TS_NANOS as i64));
674        let (_, receiver) = zx::Socket::create_stream();
675        super::dump_logs_from_socket(
676            fuchsia_async::Socket::from_socket(receiver),
677            &mut formatter,
678            &symbolizer,
679            true,
680        )
681        .await
682        .unwrap();
683        assert_eq!(formatter.logs.len(), 0);
684    }
685
686    #[fuchsia::test]
687    async fn test_format_multiple_messages() {
688        let symbolizer = NoOpSymbolizer {};
689        let mut formatter = FakeFormatter::new();
690        let (sender, receiver) = zx::Socket::create_stream();
691        let target_log_0 = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
692            moniker: "ffx".try_into().unwrap(),
693            timestamp: Timestamp::from_nanos(0),
694            component_url: Some("ffx".into()),
695            severity: Severity::Info,
696        })
697        .set_message("Hello world!")
698        .set_pid(1)
699        .set_tid(2)
700        .build();
701        let target_log_1 = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
702            moniker: "ffx".try_into().unwrap(),
703            timestamp: Timestamp::from_nanos(1),
704            component_url: Some("ffx".into()),
705            severity: Severity::Info,
706        })
707        .set_message("Hello world 2!")
708        .build();
709        sender
710            .write(serde_json::to_string(&vec![&target_log_0, &target_log_1]).unwrap().as_bytes())
711            .expect("failed to write target log");
712        drop(sender);
713        dump_logs_from_socket(
714            fuchsia_async::Socket::from_socket(receiver),
715            &mut formatter,
716            &symbolizer,
717        )
718        .await
719        .unwrap();
720        assert_eq!(
721            formatter.logs,
722            vec![
723                LogEntry { data: LogData::TargetLog(target_log_0) },
724                LogEntry { data: LogData::TargetLog(target_log_1) }
725            ]
726        );
727    }
728
729    #[fuchsia::test]
730    async fn test_format_timestamp_filter() {
731        // test since and until args for the LogFormatter
732        let symbolizer = NoOpSymbolizer {};
733        let buffers = TestBuffers::default();
734        let stdout = JsonWriter::<LogEntry>::new_test(None, &buffers);
735        let mut formatter = DefaultLogFormatter::new(
736            LogFilterCriteria::default(),
737            stdout,
738            LogFormatterOptions {
739                since: Some(DeviceOrLocalTimestamp {
740                    timestamp: Timestamp::from_nanos(1),
741                    is_boot: true,
742                }),
743                until: Some(DeviceOrLocalTimestamp {
744                    timestamp: Timestamp::from_nanos(3),
745                    is_boot: true,
746                }),
747                ..Default::default()
748            },
749        );
750        formatter.set_boot_timestamp(Timestamp::from_nanos(0));
751
752        let (sender, receiver) = zx::Socket::create_stream();
753        let target_log_0 = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
754            moniker: "ffx".try_into().unwrap(),
755            timestamp: Timestamp::from_nanos(0),
756            component_url: Some("ffx".into()),
757            severity: Severity::Info,
758        })
759        .set_message("Hello world!")
760        .build();
761        let target_log_1 = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
762            moniker: "ffx".try_into().unwrap(),
763            timestamp: Timestamp::from_nanos(1),
764            component_url: Some("ffx".into()),
765            severity: Severity::Info,
766        })
767        .set_message("Hello world 2!")
768        .build();
769        let target_log_2 = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
770            moniker: "ffx".try_into().unwrap(),
771            timestamp: Timestamp::from_nanos(2),
772            component_url: Some("ffx".into()),
773            severity: Severity::Info,
774        })
775        .set_pid(1)
776        .set_tid(2)
777        .set_message("Hello world 3!")
778        .build();
779        let target_log_3 = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
780            moniker: "ffx".try_into().unwrap(),
781            timestamp: Timestamp::from_nanos(3),
782            component_url: Some("ffx".into()),
783            severity: Severity::Info,
784        })
785        .set_message("Hello world 4!")
786        .set_pid(1)
787        .set_tid(2)
788        .build();
789        sender
790            .write(
791                serde_json::to_string(&vec![
792                    &target_log_0,
793                    &target_log_1,
794                    &target_log_2,
795                    &target_log_3,
796                ])
797                .unwrap()
798                .as_bytes(),
799            )
800            .expect("failed to write target log");
801        drop(sender);
802        assert_matches!(
803            dump_logs_from_socket(
804                fuchsia_async::Socket::from_socket(receiver),
805                &mut formatter,
806                &symbolizer,
807            )
808            .await,
809            Ok(LogProcessingResult::Exit)
810        );
811        assert_eq!(
812            buffers.stdout.into_string(),
813            "[00000.000000][1][2][ffx] INFO: Hello world 3!\n"
814        );
815    }
816
817    fn make_log_with_timestamp(timestamp: i64) -> LogsData {
818        LogsDataBuilder::new(diagnostics_data::BuilderArgs {
819            moniker: "ffx".try_into().unwrap(),
820            timestamp: Timestamp::from_nanos(timestamp),
821            component_url: Some("ffx".into()),
822            severity: Severity::Info,
823        })
824        .set_message(format!("Hello world {timestamp}!"))
825        .set_pid(1)
826        .set_tid(2)
827        .build()
828    }
829
830    #[fuchsia::test]
831    async fn test_format_timestamp_filter_utc() {
832        // test since and until args for the LogFormatter
833        let symbolizer = NoOpSymbolizer {};
834        let buffers = TestBuffers::default();
835        let stdout = JsonWriter::<LogEntry>::new_test(None, &buffers);
836        let mut formatter = DefaultLogFormatter::new(
837            LogFilterCriteria::default(),
838            stdout,
839            LogFormatterOptions {
840                since: Some(DeviceOrLocalTimestamp {
841                    timestamp: Timestamp::from_nanos(1),
842                    is_boot: false,
843                }),
844                until: Some(DeviceOrLocalTimestamp {
845                    timestamp: Timestamp::from_nanos(3),
846                    is_boot: false,
847                }),
848                display: Some(LogTextDisplayOptions {
849                    time_format: LogTimeDisplayFormat::WallTime { tz: Timezone::Utc, offset: 1 },
850                    ..Default::default()
851                }),
852            },
853        );
854        formatter.set_boot_timestamp(Timestamp::from_nanos(1));
855
856        let (sender, receiver) = zx::Socket::create_stream();
857        let logs = (0..4).map(make_log_with_timestamp).collect::<Vec<_>>();
858        sender
859            .write(serde_json::to_string(&logs).unwrap().as_bytes())
860            .expect("failed to write target log");
861        drop(sender);
862        assert_matches!(
863            dump_logs_from_socket(
864                fuchsia_async::Socket::from_socket(receiver),
865                &mut formatter,
866                &symbolizer,
867            )
868            .await,
869            Ok(LogProcessingResult::Exit)
870        );
871        assert_eq!(
872            buffers.stdout.into_string(),
873            "[1970-01-01 00:00:00.000][1][2][ffx] INFO: Hello world 1!\n"
874        );
875    }
876
877    fn logs_data_builder() -> LogsDataBuilder {
878        diagnostics_data::LogsDataBuilder::new(diagnostics_data::BuilderArgs {
879            timestamp: Timestamp::from_nanos(default_ts().as_nanos() as i64),
880            component_url: Some("component_url".into()),
881            moniker: "some/moniker".try_into().unwrap(),
882            severity: diagnostics_data::Severity::Warn,
883        })
884        .set_pid(1)
885        .set_tid(2)
886    }
887
888    fn default_ts() -> Duration {
889        Duration::from_nanos(DEFAULT_TS_NANOS)
890    }
891
892    fn log_entry() -> LogEntry {
893        LogEntry {
894            data: LogData::TargetLog(
895                logs_data_builder().add_tag("tag1").add_tag("tag2").set_message("message").build(),
896            ),
897        }
898    }
899
900    #[fuchsia::test]
901    async fn test_default_formatter() {
902        let buffers = TestBuffers::default();
903        let stdout = JsonWriter::<LogEntry>::new_test(None, &buffers);
904        let options = LogFormatterOptions::default();
905        let mut formatter =
906            DefaultLogFormatter::new(LogFilterCriteria::default(), stdout, options.clone());
907        formatter.push_log(log_entry()).await.unwrap();
908        drop(formatter);
909        assert_eq!(
910            buffers.into_stdout_str(),
911            "[1615535969.000000][1][2][some/moniker][tag1,tag2] WARN: message\n"
912        );
913    }
914
915    #[fuchsia::test]
916    async fn test_default_formatter_with_hidden_metadata() {
917        let buffers = TestBuffers::default();
918        let stdout = JsonWriter::<LogEntry>::new_test(None, &buffers);
919        let options = LogFormatterOptions {
920            display: Some(LogTextDisplayOptions { show_metadata: false, ..Default::default() }),
921            ..LogFormatterOptions::default()
922        };
923        let mut formatter =
924            DefaultLogFormatter::new(LogFilterCriteria::default(), stdout, options.clone());
925        formatter.push_log(log_entry()).await.unwrap();
926        drop(formatter);
927        assert_eq!(
928            buffers.into_stdout_str(),
929            "[1615535969.000000][some/moniker][tag1,tag2] WARN: message\n"
930        );
931    }
932
933    #[fuchsia::test]
934    async fn test_default_formatter_with_json() {
935        let buffers = TestBuffers::default();
936        let stdout = JsonWriter::<LogEntry>::new_test(Some(Format::Json), &buffers);
937        let options = LogFormatterOptions { display: None, ..Default::default() };
938        {
939            let mut formatter =
940                DefaultLogFormatter::new(LogFilterCriteria::default(), stdout, options.clone());
941            formatter.push_log(log_entry()).await.unwrap();
942        }
943        assert_eq!(
944            serde_json::from_str::<LogEntry>(&buffers.into_stdout_str()).unwrap(),
945            log_entry()
946        );
947    }
948
949    fn emit_log(sender: &mut zx::Socket, msg: &str, timestamp: i64) -> Data<Logs> {
950        let target_log = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
951            moniker: "ffx".try_into().unwrap(),
952            timestamp: Timestamp::from_nanos(timestamp),
953            component_url: Some("ffx".into()),
954            severity: Severity::Info,
955        })
956        .set_message(msg)
957        .build();
958
959        sender
960            .write(serde_json::to_string(&target_log).unwrap().as_bytes())
961            .expect("failed to write target log");
962        target_log
963    }
964
965    #[fuchsia::test]
966    async fn test_default_formatter_discards_when_told_by_symbolizer() {
967        let mut formatter = FakeFormatter::new();
968        let (mut sender, receiver) = zx::Socket::create_stream();
969        let mut target_log_0 = emit_log(&mut sender, "Hello world!", 0);
970        emit_log(&mut sender, "Dropped world!", 1);
971        let mut target_log_2 = emit_log(&mut sender, "Hello world!", 2);
972        emit_log(&mut sender, "Dropped world!", 3);
973        let mut target_log_4 = emit_log(&mut sender, "Hello world!", 4);
974        drop(sender);
975        // Drop every other log.
976        let symbolizer = FakeSymbolizerCallback::new();
977        *target_log_0.msg_mut().unwrap() = "symbolized log".into();
978        *target_log_2.msg_mut().unwrap() = "symbolized log".into();
979        *target_log_4.msg_mut().unwrap() = "symbolized log".into();
980        dump_logs_from_socket(
981            fuchsia_async::Socket::from_socket(receiver),
982            &mut formatter,
983            &symbolizer,
984        )
985        .await
986        .unwrap();
987        assert_eq!(
988            formatter.logs,
989            vec![
990                LogEntry { data: LogData::TargetLog(target_log_0) },
991                LogEntry { data: LogData::TargetLog(target_log_2) },
992                LogEntry { data: LogData::TargetLog(target_log_4) }
993            ],
994        );
995    }
996
997    #[fuchsia::test]
998    async fn test_symbolized_output() {
999        let symbolizer = FakeFuchsiaSymbolizer;
1000        let buffers = TestBuffers::default();
1001        let output = JsonWriter::<LogEntry>::new_test(None, &buffers);
1002        let mut formatter = DefaultLogFormatter::new(
1003            LogFilterCriteria::default(),
1004            output,
1005            LogFormatterOptions { ..Default::default() },
1006        );
1007        formatter.set_boot_timestamp(Timestamp::from_nanos(0));
1008        let target_log = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
1009            moniker: "ffx".try_into().unwrap(),
1010            timestamp: Timestamp::from_nanos(0),
1011            component_url: Some("ffx".into()),
1012            severity: Severity::Info,
1013        })
1014        .set_pid(1)
1015        .set_tid(2)
1016        .set_message("Hello world!")
1017        .build();
1018        let (sender, receiver) = zx::Socket::create_stream();
1019        sender
1020            .write(serde_json::to_string(&target_log).unwrap().as_bytes())
1021            .expect("failed to write target log");
1022        drop(sender);
1023        dump_logs_from_socket(
1024            fuchsia_async::Socket::from_socket(receiver),
1025            &mut formatter,
1026            &symbolizer,
1027        )
1028        .await
1029        .unwrap();
1030        assert_eq!(buffers.stdout.into_string(), "[00000.000000][1][2][ffx] INFO: Fuchsia\n");
1031    }
1032
1033    #[test]
1034    fn test_device_or_local_timestamp_returns_none_if_now_is_passed() {
1035        assert_matches!(DeviceOrLocalTimestamp::new(Some(&parse_time("now").unwrap()), None), None);
1036    }
1037}