archivist_lib/logs/
stored_message.rs

1// Copyright 2021 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::identity::ComponentIdentity;
6use crate::logs::stats::LogStreamStats;
7use anyhow::Result;
8use bstr::{BStr, ByteSlice};
9use diagnostics_data::{LogsData, Severity};
10use diagnostics_log_encoding::encode::{
11    Encoder, EncoderOpts, EncodingError, MutableBuffer, RecordEvent, WriteEventParams,
12};
13use diagnostics_log_encoding::Argument;
14use fidl_fuchsia_diagnostics_types as fdiagnostics;
15use fidl_fuchsia_logger::MAX_DATAGRAM_LEN_BYTES;
16use std::fmt::Debug;
17use std::io::Cursor;
18use std::sync::Arc;
19
20type RawSeverity = u8;
21
22#[derive(Debug, Eq, PartialEq)]
23pub struct StoredMessage {
24    bytes: Box<[u8]>,
25    severity: Severity,
26    timestamp: zx::BootInstant,
27}
28
29impl StoredMessage {
30    pub fn new(buf: Box<[u8]>, stats: &Arc<LogStreamStats>) -> Option<Self> {
31        match diagnostics_log_encoding::parse::basic_info(&buf) {
32            Ok((timestamp, severity)) => {
33                Some(StoredMessage { bytes: buf, severity: severity.into(), timestamp })
34            }
35            _ => {
36                stats.increment_invalid(buf.len());
37                None
38            }
39        }
40    }
41
42    pub fn from_debuglog(record: zx::DebugLogRecord, dropped: u64) -> Self {
43        let mut data = record.data();
44        if let Some(b'\n') = data.last() {
45            data = &data[..data.len() - 1];
46        }
47
48        let severity = match record.severity {
49            zx::DebugLogSeverity::Trace => fdiagnostics::Severity::Trace,
50            zx::DebugLogSeverity::Debug => fdiagnostics::Severity::Debug,
51            zx::DebugLogSeverity::Warn => fdiagnostics::Severity::Warn,
52            zx::DebugLogSeverity::Error => fdiagnostics::Severity::Error,
53            zx::DebugLogSeverity::Fatal => fdiagnostics::Severity::Fatal,
54            zx::DebugLogSeverity::Unknown => fdiagnostics::Severity::Info,
55            zx::DebugLogSeverity::Info => {
56                // By default `zx_log_record_t` carries INFO severity. Since `zx_debuglog_write`
57                // doesn't support setting a severity, historically logs have been tagged and
58                // annotated with their severity in the message. If we get here attempt to use the
59                // severity in the message, otherwise fallback to INFO.
60                const MAX_STRING_SEARCH_SIZE: usize = 170;
61                let last = data
62                    .char_indices()
63                    .nth(MAX_STRING_SEARCH_SIZE)
64                    .map(|(i, _, _)| i)
65                    .unwrap_or(data.len());
66                let early_contents = &data[..last];
67                if early_contents.contains_str("ERROR:") {
68                    fdiagnostics::Severity::Error
69                } else if early_contents.contains_str("WARNING:") {
70                    fdiagnostics::Severity::Warn
71                } else {
72                    fdiagnostics::Severity::Info
73                }
74            }
75        };
76
77        let mut encoder =
78            Encoder::new(Cursor::new([0u8; MAX_DATAGRAM_LEN_BYTES as _]), EncoderOpts::default());
79        let _ = encoder.write_event(WriteEventParams {
80            event: DebugLogRecordEvent {
81                severity: severity.into_primitive(),
82                data,
83                timestamp: record.timestamp,
84            },
85            tags: &["klog"],
86            metatags: std::iter::empty(),
87            pid: record.pid,
88            tid: record.tid,
89            dropped,
90        });
91        let cursor = encoder.take();
92        let position = cursor.position() as usize;
93        let buf = cursor.get_ref();
94
95        Self {
96            bytes: Box::from(&buf[..position]),
97            severity: severity.into(),
98            timestamp: record.timestamp,
99        }
100    }
101
102    pub fn bytes(&self) -> &[u8] {
103        &self.bytes
104    }
105
106    pub fn size(&self) -> usize {
107        self.bytes.len()
108    }
109
110    pub fn severity(&self) -> Severity {
111        self.severity
112    }
113
114    pub fn timestamp(&self) -> zx::BootInstant {
115        self.timestamp
116    }
117
118    pub fn parse(&self, source: &ComponentIdentity) -> Result<LogsData> {
119        let mut data = diagnostics_message::from_structured(source.into(), &self.bytes)?;
120        // TODO(https://fxbug.dev/368426475): fix chromium, then remove. The problematic logs are
121        // being ingested as sturctured logs. Not a legacy logs too.
122        match i8::from_le_bytes(data.metadata.raw_severity().to_le_bytes()) {
123            -1 => data.set_severity(Severity::Debug),
124            -2 => data.set_severity(Severity::Trace),
125            0 => data.set_severity(Severity::Info),
126            _ => {}
127        }
128        Ok(data)
129    }
130}
131
132struct DebugLogRecordEvent<'a> {
133    severity: RawSeverity,
134    data: &'a BStr,
135    timestamp: zx::BootInstant,
136}
137
138impl RecordEvent for DebugLogRecordEvent<'_> {
139    fn raw_severity(&self) -> RawSeverity {
140        self.severity
141    }
142
143    fn file(&self) -> Option<&str> {
144        None
145    }
146
147    fn line(&self) -> Option<u32> {
148        None
149    }
150
151    fn target(&self) -> &str {
152        ""
153    }
154
155    fn timestamp(&self) -> zx::BootInstant {
156        self.timestamp
157    }
158
159    fn write_arguments<B: MutableBuffer>(
160        self,
161        writer: &mut Encoder<B>,
162    ) -> Result<(), EncodingError> {
163        writer.write_argument(Argument::message(self.data.to_str_lossy().as_ref()))?;
164        Ok(())
165    }
166}
167
168#[cfg(test)]
169mod tests {
170    use super::*;
171    use crate::logs::debuglog::KERNEL_IDENTITY;
172    use crate::logs::testing::TestDebugEntry;
173    use diagnostics_data::{BuilderArgs, LogsDataBuilder};
174    use fidl_fuchsia_logger::LogMessage;
175
176    #[fuchsia::test]
177    fn convert_debuglog_to_log_message_test() {
178        let klog = TestDebugEntry::new("test log".as_bytes());
179        let data = StoredMessage::from_debuglog(klog.record, 10).parse(&KERNEL_IDENTITY).unwrap();
180        assert_eq!(
181            data,
182            LogsDataBuilder::new(BuilderArgs {
183                timestamp: klog.record.timestamp,
184                component_url: Some(KERNEL_IDENTITY.url.clone()),
185                moniker: KERNEL_IDENTITY.moniker.clone(),
186                severity: Severity::Info,
187            })
188            .set_dropped(10)
189            .set_pid(klog.record.pid.raw_koid())
190            .set_tid(klog.record.tid.raw_koid())
191            .add_tag("klog")
192            .set_message("test log".to_string())
193            .build()
194        );
195        // make sure the `klog` tag still shows up for legacy listeners
196        let log_message: LogMessage = data.into();
197        assert_eq!(
198            log_message,
199            LogMessage {
200                pid: klog.record.pid.raw_koid(),
201                tid: klog.record.tid.raw_koid(),
202                time: klog.record.timestamp,
203                severity: fdiagnostics::Severity::Info.into_primitive() as i32,
204                dropped_logs: 10,
205                tags: vec!["klog".to_string()],
206                msg: "test log".to_string(),
207            }
208        );
209
210        // maximum allowed klog size
211        let klog = TestDebugEntry::new(&vec![b'a'; zx::sys::ZX_LOG_RECORD_DATA_MAX]);
212        let data = StoredMessage::from_debuglog(klog.record, 0).parse(&KERNEL_IDENTITY).unwrap();
213        assert_eq!(
214            data,
215            LogsDataBuilder::new(BuilderArgs {
216                timestamp: klog.record.timestamp,
217                component_url: Some(KERNEL_IDENTITY.url.clone()),
218                moniker: KERNEL_IDENTITY.moniker.clone(),
219                severity: Severity::Info,
220            })
221            .set_pid(klog.record.pid.raw_koid())
222            .set_tid(klog.record.tid.raw_koid())
223            .add_tag("klog")
224            .set_message(String::from_utf8(vec![b'a'; zx::sys::ZX_LOG_RECORD_DATA_MAX]).unwrap())
225            .build()
226        );
227
228        // empty message
229        let klog = TestDebugEntry::new(&[]);
230        let data = StoredMessage::from_debuglog(klog.record, 0).parse(&KERNEL_IDENTITY).unwrap();
231        assert_eq!(
232            data,
233            LogsDataBuilder::new(BuilderArgs {
234                timestamp: klog.record.timestamp,
235                component_url: Some(KERNEL_IDENTITY.url.clone()),
236                moniker: KERNEL_IDENTITY.moniker.clone(),
237                severity: Severity::Info,
238            })
239            .set_pid(klog.record.pid.raw_koid())
240            .set_tid(klog.record.tid.raw_koid())
241            .add_tag("klog")
242            .set_message("".to_string())
243            .build()
244        );
245
246        // invalid utf-8
247        let klog = TestDebugEntry::new(b"\x00\x9f\x92");
248        let data = StoredMessage::from_debuglog(klog.record, 0).parse(&KERNEL_IDENTITY).unwrap();
249        assert_eq!(data.msg().unwrap(), "\x00��");
250    }
251}
archivist_lib/logs/stored_message.rs

archivist_lib/logs/
stored_message.rs
