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, LogSubCommand,
9    TimeFormat,
10};
11use anyhow::Result;
12use async_trait::async_trait;
13use diagnostics_data::{
14    Data, LogTextColor, LogTextDisplayOptions, LogTextPresenter, LogTimeDisplayFormat, Logs,
15    LogsData, LogsDataBuilder, LogsField, LogsProperty, Severity, Timezone,
16};
17use futures_util::future::Either;
18use futures_util::stream::FuturesUnordered;
19use futures_util::{StreamExt, select};
20use serde::{Deserialize, Serialize};
21use std::fmt::Display;
22use std::io::Write;
23use std::time::Duration;
24use thiserror::Error;
25use writer::ToolIO;
26
27pub use diagnostics_data::Timestamp;
28
29pub const TIMESTAMP_FORMAT: &str = "%Y-%m-%d %H:%M:%S.%3f";
30
31/// Type of data in a log entry
32#[derive(Clone, Debug, PartialEq, Serialize, Deserialize)]
33pub enum LogData {
34    /// A log entry from the target
35    TargetLog(LogsData),
36}
37
38impl LogData {
39    /// Gets the LogData as a target log.
40    pub fn as_target_log(&self) -> Option<&LogsData> {
41        match self {
42            LogData::TargetLog(log) => Some(log),
43        }
44    }
45
46    pub fn as_target_log_mut(&mut self) -> Option<&mut LogsData> {
47        match self {
48            LogData::TargetLog(log) => Some(log),
49        }
50    }
51}
52
53impl From<LogsData> for LogData {
54    fn from(data: LogsData) -> Self {
55        Self::TargetLog(data)
56    }
57}
58
59/// A log entry from either the host, target, or
60/// a symbolized log.
61#[derive(Clone, Debug, PartialEq, Serialize, Deserialize)]
62pub struct LogEntry {
63    /// The log
64    pub data: LogData,
65}
66
67impl LogEntry {
68    fn utc_timestamp(&self, boot_ts: Option<Timestamp>) -> Timestamp {
69        Timestamp::from_nanos(match &self.data {
70            LogData::TargetLog(data) => {
71                data.metadata.timestamp.into_nanos()
72                    + boot_ts.map(|value| value.into_nanos()).unwrap_or(0)
73            }
74        })
75    }
76}
77
78// Required if we want to use ffx's built-in I/O, but
79// this isn't really applicable to us because we have
80// custom formatting rules.
81impl Display for LogEntry {
82    fn fmt(&self, _f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
83        unreachable!("UNSUPPORTED -- This type cannot be formatted with std format.");
84    }
85}
86
87/// A trait for symbolizing log entries
88#[async_trait(?Send)]
89pub trait Symbolize {
90    /// Symbolizes a LogEntry and optionally produces a result.
91    /// The symbolizer may choose to discard the result.
92    /// This method may be called multiple times concurrently.
93    async fn symbolize(&self, entry: LogEntry) -> Option<LogEntry>;
94}
95
96async fn handle_value<S>(one: Data<Logs>, symbolizer: &S) -> Option<LogEntry>
97where
98    S: Symbolize + ?Sized,
99{
100    let entry = LogEntry { data: one.into() };
101    symbolizer.symbolize(entry).await
102}
103
104fn generate_timestamp_message(boot_timestamp: Timestamp) -> LogEntry {
105    LogEntry {
106        data: LogData::TargetLog(
107            LogsDataBuilder::new(diagnostics_data::BuilderArgs {
108                moniker: "ffx".try_into().unwrap(),
109                timestamp: Timestamp::from_nanos(0),
110                component_url: Some("ffx".into()),
111                severity: Severity::Info,
112            })
113            .set_message("Logging started")
114            .add_key(LogsProperty::String(
115                LogsField::Other("utc_time_now".into()),
116                chrono::Utc::now().to_rfc3339(),
117            ))
118            .add_key(LogsProperty::Int(
119                LogsField::Other("current_boot_timestamp".to_string()),
120                boot_timestamp.into_nanos(),
121            ))
122            .build(),
123        ),
124    }
125}
126
127/// Reads logs from a socket and formats them using the given formatter and symbolizer.
128pub async fn dump_logs_from_socket<F, S>(
129    socket: flex_client::AsyncSocket,
130    formatter: &mut F,
131    symbolizer: &S,
132    include_timestamp: bool,
133) -> Result<LogProcessingResult, JsonDeserializeError>
134where
135    F: LogFormatter + BootTimeAccessor,
136    S: Symbolize + ?Sized,
137{
138    let mut decoder = Box::pin(LogsDataStream::new(socket).fuse());
139    let mut symbolize_pending = FuturesUnordered::new();
140    if include_timestamp && !formatter.is_utc_time_format() {
141        formatter.push_log(generate_timestamp_message(formatter.get_boot_timestamp())).await?;
142    }
143    while let Some(value) = select! {
144        res = decoder.next() => Some(Either::Left(res)),
145        res = symbolize_pending.next() => Some(Either::Right(res)),
146        complete => None,
147    } {
148        match value {
149            Either::Left(Some(result)) => match result {
150                Ok(log) => symbolize_pending.push(handle_value(log, symbolizer)),
151                Err(e) => return Err(e),
152            },
153            Either::Right(Some(Some(symbolized))) => match formatter.push_log(symbolized).await? {
154                LogProcessingResult::Exit => {
155                    formatter.flush().await?;
156                    return Ok(LogProcessingResult::Exit);
157                }
158                LogProcessingResult::Continue => {}
159            },
160            _ => {}
161        }
162    }
163    formatter.flush().await?;
164    Ok(LogProcessingResult::Continue)
165}
166
167/// Reads FXT logs from a socket and formats them using the given formatter and symbolizer.
168pub async fn dump_fxt_logs_from_socket<F, S>(
169    socket: flex_client::AsyncSocket,
170    formatter: &mut F,
171    symbolizer: &S,
172    include_timestamp: bool,
173) -> Result<LogProcessingResult, LogError>
174where
175    F: LogFormatter + BootTimeAccessor,
176    S: Symbolize + ?Sized,
177{
178    let streamer = crate::fxt_streamer::FxtStreamer::new(socket);
179    let mut decoder = std::pin::pin!(streamer.stream());
180    let mut symbolize_pending = FuturesUnordered::new();
181    if include_timestamp && !formatter.is_utc_time_format() {
182        formatter.push_log(generate_timestamp_message(formatter.get_boot_timestamp())).await?;
183    }
184    while let Some(value) = select! {
185        res = decoder.next() => Some(Either::Left(res)),
186        res = symbolize_pending.next() => Some(Either::Right(res)),
187        complete => None,
188    } {
189        match value {
190            Either::Left(Some(result)) => match result {
191                Ok(log) => symbolize_pending.push(handle_value(log, symbolizer)),
192                Err(e) => return Err(e),
193            },
194            Either::Right(Some(Some(symbolized))) => match formatter.push_log(symbolized).await? {
195                LogProcessingResult::Exit => {
196                    formatter.flush().await?;
197                    return Ok(LogProcessingResult::Exit);
198                }
199                LogProcessingResult::Continue => {}
200            },
201            _ => {}
202        }
203    }
204    formatter.flush().await?;
205    Ok(LogProcessingResult::Continue)
206}
207
208pub trait BootTimeAccessor {
209    /// Sets the boot timestamp in nanoseconds since the Unix epoch.
210    fn set_boot_timestamp(&mut self, _boot_ts_nanos: Timestamp);
211
212    /// Returns the boot timestamp in nanoseconds since the Unix epoch.
213    fn get_boot_timestamp(&self) -> Timestamp;
214}
215
216/// Timestamp filter which is either either boot-based or UTC-based.
217#[derive(Clone, Debug)]
218pub struct DeviceOrLocalTimestamp {
219    /// Timestamp in boot time
220    pub timestamp: Timestamp,
221    /// True if this filter should be applied to boot time,
222    /// false if UTC time.
223    pub is_boot: bool,
224}
225
226impl DeviceOrLocalTimestamp {
227    /// Creates a DeviceOrLocalTimestamp from a real-time date/time or
228    /// a boot date/time. Returns None if both rtc and boot are None.
229    /// Returns None if the timestamp is "now".
230    pub fn new(
231        rtc: Option<&DetailedDateTime>,
232        boot: Option<&Duration>,
233    ) -> Option<DeviceOrLocalTimestamp> {
234        rtc.as_ref()
235            .filter(|value| !value.is_now)
236            .map(|value| DeviceOrLocalTimestamp {
237                timestamp: Timestamp::from_nanos(
238                    value.naive_utc().and_utc().timestamp_nanos_opt().unwrap(),
239                ),
240                is_boot: false,
241            })
242            .or_else(|| {
243                boot.map(|value| DeviceOrLocalTimestamp {
244                    timestamp: Timestamp::from_nanos(value.as_nanos() as i64),
245                    is_boot: true,
246                })
247            })
248    }
249}
250
251/// Log formatter options
252#[derive(Clone, Debug)]
253pub struct LogFormatterOptions {
254    /// Text display options
255    pub display: Option<LogTextDisplayOptions>,
256    /// Only display logs since the specified time.
257    pub since: Option<DeviceOrLocalTimestamp>,
258    /// Only display logs until the specified time.
259    pub until: Option<DeviceOrLocalTimestamp>,
260    /// Only display the last N log lines.
261    pub tail: Option<usize>,
262}
263
264impl Default for LogFormatterOptions {
265    fn default() -> Self {
266        LogFormatterOptions {
267            display: Some(Default::default()),
268            since: None,
269            until: None,
270            tail: None,
271        }
272    }
273}
274
275/// Log formatter error
276#[derive(Error, Debug)]
277pub enum FormatterError {
278    /// An unknown error occurred
279    #[error(transparent)]
280    Other(#[from] anyhow::Error),
281    /// An IO error occurred
282    #[error(transparent)]
283    IO(#[from] std::io::Error),
284}
285
286impl FormatterError {
287    pub fn is_broken_pipe(&self) -> bool {
288        match self {
289            FormatterError::IO(error) => error.kind() == std::io::ErrorKind::BrokenPipe,
290            FormatterError::Other(_) => false,
291        }
292    }
293}
294
295/// Default formatter implementation
296pub struct DefaultLogFormatter<W>
297where
298    W: Write + ToolIO<OutputItem = LogEntry>,
299{
300    writer: W,
301    filters: LogFilterCriteria,
302    options: LogFormatterOptions,
303    boot_ts_nanos: Option<Timestamp>,
304    tail_queue: std::collections::VecDeque<LogEntry>,
305    tail_limit: Option<usize>,
306}
307
308/// Converts from UTC time to boot time.
309fn utc_to_boot(boot_ts: Timestamp, utc: Timestamp) -> Timestamp {
310    Timestamp::from_nanos(utc.into_nanos() - boot_ts.into_nanos())
311}
312
313#[async_trait(?Send)]
314impl<W> LogFormatter for DefaultLogFormatter<W>
315where
316    W: Write + ToolIO<OutputItem = LogEntry>,
317{
318    async fn push_log(&mut self, log_entry: LogEntry) -> Result<LogProcessingResult, LogError> {
319        self.push_log_internal(log_entry, true).await.or_else(|err| {
320            if err.is_broken_pipe() { Ok(LogProcessingResult::Exit) } else { Err(err) }
321        })
322    }
323
324    fn is_utc_time_format(&self) -> bool {
325        self.options.display.iter().any(|options| match options.time_format {
326            LogTimeDisplayFormat::Original => false,
327            LogTimeDisplayFormat::WallTime { tz, offset: _ } => tz == Timezone::Utc,
328        })
329    }
330
331    async fn flush(&mut self) -> Result<(), LogError> {
332        self.flush_tail().await
333    }
334}
335
336impl<W> BootTimeAccessor for DefaultLogFormatter<W>
337where
338    W: Write + ToolIO<OutputItem = LogEntry>,
339{
340    fn set_boot_timestamp(&mut self, boot_ts_nanos: Timestamp) {
341        if let Some(LogTextDisplayOptions {
342            time_format: LogTimeDisplayFormat::WallTime { offset, .. },
343            ..
344        }) = &mut self.options.display
345        {
346            *offset = boot_ts_nanos.into_nanos();
347        }
348        self.boot_ts_nanos = Some(boot_ts_nanos);
349    }
350    fn get_boot_timestamp(&self) -> Timestamp {
351        debug_assert!(self.boot_ts_nanos.is_some());
352        self.boot_ts_nanos.unwrap_or_else(|| Timestamp::from_nanos(0))
353    }
354}
355
356/// Object which contains a Writer that can be borrowed
357pub trait WriterContainer<W>
358where
359    W: Write + ToolIO<OutputItem = LogEntry>,
360{
361    fn writer(&mut self) -> &mut W;
362}
363
364impl<W> WriterContainer<W> for DefaultLogFormatter<W>
365where
366    W: Write + ToolIO<OutputItem = LogEntry>,
367{
368    fn writer(&mut self) -> &mut W {
369        &mut self.writer
370    }
371}
372
373impl<W> DefaultLogFormatter<W>
374where
375    W: Write + ToolIO<OutputItem = LogEntry>,
376{
377    /// Creates a new DefaultLogFormatter with the given writer and options.
378    pub fn new(filters: LogFilterCriteria, writer: W, options: LogFormatterOptions) -> Self {
379        let tail_limit = options.tail;
380        Self {
381            filters,
382            writer,
383            options,
384            boot_ts_nanos: None,
385            tail_queue: std::collections::VecDeque::new(),
386            tail_limit,
387        }
388    }
389
390    pub async fn expand_monikers(&mut self, getter: &impl InstanceGetter) -> Result<(), LogError> {
391        let warnings = self.filters.expand_monikers(getter).await?;
392        for warning in warnings {
393            writeln!(
394                self.writer.stderr(),
395                "WARN: Provided moniker '{}' was not an exact match. Using fuzzy match '{}' instead. Please check your component topology variations.",
396                warning.query,
397                warning.resolved
398            )?;
399        }
400        Ok(())
401    }
402
403    pub async fn push_unfiltered_log(
404        &mut self,
405        log_entry: LogEntry,
406    ) -> Result<LogProcessingResult, LogError> {
407        self.push_log_internal(log_entry, false).await
408    }
409
410    async fn flush_tail(&mut self) -> Result<(), LogError> {
411        while let Some(log_entry) = self.tail_queue.pop_front() {
412            self.write_log_entry(log_entry, true)?;
413        }
414        Ok(())
415    }
416
417    fn write_log_entry(
418        &mut self,
419        log_entry: LogEntry,
420        enable_filters: bool,
421    ) -> Result<(), LogError> {
422        match self.options.display {
423            Some(text_options) => {
424                let mut options_for_this_line_only = self.options.clone();
425                options_for_this_line_only.display = Some(text_options);
426                // For host logs, don't apply the boot time offset
427                // as this is with reference to the UTC timeline
428                if !enable_filters
429                    && let LogTimeDisplayFormat::WallTime { ref mut offset, .. } =
430                        options_for_this_line_only.display.as_mut().unwrap().time_format
431                {
432                    // 1 nanosecond so that LogTimeDisplayFormat in diagnostics_data
433                    // knows that we have a valid UTC offset. It normally falls back if
434                    // the UTC offset is 0. It prints at millisecond precision so being
435                    // off by +1 nanosecond isn't an issue.
436                    *offset = 1;
437                }
438                self.format_text_log(options_for_this_line_only, log_entry)
439                    .map_err(LogError::FormatterError)?;
440            }
441            None => {
442                self.writer.item(&log_entry).map_err(|err| LogError::UnknownError(err.into()))?;
443            }
444        };
445        Ok(())
446    }
447
448    async fn push_log_internal(
449        &mut self,
450        log_entry: LogEntry,
451        enable_filters: bool,
452    ) -> Result<LogProcessingResult, LogError> {
453        if enable_filters {
454            if self.filter_by_timestamp(&log_entry, self.options.since.as_ref(), |a, b| a <= b) {
455                return Ok(LogProcessingResult::Continue);
456            }
457
458            if self.filter_by_timestamp(&log_entry, self.options.until.as_ref(), |a, b| a >= b) {
459                return Ok(LogProcessingResult::Exit);
460            }
461
462            if !self.filters.matches(&log_entry) {
463                return Ok(LogProcessingResult::Continue);
464            }
465        }
466
467        if let Some(limit) = self.tail_limit {
468            self.tail_queue.push_back(log_entry);
469            if self.tail_queue.len() > limit {
470                self.tail_queue.pop_front();
471            }
472        } else {
473            self.write_log_entry(log_entry, enable_filters)?;
474        }
475        Ok(LogProcessingResult::Continue)
476    }
477
478    /// Creates a new DefaultLogFormatter from command-line arguments.
479    pub fn new_from_args(cmd: &LogCommand, writer: W) -> Result<Self, LogError> {
480        let is_json = writer.is_machine();
481
482        Ok(DefaultLogFormatter::new(
483            LogFilterCriteria::try_from(cmd.clone())?,
484            writer,
485            LogFormatterOptions {
486                display: if is_json {
487                    None
488                } else {
489                    Some(LogTextDisplayOptions {
490                        show_tags: !cmd.hide_tags(),
491                        color: if cmd.no_color() {
492                            LogTextColor::None
493                        } else {
494                            LogTextColor::BySeverity
495                        },
496                        show_metadata: cmd.show_metadata(),
497                        time_format: match cmd.clock() {
498                            TimeFormat::Boot => LogTimeDisplayFormat::Original,
499                            TimeFormat::Local => LogTimeDisplayFormat::WallTime {
500                                tz: Timezone::Local,
501                                // This will receive a correct value when logging actually starts,
502                                // see `set_boot_timestamp()` method on the log formatter.
503                                offset: 0,
504                            },
505                            TimeFormat::Utc => LogTimeDisplayFormat::WallTime {
506                                tz: Timezone::Utc,
507                                // This will receive a correct value when logging actually starts,
508                                // see `set_boot_timestamp()` method on the log formatter.
509                                offset: 0,
510                            },
511                        },
512                        show_file: !cmd.hide_file(),
513                        show_moniker: !cmd.hide_moniker(),
514                        show_full_moniker: cmd.show_full_moniker(),
515                        prefer_url_component_name: cmd.prefer_url_component_name(),
516                    })
517                },
518                since: DeviceOrLocalTimestamp::new(cmd.since(), cmd.since_boot().as_ref()),
519                until: DeviceOrLocalTimestamp::new(cmd.until(), cmd.until_boot().as_ref()),
520                tail: match &cmd.sub_command {
521                    Some(LogSubCommand::Dump(dump)) => dump.tail,
522                    _ => None,
523                },
524            },
525        ))
526    }
527
528    fn filter_by_timestamp(
529        &self,
530        log_entry: &LogEntry,
531        timestamp: Option<&DeviceOrLocalTimestamp>,
532        callback: impl Fn(&Timestamp, &Timestamp) -> bool,
533    ) -> bool {
534        let Some(timestamp) = timestamp else {
535            return false;
536        };
537        if timestamp.is_boot {
538            callback(
539                &utc_to_boot(
540                    self.get_boot_timestamp(),
541                    log_entry.utc_timestamp(self.boot_ts_nanos),
542                ),
543                &timestamp.timestamp,
544            )
545        } else {
546            callback(&log_entry.utc_timestamp(self.boot_ts_nanos), &timestamp.timestamp)
547        }
548    }
549
550    // This function's arguments are copied to make lifetimes in push_log easier since borrowing
551    // &self would complicate spam highlighting.
552    fn format_text_log(
553        &mut self,
554        options: LogFormatterOptions,
555        log_entry: LogEntry,
556    ) -> Result<(), FormatterError> {
557        let text_options = match options.display {
558            Some(o) => o,
559            None => {
560                unreachable!("If we are here, we can only be formatting text");
561            }
562        };
563        match log_entry {
564            LogEntry { data: LogData::TargetLog(data), .. } => {
565                // TODO(https://fxbug.dev/42072442): Add support for log spam redaction and other
566                // features listed in the design doc.
567                writeln!(self.writer, "{}", LogTextPresenter::new(&data, text_options))?;
568            }
569        }
570        Ok(())
571    }
572}
573
574#[allow(dead_code)] // TODO(https://fxbug.dev/421409178)
575/// Symbolizer that does nothing.
576pub struct NoOpSymbolizer;
577
578#[async_trait(?Send)]
579impl Symbolize for NoOpSymbolizer {
580    async fn symbolize(&self, entry: LogEntry) -> Option<LogEntry> {
581        Some(entry)
582    }
583}
584
585/// Trait for formatting logs one at a time.
586#[async_trait(?Send)]
587pub trait LogFormatter {
588    /// Formats a log entry and writes it to the output.
589    async fn push_log(&mut self, log_entry: LogEntry) -> Result<LogProcessingResult, LogError>;
590
591    /// Returns true if the formatter is configured to output in UTC time format.
592    fn is_utc_time_format(&self) -> bool;
593
594    /// Flushes any buffered logs.
595    async fn flush(&mut self) -> Result<(), LogError> {
596        Ok(())
597    }
598}
599
600#[cfg(test)]
601mod test {
602    use crate::parse_time;
603    use assert_matches::assert_matches;
604    use diagnostics_data::{LogsDataBuilder, Severity};
605    use std::cell::Cell;
606    use writer::{Format, JsonWriter, TestBuffers};
607
608    use super::*;
609
610    const DEFAULT_TS_NANOS: u64 = 1615535969000000000;
611
612    struct FakeFormatter {
613        logs: Vec<LogEntry>,
614        boot_timestamp: Timestamp,
615        is_utc_time_format: bool,
616    }
617
618    impl FakeFormatter {
619        fn new() -> Self {
620            Self {
621                logs: Vec::new(),
622                boot_timestamp: Timestamp::from_nanos(0),
623                is_utc_time_format: false,
624            }
625        }
626    }
627
628    impl BootTimeAccessor for FakeFormatter {
629        fn set_boot_timestamp(&mut self, boot_ts_nanos: Timestamp) {
630            self.boot_timestamp = boot_ts_nanos;
631        }
632
633        fn get_boot_timestamp(&self) -> Timestamp {
634            self.boot_timestamp
635        }
636    }
637
638    #[async_trait(?Send)]
639    impl LogFormatter for FakeFormatter {
640        async fn push_log(&mut self, log_entry: LogEntry) -> Result<LogProcessingResult, LogError> {
641            self.logs.push(log_entry);
642            Ok(LogProcessingResult::Continue)
643        }
644
645        fn is_utc_time_format(&self) -> bool {
646            self.is_utc_time_format
647        }
648    }
649
650    /// Symbolizer that prints "Fuchsia".
651    pub struct FakeFuchsiaSymbolizer;
652
653    fn set_log_msg(entry: &mut LogEntry, msg: impl Into<String>) {
654        *entry.data.as_target_log_mut().unwrap().msg_mut().unwrap() = msg.into();
655    }
656
657    #[async_trait(?Send)]
658    impl Symbolize for FakeFuchsiaSymbolizer {
659        async fn symbolize(&self, mut entry: LogEntry) -> Option<LogEntry> {
660            set_log_msg(&mut entry, "Fuchsia");
661            Some(entry)
662        }
663    }
664
665    struct FakeSymbolizerCallback {
666        should_discard: Cell<bool>,
667    }
668
669    impl FakeSymbolizerCallback {
670        fn new() -> Self {
671            Self { should_discard: Cell::new(true) }
672        }
673    }
674
675    async fn dump_logs_from_socket<F, S>(
676        socket: fuchsia_async::Socket,
677        formatter: &mut F,
678        symbolizer: &S,
679    ) -> Result<LogProcessingResult, JsonDeserializeError>
680    where
681        F: LogFormatter + BootTimeAccessor,
682        S: Symbolize + ?Sized,
683    {
684        super::dump_logs_from_socket(socket, formatter, symbolizer, false).await
685    }
686
687    #[async_trait(?Send)]
688    impl Symbolize for FakeSymbolizerCallback {
689        async fn symbolize(&self, mut input: LogEntry) -> Option<LogEntry> {
690            self.should_discard.set(!self.should_discard.get());
691            if self.should_discard.get() {
692                None
693            } else {
694                set_log_msg(&mut input, "symbolized log");
695                Some(input)
696            }
697        }
698    }
699
700    #[fuchsia::test]
701    async fn test_boot_timestamp_setter() {
702        let buffers = TestBuffers::default();
703        let stdout = JsonWriter::<LogEntry>::new_test(None, &buffers);
704        let options = LogFormatterOptions {
705            display: Some(LogTextDisplayOptions {
706                time_format: LogTimeDisplayFormat::WallTime { tz: Timezone::Utc, offset: 0 },
707                ..Default::default()
708            }),
709            ..Default::default()
710        };
711        let mut formatter =
712            DefaultLogFormatter::new(LogFilterCriteria::default(), stdout, options.clone());
713        formatter.set_boot_timestamp(Timestamp::from_nanos(1234));
714        assert_eq!(formatter.get_boot_timestamp(), Timestamp::from_nanos(1234));
715
716        // Boot timestamp is supported when using JSON output (for filtering)
717        let buffers = TestBuffers::default();
718        let output = JsonWriter::<LogEntry>::new_test(None, &buffers);
719        let options = LogFormatterOptions { display: None, ..Default::default() };
720        let mut formatter = DefaultLogFormatter::new(LogFilterCriteria::default(), output, options);
721        formatter.set_boot_timestamp(Timestamp::from_nanos(1234));
722        assert_eq!(formatter.get_boot_timestamp(), Timestamp::from_nanos(1234));
723    }
724
725    #[fuchsia::test]
726    async fn test_format_single_message() {
727        let symbolizer = NoOpSymbolizer {};
728        let mut formatter = FakeFormatter::new();
729        let target_log = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
730            moniker: "ffx".try_into().unwrap(),
731            timestamp: Timestamp::from_nanos(0),
732            component_url: Some("ffx".into()),
733            severity: Severity::Info,
734        })
735        .set_message("Hello world!")
736        .build();
737        let (sender, receiver) = zx::Socket::create_stream();
738        sender
739            .write(serde_json::to_string(&target_log).unwrap().as_bytes())
740            .expect("failed to write target log");
741        drop(sender);
742        dump_logs_from_socket(flex_client::socket_to_async(receiver), &mut formatter, &symbolizer)
743            .await
744            .unwrap();
745        assert_eq!(formatter.logs, vec![LogEntry { data: LogData::TargetLog(target_log) }]);
746    }
747
748    #[fuchsia::test]
749    async fn test_format_utc_timestamp() {
750        let symbolizer = NoOpSymbolizer {};
751        let mut formatter = FakeFormatter::new();
752        formatter.set_boot_timestamp(Timestamp::from_nanos(DEFAULT_TS_NANOS as i64));
753        let (_, receiver) = zx::Socket::create_stream();
754        super::dump_logs_from_socket(
755            flex_client::socket_to_async(receiver),
756            &mut formatter,
757            &symbolizer,
758            true,
759        )
760        .await
761        .unwrap();
762        let target_log = formatter.logs[0].data.as_target_log().unwrap();
763        let properties = target_log.payload_keys().unwrap();
764        assert_eq!(target_log.msg().unwrap(), "Logging started");
765
766        // Ensure the end has a valid timestamp
767        chrono::DateTime::parse_from_rfc3339(
768            properties.get_property("utc_time_now").unwrap().string().unwrap(),
769        )
770        .unwrap();
771        assert_eq!(
772            properties.get_property("current_boot_timestamp").unwrap().int().unwrap(),
773            DEFAULT_TS_NANOS as i64
774        );
775    }
776
777    #[fuchsia::test]
778    async fn test_format_utc_timestamp_does_not_print_if_utc_time() {
779        let symbolizer = NoOpSymbolizer {};
780        let mut formatter = FakeFormatter::new();
781        formatter.is_utc_time_format = true;
782        formatter.set_boot_timestamp(Timestamp::from_nanos(DEFAULT_TS_NANOS as i64));
783        let (_, receiver) = zx::Socket::create_stream();
784        super::dump_logs_from_socket(
785            flex_client::socket_to_async(receiver),
786            &mut formatter,
787            &symbolizer,
788            true,
789        )
790        .await
791        .unwrap();
792        assert_eq!(formatter.logs.len(), 0);
793    }
794
795    #[fuchsia::test]
796    async fn test_format_multiple_messages() {
797        let symbolizer = NoOpSymbolizer {};
798        let mut formatter = FakeFormatter::new();
799        let (sender, receiver) = zx::Socket::create_stream();
800        let target_log_0 = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
801            moniker: "ffx".try_into().unwrap(),
802            timestamp: Timestamp::from_nanos(0),
803            component_url: Some("ffx".into()),
804            severity: Severity::Info,
805        })
806        .set_message("Hello world!")
807        .set_pid(1)
808        .set_tid(2)
809        .build();
810        let target_log_1 = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
811            moniker: "ffx".try_into().unwrap(),
812            timestamp: Timestamp::from_nanos(1),
813            component_url: Some("ffx".into()),
814            severity: Severity::Info,
815        })
816        .set_message("Hello world 2!")
817        .build();
818        sender
819            .write(serde_json::to_string(&vec![&target_log_0, &target_log_1]).unwrap().as_bytes())
820            .expect("failed to write target log");
821        drop(sender);
822        dump_logs_from_socket(flex_client::socket_to_async(receiver), &mut formatter, &symbolizer)
823            .await
824            .unwrap();
825        assert_eq!(
826            formatter.logs,
827            vec![
828                LogEntry { data: LogData::TargetLog(target_log_0) },
829                LogEntry { data: LogData::TargetLog(target_log_1) }
830            ]
831        );
832    }
833
834    #[fuchsia::test]
835    async fn test_format_timestamp_filter() {
836        // test since and until args for the LogFormatter
837        let symbolizer = NoOpSymbolizer {};
838        let buffers = TestBuffers::default();
839        let stdout = JsonWriter::<LogEntry>::new_test(None, &buffers);
840        let mut formatter = DefaultLogFormatter::new(
841            LogFilterCriteria::default(),
842            stdout,
843            LogFormatterOptions {
844                since: Some(DeviceOrLocalTimestamp {
845                    timestamp: Timestamp::from_nanos(1),
846                    is_boot: true,
847                }),
848                until: Some(DeviceOrLocalTimestamp {
849                    timestamp: Timestamp::from_nanos(3),
850                    is_boot: true,
851                }),
852                ..Default::default()
853            },
854        );
855        formatter.set_boot_timestamp(Timestamp::from_nanos(0));
856
857        let (sender, receiver) = zx::Socket::create_stream();
858        let target_log_0 = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
859            moniker: "ffx".try_into().unwrap(),
860            timestamp: Timestamp::from_nanos(0),
861            component_url: Some("ffx".into()),
862            severity: Severity::Info,
863        })
864        .set_message("Hello world!")
865        .build();
866        let target_log_1 = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
867            moniker: "ffx".try_into().unwrap(),
868            timestamp: Timestamp::from_nanos(1),
869            component_url: Some("ffx".into()),
870            severity: Severity::Info,
871        })
872        .set_message("Hello world 2!")
873        .build();
874        let target_log_2 = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
875            moniker: "ffx".try_into().unwrap(),
876            timestamp: Timestamp::from_nanos(2),
877            component_url: Some("ffx".into()),
878            severity: Severity::Info,
879        })
880        .set_pid(1)
881        .set_tid(2)
882        .set_message("Hello world 3!")
883        .build();
884        let target_log_3 = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
885            moniker: "ffx".try_into().unwrap(),
886            timestamp: Timestamp::from_nanos(3),
887            component_url: Some("ffx".into()),
888            severity: Severity::Info,
889        })
890        .set_message("Hello world 4!")
891        .set_pid(1)
892        .set_tid(2)
893        .build();
894        sender
895            .write(
896                serde_json::to_string(&vec![
897                    &target_log_0,
898                    &target_log_1,
899                    &target_log_2,
900                    &target_log_3,
901                ])
902                .unwrap()
903                .as_bytes(),
904            )
905            .expect("failed to write target log");
906        drop(sender);
907        assert_matches!(
908            dump_logs_from_socket(
909                flex_client::socket_to_async(receiver),
910                &mut formatter,
911                &symbolizer,
912            )
913            .await,
914            Ok(LogProcessingResult::Exit)
915        );
916        assert_eq!(
917            buffers.stdout.into_string(),
918            "[00000.000000][1][2][ffx] INFO: Hello world 3!\n"
919        );
920    }
921
922    fn make_log_with_timestamp(timestamp: i64) -> LogsData {
923        LogsDataBuilder::new(diagnostics_data::BuilderArgs {
924            moniker: "ffx".try_into().unwrap(),
925            timestamp: Timestamp::from_nanos(timestamp),
926            component_url: Some("ffx".into()),
927            severity: Severity::Info,
928        })
929        .set_message(format!("Hello world {timestamp}!"))
930        .set_pid(1)
931        .set_tid(2)
932        .build()
933    }
934
935    #[fuchsia::test]
936    async fn test_format_timestamp_filter_utc() {
937        // test since and until args for the LogFormatter
938        let symbolizer = NoOpSymbolizer {};
939        let buffers = TestBuffers::default();
940        let stdout = JsonWriter::<LogEntry>::new_test(None, &buffers);
941        let mut formatter = DefaultLogFormatter::new(
942            LogFilterCriteria::default(),
943            stdout,
944            LogFormatterOptions {
945                since: Some(DeviceOrLocalTimestamp {
946                    timestamp: Timestamp::from_nanos(1),
947                    is_boot: false,
948                }),
949                until: Some(DeviceOrLocalTimestamp {
950                    timestamp: Timestamp::from_nanos(3),
951                    is_boot: false,
952                }),
953                display: Some(LogTextDisplayOptions {
954                    time_format: LogTimeDisplayFormat::WallTime { tz: Timezone::Utc, offset: 1 },
955                    ..Default::default()
956                }),
957                ..Default::default()
958            },
959        );
960        formatter.set_boot_timestamp(Timestamp::from_nanos(1));
961
962        let (sender, receiver) = zx::Socket::create_stream();
963        let logs = (0..4).map(make_log_with_timestamp).collect::<Vec<_>>();
964        sender
965            .write(serde_json::to_string(&logs).unwrap().as_bytes())
966            .expect("failed to write target log");
967        drop(sender);
968        assert_matches!(
969            dump_logs_from_socket(
970                flex_client::socket_to_async(receiver),
971                &mut formatter,
972                &symbolizer,
973            )
974            .await,
975            Ok(LogProcessingResult::Exit)
976        );
977        assert_eq!(
978            buffers.stdout.into_string(),
979            "[1970-01-01 00:00:00.000][1][2][ffx] INFO: Hello world 1!\n"
980        );
981    }
982
983    fn logs_data_builder() -> LogsDataBuilder {
984        diagnostics_data::LogsDataBuilder::new(diagnostics_data::BuilderArgs {
985            timestamp: Timestamp::from_nanos(default_ts().as_nanos() as i64),
986            component_url: Some("component_url".into()),
987            moniker: "some/moniker".try_into().unwrap(),
988            severity: diagnostics_data::Severity::Warn,
989        })
990        .set_pid(1)
991        .set_tid(2)
992    }
993
994    fn default_ts() -> Duration {
995        Duration::from_nanos(DEFAULT_TS_NANOS)
996    }
997
998    fn log_entry() -> LogEntry {
999        LogEntry {
1000            data: LogData::TargetLog(
1001                logs_data_builder().add_tag("tag1").add_tag("tag2").set_message("message").build(),
1002            ),
1003        }
1004    }
1005
1006    #[fuchsia::test]
1007    async fn test_default_formatter() {
1008        let buffers = TestBuffers::default();
1009        let stdout = JsonWriter::<LogEntry>::new_test(None, &buffers);
1010        let options = LogFormatterOptions::default();
1011        let mut formatter =
1012            DefaultLogFormatter::new(LogFilterCriteria::default(), stdout, options.clone());
1013        formatter.push_log(log_entry()).await.unwrap();
1014        drop(formatter);
1015        assert_eq!(
1016            buffers.into_stdout_str(),
1017            "[1615535969.000000][1][2][some/moniker][tag1,tag2] WARN: message\n"
1018        );
1019    }
1020
1021    #[fuchsia::test]
1022    async fn test_default_formatter_with_hidden_metadata() {
1023        let buffers = TestBuffers::default();
1024        let stdout = JsonWriter::<LogEntry>::new_test(None, &buffers);
1025        let options = LogFormatterOptions {
1026            display: Some(LogTextDisplayOptions { show_metadata: false, ..Default::default() }),
1027            ..LogFormatterOptions::default()
1028        };
1029        let mut formatter =
1030            DefaultLogFormatter::new(LogFilterCriteria::default(), stdout, options.clone());
1031        formatter.push_log(log_entry()).await.unwrap();
1032        drop(formatter);
1033        assert_eq!(
1034            buffers.into_stdout_str(),
1035            "[1615535969.000000][some/moniker][tag1,tag2] WARN: message\n"
1036        );
1037    }
1038
1039    #[fuchsia::test]
1040    async fn test_default_formatter_with_json() {
1041        let buffers = TestBuffers::default();
1042        let stdout = JsonWriter::<LogEntry>::new_test(Some(Format::Json), &buffers);
1043        let options = LogFormatterOptions { display: None, ..Default::default() };
1044        {
1045            let mut formatter =
1046                DefaultLogFormatter::new(LogFilterCriteria::default(), stdout, options.clone());
1047            formatter.push_log(log_entry()).await.unwrap();
1048        }
1049        assert_eq!(
1050            serde_json::from_str::<LogEntry>(&buffers.into_stdout_str()).unwrap(),
1051            log_entry()
1052        );
1053    }
1054
1055    fn emit_log(sender: &mut zx::Socket, msg: &str, timestamp: i64) -> Data<Logs> {
1056        let target_log = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
1057            moniker: "ffx".try_into().unwrap(),
1058            timestamp: Timestamp::from_nanos(timestamp),
1059            component_url: Some("ffx".into()),
1060            severity: Severity::Info,
1061        })
1062        .set_message(msg)
1063        .build();
1064
1065        sender
1066            .write(serde_json::to_string(&target_log).unwrap().as_bytes())
1067            .expect("failed to write target log");
1068        target_log
1069    }
1070
1071    #[fuchsia::test]
1072    async fn test_default_formatter_discards_when_told_by_symbolizer() {
1073        let mut formatter = FakeFormatter::new();
1074        let (mut sender, receiver) = zx::Socket::create_stream();
1075        let mut target_log_0 = emit_log(&mut sender, "Hello world!", 0);
1076        emit_log(&mut sender, "Dropped world!", 1);
1077        let mut target_log_2 = emit_log(&mut sender, "Hello world!", 2);
1078        emit_log(&mut sender, "Dropped world!", 3);
1079        let mut target_log_4 = emit_log(&mut sender, "Hello world!", 4);
1080        drop(sender);
1081        // Drop every other log.
1082        let symbolizer = FakeSymbolizerCallback::new();
1083        *target_log_0.msg_mut().unwrap() = "symbolized log".into();
1084        *target_log_2.msg_mut().unwrap() = "symbolized log".into();
1085        *target_log_4.msg_mut().unwrap() = "symbolized log".into();
1086        dump_logs_from_socket(flex_client::socket_to_async(receiver), &mut formatter, &symbolizer)
1087            .await
1088            .unwrap();
1089        assert_eq!(
1090            formatter.logs,
1091            vec![
1092                LogEntry { data: LogData::TargetLog(target_log_0) },
1093                LogEntry { data: LogData::TargetLog(target_log_2) },
1094                LogEntry { data: LogData::TargetLog(target_log_4) }
1095            ],
1096        );
1097    }
1098
1099    #[fuchsia::test]
1100    async fn test_symbolized_output() {
1101        let symbolizer = FakeFuchsiaSymbolizer;
1102        let buffers = TestBuffers::default();
1103        let output = JsonWriter::<LogEntry>::new_test(None, &buffers);
1104        let mut formatter = DefaultLogFormatter::new(
1105            LogFilterCriteria::default(),
1106            output,
1107            LogFormatterOptions { ..Default::default() },
1108        );
1109        formatter.set_boot_timestamp(Timestamp::from_nanos(0));
1110        let target_log = LogsDataBuilder::new(diagnostics_data::BuilderArgs {
1111            moniker: "ffx".try_into().unwrap(),
1112            timestamp: Timestamp::from_nanos(0),
1113            component_url: Some("ffx".into()),
1114            severity: Severity::Info,
1115        })
1116        .set_pid(1)
1117        .set_tid(2)
1118        .set_message("Hello world!")
1119        .build();
1120        let (sender, receiver) = zx::Socket::create_stream();
1121        sender
1122            .write(serde_json::to_string(&target_log).unwrap().as_bytes())
1123            .expect("failed to write target log");
1124        drop(sender);
1125        dump_logs_from_socket(flex_client::socket_to_async(receiver), &mut formatter, &symbolizer)
1126            .await
1127            .unwrap();
1128        assert_eq!(buffers.stdout.into_string(), "[00000.000000][1][2][ffx] INFO: Fuchsia\n");
1129    }
1130
1131    #[test]
1132    fn test_device_or_local_timestamp_returns_none_if_now_is_passed() {
1133        assert_matches!(DeviceOrLocalTimestamp::new(Some(&parse_time("now").unwrap()), None), None);
1134    }
1135
1136    struct BrokenPipeWriter;
1137    impl std::io::Write for BrokenPipeWriter {
1138        fn write(&mut self, _buf: &[u8]) -> std::io::Result<usize> {
1139            Err(std::io::Error::new(std::io::ErrorKind::BrokenPipe, "broken pipe"))
1140        }
1141
1142        fn flush(&mut self) -> std::io::Result<()> {
1143            Err(std::io::Error::new(std::io::ErrorKind::BrokenPipe, "broken pipe"))
1144        }
1145    }
1146
1147    impl ToolIO for BrokenPipeWriter {
1148        type OutputItem = LogEntry;
1149        fn is_machine(&self) -> bool {
1150            false
1151        }
1152
1153        fn stderr(&mut self) -> &mut dyn std::io::Write {
1154            self
1155        }
1156
1157        fn item(&mut self, _value: &Self::OutputItem) -> writer::Result<()> {
1158            Err(writer::Error::Io(std::io::Error::new(
1159                std::io::ErrorKind::BrokenPipe,
1160                "broken pipe",
1161            )))
1162        }
1163    }
1164
1165    #[fuchsia::test]
1166    async fn test_default_formatter_exits_on_broken_pipe() {
1167        let stdout = BrokenPipeWriter;
1168        let options = LogFormatterOptions::default();
1169        let mut formatter =
1170            DefaultLogFormatter::new(LogFilterCriteria::default(), stdout, options.clone());
1171        let result = formatter.push_log(log_entry()).await;
1172        assert_matches!(result, Ok(LogProcessingResult::Exit));
1173    }
1174
1175    #[test]
1176    fn test_formatter_error_is_broken_pipe() {
1177        assert!(
1178            FormatterError::IO(std::io::Error::new(std::io::ErrorKind::BrokenPipe, "broken pipe"))
1179                .is_broken_pipe()
1180        );
1181        assert!(!FormatterError::IO(std::io::Error::other("other")).is_broken_pipe());
1182        assert!(!FormatterError::Other(anyhow::anyhow!("other")).is_broken_pipe());
1183    }
1184
1185    #[cfg(not(feature = "fdomain"))]
1186    #[fuchsia::test]
1187    async fn test_json_and_fxt_output_identical() {
1188        use diagnostics_data::ExtendedMoniker;
1189        use diagnostics_log_encoding::encode::{Encoder, EncoderOpts, ResizableBuffer};
1190        use diagnostics_log_encoding::{Argument, Header, LOG_CONTROL_BIT, MONIKER, Record, URL};
1191        use diagnostics_message::MonikerWithUrl;
1192        use flyweights::FlyStr;
1193        use zerocopy::{FromBytes, IntoBytes};
1194
1195        let symbolizer = NoOpSymbolizer {};
1196        let options = LogFormatterOptions::default();
1197
1198        let fn_encode = |record: Record<'_>, tag: u32| -> Vec<u8> {
1199            let mut encoder = Encoder::new(
1200                std::io::Cursor::new(ResizableBuffer::from(Vec::new())),
1201                EncoderOpts::default(),
1202            );
1203            encoder.write_record(record).unwrap();
1204            let mut bytes = encoder.take().into_inner().into_inner();
1205            let mut header = Header::read_from_bytes(&bytes[0..8]).unwrap();
1206            header.set_tag(tag);
1207            bytes[0..8].copy_from_slice(header.as_bytes());
1208            bytes
1209        };
1210
1211        let manifest_bytes = fn_encode(
1212            Record {
1213                timestamp: zx::BootInstant::from_nanos(0),
1214                severity: 0x30, // INFO
1215                arguments: vec![
1216                    Argument::other(MONIKER, "core/foo"),
1217                    Argument::other(URL, "fuchsia-pkg://foo"),
1218                ],
1219            },
1220            1 | LOG_CONTROL_BIT,
1221        );
1222
1223        let log_bytes1 = fn_encode(
1224            Record {
1225                timestamp: zx::BootInstant::from_nanos(123456),
1226                severity: 0x30, // INFO
1227                arguments: vec![
1228                    Argument::pid(zx::Koid::from_raw(1000)),
1229                    Argument::tid(zx::Koid::from_raw(2000)),
1230                    Argument::tag("my_tag"),
1231                    Argument::message("Hello identical world!"),
1232                ],
1233            },
1234            1,
1235        );
1236
1237        let log_bytes2 = fn_encode(
1238            Record {
1239                timestamp: zx::BootInstant::from_nanos(123457),
1240                severity: 0x40, // WARN
1241                arguments: vec![
1242                    Argument::file("src/main.rs"),
1243                    Argument::line(42),
1244                    Argument::dropped(5),
1245                    Argument::message("Warning with source location and dropped count"),
1246                ],
1247            },
1248            1,
1249        );
1250
1251        let log_bytes3_signed = fn_encode(
1252            Record {
1253                timestamp: zx::BootInstant::from_nanos(123458),
1254                severity: 0x50, // ERROR
1255                arguments: vec![
1256                    Argument::message("Error with custom signed int"),
1257                    Argument::new("signed_val", -12345i64),
1258                ],
1259            },
1260            1,
1261        );
1262
1263        let log_bytes3_unsigned = fn_encode(
1264            Record {
1265                timestamp: zx::BootInstant::from_nanos(123458),
1266                severity: 0x50, // ERROR
1267                arguments: vec![
1268                    Argument::message("Error with custom unsigned int"),
1269                    Argument::new("unsigned_val", 67890u64),
1270                ],
1271            },
1272            1,
1273        );
1274
1275        let log_bytes3_bool = fn_encode(
1276            Record {
1277                timestamp: zx::BootInstant::from_nanos(123458),
1278                severity: 0x50, // ERROR
1279                arguments: vec![
1280                    Argument::message("Error with custom boolean"),
1281                    Argument::new("bool_val", true),
1282                ],
1283            },
1284            1,
1285        );
1286
1287        let log_bytes3_str = fn_encode(
1288            Record {
1289                timestamp: zx::BootInstant::from_nanos(123458),
1290                severity: 0x50, // ERROR
1291                arguments: vec![
1292                    Argument::message("Error with custom string"),
1293                    Argument::new("string_val", "custom string"),
1294                ],
1295            },
1296            1,
1297        );
1298
1299        let log_bytes4_pi = fn_encode(
1300            Record {
1301                timestamp: zx::BootInstant::from_nanos(123459),
1302                severity: 0x60, // FATAL
1303                arguments: vec![
1304                    Argument::message("Fatal with float pi"),
1305                    Argument::new("float_pi", std::f64::consts::PI),
1306                ],
1307            },
1308            1,
1309        );
1310
1311        let log_bytes4_zero = fn_encode(
1312            Record {
1313                timestamp: zx::BootInstant::from_nanos(123459),
1314                severity: 0x60, // FATAL
1315                arguments: vec![
1316                    Argument::message("Fatal with float zero"),
1317                    Argument::new("float_zero", 0.0f64),
1318                ],
1319            },
1320            1,
1321        );
1322
1323        let log_bytes4_large = fn_encode(
1324            Record {
1325                timestamp: zx::BootInstant::from_nanos(123459),
1326                severity: 0x60, // FATAL
1327                arguments: vec![
1328                    Argument::message("Fatal with float large"),
1329                    Argument::new("float_large", 123456.789f64),
1330                ],
1331            },
1332            1,
1333        );
1334
1335        let all_records = [
1336            &log_bytes1,
1337            &log_bytes2,
1338            &log_bytes3_signed,
1339            &log_bytes3_unsigned,
1340            &log_bytes3_bool,
1341            &log_bytes3_str,
1342            &log_bytes4_pi,
1343            &log_bytes4_zero,
1344            &log_bytes4_large,
1345        ];
1346
1347        // 1. JSON setup and execution using converted FXT messages
1348        let buffers_json = TestBuffers::default();
1349        let stdout_json = JsonWriter::<LogEntry>::new_test(None, &buffers_json);
1350        let mut formatter_json =
1351            DefaultLogFormatter::new(LogFilterCriteria::default(), stdout_json, options.clone());
1352        formatter_json.set_boot_timestamp(Timestamp::from_nanos(0));
1353
1354        let source = MonikerWithUrl {
1355            moniker: ExtendedMoniker::parse_str("core/foo").unwrap(),
1356            url: FlyStr::new("fuchsia-pkg://foo"),
1357        };
1358
1359        let (sender_json, receiver_json) = zx::Socket::create_stream();
1360        let mut json_stream_bytes = Vec::new();
1361        for record_bytes in &all_records {
1362            let target_log =
1363                diagnostics_message::from_structured(source.clone(), record_bytes).unwrap();
1364            serde_json::to_writer(&mut json_stream_bytes, &target_log).unwrap();
1365            json_stream_bytes.push(b'\n');
1366        }
1367        sender_json.write(&json_stream_bytes).expect("failed to write target logs");
1368        drop(sender_json);
1369
1370        super::dump_logs_from_socket(
1371            flex_client::socket_to_async(receiver_json),
1372            &mut formatter_json,
1373            &symbolizer,
1374            false,
1375        )
1376        .await
1377        .unwrap();
1378
1379        // 2. FXT setup and execution
1380        let buffers_fxt = TestBuffers::default();
1381        let stdout_fxt = JsonWriter::<LogEntry>::new_test(None, &buffers_fxt);
1382        let mut formatter_fxt =
1383            DefaultLogFormatter::new(LogFilterCriteria::default(), stdout_fxt, options.clone());
1384        formatter_fxt.set_boot_timestamp(Timestamp::from_nanos(0));
1385
1386        let (sender_fxt, receiver_fxt) = zx::Socket::create_stream();
1387        sender_fxt.write(&manifest_bytes).unwrap();
1388        for record_bytes in &all_records {
1389            sender_fxt.write(record_bytes).unwrap();
1390        }
1391        drop(sender_fxt);
1392
1393        super::dump_fxt_logs_from_socket(
1394            flex_client::socket_to_async(receiver_fxt),
1395            &mut formatter_fxt,
1396            &symbolizer,
1397            false,
1398        )
1399        .await
1400        .unwrap();
1401
1402        // 3. Verify identity
1403        assert_eq!(buffers_json.stdout.into_string(), buffers_fxt.stdout.into_string());
1404    }
1405
1406    #[fuchsia::test]
1407    async fn test_default_formatter_tail_limit() {
1408        let buffers = TestBuffers::default();
1409        let stdout = JsonWriter::<LogEntry>::new_test(None, &buffers);
1410        let options = LogFormatterOptions { tail: Some(2), ..Default::default() };
1411        let mut formatter = DefaultLogFormatter::new(LogFilterCriteria::default(), stdout, options);
1412
1413        let entry1 = LogEntry {
1414            data: LogData::TargetLog(
1415                logs_data_builder().add_tag("tag1").set_message("msg1").build(),
1416            ),
1417        };
1418        let entry2 = LogEntry {
1419            data: LogData::TargetLog(
1420                logs_data_builder().add_tag("tag1").set_message("msg2").build(),
1421            ),
1422        };
1423        let entry3 = LogEntry {
1424            data: LogData::TargetLog(
1425                logs_data_builder().add_tag("tag1").set_message("msg3").build(),
1426            ),
1427        };
1428
1429        formatter.push_log(entry1).await.unwrap();
1430        formatter.push_log(entry2).await.unwrap();
1431        formatter.push_log(entry3).await.unwrap();
1432
1433        // Before flushing, nothing should be outputted because tail buffering delays output
1434        let stdout_snapshot = buffers.stdout.clone().into_string();
1435        assert_eq!(stdout_snapshot, "");
1436
1437        formatter.flush().await.unwrap();
1438
1439        // After flushing, only the last 2 entries should be outputted
1440        let output = buffers.into_stdout_str();
1441        assert!(!output.contains("msg1"));
1442        assert!(output.contains("msg2"));
1443        assert!(output.contains("msg3"));
1444    }
1445}
log_command/log_formatter.rs

log_command/
log_formatter.rs
