archivist_lib/logs/
debuglog.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
5// Read debug logs, convert them to LogMessages and serve them.
6
7use crate::identity::ComponentIdentity;
8use crate::logs::error::LogsError;
9use crate::logs::stored_message::StoredMessage;
10use fidl::prelude::*;
11use fidl_fuchsia_boot::ReadOnlyLogMarker;
12use fuchsia_async as fasync;
13use fuchsia_component::client::connect_to_protocol;
14use futures::stream::{Stream, unfold};
15use moniker::ExtendedMoniker;
16use std::future::Future;
17use std::sync::{Arc, LazyLock};
18
19const KERNEL_URL: &str = "fuchsia-boot://kernel";
20pub static KERNEL_IDENTITY: LazyLock<Arc<ComponentIdentity>> = LazyLock::new(|| {
21    Arc::new(ComponentIdentity::new(ExtendedMoniker::parse_str("./klog").unwrap(), KERNEL_URL))
22});
23
24pub trait DebugLog {
25    /// Reads a single entry off the debug log into `buffer`.  Any existing
26    /// contents in `buffer` are overwritten.
27    fn read(&self) -> Result<zx::DebugLogRecord, zx::Status>;
28
29    /// Returns a future that completes when there is another log to read.
30    fn ready_signal(&self) -> impl Future<Output = Result<(), zx::Status>> + Send;
31}
32
33pub struct KernelDebugLog {
34    debuglogger: zx::DebugLog,
35}
36
37impl DebugLog for KernelDebugLog {
38    fn read(&self) -> Result<zx::DebugLogRecord, zx::Status> {
39        self.debuglogger.read()
40    }
41
42    async fn ready_signal(&self) -> Result<(), zx::Status> {
43        fasync::OnSignals::new(&self.debuglogger, zx::Signals::LOG_READABLE).await?;
44        Ok(())
45    }
46}
47
48impl KernelDebugLog {
49    /// Connects to `fuchsia.boot.ReadOnlyLog` to retrieve a handle.
50    pub async fn new() -> Result<Self, LogsError> {
51        let boot_log = connect_to_protocol::<ReadOnlyLogMarker>().map_err(|source| {
52            LogsError::ConnectingToService { protocol: ReadOnlyLogMarker::PROTOCOL_NAME, source }
53        })?;
54        let debuglogger =
55            boot_log.get().await.map_err(|source| LogsError::RetrievingDebugLog { source })?;
56        Ok(KernelDebugLog { debuglogger })
57    }
58}
59
60pub struct DebugLogBridge<K: DebugLog> {
61    debug_log: K,
62    next_sequence_id: u64,
63}
64
65impl<K: DebugLog> DebugLogBridge<K> {
66    pub fn create(debug_log: K) -> Self {
67        DebugLogBridge { debug_log, next_sequence_id: 0 }
68    }
69
70    fn read_log(&mut self) -> Result<StoredMessage, zx::Status> {
71        let record = self.debug_log.read()?;
72        let dropped = record.sequence - self.next_sequence_id;
73        self.next_sequence_id = record.sequence + 1;
74        Ok(StoredMessage::from_debuglog(record, dropped))
75    }
76
77    pub fn existing_logs(&mut self) -> Result<Vec<StoredMessage>, zx::Status> {
78        let mut result = vec![];
79        loop {
80            match self.read_log() {
81                Err(zx::Status::SHOULD_WAIT) => break,
82                Err(err) => return Err(err),
83                Ok(log) => result.push(log),
84            }
85        }
86        Ok(result)
87    }
88
89    pub fn listen(self) -> impl Stream<Item = Result<StoredMessage, zx::Status>> {
90        unfold((true, self), move |(mut is_readable, mut klogger)| async move {
91            loop {
92                if !is_readable {
93                    if let Err(e) = klogger.debug_log.ready_signal().await {
94                        break Some((Err(e), (is_readable, klogger)));
95                    }
96                }
97                is_readable = true;
98                match klogger.read_log() {
99                    Err(zx::Status::SHOULD_WAIT) => {
100                        is_readable = false;
101                        continue;
102                    }
103                    x => break Some((x, (is_readable, klogger))),
104                }
105            }
106        })
107    }
108}
109
110#[cfg(test)]
111mod tests {
112    use super::*;
113    use crate::logs::testing::*;
114    use diagnostics_data::{BuilderArgs, LogsDataBuilder, Severity};
115    use futures::stream::{StreamExt, TryStreamExt};
116
117    #[fuchsia::test]
118    fn logger_existing_logs_test() {
119        let debug_log = TestDebugLog::default();
120        let klog = TestDebugEntry::new("test log".as_bytes());
121        debug_log.enqueue_read_entry(&klog);
122        debug_log.enqueue_read_fail(zx::Status::SHOULD_WAIT);
123        let mut log_bridge = DebugLogBridge::create(debug_log);
124
125        assert_eq!(
126            log_bridge
127                .existing_logs()
128                .unwrap()
129                .into_iter()
130                .map(|m| m.parse(&KERNEL_IDENTITY).unwrap())
131                .collect::<Vec<_>>(),
132            vec![
133                LogsDataBuilder::new(BuilderArgs {
134                    timestamp: klog.record.timestamp,
135                    component_url: Some(KERNEL_IDENTITY.url.clone()),
136                    moniker: KERNEL_IDENTITY.moniker.clone(),
137                    severity: Severity::Info,
138                })
139                .set_pid(klog.record.pid.raw_koid())
140                .set_tid(klog.record.tid.raw_koid())
141                .add_tag("klog")
142                .set_message("test log".to_string())
143                .build()
144            ]
145        );
146
147        // Unprocessable logs should be skipped.
148        let debug_log = TestDebugLog::default();
149        // This is a malformed record because the message contains invalid UTF8.
150        let malformed_klog = TestDebugEntry::new(b"\x80");
151        debug_log.enqueue_read_entry(&malformed_klog);
152
153        debug_log.enqueue_read_fail(zx::Status::SHOULD_WAIT);
154        let mut log_bridge = DebugLogBridge::create(debug_log);
155        assert!(!log_bridge.existing_logs().unwrap().is_empty());
156    }
157
158    #[fasync::run_until_stalled(test)]
159    async fn logger_keep_listening_after_exhausting_initial_contents_test() {
160        let debug_log = TestDebugLog::default();
161        debug_log.enqueue_read_entry(&TestDebugEntry::new("test log".as_bytes()));
162        debug_log.enqueue_read_fail(zx::Status::SHOULD_WAIT);
163        debug_log.enqueue_read_entry(&TestDebugEntry::new("second test log".as_bytes()));
164        let log_bridge = DebugLogBridge::create(debug_log);
165        let mut log_stream =
166            Box::pin(log_bridge.listen()).map(|r| r.unwrap().parse(&KERNEL_IDENTITY));
167        let log_message = log_stream.try_next().await.unwrap().unwrap();
168        assert_eq!(log_message.msg().unwrap(), "test log");
169        let log_message = log_stream.try_next().await.unwrap().unwrap();
170        assert_eq!(log_message.msg().unwrap(), "second test log");
171
172        // Unprocessable logs should NOT be skipped.
173        let debug_log = TestDebugLog::default();
174        // This is a malformed record because the message contains invalid UTF8.
175        let malformed_klog = TestDebugEntry::new(b"\x80");
176        debug_log.enqueue_read_entry(&malformed_klog);
177
178        debug_log.enqueue_read_entry(&TestDebugEntry::new("test log".as_bytes()));
179        let log_bridge = DebugLogBridge::create(debug_log);
180        let mut log_stream = Box::pin(log_bridge.listen());
181        let log_message =
182            log_stream.try_next().await.unwrap().unwrap().parse(&KERNEL_IDENTITY).unwrap();
183        assert_eq!(log_message.msg().unwrap(), "�");
184    }
185
186    #[fasync::run_until_stalled(test)]
187    async fn severity_parsed_from_log() {
188        let debug_log = TestDebugLog::default();
189        debug_log.enqueue_read_entry(&TestDebugEntry::new("ERROR: first log".as_bytes()));
190        // We look for the string 'ERROR:' to label this as a Severity::Error.
191        debug_log.enqueue_read_entry(&TestDebugEntry::new("first log error".as_bytes()));
192        debug_log.enqueue_read_entry(&TestDebugEntry::new("WARNING: second log".as_bytes()));
193        debug_log.enqueue_read_entry(&TestDebugEntry::new("INFO: third log".as_bytes()));
194        debug_log.enqueue_read_entry(&TestDebugEntry::new("fourth log".as_bytes()));
195        debug_log.enqueue_read_entry(&TestDebugEntry::new_with_severity(
196            "ERROR: severity takes precedence over msg when not info".as_bytes(),
197            zx::DebugLogSeverity::Warn,
198        ));
199        // Create a string prefixed with multi-byte UTF-8 characters. This entry will be labeled as
200        // Info rather than Error because the string "ERROR:" only appears after the
201        // MAX_STRING_SEARCH_SIZE. It's crucial that we use multi-byte UTF-8 characters because we
202        // want to verify that the search is character oriented rather than byte oriented and that
203        // it can handle the MAX_STRING_SEARCH_SIZE boundary falling in the middle of a multi-byte
204        // character.
205        let long_padding = (0..100).map(|_| "\u{10FF}").collect::<String>();
206        let long_log = format!("{long_padding}ERROR: fifth log");
207        debug_log.enqueue_read_entry(&TestDebugEntry::new(long_log.as_bytes()));
208
209        let log_bridge = DebugLogBridge::create(debug_log);
210        let mut log_stream =
211            Box::pin(log_bridge.listen()).map(|r| r.unwrap().parse(&KERNEL_IDENTITY));
212
213        let log_message = log_stream.try_next().await.unwrap().unwrap();
214        assert_eq!(log_message.msg().unwrap(), "ERROR: first log");
215        assert_eq!(log_message.metadata.severity, Severity::Error);
216
217        let log_message = log_stream.try_next().await.unwrap().unwrap();
218        assert_eq!(log_message.msg().unwrap(), "first log error");
219        assert_eq!(log_message.metadata.severity, Severity::Info);
220
221        let log_message = log_stream.try_next().await.unwrap().unwrap();
222        assert_eq!(log_message.msg().unwrap(), "WARNING: second log");
223        assert_eq!(log_message.metadata.severity, Severity::Warn);
224
225        let log_message = log_stream.try_next().await.unwrap().unwrap();
226        assert_eq!(log_message.msg().unwrap(), "INFO: third log");
227        assert_eq!(log_message.metadata.severity, Severity::Info);
228
229        let log_message = log_stream.try_next().await.unwrap().unwrap();
230        assert_eq!(log_message.msg().unwrap(), "fourth log");
231        assert_eq!(log_message.metadata.severity, Severity::Info);
232
233        let log_message = log_stream.try_next().await.unwrap().unwrap();
234        assert_eq!(
235            log_message.msg().unwrap(),
236            "ERROR: severity takes precedence over msg when not info"
237        );
238        assert_eq!(log_message.metadata.severity, Severity::Warn);
239
240        // TODO(https://fxbug.dev/42154302): Once 74601 is resolved, uncomment the lines below. Prior to 74601
241        // being resolved, the follow case may fail because the line is very long, may be truncated,
242        // and if it is truncated, may no longer be valid UTF8 because the truncation may occur in
243        // the middle of a multi-byte character.
244        //
245        // let log_message = log_stream.try_next().await.unwrap().unwrap();
246        // assert_eq!(log_message.msg().unwrap(), &long_log);
247        // assert_eq!(log_message.metadata.severity, Severity::Info);
248    }
249}
archivist_lib/logs/debuglog.rs

archivist_lib/logs/
debuglog.rs
