archivist_lib/logs/
debuglog.rs

Help
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::{unfold, Stream};
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![LogsDataBuilder::new(BuilderArgs {
133                timestamp: klog.record.timestamp,
134                component_url: Some(KERNEL_IDENTITY.url.clone()),
135                moniker: KERNEL_IDENTITY.moniker.clone(),
136                severity: Severity::Info,
137            })
138            .set_pid(klog.record.pid.raw_koid())
139            .set_tid(klog.record.tid.raw_koid())
140            .add_tag("klog")
141            .set_message("test log".to_string())
142            .build()]
143        );
144
145        // Unprocessable logs should be skipped.
146        let debug_log = TestDebugLog::default();
147        // This is a malformed record because the message contains invalid UTF8.
148        let malformed_klog = TestDebugEntry::new(b"\x80");
149        debug_log.enqueue_read_entry(&malformed_klog);
150
151        debug_log.enqueue_read_fail(zx::Status::SHOULD_WAIT);
152        let mut log_bridge = DebugLogBridge::create(debug_log);
153        assert!(!log_bridge.existing_logs().unwrap().is_empty());
154    }
155
156    #[fasync::run_until_stalled(test)]
157    async fn logger_keep_listening_after_exhausting_initial_contents_test() {
158        let debug_log = TestDebugLog::default();
159        debug_log.enqueue_read_entry(&TestDebugEntry::new("test log".as_bytes()));
160        debug_log.enqueue_read_fail(zx::Status::SHOULD_WAIT);
161        debug_log.enqueue_read_entry(&TestDebugEntry::new("second test log".as_bytes()));
162        let log_bridge = DebugLogBridge::create(debug_log);
163        let mut log_stream =
164            Box::pin(log_bridge.listen()).map(|r| r.unwrap().parse(&KERNEL_IDENTITY));
165        let log_message = log_stream.try_next().await.unwrap().unwrap();
166        assert_eq!(log_message.msg().unwrap(), "test log");
167        let log_message = log_stream.try_next().await.unwrap().unwrap();
168        assert_eq!(log_message.msg().unwrap(), "second test log");
169
170        // Unprocessable logs should NOT be skipped.
171        let debug_log = TestDebugLog::default();
172        // This is a malformed record because the message contains invalid UTF8.
173        let malformed_klog = TestDebugEntry::new(b"\x80");
174        debug_log.enqueue_read_entry(&malformed_klog);
175
176        debug_log.enqueue_read_entry(&TestDebugEntry::new("test log".as_bytes()));
177        let log_bridge = DebugLogBridge::create(debug_log);
178        let mut log_stream = Box::pin(log_bridge.listen());
179        let log_message =
180            log_stream.try_next().await.unwrap().unwrap().parse(&KERNEL_IDENTITY).unwrap();
181        assert_eq!(log_message.msg().unwrap(), "�");
182    }
183
184    #[fasync::run_until_stalled(test)]
185    async fn severity_parsed_from_log() {
186        let debug_log = TestDebugLog::default();
187        debug_log.enqueue_read_entry(&TestDebugEntry::new("ERROR: first log".as_bytes()));
188        // We look for the string 'ERROR:' to label this as a Severity::Error.
189        debug_log.enqueue_read_entry(&TestDebugEntry::new("first log error".as_bytes()));
190        debug_log.enqueue_read_entry(&TestDebugEntry::new("WARNING: second log".as_bytes()));
191        debug_log.enqueue_read_entry(&TestDebugEntry::new("INFO: third log".as_bytes()));
192        debug_log.enqueue_read_entry(&TestDebugEntry::new("fourth log".as_bytes()));
193        debug_log.enqueue_read_entry(&TestDebugEntry::new_with_severity(
194            "ERROR: severity takes precedence over msg when not info".as_bytes(),
195            zx::DebugLogSeverity::Warn,
196        ));
197        // Create a string prefixed with multi-byte UTF-8 characters. This entry will be labeled as
198        // Info rather than Error because the string "ERROR:" only appears after the
199        // MAX_STRING_SEARCH_SIZE. It's crucial that we use multi-byte UTF-8 characters because we
200        // want to verify that the search is character oriented rather than byte oriented and that
201        // it can handle the MAX_STRING_SEARCH_SIZE boundary falling in the middle of a multi-byte
202        // character.
203        let long_padding = (0..100).map(|_| "\u{10FF}").collect::<String>();
204        let long_log = format!("{long_padding}ERROR: fifth log");
205        debug_log.enqueue_read_entry(&TestDebugEntry::new(long_log.as_bytes()));
206
207        let log_bridge = DebugLogBridge::create(debug_log);
208        let mut log_stream =
209            Box::pin(log_bridge.listen()).map(|r| r.unwrap().parse(&KERNEL_IDENTITY));
210
211        let log_message = log_stream.try_next().await.unwrap().unwrap();
212        assert_eq!(log_message.msg().unwrap(), "ERROR: first log");
213        assert_eq!(log_message.metadata.severity, Severity::Error);
214
215        let log_message = log_stream.try_next().await.unwrap().unwrap();
216        assert_eq!(log_message.msg().unwrap(), "first log error");
217        assert_eq!(log_message.metadata.severity, Severity::Info);
218
219        let log_message = log_stream.try_next().await.unwrap().unwrap();
220        assert_eq!(log_message.msg().unwrap(), "WARNING: second log");
221        assert_eq!(log_message.metadata.severity, Severity::Warn);
222
223        let log_message = log_stream.try_next().await.unwrap().unwrap();
224        assert_eq!(log_message.msg().unwrap(), "INFO: third log");
225        assert_eq!(log_message.metadata.severity, Severity::Info);
226
227        let log_message = log_stream.try_next().await.unwrap().unwrap();
228        assert_eq!(log_message.msg().unwrap(), "fourth log");
229        assert_eq!(log_message.metadata.severity, Severity::Info);
230
231        let log_message = log_stream.try_next().await.unwrap().unwrap();
232        assert_eq!(
233            log_message.msg().unwrap(),
234            "ERROR: severity takes precedence over msg when not info"
235        );
236        assert_eq!(log_message.metadata.severity, Severity::Warn);
237
238        // TODO(https://fxbug.dev/42154302): Once 74601 is resolved, uncomment the lines below. Prior to 74601
239        // being resolved, the follow case may fail because the line is very long, may be truncated,
240        // and if it is truncated, may no longer be valid UTF8 because the truncation may occur in
241        // the middle of a multi-byte character.
242        //
243        // let log_message = log_stream.try_next().await.unwrap().unwrap();
244        // assert_eq!(log_message.msg().unwrap(), &long_log);
245        // assert_eq!(log_message.metadata.severity, Severity::Info);
246    }
247}
archivist_lib/logs/debuglog.rs

archivist_lib/logs/
debuglog.rs
