archivist_lib/logs/
mod.rs

1// Copyright 2018 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
5pub mod container;
6pub mod debuglog;
7pub mod error;
8pub mod listener;
9pub mod multiplex;
10pub mod repository;
11pub mod serial;
12pub mod servers;
13pub mod shared_buffer;
14pub mod socket;
15pub mod stats;
16pub mod stored_message;
17#[cfg(test)]
18pub mod testing;
19
20#[cfg(test)]
21mod tests {
22    use crate::identity::ComponentIdentity;
23    use crate::logs::testing::*;
24    use diagnostics_assertions::{assert_data_tree, AnyProperty};
25    use diagnostics_log_encoding::{Argument, Record};
26    use diagnostics_log_types::Severity;
27    use fidl_fuchsia_logger::{LogFilterOptions, LogLevelFilter, LogMessage};
28    use fuchsia_async as fasync;
29    use moniker::ExtendedMoniker;
30    use std::sync::Arc;
31
32    #[fuchsia::test]
33    async fn test_log_manager_simple() {
34        Box::pin(TestHarness::default().manager_test(false)).await;
35    }
36
37    #[fuchsia::test]
38    async fn test_log_manager_dump() {
39        Box::pin(TestHarness::default().manager_test(true)).await;
40    }
41
42    #[fuchsia::test]
43    async fn unfiltered_stats() {
44        let first_packet = setup_default_packet();
45        let first_message = LogMessage {
46            pid: first_packet.metadata.pid,
47            tid: first_packet.metadata.tid,
48            time: zx::BootInstant::from_nanos(first_packet.metadata.time),
49            dropped_logs: first_packet.metadata.dropped_logs,
50            severity: first_packet.metadata.severity,
51            msg: String::from("BBBBB"),
52            tags: vec![String::from("AAAAA")],
53        };
54
55        let (mut second_packet, mut second_message) = (first_packet.clone(), first_message.clone());
56        second_packet.metadata.pid = 0;
57        second_message.pid = second_packet.metadata.pid;
58
59        let (mut third_packet, mut third_message) = (second_packet.clone(), second_message.clone());
60        third_packet.metadata.severity = LogLevelFilter::Info.into_primitive().into();
61        third_message.severity = third_packet.metadata.severity;
62
63        let (fourth_packet, fourth_message) = (third_packet.clone(), third_message.clone());
64
65        let (mut fifth_packet, mut fifth_message) = (fourth_packet.clone(), fourth_message.clone());
66        fifth_packet.metadata.severity = LogLevelFilter::Error.into_primitive().into();
67        fifth_message.severity = fifth_packet.metadata.severity;
68
69        let mut harness = TestHarness::default();
70        let mut stream = harness.create_stream(Arc::new(ComponentIdentity::unknown()));
71        stream.write_packets(vec![
72            first_packet,
73            second_packet,
74            third_packet,
75            fourth_packet,
76            fifth_packet,
77        ]);
78        drop(stream);
79
80        let log_stats_tree = harness
81            .filter_test(
82                vec![first_message, second_message, third_message, fourth_message, fifth_message],
83                None,
84            )
85            .await;
86
87        assert_data_tree!(
88            log_stats_tree,
89            root: contains {
90                log_sources: {
91                    "UNKNOWN": {
92                        url: "fuchsia-pkg://UNKNOWN",
93                        last_timestamp: AnyProperty,
94                        sockets_closed: 1u64,
95                        sockets_opened: 1u64,
96                        invalid: {
97                            number: 0u64,
98                            bytes: 0u64,
99                        },
100                        total: {
101                            number: 5u64,
102                            bytes: AnyProperty,
103                        },
104                        rolled_out: {
105                            number: 0u64,
106                            bytes: 0u64,
107                        },
108                        trace: {
109                            number: 0u64,
110                            bytes: 0u64,
111                        },
112                        debug: {
113                            number: 0u64,
114                            bytes: 0u64,
115                        },
116                        info: {
117                            number: 2u64,
118                            bytes: AnyProperty,
119                        },
120                        warn: {
121                            number: 2u64,
122                            bytes: AnyProperty,
123                        },
124                        error: {
125                            number: 1u64,
126                            bytes: AnyProperty,
127                        },
128                        fatal: {
129                            number: 0u64,
130                            bytes: 0u64,
131                        },
132                    },
133                }
134            }
135        );
136    }
137
138    macro_rules! attributed_inspect_two_streams_different_identities_by_reader {
139        (
140            $harness:ident,
141            $log_reader1:ident @ $foo_moniker:literal,
142            $log_reader2:ident @ $bar_moniker:literal,
143        ) => {{
144            let packet = setup_default_packet();
145            let message = LogMessage {
146                pid: packet.metadata.pid,
147                tid: packet.metadata.tid,
148                time: zx::BootInstant::from_nanos(packet.metadata.time),
149                dropped_logs: packet.metadata.dropped_logs,
150                severity: packet.metadata.severity,
151                msg: String::from("BBBBB"),
152                tags: vec![String::from("AAAAA")],
153            };
154
155            let mut packet2 = packet.clone();
156            packet2.metadata.severity = LogLevelFilter::Error.into_primitive().into();
157            let mut message2 = message.clone();
158            message2.severity = packet2.metadata.severity;
159
160            let mut foo_stream = $harness.create_stream_from_log_reader($log_reader1);
161            foo_stream.write_packet(packet);
162
163            let mut bar_stream = $harness.create_stream_from_log_reader($log_reader2);
164            bar_stream.write_packet(packet2);
165            drop((foo_stream, bar_stream));
166
167            let log_stats_tree = $harness.filter_test(vec![message, message2], None).await;
168
169            assert_data_tree!(
170                log_stats_tree,
171                root: contains {
172                    log_sources: {
173                        $foo_moniker: {
174                            url: "http://foo.com",
175                            last_timestamp: AnyProperty,
176                            sockets_closed: 1u64,
177                            sockets_opened: 1u64,
178                            invalid: {
179                                number: 0u64,
180                                bytes: 0u64,
181                            },
182                            total: {
183                                number: 1u64,
184                                bytes: AnyProperty,
185                            },
186                            rolled_out: {
187                                number: 0u64,
188                                bytes: 0u64,
189                            },
190                            trace: {
191                                number: 0u64,
192                                bytes: 0u64,
193                            },
194                            debug: {
195                                number: 0u64,
196                                bytes: 0u64,
197                            },
198                            info: {
199                                number: 0u64,
200                                bytes: 0u64,
201                            },
202                            warn: {
203                                number: 1u64,
204                                bytes: AnyProperty,
205                            },
206                            error: {
207                                number: 0u64,
208                                bytes: 0u64,
209                            },
210                            fatal: {
211                                number: 0u64,
212                                bytes: 0u64,
213                            },
214                        },
215                        $bar_moniker: {
216                            url: "http://bar.com",
217                            last_timestamp: AnyProperty,
218                            sockets_closed: 1u64,
219                            sockets_opened: 1u64,
220                            invalid: {
221                                number: 0u64,
222                                bytes: 0u64,
223                            },
224                            total: {
225                                number: 1u64,
226                                bytes: AnyProperty,
227                            },
228                            rolled_out: {
229                                number: 0u64,
230                                bytes: 0u64,
231                            },
232                            trace: {
233                                number: 0u64,
234                                bytes: 0u64,
235                            },
236                            debug: {
237                                number: 0u64,
238                                bytes: 0u64,
239                            },
240                            info: {
241                                number: 0u64,
242                                bytes: 0u64,
243                            },
244                            warn: {
245                                number: 0u64,
246                                bytes: 0u64,
247                            },
248                            error: {
249                                number: 1u64,
250                                bytes: AnyProperty,
251                            },
252                            fatal: {
253                                number: 0u64,
254                                bytes: 0u64,
255                            },
256                        },
257                    },
258                }
259            );
260        }}
261    }
262
263    #[fuchsia::test]
264    async fn attributed_inspect_two_streams_different_identities() {
265        let mut harness = TestHarness::with_retained_sinks();
266
267        let log_reader1 = harness.create_default_reader(ComponentIdentity::new(
268            ExtendedMoniker::parse_str("./foo").unwrap(),
269            "http://foo.com",
270        ));
271
272        let log_reader2 = harness.create_default_reader(ComponentIdentity::new(
273            ExtendedMoniker::parse_str("./bar").unwrap(),
274            "http://bar.com",
275        ));
276
277        attributed_inspect_two_streams_different_identities_by_reader!(
278            harness,
279            log_reader1 @ "foo",
280            log_reader2 @ "bar",
281        );
282    }
283
284    #[fuchsia::test]
285    async fn attributed_inspect_two_v2_streams_different_identities() {
286        let mut harness = TestHarness::with_retained_sinks();
287        let log_reader1 = harness.create_event_stream_reader("./foo", "http://foo.com");
288        let log_reader2 = harness.create_event_stream_reader("./bar", "http://bar.com");
289
290        attributed_inspect_two_streams_different_identities_by_reader!(
291            harness,
292            log_reader1 @ "foo",
293            log_reader2 @ "bar",
294        );
295    }
296
297    #[fuchsia::test]
298    async fn attributed_inspect_two_mixed_streams_different_identities() {
299        let mut harness = TestHarness::with_retained_sinks();
300        let log_reader1 = harness.create_event_stream_reader("./foo", "http://foo.com");
301        let log_reader2 = harness.create_default_reader(ComponentIdentity::new(
302            ExtendedMoniker::parse_str("./bar").unwrap(),
303            "http://bar.com",
304        ));
305
306        attributed_inspect_two_streams_different_identities_by_reader!(
307            harness,
308            log_reader1 @ "foo",
309            log_reader2 @ "bar",
310        );
311    }
312
313    #[fuchsia::test]
314    async fn test_filter_by_pid() {
315        let p = setup_default_packet();
316        let mut p2 = p.clone();
317        p2.metadata.pid = 0;
318        let lm = LogMessage {
319            pid: p.metadata.pid,
320            tid: p.metadata.tid,
321            time: zx::BootInstant::from_nanos(p.metadata.time),
322            dropped_logs: p.metadata.dropped_logs,
323            severity: p.metadata.severity,
324            msg: String::from("BBBBB"),
325            tags: vec![String::from("AAAAA")],
326        };
327        let options = LogFilterOptions {
328            filter_by_pid: true,
329            pid: 1,
330            filter_by_tid: false,
331            tid: 0,
332            min_severity: LogLevelFilter::None,
333            verbosity: 0,
334            tags: vec![],
335        };
336
337        let mut harness = TestHarness::default();
338        let mut stream = harness.create_stream(Arc::new(ComponentIdentity::unknown()));
339        stream.write_packets(vec![p, p2]);
340        drop(stream);
341        harness.filter_test(vec![lm], Some(options)).await;
342    }
343
344    #[fuchsia::test]
345    async fn test_filter_by_tid() {
346        let mut p = setup_default_packet();
347        p.metadata.pid = 0;
348        let mut p2 = p.clone();
349        p2.metadata.tid = 0;
350        let lm = LogMessage {
351            pid: p.metadata.pid,
352            tid: p.metadata.tid,
353            time: zx::BootInstant::from_nanos(p.metadata.time),
354            dropped_logs: p.metadata.dropped_logs,
355            severity: p.metadata.severity,
356            msg: String::from("BBBBB"),
357            tags: vec![String::from("AAAAA")],
358        };
359        let options = LogFilterOptions {
360            filter_by_pid: false,
361            pid: 1,
362            filter_by_tid: true,
363            tid: 1,
364            min_severity: LogLevelFilter::None,
365            verbosity: 0,
366            tags: vec![],
367        };
368
369        let mut harness = TestHarness::default();
370        let mut stream = harness.create_stream(Arc::new(ComponentIdentity::unknown()));
371        stream.write_packets(vec![p, p2]);
372        drop(stream);
373        harness.filter_test(vec![lm], Some(options)).await;
374    }
375
376    #[fuchsia::test]
377    async fn test_filter_by_min_severity() {
378        let p = setup_default_packet();
379        let mut p2 = p.clone();
380        p2.metadata.pid = 0;
381        p2.metadata.tid = 0;
382        p2.metadata.severity = LogLevelFilter::Error.into_primitive().into();
383        let mut p3 = p.clone();
384        p3.metadata.severity = LogLevelFilter::Info.into_primitive().into();
385        let mut p4 = p.clone();
386        p4.metadata.severity = 0x70; // custom
387        let mut p5 = p.clone();
388        p5.metadata.severity = LogLevelFilter::Fatal.into_primitive().into();
389        let lm = LogMessage {
390            pid: p2.metadata.pid,
391            tid: p2.metadata.tid,
392            time: zx::BootInstant::from_nanos(p2.metadata.time),
393            dropped_logs: p2.metadata.dropped_logs,
394            severity: p2.metadata.severity,
395            msg: String::from("BBBBB"),
396            tags: vec![String::from("AAAAA")],
397        };
398        let options = LogFilterOptions {
399            filter_by_pid: false,
400            pid: 1,
401            filter_by_tid: false,
402            tid: 1,
403            min_severity: LogLevelFilter::Error,
404            verbosity: 0,
405            tags: vec![],
406        };
407
408        let mut harness = TestHarness::default();
409        let mut stream = harness.create_stream(Arc::new(ComponentIdentity::unknown()));
410        stream.write_packets(vec![p, p2, p3, p4, p5]);
411        drop(stream);
412        harness.filter_test(vec![lm], Some(options)).await;
413    }
414
415    #[fuchsia::test]
416    async fn test_filter_by_combination() {
417        let mut p = setup_default_packet();
418        p.metadata.pid = 0;
419        p.metadata.tid = 0;
420        let mut p2 = p.clone();
421        p2.metadata.severity = LogLevelFilter::Error.into_primitive().into();
422        let mut p3 = p.clone();
423        p3.metadata.pid = 1;
424        let lm = LogMessage {
425            pid: p2.metadata.pid,
426            tid: p2.metadata.tid,
427            time: zx::BootInstant::from_nanos(p2.metadata.time),
428            dropped_logs: p2.metadata.dropped_logs,
429            severity: p2.metadata.severity,
430            msg: String::from("BBBBB"),
431            tags: vec![String::from("AAAAA")],
432        };
433        let options = LogFilterOptions {
434            filter_by_pid: true,
435            pid: 0,
436            filter_by_tid: false,
437            tid: 1,
438            min_severity: LogLevelFilter::Error,
439            verbosity: 0,
440            tags: vec![],
441        };
442
443        let mut harness = TestHarness::default();
444        let mut stream = harness.create_stream(Arc::new(ComponentIdentity::unknown()));
445        stream.write_packets(vec![p, p2, p3]);
446        drop(stream);
447        harness.filter_test(vec![lm], Some(options)).await;
448    }
449
450    #[fuchsia::test]
451    async fn test_filter_by_tags() {
452        let mut p = setup_default_packet();
453        let mut p2 = p.clone();
454        // p tags - "DDDDD"
455        p.fill_data(1..6, 68);
456
457        p2.metadata.pid = 0;
458        p2.metadata.tid = 0;
459        p2.data[6] = 5;
460        // p2 tag - "AAAAA", "BBBBB"
461        // p2 msg - "CCCCC"
462        p2.fill_data(13..18, 67);
463
464        let lm1 = LogMessage {
465            pid: p.metadata.pid,
466            tid: p.metadata.tid,
467            time: zx::BootInstant::from_nanos(p.metadata.time),
468            dropped_logs: p.metadata.dropped_logs,
469            severity: p.metadata.severity,
470            msg: String::from("BBBBB"),
471            tags: vec![String::from("DDDDD")],
472        };
473        let lm2 = LogMessage {
474            pid: p2.metadata.pid,
475            tid: p2.metadata.tid,
476            time: zx::BootInstant::from_nanos(p2.metadata.time),
477            dropped_logs: p2.metadata.dropped_logs,
478            severity: p2.metadata.severity,
479            msg: String::from("CCCCC"),
480            tags: vec![String::from("AAAAA"), String::from("BBBBB")],
481        };
482        let options = LogFilterOptions {
483            filter_by_pid: false,
484            pid: 1,
485            filter_by_tid: false,
486            tid: 1,
487            min_severity: LogLevelFilter::None,
488            verbosity: 0,
489            tags: vec![String::from("BBBBB"), String::from("DDDDD")],
490        };
491
492        let mut harness = TestHarness::default();
493        let mut stream = harness.create_stream(Arc::new(ComponentIdentity::unknown()));
494        stream.write_packets(vec![p, p2]);
495        drop(stream);
496        harness.filter_test(vec![lm1, lm2], Some(options)).await;
497    }
498
499    #[fuchsia::test]
500    async fn test_structured_log() {
501        let logs = vec![
502            Record {
503                timestamp: zx::BootInstant::from_nanos(6),
504                severity: Severity::Info as u8,
505                arguments: vec![Argument::message("hi")],
506            },
507            Record {
508                timestamp: zx::BootInstant::from_nanos(13),
509                severity: Severity::Error as u8,
510                arguments: vec![],
511            },
512            Record {
513                timestamp: zx::BootInstant::from_nanos(19),
514                severity: Severity::Warn as u8,
515                arguments: vec![
516                    Argument::pid(zx::Koid::from_raw(0x1d1)),
517                    Argument::tid(zx::Koid::from_raw(0x1d2)),
518                    Argument::dropped(23),
519                    Argument::tag("tag"),
520                    Argument::message("message"),
521                ],
522            },
523            Record {
524                timestamp: zx::BootInstant::from_nanos(21),
525                severity: Severity::Warn as u8,
526                arguments: vec![Argument::tag("tag-1"), Argument::tag("tag-2")],
527            },
528        ];
529
530        let expected_logs = vec![
531            LogMessage {
532                pid: zx::sys::ZX_KOID_INVALID,
533                tid: zx::sys::ZX_KOID_INVALID,
534                time: zx::BootInstant::from_nanos(6),
535                severity: LogLevelFilter::Info as i32,
536                dropped_logs: 0,
537                msg: String::from("hi"),
538                tags: vec!["UNKNOWN".to_owned()],
539            },
540            LogMessage {
541                pid: zx::sys::ZX_KOID_INVALID,
542                tid: zx::sys::ZX_KOID_INVALID,
543                time: zx::BootInstant::from_nanos(14),
544                severity: LogLevelFilter::Error as i32,
545                dropped_logs: 0,
546                msg: String::from(""),
547                tags: vec!["UNKNOWN".to_owned()],
548            },
549            LogMessage {
550                pid: 0x1d1,
551                tid: 0x1d2,
552                time: zx::BootInstant::from_nanos(19),
553                severity: LogLevelFilter::Warn as i32,
554                dropped_logs: 23,
555                msg: String::from("message"),
556                tags: vec![String::from("tag")],
557            },
558            LogMessage {
559                pid: zx::sys::ZX_KOID_INVALID,
560                tid: zx::sys::ZX_KOID_INVALID,
561                time: zx::BootInstant::from_nanos(21),
562                severity: LogLevelFilter::Warn as i32,
563                dropped_logs: 0,
564                msg: String::from(""),
565                tags: vec![String::from("tag-1"), String::from("tag-2")],
566            },
567        ];
568        let mut harness = TestHarness::default();
569        let mut stream = harness.create_structured_stream(Arc::new(ComponentIdentity::unknown()));
570        stream.write_packets(logs);
571        drop(stream);
572        harness.filter_test(expected_logs, None).await;
573    }
574
575    #[fuchsia::test]
576    async fn test_debuglog_drainer() {
577        let log1 = TestDebugEntry::new("log1".as_bytes());
578        let log2 = TestDebugEntry::new("log2".as_bytes());
579        let log3 = TestDebugEntry::new("log3".as_bytes());
580
581        let klog_reader = TestDebugLog::default();
582        klog_reader.enqueue_read_entry(&log1);
583        klog_reader.enqueue_read_entry(&log2);
584        // logs received after kernel indicates no logs should be read
585        klog_reader.enqueue_read_fail(zx::Status::SHOULD_WAIT);
586        klog_reader.enqueue_read_entry(&log3);
587        klog_reader.enqueue_read_fail(zx::Status::SHOULD_WAIT);
588
589        let expected_logs = vec![
590            LogMessage {
591                pid: log1.record.pid.raw_koid(),
592                tid: log1.record.tid.raw_koid(),
593                time: log1.record.timestamp,
594                dropped_logs: 0,
595                severity: LogLevelFilter::Info as i32,
596                msg: String::from("log1"),
597                tags: vec![String::from("klog")],
598            },
599            LogMessage {
600                pid: log2.record.pid.raw_koid(),
601                tid: log2.record.tid.raw_koid(),
602                time: log2.record.timestamp,
603                dropped_logs: 0,
604                severity: LogLevelFilter::Info as i32,
605                msg: String::from("log2"),
606                tags: vec![String::from("klog")],
607            },
608            LogMessage {
609                pid: log3.record.pid.raw_koid(),
610                tid: log3.record.tid.raw_koid(),
611                time: log3.record.timestamp,
612                dropped_logs: 0,
613                severity: LogLevelFilter::Info as i32,
614                msg: String::from("log3"),
615                tags: vec![String::from("klog")],
616            },
617        ];
618
619        let scope = fasync::Scope::new();
620        let klog_stats_tree = debuglog_test(expected_logs, klog_reader, scope.new_child()).await;
621        assert_data_tree!(
622            klog_stats_tree,
623            root: contains {
624                log_sources: {
625                    "klog": {
626                        url: "fuchsia-boot://kernel",
627                        last_timestamp: AnyProperty,
628                        sockets_closed: 0u64,
629                        sockets_opened: 0u64,
630                        invalid: {
631                            number: 0u64,
632                            bytes: 0u64,
633                        },
634                        total: {
635                            number: 3u64,
636                            bytes: AnyProperty,
637                        },
638                        rolled_out: {
639                            number: 0u64,
640                            bytes: 0u64,
641                        },
642                        trace: {
643                            number: 0u64,
644                            bytes: 0u64,
645                        },
646                        debug: {
647                            number: 0u64,
648                            bytes: 0u64,
649                        },
650                        info: {
651                            number: 3u64,
652                            bytes: AnyProperty,
653                        },
654                        warn: {
655                            number: 0u64,
656                            bytes: 0u64,
657                        },
658                        error: {
659                            number: 0u64,
660                            bytes: 0u64,
661                        },
662                        fatal: {
663                            number: 0u64,
664                            bytes: 0u64,
665                        },
666                    },
667                }
668            }
669        );
670    }
671}
archivist_lib/logs/mod.rs

archivist_lib/logs/
mod.rs
