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

archivist_lib/logs/
stored_message.rs
