1use 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#[derive(Clone, Debug, Deserialize, PartialEq, Serialize)]
32pub enum EventType {
33 LoggingStarted,
35 TargetDisconnected,
37}
38
39#[derive(Clone, Debug, PartialEq, Serialize, Deserialize)]
41pub enum LogData {
42 TargetLog(LogsData),
44}
45
46impl LogData {
47 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#[derive(Clone, Debug, PartialEq, Serialize, Deserialize)]
70pub struct LogEntry {
71 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
86impl 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#[async_trait(?Send)]
97pub trait Symbolize {
98 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
135pub 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 fn set_boot_timestamp(&mut self, _boot_ts_nanos: Timestamp);
175
176 fn get_boot_timestamp(&self) -> Timestamp;
178}
179
180#[derive(Clone, Debug)]
182pub struct DeviceOrLocalTimestamp {
183 pub timestamp: Timestamp,
185 pub is_boot: bool,
188}
189
190impl DeviceOrLocalTimestamp {
191 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#[derive(Clone, Debug)]
215pub struct LogFormatterOptions {
216 pub display: Option<LogTextDisplayOptions>,
218 pub since: Option<DeviceOrLocalTimestamp>,
220 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#[derive(Error, Debug)]
232pub enum FormatterError {
233 #[error(transparent)]
235 Other(#[from] anyhow::Error),
236 #[error(transparent)]
238 IO(#[from] std::io::Error),
239}
240
241pub 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
252fn 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
294pub 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 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 if let LogTimeDisplayFormat::WallTime { ref mut offset, .. } =
357 options_for_this_line_only.display.as_mut().unwrap().time_format
358 {
359 *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 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 offset: 0,
401 },
402 TimeFormat::Utc => LogTimeDisplayFormat::WallTime {
403 tz: Timezone::Utc,
404 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 ×tamp.timestamp,
436 )
437 } else {
438 callback(&log_entry.utc_timestamp(self.boot_ts_nanos), ×tamp.timestamp)
439 }
440 }
441
442 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 writeln!(self.writer, "{}", LogTextPresenter::new(&data, text_options))?;
460 }
461 }
462 Ok(())
463 }
464}
465
466#[allow(dead_code)] pub 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#[async_trait(?Send)]
479pub trait LogFormatter {
480 async fn push_log(&mut self, log_entry: LogEntry) -> Result<LogProcessingResult, LogError>;
482
483 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 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 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 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 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 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 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}