1use crate::security;
6use crate::task::dynamic_thread_spawner::SpawnRequestBuilder;
7use crate::task::{CurrentTask, EventHandler, WaitCallback, WaitCanceler, WaitQueue, Waiter};
8use crate::vfs::OutputBuffer;
9use diagnostics_data::{Data, Logs, LogsData, Severity};
10use estimate_timeline::{DefaultFetcher, TimeFetcher, TimelineEstimator};
11use fidl_fuchsia_diagnostics as fdiagnostics;
12use fuchsia_component::client::connect_to_protocol_sync;
13use fuchsia_inspect::Inspector;
14use futures::FutureExt;
15use serde::Deserialize;
16use starnix_sync::{Locked, Mutex, Unlocked};
17use starnix_uapi::auth::CAP_SYSLOG;
18use starnix_uapi::errors::{EAGAIN, Errno, errno, error};
19use starnix_uapi::syslog::SyslogAction;
20use starnix_uapi::vfs::FdEvents;
21use std::cmp;
22use std::collections::VecDeque;
23use std::io::{self, Write};
24use std::sync::atomic::Ordering;
25use std::sync::{Arc, OnceLock, mpsc};
26use zerocopy::{FromBytes, Immutable, IntoBytes, KnownLayout, TryFromBytes};
27
28const BUFFER_SIZE: i32 = 1_049_000;
29
30const NANOS_PER_SECOND: i64 = 1_000_000_000;
31const MICROS_PER_NANOSECOND: i64 = 1_000;
32
33#[derive(Default)]
34pub struct Syslog {
35 syscall_subscription: OnceLock<Mutex<LogSubscription>>,
36 state: Arc<Mutex<TimelineEstimator<DefaultFetcher>>>,
37}
38
39#[derive(Debug)]
40pub enum SyslogAccess {
41 DevKmsgRead,
42 ProcKmsg(SyslogAction),
43 Syscall(SyslogAction),
44}
45
46impl Syslog {
47 pub fn init(&self, system_task: &CurrentTask) -> Result<(), anyhow::Error> {
48 let state = self.state.clone();
49 system_task.kernel.inspect_node.record_lazy_child("syslog", move || {
50 let state = state.clone();
51 async move {
52 let inspector = Inspector::default();
53 let state_guard = state.lock();
54 inspector.root().record_uint("max_timeline_size", state_guard.max_timeline_size());
55 inspector
56 .root()
57 .record_uint("timeline_overflows", state_guard.timeline_overflows());
58 Ok(inspector)
59 }
60 .boxed()
61 });
62
63 let subscription = LogSubscription::snapshot_then_subscribe(system_task)?;
64 self.syscall_subscription.set(Mutex::new(subscription)).expect("syslog inititialized once");
65 Ok(())
66 }
67
68 pub fn access(
69 &self,
70 current_task: &CurrentTask,
71 access: SyslogAccess,
72 ) -> Result<GrantedSyslog<'_>, Errno> {
73 Self::validate_access(current_task, access)?;
74 let syscall_subscription = self.subscription()?;
75 Ok(GrantedSyslog { syscall_subscription })
76 }
77
78 pub fn validate_access(current_task: &CurrentTask, access: SyslogAccess) -> Result<(), Errno> {
81 let (action, check_capabilities) = match access {
82 SyslogAccess::ProcKmsg(SyslogAction::Open) => (SyslogAction::Open, true),
83 SyslogAccess::DevKmsgRead => (SyslogAction::ReadAll, true),
84 SyslogAccess::Syscall(a) => (a, true),
85 SyslogAccess::ProcKmsg(a) => (a, false),
87 };
88
89 let action_is_privileged = !matches!(
92 access,
93 SyslogAccess::Syscall(SyslogAction::ReadAll | SyslogAction::SizeBuffer)
94 | SyslogAccess::DevKmsgRead,
95 );
96 let restrict_dmesg = current_task.kernel().restrict_dmesg.load(Ordering::Relaxed);
97 if check_capabilities && (action_is_privileged || restrict_dmesg) {
98 security::check_task_capable(current_task, CAP_SYSLOG)?;
99 }
100
101 security::check_syslog_access(current_task, action)?;
102 Ok(())
103 }
104
105 pub fn snapshot_then_subscribe(current_task: &CurrentTask) -> Result<LogSubscription, Errno> {
106 LogSubscription::snapshot_then_subscribe(current_task)
107 }
108
109 pub fn subscribe(current_task: &CurrentTask) -> Result<LogSubscription, Errno> {
110 LogSubscription::subscribe(current_task)
111 }
112
113 fn subscription(&self) -> Result<&Mutex<LogSubscription>, Errno> {
114 self.syscall_subscription.get().ok_or_else(|| errno!(ENOENT))
115 }
116}
117
118pub struct GrantedSyslog<'a> {
119 syscall_subscription: &'a Mutex<LogSubscription>,
120}
121
122impl GrantedSyslog<'_> {
123 pub fn read(&self, out: &mut dyn OutputBuffer) -> Result<i32, Errno> {
124 let mut subscription = self.syscall_subscription.lock();
125 if let Some(log) = subscription.try_next()? {
126 let size_to_write = cmp::min(log.len(), out.available() as usize);
127 out.write(&log[..size_to_write])?;
128 return Ok(size_to_write as i32);
129 }
130 Ok(0)
131 }
132
133 pub fn wait(&self, waiter: &Waiter, events: FdEvents, handler: EventHandler) -> WaitCanceler {
134 self.syscall_subscription.lock().wait(waiter, events, handler)
135 }
136
137 pub fn blocking_read(
138 &self,
139 locked: &mut Locked<Unlocked>,
140 current_task: &CurrentTask,
141 out: &mut dyn OutputBuffer,
142 ) -> Result<i32, Errno> {
143 let mut subscription = self.syscall_subscription.lock();
144 let mut write_log = |log: Vec<u8>| {
145 let size_to_write = cmp::min(log.len(), out.available() as usize);
146 out.write(&log[..size_to_write])?;
147 Ok(size_to_write as i32)
148 };
149 match subscription.try_next() {
150 Err(errno) if errno == EAGAIN => {}
151 Err(errno) => return Err(errno),
152 Ok(Some(log)) => return write_log(log),
153 Ok(None) => return Ok(0),
154 }
155 let waiter = Waiter::new();
156 loop {
157 let _w = subscription.wait(
158 &waiter,
159 FdEvents::POLLIN | FdEvents::POLLHUP,
160 WaitCallback::none(),
161 );
162 match subscription.try_next() {
163 Err(errno) if errno == EAGAIN => {}
164 Err(errno) => return Err(errno),
165 Ok(Some(log)) => return write_log(log),
166 Ok(None) => return Ok(0),
167 }
168 waiter.wait(locked, current_task)?;
169 }
170 }
171
172 pub fn read_all(
173 &self,
174 current_task: &CurrentTask,
175 out: &mut dyn OutputBuffer,
176 ) -> Result<i32, Errno> {
177 let mut subscription = LogSubscription::snapshot(current_task)?;
178 let mut buffer = ResultBuffer::new(out.available());
179 while let Some(log_result) = subscription.next() {
180 buffer.push(log_result?);
181 }
182 let result: Vec<u8> = buffer.into();
183 out.write(result.as_slice())?;
184 Ok(result.len() as i32)
185 }
186
187 pub fn size_unread(&self) -> Result<i32, Errno> {
188 let mut subscription = self.syscall_subscription.lock();
189 Ok(subscription.available()?.try_into().unwrap_or(std::i32::MAX))
190 }
191
192 pub fn size_buffer(&self) -> Result<i32, Errno> {
193 Ok(BUFFER_SIZE)
195 }
196}
197
198#[derive(Debug)]
199pub struct LogSubscription {
200 pending: Option<Vec<u8>>,
201 receiver: mpsc::Receiver<Result<Vec<u8>, Errno>>,
202 waiters: Arc<WaitQueue>,
203}
204
205#[derive(Debug, Deserialize)]
206#[serde(untagged)]
207enum OneOrMany<T> {
208 Many(Vec<T>),
209 One(T),
210}
211
212impl LogSubscription {
213 pub fn wait(&self, waiter: &Waiter, events: FdEvents, handler: EventHandler) -> WaitCanceler {
214 self.waiters.wait_async_fd_events(waiter, events, handler)
215 }
216
217 pub fn available(&mut self) -> Result<usize, Errno> {
218 if let Some(log) = &self.pending {
219 return Ok(log.len());
220 }
221 match self.try_next() {
222 Err(err) if err == EAGAIN => Ok(0),
223 Err(err) => Err(err),
224 Ok(Some(log)) => {
225 let size = log.len();
226 self.pending.replace(log);
227 return Ok(size);
228 }
229 Ok(None) => Ok(0),
230 }
231 }
232
233 fn snapshot(current_task: &CurrentTask) -> Result<LogIterator, Errno> {
234 LogIterator::new(¤t_task.kernel.syslog, fdiagnostics::StreamMode::Snapshot)
235 }
236
237 fn subscribe(current_task: &CurrentTask) -> Result<Self, Errno> {
238 Self::new_listening(current_task, fdiagnostics::StreamMode::Subscribe)
239 }
240
241 fn snapshot_then_subscribe(current_task: &CurrentTask) -> Result<Self, Errno> {
242 Self::new_listening(current_task, fdiagnostics::StreamMode::SnapshotThenSubscribe)
243 }
244
245 fn new_listening(
246 current_task: &CurrentTask,
247 mode: fdiagnostics::StreamMode,
248 ) -> Result<Self, Errno> {
249 let iterator = LogIterator::new(¤t_task.kernel.syslog, mode)?;
250 let (snd, receiver) = mpsc::sync_channel(1);
251 let waiters = Arc::new(WaitQueue::default());
252 let waiters_clone = waiters.clone();
253 let closure = move |_: &mut Locked<Unlocked>, _: &CurrentTask| {
254 scopeguard::defer! {
255 waiters_clone.notify_fd_events(FdEvents::POLLHUP);
256 };
257 for log in iterator {
258 if snd.send(log).is_err() {
259 break;
260 };
261 waiters_clone.notify_fd_events(FdEvents::POLLIN);
262 }
263 };
264 let req = SpawnRequestBuilder::new()
265 .with_debug_name("syslog-listener")
266 .with_sync_closure(closure)
267 .build();
268 current_task.kernel().kthreads.spawner().spawn_from_request(req);
269
270 Ok(Self { receiver, waiters, pending: Default::default() })
271 }
272
273 fn try_next(&mut self) -> Result<Option<Vec<u8>>, Errno> {
274 if let Some(value) = self.pending.take() {
275 return Ok(Some(value));
276 }
277 match self.receiver.try_recv() {
278 Ok(Ok(log)) => Ok(Some(log)),
280 Ok(Err(err)) => Err(err),
282 Err(mpsc::TryRecvError::Disconnected) => Ok(None),
284 Err(mpsc::TryRecvError::Empty) => error!(EAGAIN),
286 }
287 }
288}
289
290struct LogIterator {
291 iterator: fdiagnostics::BatchIteratorSynchronousProxy,
292 pending_formatted_contents: VecDeque<fdiagnostics::FormattedContent>,
293 pending_datas: VecDeque<Data<Logs>>,
294 state: Arc<Mutex<TimelineEstimator<DefaultFetcher>>>,
295 tags: std::collections::HashMap<u64, diagnostics_message::MonikerWithUrl>,
296}
297
298impl LogIterator {
299 fn new(syslog: &Syslog, mode: fdiagnostics::StreamMode) -> Result<Self, Errno> {
300 let accessor = connect_to_protocol_sync::<fdiagnostics::ArchiveAccessorMarker>()
301 .map_err(|_| errno!(ENOENT, format!("Failed to connecto to ArchiveAccessor")))?;
302 let is_subscribe = matches!(mode, fdiagnostics::StreamMode::Subscribe);
303 let stream_parameters = fdiagnostics::StreamParameters {
304 stream_mode: Some(mode),
305 data_type: Some(fdiagnostics::DataType::Logs),
306 format: Some(fdiagnostics::Format::Fxt),
307 client_selector_configuration: Some(
308 fdiagnostics::ClientSelectorConfiguration::SelectAll(true),
309 ),
310 subscribe_to_manifest: Some(true),
311 ..fdiagnostics::StreamParameters::default()
312 };
313 let (client_end, server_end) =
314 fidl::endpoints::create_endpoints::<fdiagnostics::BatchIteratorMarker>();
315 accessor.stream_diagnostics(&stream_parameters, server_end).map_err(|err| {
316 errno!(EIO, format!("ArchiveAccessor/StreamDiagnostics failed: {err}"))
317 })?;
318 let iterator = fdiagnostics::BatchIteratorSynchronousProxy::new(client_end.into_channel());
319 if is_subscribe {
320 let () = iterator.wait_for_ready(zx::MonotonicInstant::INFINITE).map_err(|err| {
321 errno!(EIO, format!("Failed to wait for BatchIterator being ready: {err}"))
322 })?;
323 }
324 Ok(Self {
325 iterator,
326 pending_formatted_contents: VecDeque::new(),
327 pending_datas: VecDeque::new(),
328 state: syslog.state.clone(),
329 tags: std::collections::HashMap::new(),
330 })
331 }
332
333 fn get_next(&mut self) -> Result<Option<Vec<u8>>, Errno> {
336 'main_loop: loop {
337 while let Some(data) = self.pending_datas.pop_front() {
338 if let Some(log) = format_log(data, &self.state).map_err(|_| errno!(EIO))? {
339 return Ok(Some(log));
340 }
341 }
342 while let Some(formatted_content) = self.pending_formatted_contents.pop_front() {
343 let output: OneOrMany<Data<Logs>> = match formatted_content {
344 fdiagnostics::FormattedContent::Fxt(data) => {
345 let buf = data
346 .read_to_vec(
347 0,
348 data.get_content_size().map_err(|a| {
349 errno!(EIO, format!("Error {a} getting VMO size"))
350 })?,
351 )
352 .map_err(|err| {
353 errno!(EIO, format!("failed to read logs vmo: {err}"))
354 })?;
355 let mut current_slice = buf.as_ref();
356 let mut ret: Option<OneOrMany<LogsData>> = None;
357 loop {
358 let (record, remaining) =
359 diagnostics_log_encoding::parse::parse_record(current_slice)
360 .map_err(|a| errno!(EIO, format!("Error {a} parsing FXT")))?;
361
362 let record_len = current_slice.len() - remaining.len();
363 let record_bytes = ¤t_slice[..record_len];
364
365 let header = diagnostics_log_encoding::Header::read_from_bytes(
366 ¤t_slice[..8],
367 )
368 .map_err(|_| errno!(EIO, "Invalid FXT header"))?;
369 let tag = header.tag();
370 let is_manifest =
371 (tag & diagnostics_log_encoding::LOG_CONTROL_BIT) != 0;
372 let actual_tag = tag & !diagnostics_log_encoding::LOG_CONTROL_BIT;
373
374 if is_manifest {
375 let mut moniker = None;
376 let mut url = None;
377 for arg in &record.arguments {
378 use diagnostics_log_encoding::Value;
379 if arg.name() == "moniker" {
380 if let Value::Text(t) = arg.value() {
381 moniker = Some(diagnostics_data::ExtendedMoniker::parse_str(&t).unwrap_or_else(|_| diagnostics_data::ExtendedMoniker::ComponentInstance(moniker::Moniker::parse_str("unknown").unwrap())));
382 }
383 } else if arg.name() == "url" {
384 if let Value::Text(t) = arg.value() {
385 url = Some(flyweights::FlyStr::new(t));
386 }
387 }
388 }
389 if let (Some(moniker), Some(url)) = (moniker, url) {
390 self.tags.insert(
391 actual_tag as u64,
392 diagnostics_message::MonikerWithUrl { moniker, url },
393 );
394 }
395 } else {
396 let source = self
397 .tags
398 .get(&(actual_tag as u64))
399 .cloned()
400 .unwrap_or_else(|| diagnostics_message::MonikerWithUrl {
401 moniker:
402 diagnostics_data::ExtendedMoniker::ComponentInstance(
403 moniker::Moniker::parse_str("unknown").unwrap(),
404 ),
405 url: flyweights::FlyStr::new("unknown"),
406 });
407
408 let data =
409 diagnostics_message::from_structured(source, record_bytes)
410 .map_err(|a| {
411 errno!(EIO, format!("Error {a} parsing FXT"))
412 })?;
413
414 ret = Some(match ret.take() {
415 Some(OneOrMany::One(one)) => OneOrMany::Many(vec![one, data]),
416 Some(OneOrMany::Many(mut many)) => {
417 many.push(data);
418 OneOrMany::Many(many)
419 }
420 None => OneOrMany::One(data),
421 });
422 }
423
424 if remaining.is_empty() {
425 break;
426 }
427 current_slice = remaining;
428 }
429 ret.unwrap_or_else(|| OneOrMany::Many(vec![]))
430 }
431 format => {
432 unreachable!("we only request and expect one format. Got: {format:?}")
433 }
434 };
435 match output {
436 OneOrMany::One(data) => {
437 if let Some(log) = format_log(data, &self.state).map_err(|_| errno!(EIO))? {
438 return Ok(Some(log));
439 }
440 }
441 OneOrMany::Many(datas) => {
442 if datas.len() > 0 {
443 self.pending_datas.extend(datas);
444 continue 'main_loop;
445 }
446 }
447 }
448 }
449 let next_batch = self
450 .iterator
451 .get_next(zx::MonotonicInstant::INFINITE)
452 .map_err(|_| errno!(ENOENT))?
453 .map_err(|_| errno!(ENOENT))?;
454 if next_batch.is_empty() {
455 return Ok(None);
456 }
457 self.pending_formatted_contents = VecDeque::from(next_batch);
458 }
459 }
460}
461
462impl Iterator for LogIterator {
463 type Item = Result<Vec<u8>, Errno>;
464
465 fn next(&mut self) -> Option<Result<Vec<u8>, Errno>> {
466 self.get_next().transpose()
467 }
468}
469
470impl Iterator for LogSubscription {
471 type Item = Result<Vec<u8>, Errno>;
472
473 fn next(&mut self) -> Option<Self::Item> {
474 self.try_next().transpose()
475 }
476}
477
478struct ResultBuffer {
479 max_size: usize,
480 buffer: VecDeque<Vec<u8>>,
481 current_size: usize,
482}
483
484impl ResultBuffer {
485 fn new(max_size: usize) -> Self {
486 Self { max_size, buffer: VecDeque::default(), current_size: 0 }
487 }
488
489 fn push(&mut self, data: Vec<u8>) {
490 while !self.buffer.is_empty() && self.current_size + data.len() > self.max_size {
491 let old = self.buffer.pop_front().unwrap();
492 self.current_size -= old.len();
493 }
494 self.current_size += data.len();
495 self.buffer.push_back(data);
496 }
497}
498
499impl Into<Vec<u8>> for ResultBuffer {
500 fn into(self) -> Vec<u8> {
501 let mut result = Vec::with_capacity(self.current_size);
502 for mut item in self.buffer {
503 result.append(&mut item);
504 }
505 let size = std::cmp::min(result.len(), std::cmp::min(self.max_size, self.current_size));
508 if result.len() != size {
509 result.resize(size, 0);
510 }
511 result
512 }
513}
514
515#[derive(Debug, Eq, PartialEq, Copy, Clone, KnownLayout, TryFromBytes, Immutable, IntoBytes)]
516#[repr(u8)]
517pub enum KmsgLevel {
518 Emergency = 0,
519 Alert = 1,
520 Critical = 2,
521 Error = 3,
522 Warning = 4,
523 Notice = 5,
524 Info = 6,
525 Debug = 7,
526}
527
528impl KmsgLevel {
529 fn from_raw(value: u8) -> Option<KmsgLevel> {
530 zerocopy::try_transmute!(value).ok()
531 }
532}
533
534pub(crate) fn extract_level(msg: &[u8]) -> Option<(KmsgLevel, &[u8])> {
541 let mut bytes_iter = msg.iter();
542 let Some(c) = bytes_iter.next() else {
543 return None;
544 };
545 if *c != b'<' {
546 return None;
547 }
548 let Some(end) = bytes_iter.enumerate().find(|(_, c)| **c == b'>').map(|(i, _)| i + 1) else {
549 return None;
550 };
551 std::str::from_utf8(&msg[1..end])
552 .ok()
553 .and_then(|s| s.parse::<u64>().ok())
554 .map(|level| (level & 0x07) as u8)
555 .and_then(KmsgLevel::from_raw)
556 .map(|level| (level, &msg[end + 1..]))
557}
558
559fn format_log<T: TimeFetcher>(
560 data: Data<Logs>,
561 state: &Arc<Mutex<TimelineEstimator<T>>>,
562) -> Result<Option<Vec<u8>>, io::Error> {
563 let mut formatted_tags = match data.tags() {
564 None => vec![],
565 Some(tags) => {
566 let mut formatted = vec![];
567 for (i, tag) in tags.iter().enumerate() {
568 if tag.contains("fxlogcat") {
570 return Ok(None);
571 }
572 if i != 0 {
573 write!(&mut formatted, ",")?;
574 }
575 write!(&mut formatted, "{tag}")?;
576 }
577 write!(&mut formatted, ": ")?;
578 formatted
579 }
580 };
581
582 let mut result = Vec::<u8>::new();
583 let (level, msg_after_level) = match data.msg().and_then(|msg| extract_level(msg.as_bytes())) {
584 Some((level, remaining_msg)) => (level as u8, Some(remaining_msg)),
585 None => match data.severity() {
586 Severity::Trace | Severity::Debug => (KmsgLevel::Debug as u8, None),
587 Severity::Info => (KmsgLevel::Info as u8, None),
588 Severity::Warn => (KmsgLevel::Warning as u8, None),
589 Severity::Error => (KmsgLevel::Error as u8, None),
590 Severity::Fatal => (KmsgLevel::Critical as u8, None),
591 },
592 };
593
594 let time = state.lock().boot_time_to_monotonic_time(data.metadata.timestamp);
599 let time_nanos = time.into_nanos();
600 let time_secs = time_nanos / NANOS_PER_SECOND;
601 let time_fract = (time_nanos % NANOS_PER_SECOND) / MICROS_PER_NANOSECOND;
603 let component_name = data.component_name();
604 write!(&mut result, "<{level}>[{time_secs:05}.{time_fract:06}] {component_name}",)?;
605
606 match data.metadata.pid {
607 Some(pid) => write!(&mut result, "[{pid}]: ")?,
608 None => write!(&mut result, ": ")?,
609 }
610
611 result.append(&mut formatted_tags);
612
613 if let Some(msg) = msg_after_level {
614 write!(&mut result, "{}", String::from_utf8_lossy(msg))?;
615 } else if let Some(msg) = data.msg() {
616 write!(&mut result, "{msg}")?;
617 }
618
619 for kvp in data.payload_keys_strings() {
620 write!(&mut result, " {kvp}")?;
621 }
622 write!(&mut result, "\n")?;
623 Ok(Some(result))
624}
625
626#[cfg(test)]
627mod tests {
628 use super::*;
629
630 #[test]
631 fn test_result_buffer() {
632 let mut buffer = ResultBuffer::new(100);
633 buffer.push(vec![0; 200]);
634 let result: Vec<u8> = buffer.into();
635 assert_eq!(result.len(), 100);
636
637 let mut buffer = ResultBuffer::new(100);
638 buffer.push(Vec::from_iter(0..20));
639 buffer.push(Vec::from_iter(20..50));
640 let result: Vec<u8> = buffer.into();
641 assert_eq!(result.len(), 50);
642 for i in 0..50u8 {
643 assert_eq!(result[i as usize], i);
644 }
645 }
646
647 #[test]
648 fn test_extract_level() {
649 for level in 0..8 {
650 let msg = format!("<{level}> some message");
651 let result = extract_level(msg.as_bytes()).map(|(x, i)| (x as u8, i));
652 assert_eq!(Some((level, " some message".as_bytes())), result);
653 }
654 }
655
656 #[test]
657 fn parse_message_accepts_levels_greater_than_7() {
658 assert_eq!(
659 Some((KmsgLevel::Warning, " message".as_bytes())),
660 extract_level("<100> message".as_bytes())
661 );
662 }
663
664 #[test]
665 fn parse_message_defaults_when_non_numbers() {
666 assert_eq!(None, extract_level("<a> some message".as_bytes()));
667 }
668
669 #[test]
670 fn parse_message_defaults_when_invalid_level_syntax() {
671 assert_eq!(None, extract_level("<1 some message".as_bytes()));
672 }
673
674 #[test]
675 fn parse_message_defaults_when_no_level() {
676 assert_eq!(None, extract_level("some message".as_bytes()));
677 }
678}