|
@@ -0,0 +1,381 @@
|
|
|
+//! A logging framework for eBPF programs.
|
|
|
+//!
|
|
|
+//! This is the user space side of the [Aya] logging framework. For the eBPF
|
|
|
+//! side, see the `aya-log-ebpf` crate.
|
|
|
+//!
|
|
|
+//! `aya-log` provides the [BpfLogger] type, which reads log records created by
|
|
|
+//! `aya-log-ebpf` and logs them using the [log] crate. Any logger that
|
|
|
+//! implements the [Log] trait can be used with this crate.
|
|
|
+//!
|
|
|
+//! # Example:
|
|
|
+//!
|
|
|
+//! This example uses the [simplelog] crate to log messages to the terminal.
|
|
|
+//!
|
|
|
+//! ```no_run
|
|
|
+//! # let mut bpf = aya::Bpf::load(&[]).unwrap();
|
|
|
+//! use simplelog::{ColorChoice, ConfigBuilder, LevelFilter, TermLogger, TerminalMode};
|
|
|
+//! use aya_log::BpfLogger;
|
|
|
+//!
|
|
|
+//! // initialize simplelog::TermLogger as the default logger
|
|
|
+//! TermLogger::init(
|
|
|
+//! LevelFilter::Debug,
|
|
|
+//! ConfigBuilder::new()
|
|
|
+//! .set_target_level(LevelFilter::Error)
|
|
|
+//! .set_location_level(LevelFilter::Error)
|
|
|
+//! .build(),
|
|
|
+//! TerminalMode::Mixed,
|
|
|
+//! ColorChoice::Auto,
|
|
|
+//! )
|
|
|
+//! .unwrap();
|
|
|
+//!
|
|
|
+//! // start reading aya-log records and log them using the default logger
|
|
|
+//! BpfLogger::init(&mut bpf).unwrap();
|
|
|
+//! ```
|
|
|
+//!
|
|
|
+//! With the following eBPF code:
|
|
|
+//!
|
|
|
+//! ```ignore
|
|
|
+//! # let ctx = ();
|
|
|
+//! use aya_log_ebpf::{debug, error, info, trace, warn};
|
|
|
+//!
|
|
|
+//! error!(&ctx, "this is an error message 🚨");
|
|
|
+//! warn!(&ctx, "this is a warning message ⚠️");
|
|
|
+//! info!(&ctx, "this is an info message ℹ️");
|
|
|
+//! debug!(&ctx, "this is a debug message ️🐝");
|
|
|
+//! trace!(&ctx, "this is a trace message 🔍");
|
|
|
+//! ```
|
|
|
+//! Outputs:
|
|
|
+//!
|
|
|
+//! ```text
|
|
|
+//! 21:58:55 [ERROR] xxx: [src/main.rs:35] this is an error message 🚨
|
|
|
+//! 21:58:55 [WARN] xxx: [src/main.rs:36] this is a warning message ⚠️
|
|
|
+//! 21:58:55 [INFO] xxx: [src/main.rs:37] this is an info message ℹ️
|
|
|
+//! 21:58:55 [DEBUG] (7) xxx: [src/main.rs:38] this is a debug message ️🐝
|
|
|
+//! 21:58:55 [TRACE] (7) xxx: [src/main.rs:39] this is a trace message 🔍
|
|
|
+//! ```
|
|
|
+//!
|
|
|
+//! [Aya]: https://docs.rs/aya
|
|
|
+//! [simplelog]: https://docs.rs/simplelog
|
|
|
+//! [Log]: https://docs.rs/log/0.4.14/log/trait.Log.html
|
|
|
+//! [log]: https://docs.rs/log
|
|
|
+//!
|
|
|
+use std::{convert::TryInto, io, mem, ptr, str, sync::Arc};
|
|
|
+
|
|
|
+use aya_log_common::{ArgType, RecordField, LOG_BUF_CAPACITY, LOG_FIELDS};
|
|
|
+use bytes::BytesMut;
|
|
|
+use dyn_fmt::AsStrFormatExt;
|
|
|
+use log::{error, Level, Log, Record};
|
|
|
+use thiserror::Error;
|
|
|
+
|
|
|
+use aya::{
|
|
|
+ maps::{
|
|
|
+ perf::{AsyncPerfEventArray, PerfBufferError},
|
|
|
+ MapError,
|
|
|
+ },
|
|
|
+ util::online_cpus,
|
|
|
+ Bpf, Pod,
|
|
|
+};
|
|
|
+
|
|
|
+/// Log messages generated by `aya_log_ebpf` using the [log] crate.
|
|
|
+///
|
|
|
+/// For more details see the [module level documentation](crate).
|
|
|
+pub struct BpfLogger;
|
|
|
+
|
|
|
+impl BpfLogger {
|
|
|
+ /// Starts reading log records created with `aya-log-ebpf` and logs them
|
|
|
+ /// with the default logger. See [log::logger].
|
|
|
+ pub fn init(bpf: &mut Bpf) -> Result<BpfLogger, Error> {
|
|
|
+ BpfLogger::init_with_logger(bpf, DefaultLogger {})
|
|
|
+ }
|
|
|
+
|
|
|
+ /// Starts reading log records created with `aya-log-ebpf` and logs them
|
|
|
+ /// with the given logger.
|
|
|
+ pub fn init_with_logger<T: Log + 'static>(
|
|
|
+ bpf: &mut Bpf,
|
|
|
+ logger: T,
|
|
|
+ ) -> Result<BpfLogger, Error> {
|
|
|
+ let logger = Arc::new(logger);
|
|
|
+ let mut logs: AsyncPerfEventArray<_> = bpf.map_mut("AYA_LOGS")?.try_into()?;
|
|
|
+
|
|
|
+ for cpu_id in online_cpus().map_err(Error::InvalidOnlineCpu)? {
|
|
|
+ let mut buf = logs.open(cpu_id, None)?;
|
|
|
+
|
|
|
+ let log = logger.clone();
|
|
|
+ tokio::spawn(async move {
|
|
|
+ let mut buffers = (0..10)
|
|
|
+ .map(|_| BytesMut::with_capacity(LOG_BUF_CAPACITY))
|
|
|
+ .collect::<Vec<_>>();
|
|
|
+
|
|
|
+ loop {
|
|
|
+ let events = buf.read_events(&mut buffers).await.unwrap();
|
|
|
+
|
|
|
+ #[allow(clippy::needless_range_loop)]
|
|
|
+ for i in 0..events.read {
|
|
|
+ let buf = &mut buffers[i];
|
|
|
+ log_buf(buf, &*log).unwrap();
|
|
|
+ }
|
|
|
+ }
|
|
|
+ });
|
|
|
+ }
|
|
|
+
|
|
|
+ Ok(BpfLogger {})
|
|
|
+ }
|
|
|
+}
|
|
|
+
|
|
|
+#[derive(Copy, Clone, Debug)]
|
|
|
+struct DefaultLogger;
|
|
|
+
|
|
|
+impl Log for DefaultLogger {
|
|
|
+ fn enabled(&self, metadata: &log::Metadata) -> bool {
|
|
|
+ log::logger().enabled(metadata)
|
|
|
+ }
|
|
|
+
|
|
|
+ fn log(&self, record: &Record) {
|
|
|
+ log::logger().log(record)
|
|
|
+ }
|
|
|
+
|
|
|
+ fn flush(&self) {
|
|
|
+ log::logger().flush()
|
|
|
+ }
|
|
|
+}
|
|
|
+
|
|
|
+#[derive(Error, Debug)]
|
|
|
+pub enum Error {
|
|
|
+ #[error("error opening log event array")]
|
|
|
+ MapError(#[from] MapError),
|
|
|
+
|
|
|
+ #[error("error opening log buffer")]
|
|
|
+ PerfBufferError(#[from] PerfBufferError),
|
|
|
+
|
|
|
+ #[error("invalid /sys/devices/system/cpu/online format")]
|
|
|
+ InvalidOnlineCpu(#[source] io::Error),
|
|
|
+}
|
|
|
+
|
|
|
+fn log_buf(mut buf: &[u8], logger: &dyn Log) -> Result<(), ()> {
|
|
|
+ let mut target = None;
|
|
|
+ let mut level = Level::Trace;
|
|
|
+ let mut module = None;
|
|
|
+ let mut file = None;
|
|
|
+ let mut line = None;
|
|
|
+ let mut log = None;
|
|
|
+ let mut num_args = None;
|
|
|
+
|
|
|
+ for _ in 0..LOG_FIELDS {
|
|
|
+ let (attr, rest) = unsafe { TagLenValue::<'_, RecordField>::try_read(buf)? };
|
|
|
+
|
|
|
+ match attr.tag {
|
|
|
+ RecordField::Target => {
|
|
|
+ target = Some(std::str::from_utf8(attr.value).map_err(|_| ())?);
|
|
|
+ }
|
|
|
+ RecordField::Level => {
|
|
|
+ level = unsafe { ptr::read_unaligned(attr.value.as_ptr() as *const _) }
|
|
|
+ }
|
|
|
+ RecordField::Module => {
|
|
|
+ module = Some(std::str::from_utf8(attr.value).map_err(|_| ())?);
|
|
|
+ }
|
|
|
+ RecordField::File => {
|
|
|
+ file = Some(std::str::from_utf8(attr.value).map_err(|_| ())?);
|
|
|
+ }
|
|
|
+ RecordField::Line => {
|
|
|
+ line = Some(u32::from_ne_bytes(attr.value.try_into().map_err(|_| ())?));
|
|
|
+ }
|
|
|
+ RecordField::NumArgs => {
|
|
|
+ num_args = Some(usize::from_ne_bytes(attr.value.try_into().map_err(|_| ())?));
|
|
|
+ }
|
|
|
+ RecordField::Log => {
|
|
|
+ log = Some(std::str::from_utf8(attr.value).map_err(|_| ())?);
|
|
|
+ }
|
|
|
+ }
|
|
|
+
|
|
|
+ buf = rest;
|
|
|
+ }
|
|
|
+
|
|
|
+ let log_msg = log.ok_or(())?;
|
|
|
+ let full_log_msg = match num_args {
|
|
|
+ Some(n) => {
|
|
|
+ let mut args: Vec<String> = Vec::new();
|
|
|
+ for _ in 0..n {
|
|
|
+ let (attr, rest) = unsafe { TagLenValue::<'_, ArgType>::try_read(buf)? };
|
|
|
+
|
|
|
+ match attr.tag {
|
|
|
+ ArgType::I8 => {
|
|
|
+ args.push(
|
|
|
+ i8::from_ne_bytes(attr.value.try_into().map_err(|_| ())?).to_string(),
|
|
|
+ );
|
|
|
+ }
|
|
|
+ ArgType::I16 => {
|
|
|
+ args.push(
|
|
|
+ i16::from_ne_bytes(attr.value.try_into().map_err(|_| ())?).to_string(),
|
|
|
+ );
|
|
|
+ }
|
|
|
+ ArgType::I32 => {
|
|
|
+ args.push(
|
|
|
+ i32::from_ne_bytes(attr.value.try_into().map_err(|_| ())?).to_string(),
|
|
|
+ );
|
|
|
+ }
|
|
|
+ ArgType::I64 => {
|
|
|
+ args.push(
|
|
|
+ i64::from_ne_bytes(attr.value.try_into().map_err(|_| ())?).to_string(),
|
|
|
+ );
|
|
|
+ }
|
|
|
+ ArgType::I128 => {
|
|
|
+ args.push(
|
|
|
+ i128::from_ne_bytes(attr.value.try_into().map_err(|_| ())?).to_string(),
|
|
|
+ );
|
|
|
+ }
|
|
|
+ ArgType::Isize => {
|
|
|
+ args.push(
|
|
|
+ isize::from_ne_bytes(attr.value.try_into().map_err(|_| ())?)
|
|
|
+ .to_string(),
|
|
|
+ );
|
|
|
+ }
|
|
|
+ ArgType::U8 => {
|
|
|
+ args.push(
|
|
|
+ u8::from_ne_bytes(attr.value.try_into().map_err(|_| ())?).to_string(),
|
|
|
+ );
|
|
|
+ }
|
|
|
+ ArgType::U16 => {
|
|
|
+ args.push(
|
|
|
+ u16::from_ne_bytes(attr.value.try_into().map_err(|_| ())?).to_string(),
|
|
|
+ );
|
|
|
+ }
|
|
|
+ ArgType::U32 => {
|
|
|
+ args.push(
|
|
|
+ u32::from_ne_bytes(attr.value.try_into().map_err(|_| ())?).to_string(),
|
|
|
+ );
|
|
|
+ }
|
|
|
+ ArgType::U64 => {
|
|
|
+ args.push(
|
|
|
+ u64::from_ne_bytes(attr.value.try_into().map_err(|_| ())?).to_string(),
|
|
|
+ );
|
|
|
+ }
|
|
|
+ ArgType::U128 => {
|
|
|
+ args.push(
|
|
|
+ u128::from_ne_bytes(attr.value.try_into().map_err(|_| ())?).to_string(),
|
|
|
+ );
|
|
|
+ }
|
|
|
+ ArgType::Usize => {
|
|
|
+ args.push(
|
|
|
+ usize::from_ne_bytes(attr.value.try_into().map_err(|_| ())?)
|
|
|
+ .to_string(),
|
|
|
+ );
|
|
|
+ }
|
|
|
+ ArgType::F32 => {
|
|
|
+ args.push(
|
|
|
+ f32::from_ne_bytes(attr.value.try_into().map_err(|_| ())?).to_string(),
|
|
|
+ );
|
|
|
+ }
|
|
|
+ ArgType::F64 => {
|
|
|
+ args.push(
|
|
|
+ f64::from_ne_bytes(attr.value.try_into().map_err(|_| ())?).to_string(),
|
|
|
+ );
|
|
|
+ }
|
|
|
+ ArgType::Str => match str::from_utf8(attr.value) {
|
|
|
+ Ok(v) => args.push(v.to_string()),
|
|
|
+ Err(e) => error!("received invalid utf8 string: {}", e),
|
|
|
+ },
|
|
|
+ }
|
|
|
+
|
|
|
+ buf = rest;
|
|
|
+ }
|
|
|
+
|
|
|
+ log_msg.format(&args)
|
|
|
+ }
|
|
|
+ None => log_msg.to_string(),
|
|
|
+ };
|
|
|
+
|
|
|
+ logger.log(
|
|
|
+ &Record::builder()
|
|
|
+ .args(format_args!("{}", full_log_msg))
|
|
|
+ .target(target.ok_or(())?)
|
|
|
+ .level(level)
|
|
|
+ .module_path(module)
|
|
|
+ .file(file)
|
|
|
+ .line(line)
|
|
|
+ .build(),
|
|
|
+ );
|
|
|
+ logger.flush();
|
|
|
+ Ok(())
|
|
|
+}
|
|
|
+
|
|
|
+struct TagLenValue<'a, T: Pod> {
|
|
|
+ tag: T,
|
|
|
+ value: &'a [u8],
|
|
|
+}
|
|
|
+
|
|
|
+impl<'a, T: Pod> TagLenValue<'a, T> {
|
|
|
+ unsafe fn try_read(mut buf: &'a [u8]) -> Result<(TagLenValue<'a, T>, &'a [u8]), ()> {
|
|
|
+ if buf.len() < mem::size_of::<T>() + mem::size_of::<usize>() {
|
|
|
+ return Err(());
|
|
|
+ }
|
|
|
+
|
|
|
+ let tag = ptr::read_unaligned(buf.as_ptr() as *const T);
|
|
|
+ buf = &buf[mem::size_of::<T>()..];
|
|
|
+
|
|
|
+ let len = usize::from_ne_bytes(buf[..mem::size_of::<usize>()].try_into().unwrap());
|
|
|
+ buf = &buf[mem::size_of::<usize>()..];
|
|
|
+
|
|
|
+ if buf.len() < len {
|
|
|
+ return Err(());
|
|
|
+ }
|
|
|
+
|
|
|
+ Ok((
|
|
|
+ TagLenValue {
|
|
|
+ tag,
|
|
|
+ value: &buf[..len],
|
|
|
+ },
|
|
|
+ &buf[len..],
|
|
|
+ ))
|
|
|
+ }
|
|
|
+}
|
|
|
+
|
|
|
+#[cfg(test)]
|
|
|
+mod test {
|
|
|
+ use super::*;
|
|
|
+ use aya_log_common::{write_record_header, write_record_message, WriteToBuf};
|
|
|
+ use log::logger;
|
|
|
+ use testing_logger;
|
|
|
+
|
|
|
+ fn new_log(msg: &str, args: usize) -> Result<(usize, Vec<u8>), ()> {
|
|
|
+ let mut buf = vec![0; 8192];
|
|
|
+ let mut len = write_record_header(
|
|
|
+ &mut buf,
|
|
|
+ "test",
|
|
|
+ aya_log_common::Level::Info,
|
|
|
+ "test",
|
|
|
+ "test.rs",
|
|
|
+ 123,
|
|
|
+ args,
|
|
|
+ )?;
|
|
|
+ len += write_record_message(&mut buf[len..], msg)?;
|
|
|
+ Ok((len, buf))
|
|
|
+ }
|
|
|
+
|
|
|
+ #[test]
|
|
|
+ fn test_str() {
|
|
|
+ testing_logger::setup();
|
|
|
+ let (_, input) = new_log("test", 0).unwrap();
|
|
|
+ let logger = logger();
|
|
|
+ let _ = log_buf(&input, logger);
|
|
|
+ testing_logger::validate(|captured_logs| {
|
|
|
+ assert_eq!(captured_logs.len(), 1);
|
|
|
+ assert_eq!(captured_logs[0].body, "test");
|
|
|
+ assert_eq!(captured_logs[0].level, Level::Info);
|
|
|
+ });
|
|
|
+ }
|
|
|
+
|
|
|
+ #[test]
|
|
|
+ fn test_str_with_args() {
|
|
|
+ testing_logger::setup();
|
|
|
+ let (len, mut input) = new_log("hello {}", 1).unwrap();
|
|
|
+ let name = "test";
|
|
|
+ (*name).write(&mut input[len..]).unwrap();
|
|
|
+ let logger = logger();
|
|
|
+ let _ = log_buf(&input, logger);
|
|
|
+ testing_logger::validate(|captured_logs| {
|
|
|
+ assert_eq!(captured_logs.len(), 1);
|
|
|
+ assert_eq!(captured_logs[0].body, "hello test");
|
|
|
+ assert_eq!(captured_logs[0].level, Level::Info);
|
|
|
+ });
|
|
|
+ }
|
|
|
+}
|