Merge pull request #585 from probulate/tag-len-value

aya-log-common: support logging byte slices
pull/608/head
Alessandro Decina 2 years ago committed by GitHub
commit 5165bf2f99
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23

@ -32,7 +32,7 @@ jobs:
- uses: taiki-e/install-action@cargo-hack - uses: taiki-e/install-action@cargo-hack
- name: Check - name: Check
run: cargo hack check --feature-powerset --ignore-private run: cargo hack check --all-targets --feature-powerset --ignore-private
- uses: Swatinem/rust-cache@v1 - uses: Swatinem/rust-cache@v1
- name: Prereqs - name: Prereqs

@ -1,6 +1,6 @@
#![no_std] #![no_std]
use core::{cmp, mem, ptr, slice}; use core::{mem, num, ptr};
use num_enum::IntoPrimitive; use num_enum::IntoPrimitive;
@ -8,8 +8,10 @@ pub const LOG_BUF_CAPACITY: usize = 8192;
pub const LOG_FIELDS: usize = 6; pub const LOG_FIELDS: usize = 6;
#[repr(usize)] pub type LogValueLength = u16;
#[derive(Copy, Clone, Eq, PartialEq, Debug, Hash)]
#[repr(u8)]
#[derive(Copy, Clone, Eq, PartialEq, Debug, Hash, IntoPrimitive)]
pub enum Level { pub enum Level {
/// The "error" level. /// The "error" level.
/// ///
@ -33,7 +35,7 @@ pub enum Level {
Trace, Trace,
} }
#[repr(usize)] #[repr(u8)]
#[derive(Copy, Clone, Debug)] #[derive(Copy, Clone, Debug)]
pub enum RecordField { pub enum RecordField {
Target = 1, Target = 1,
@ -46,7 +48,7 @@ pub enum RecordField {
/// Types which are supported by aya-log and can be safely sent from eBPF /// Types which are supported by aya-log and can be safely sent from eBPF
/// programs to userspace. /// programs to userspace.
#[repr(usize)] #[repr(u8)]
#[derive(Copy, Clone, Debug)] #[derive(Copy, Clone, Debug)]
pub enum Argument { pub enum Argument {
DisplayHint, DisplayHint,
@ -73,6 +75,7 @@ pub enum Argument {
/// `[u16; 8]` array which represents an IPv6 address. /// `[u16; 8]` array which represents an IPv6 address.
ArrU16Len8, ArrU16Len8,
Bytes,
Str, Str,
} }
@ -96,55 +99,65 @@ pub enum DisplayHint {
UpperMac, UpperMac,
} }
struct TagLenValue<'a, T> { struct TagLenValue<T, V> {
tag: T, pub tag: T,
value: &'a [u8], pub value: V,
} }
impl<'a, T> TagLenValue<'a, T> impl<T, V> TagLenValue<T, V>
where where
T: Copy, V: IntoIterator<Item = u8>,
<V as IntoIterator>::IntoIter: ExactSizeIterator,
{ {
#[inline(always)] pub(crate) fn write(self, mut buf: &mut [u8]) -> Result<usize, ()> {
pub(crate) fn new(tag: T, value: &'a [u8]) -> TagLenValue<'a, T> { // Break the abstraction to please the verifier.
TagLenValue { tag, value } if buf.len() > LOG_BUF_CAPACITY {
buf = &mut buf[..LOG_BUF_CAPACITY];
} }
let Self { tag, value } = self;
pub(crate) fn write(&self, mut buf: &mut [u8]) -> Result<usize, ()> { let value = value.into_iter();
let size = mem::size_of::<T>() + mem::size_of::<usize>() + self.value.len(); let len = value.len();
let remaining = cmp::min(buf.len(), LOG_BUF_CAPACITY); let wire_len: LogValueLength = value
// Check if the size doesn't exceed the buffer bounds. .len()
if size > remaining { .try_into()
.map_err(|num::TryFromIntError { .. }| ())?;
let size = mem::size_of_val(&tag) + mem::size_of_val(&wire_len) + len;
if size > buf.len() {
return Err(()); return Err(());
} }
unsafe { ptr::write_unaligned(buf.as_mut_ptr() as *mut _, self.tag) }; let tag_size = mem::size_of_val(&tag);
buf = &mut buf[mem::size_of::<T>()..]; unsafe { ptr::write_unaligned(buf.as_mut_ptr() as *mut _, tag) };
buf = &mut buf[tag_size..];
unsafe { ptr::write_unaligned(buf.as_mut_ptr() as *mut _, self.value.len()) }; unsafe { ptr::write_unaligned(buf.as_mut_ptr() as *mut _, wire_len) };
buf = &mut buf[mem::size_of::<usize>()..]; buf = &mut buf[mem::size_of_val(&wire_len)..];
buf.iter_mut().zip(value).for_each(|(dst, src)| {
*dst = src;
});
let len = cmp::min(buf.len(), self.value.len());
// The verifier isn't happy with `len` being unbounded, so compare it
// with `LOG_BUF_CAPACITY`.
if len > LOG_BUF_CAPACITY {
return Err(());
}
buf[..len].copy_from_slice(&self.value[..len]);
Ok(size) Ok(size)
} }
} }
impl<T, V> TagLenValue<T, V> {
#[inline(always)]
pub(crate) fn new(tag: T, value: V) -> TagLenValue<T, V> {
TagLenValue { tag, value }
}
}
pub trait WriteToBuf { pub trait WriteToBuf {
#[allow(clippy::result_unit_err)] #[allow(clippy::result_unit_err)]
fn write(&self, buf: &mut [u8]) -> Result<usize, ()>; fn write(self, buf: &mut [u8]) -> Result<usize, ()>;
} }
macro_rules! impl_write_to_buf { macro_rules! impl_write_to_buf {
($type:ident, $arg_type:expr) => { ($type:ident, $arg_type:expr) => {
impl WriteToBuf for $type { impl WriteToBuf for $type {
fn write(&self, buf: &mut [u8]) -> Result<usize, ()> { fn write(self, buf: &mut [u8]) -> Result<usize, ()> {
TagLenValue::<Argument>::new($arg_type, &self.to_ne_bytes()).write(buf) TagLenValue::new($arg_type, self.to_ne_bytes()).write(buf)
} }
} }
}; };
@ -166,35 +179,40 @@ impl_write_to_buf!(f32, Argument::F32);
impl_write_to_buf!(f64, Argument::F64); impl_write_to_buf!(f64, Argument::F64);
impl WriteToBuf for [u8; 16] { impl WriteToBuf for [u8; 16] {
fn write(&self, buf: &mut [u8]) -> Result<usize, ()> { fn write(self, buf: &mut [u8]) -> Result<usize, ()> {
TagLenValue::<Argument>::new(Argument::ArrU8Len16, self).write(buf) TagLenValue::new(Argument::ArrU8Len16, self).write(buf)
} }
} }
impl WriteToBuf for [u16; 8] { impl WriteToBuf for [u16; 8] {
fn write(&self, buf: &mut [u8]) -> Result<usize, ()> { fn write(self, buf: &mut [u8]) -> Result<usize, ()> {
let ptr = self.as_ptr().cast::<u8>(); let bytes = unsafe { core::mem::transmute::<_, [u8; 16]>(self) };
let bytes = unsafe { slice::from_raw_parts(ptr, 16) }; TagLenValue::new(Argument::ArrU16Len8, bytes).write(buf)
TagLenValue::<Argument>::new(Argument::ArrU16Len8, bytes).write(buf)
} }
} }
impl WriteToBuf for [u8; 6] { impl WriteToBuf for [u8; 6] {
fn write(&self, buf: &mut [u8]) -> Result<usize, ()> { fn write(self, buf: &mut [u8]) -> Result<usize, ()> {
TagLenValue::<Argument>::new(Argument::ArrU8Len6, self).write(buf) TagLenValue::new(Argument::ArrU8Len6, self).write(buf)
} }
} }
impl WriteToBuf for str { impl WriteToBuf for &[u8] {
fn write(&self, buf: &mut [u8]) -> Result<usize, ()> { fn write(self, buf: &mut [u8]) -> Result<usize, ()> {
TagLenValue::<Argument>::new(Argument::Str, self.as_bytes()).write(buf) TagLenValue::new(Argument::Bytes, self.iter().copied()).write(buf)
}
}
impl WriteToBuf for &str {
fn write(self, buf: &mut [u8]) -> Result<usize, ()> {
TagLenValue::new(Argument::Str, self.as_bytes().iter().copied()).write(buf)
} }
} }
impl WriteToBuf for DisplayHint { impl WriteToBuf for DisplayHint {
fn write(&self, buf: &mut [u8]) -> Result<usize, ()> { fn write(self, buf: &mut [u8]) -> Result<usize, ()> {
let v: u8 = (*self).into(); let v: u8 = self.into();
TagLenValue::<Argument>::new(Argument::DisplayHint, &v.to_ne_bytes()).write(buf) TagLenValue::new(Argument::DisplayHint, v.to_ne_bytes()).write(buf)
} }
} }
@ -210,17 +228,31 @@ pub fn write_record_header(
line: u32, line: u32,
num_args: usize, num_args: usize,
) -> Result<usize, ()> { ) -> Result<usize, ()> {
let level: u8 = level.into();
let mut size = 0; let mut size = 0;
for attr in [ size += TagLenValue::new(RecordField::Target, target.as_bytes().iter().copied())
TagLenValue::<RecordField>::new(RecordField::Target, target.as_bytes()), .write(&mut buf[size..])?;
TagLenValue::<RecordField>::new(RecordField::Level, &(level as usize).to_ne_bytes()), size += TagLenValue::new(RecordField::Level, level.to_ne_bytes()).write(&mut buf[size..])?;
TagLenValue::<RecordField>::new(RecordField::Module, module.as_bytes()), size += TagLenValue::new(RecordField::Module, module.as_bytes().iter().copied())
TagLenValue::<RecordField>::new(RecordField::File, file.as_bytes()), .write(&mut buf[size..])?;
TagLenValue::<RecordField>::new(RecordField::Line, &line.to_ne_bytes()), size += TagLenValue::new(RecordField::File, file.as_bytes().iter().copied())
TagLenValue::<RecordField>::new(RecordField::NumArgs, &num_args.to_ne_bytes()), .write(&mut buf[size..])?;
] { size += TagLenValue::new(RecordField::Line, line.to_ne_bytes()).write(&mut buf[size..])?;
size += attr.write(&mut buf[size..])?; size +=
TagLenValue::new(RecordField::NumArgs, num_args.to_ne_bytes()).write(&mut buf[size..])?;
Ok(size)
} }
Ok(size) #[cfg(test)]
mod test {
use super::*;
fn log_value_length_sufficient() {
assert!(
LOG_BUF_CAPACITY >= LogValueLength::MAX.into(),
"{} < {}",
LOG_BUF_CAPACITY,
LogValueLength::MAX
);
}
} }

@ -151,12 +151,11 @@ pub(crate) fn log(args: LogArgs, level: Option<TokenStream>) -> Result<TokenStre
let record_len = header_len; let record_len = header_len;
if let Ok(record_len) = { if let Ok(record_len) = {
use ::aya_log_ebpf::WriteToBuf;
Ok::<_, ()>(record_len) #( .and_then(|record_len| { Ok::<_, ()>(record_len) #( .and_then(|record_len| {
if record_len >= buf.buf.len() { if record_len >= buf.buf.len() {
return Err(()); return Err(());
} }
{ #values_iter }.write(&mut buf.buf[record_len..]).map(|len| record_len + len) aya_log_ebpf::WriteToBuf::write({ #values_iter }, &mut buf.buf[record_len..]).map(|len| record_len + len)
}) )* }) )*
} { } {
unsafe { ::aya_log_ebpf::AYA_LOGS.output( unsafe { ::aya_log_ebpf::AYA_LOGS.output(

@ -59,9 +59,11 @@ use std::{
const MAP_NAME: &str = "AYA_LOGS"; const MAP_NAME: &str = "AYA_LOGS";
use aya_log_common::{Argument, DisplayHint, RecordField, LOG_BUF_CAPACITY, LOG_FIELDS}; use aya_log_common::{
Argument, DisplayHint, Level, LogValueLength, RecordField, LOG_BUF_CAPACITY, LOG_FIELDS,
};
use bytes::BytesMut; use bytes::BytesMut;
use log::{error, Level, Log, Record}; use log::{error, Log, Record};
use thiserror::Error; use thiserror::Error;
use aya::{ use aya::{
@ -116,9 +118,7 @@ impl BpfLogger {
let log = logger.clone(); let log = logger.clone();
tokio::spawn(async move { tokio::spawn(async move {
let mut buffers = (0..10) let mut buffers = vec![BytesMut::with_capacity(LOG_BUF_CAPACITY); 10];
.map(|_| BytesMut::with_capacity(LOG_BUF_CAPACITY))
.collect::<Vec<_>>();
loop { loop {
let events = buf.read_events(&mut buffers).await.unwrap(); let events = buf.read_events(&mut buffers).await.unwrap();
@ -160,6 +160,20 @@ where
} }
} }
pub struct LowerHexDebugFormatter;
impl<T> Formatter<&[T]> for LowerHexDebugFormatter
where
T: LowerHex,
{
fn format(v: &[T]) -> String {
let mut s = String::new();
for v in v {
let () = core::fmt::write(&mut s, format_args!("{v:x}")).unwrap();
}
s
}
}
pub struct UpperHexFormatter; pub struct UpperHexFormatter;
impl<T> Formatter<T> for UpperHexFormatter impl<T> Formatter<T> for UpperHexFormatter
where where
@ -170,6 +184,20 @@ where
} }
} }
pub struct UpperHexDebugFormatter;
impl<T> Formatter<&[T]> for UpperHexDebugFormatter
where
T: UpperHex,
{
fn format(v: &[T]) -> String {
let mut s = String::new();
for v in v {
let () = core::fmt::write(&mut s, format_args!("{v:X}")).unwrap();
}
s
}
}
pub struct Ipv4Formatter; pub struct Ipv4Formatter;
impl<T> Formatter<T> for Ipv4Formatter impl<T> Formatter<T> for Ipv4Formatter
where where
@ -214,9 +242,19 @@ trait Format {
fn format(&self, last_hint: Option<DisplayHintWrapper>) -> Result<String, ()>; fn format(&self, last_hint: Option<DisplayHintWrapper>) -> Result<String, ()>;
} }
impl Format for &[u8] {
fn format(&self, last_hint: Option<DisplayHintWrapper>) -> Result<String, ()> {
match last_hint.map(|DisplayHintWrapper(dh)| dh) {
Some(DisplayHint::LowerHex) => Ok(LowerHexDebugFormatter::format(self)),
Some(DisplayHint::UpperHex) => Ok(UpperHexDebugFormatter::format(self)),
_ => Err(()),
}
}
}
impl Format for u32 { impl Format for u32 {
fn format(&self, last_hint: Option<DisplayHintWrapper>) -> Result<String, ()> { fn format(&self, last_hint: Option<DisplayHintWrapper>) -> Result<String, ()> {
match last_hint.map(|h| h.0) { match last_hint.map(|DisplayHintWrapper(dh)| dh) {
Some(DisplayHint::Default) => Ok(DefaultFormatter::format(self)), Some(DisplayHint::Default) => Ok(DefaultFormatter::format(self)),
Some(DisplayHint::LowerHex) => Ok(LowerHexFormatter::format(self)), Some(DisplayHint::LowerHex) => Ok(LowerHexFormatter::format(self)),
Some(DisplayHint::UpperHex) => Ok(UpperHexFormatter::format(self)), Some(DisplayHint::UpperHex) => Ok(UpperHexFormatter::format(self)),
@ -231,7 +269,7 @@ impl Format for u32 {
impl Format for [u8; 6] { impl Format for [u8; 6] {
fn format(&self, last_hint: Option<DisplayHintWrapper>) -> Result<String, ()> { fn format(&self, last_hint: Option<DisplayHintWrapper>) -> Result<String, ()> {
match last_hint.map(|h| h.0) { match last_hint.map(|DisplayHintWrapper(dh)| dh) {
Some(DisplayHint::Default) => Err(()), Some(DisplayHint::Default) => Err(()),
Some(DisplayHint::LowerHex) => Err(()), Some(DisplayHint::LowerHex) => Err(()),
Some(DisplayHint::UpperHex) => Err(()), Some(DisplayHint::UpperHex) => Err(()),
@ -246,7 +284,7 @@ impl Format for [u8; 6] {
impl Format for [u8; 16] { impl Format for [u8; 16] {
fn format(&self, last_hint: Option<DisplayHintWrapper>) -> Result<String, ()> { fn format(&self, last_hint: Option<DisplayHintWrapper>) -> Result<String, ()> {
match last_hint.map(|h| h.0) { match last_hint.map(|DisplayHintWrapper(dh)| dh) {
Some(DisplayHint::Default) => Err(()), Some(DisplayHint::Default) => Err(()),
Some(DisplayHint::LowerHex) => Err(()), Some(DisplayHint::LowerHex) => Err(()),
Some(DisplayHint::UpperHex) => Err(()), Some(DisplayHint::UpperHex) => Err(()),
@ -261,7 +299,7 @@ impl Format for [u8; 16] {
impl Format for [u16; 8] { impl Format for [u16; 8] {
fn format(&self, last_hint: Option<DisplayHintWrapper>) -> Result<String, ()> { fn format(&self, last_hint: Option<DisplayHintWrapper>) -> Result<String, ()> {
match last_hint.map(|h| h.0) { match last_hint.map(|DisplayHintWrapper(dh)| dh) {
Some(DisplayHint::Default) => Err(()), Some(DisplayHint::Default) => Err(()),
Some(DisplayHint::LowerHex) => Err(()), Some(DisplayHint::LowerHex) => Err(()),
Some(DisplayHint::UpperHex) => Err(()), Some(DisplayHint::UpperHex) => Err(()),
@ -278,7 +316,7 @@ macro_rules! impl_format {
($type:ident) => { ($type:ident) => {
impl Format for $type { impl Format for $type {
fn format(&self, last_hint: Option<DisplayHintWrapper>) -> Result<String, ()> { fn format(&self, last_hint: Option<DisplayHintWrapper>) -> Result<String, ()> {
match last_hint.map(|h| h.0) { match last_hint.map(|DisplayHintWrapper(dh)| dh) {
Some(DisplayHint::Default) => Ok(DefaultFormatter::format(self)), Some(DisplayHint::Default) => Ok(DefaultFormatter::format(self)),
Some(DisplayHint::LowerHex) => Ok(LowerHexFormatter::format(self)), Some(DisplayHint::LowerHex) => Ok(LowerHexFormatter::format(self)),
Some(DisplayHint::UpperHex) => Ok(UpperHexFormatter::format(self)), Some(DisplayHint::UpperHex) => Ok(UpperHexFormatter::format(self)),
@ -308,7 +346,7 @@ macro_rules! impl_format_float {
($type:ident) => { ($type:ident) => {
impl Format for $type { impl Format for $type {
fn format(&self, last_hint: Option<DisplayHintWrapper>) -> Result<String, ()> { fn format(&self, last_hint: Option<DisplayHintWrapper>) -> Result<String, ()> {
match last_hint.map(|h| h.0) { match last_hint.map(|DisplayHintWrapper(dh)| dh) {
Some(DisplayHint::Default) => Ok(DefaultFormatter::format(self)), Some(DisplayHint::Default) => Ok(DefaultFormatter::format(self)),
Some(DisplayHint::LowerHex) => Err(()), Some(DisplayHint::LowerHex) => Err(()),
Some(DisplayHint::UpperHex) => Err(()), Some(DisplayHint::UpperHex) => Err(()),
@ -360,33 +398,42 @@ pub enum Error {
fn log_buf(mut buf: &[u8], logger: &dyn Log) -> Result<(), ()> { fn log_buf(mut buf: &[u8], logger: &dyn Log) -> Result<(), ()> {
let mut target = None; let mut target = None;
let mut level = Level::Trace; let mut level = None;
let mut module = None; let mut module = None;
let mut file = None; let mut file = None;
let mut line = None; let mut line = None;
let mut num_args = None; let mut num_args = None;
for _ in 0..LOG_FIELDS { for _ in 0..LOG_FIELDS {
let (attr, rest) = unsafe { TagLenValue::<'_, RecordFieldWrapper>::try_read(buf)? }; let (RecordFieldWrapper(tag), value, rest) = try_read(buf)?;
match attr.tag.0 { match tag {
RecordField::Target => { RecordField::Target => {
target = Some(std::str::from_utf8(attr.value).map_err(|_| ())?); target = Some(str::from_utf8(value).map_err(|_| ())?);
} }
RecordField::Level => { RecordField::Level => {
level = unsafe { ptr::read_unaligned(attr.value.as_ptr() as *const _) } level = Some({
let level = unsafe { ptr::read_unaligned(value.as_ptr() as *const _) };
match level {
Level::Error => log::Level::Error,
Level::Warn => log::Level::Warn,
Level::Info => log::Level::Info,
Level::Debug => log::Level::Debug,
Level::Trace => log::Level::Trace,
}
})
} }
RecordField::Module => { RecordField::Module => {
module = Some(std::str::from_utf8(attr.value).map_err(|_| ())?); module = Some(str::from_utf8(value).map_err(|_| ())?);
} }
RecordField::File => { RecordField::File => {
file = Some(std::str::from_utf8(attr.value).map_err(|_| ())?); file = Some(str::from_utf8(value).map_err(|_| ())?);
} }
RecordField::Line => { RecordField::Line => {
line = Some(u32::from_ne_bytes(attr.value.try_into().map_err(|_| ())?)); line = Some(u32::from_ne_bytes(value.try_into().map_err(|_| ())?));
} }
RecordField::NumArgs => { RecordField::NumArgs => {
num_args = Some(usize::from_ne_bytes(attr.value.try_into().map_err(|_| ())?)); num_args = Some(usize::from_ne_bytes(value.try_into().map_err(|_| ())?));
} }
} }
@ -396,101 +443,104 @@ fn log_buf(mut buf: &[u8], logger: &dyn Log) -> Result<(), ()> {
let mut full_log_msg = String::new(); let mut full_log_msg = String::new();
let mut last_hint: Option<DisplayHintWrapper> = None; let mut last_hint: Option<DisplayHintWrapper> = None;
for _ in 0..num_args.ok_or(())? { for _ in 0..num_args.ok_or(())? {
let (attr, rest) = unsafe { TagLenValue::<'_, ArgumentWrapper>::try_read(buf)? }; let (ArgumentWrapper(tag), value, rest) = try_read(buf)?;
match attr.tag.0 { match tag {
Argument::DisplayHint => { Argument::DisplayHint => {
last_hint = Some(unsafe { ptr::read_unaligned(attr.value.as_ptr() as *const _) }); last_hint = Some(unsafe { ptr::read_unaligned(value.as_ptr() as *const _) });
} }
Argument::I8 => { Argument::I8 => {
full_log_msg.push_str( full_log_msg.push_str(
&i8::from_ne_bytes(attr.value.try_into().map_err(|_| ())?) &i8::from_ne_bytes(value.try_into().map_err(|_| ())?)
.format(last_hint.take())?, .format(last_hint.take())?,
); );
} }
Argument::I16 => { Argument::I16 => {
full_log_msg.push_str( full_log_msg.push_str(
&i16::from_ne_bytes(attr.value.try_into().map_err(|_| ())?) &i16::from_ne_bytes(value.try_into().map_err(|_| ())?)
.format(last_hint.take())?, .format(last_hint.take())?,
); );
} }
Argument::I32 => { Argument::I32 => {
full_log_msg.push_str( full_log_msg.push_str(
&i32::from_ne_bytes(attr.value.try_into().map_err(|_| ())?) &i32::from_ne_bytes(value.try_into().map_err(|_| ())?)
.format(last_hint.take())?, .format(last_hint.take())?,
); );
} }
Argument::I64 => { Argument::I64 => {
full_log_msg.push_str( full_log_msg.push_str(
&i64::from_ne_bytes(attr.value.try_into().map_err(|_| ())?) &i64::from_ne_bytes(value.try_into().map_err(|_| ())?)
.format(last_hint.take())?, .format(last_hint.take())?,
); );
} }
Argument::Isize => { Argument::Isize => {
full_log_msg.push_str( full_log_msg.push_str(
&isize::from_ne_bytes(attr.value.try_into().map_err(|_| ())?) &isize::from_ne_bytes(value.try_into().map_err(|_| ())?)
.format(last_hint.take())?, .format(last_hint.take())?,
); );
} }
Argument::U8 => { Argument::U8 => {
full_log_msg.push_str( full_log_msg.push_str(
&u8::from_ne_bytes(attr.value.try_into().map_err(|_| ())?) &u8::from_ne_bytes(value.try_into().map_err(|_| ())?)
.format(last_hint.take())?, .format(last_hint.take())?,
); );
} }
Argument::U16 => { Argument::U16 => {
full_log_msg.push_str( full_log_msg.push_str(
&u16::from_ne_bytes(attr.value.try_into().map_err(|_| ())?) &u16::from_ne_bytes(value.try_into().map_err(|_| ())?)
.format(last_hint.take())?, .format(last_hint.take())?,
); );
} }
Argument::U32 => { Argument::U32 => {
full_log_msg.push_str( full_log_msg.push_str(
&u32::from_ne_bytes(attr.value.try_into().map_err(|_| ())?) &u32::from_ne_bytes(value.try_into().map_err(|_| ())?)
.format(last_hint.take())?, .format(last_hint.take())?,
); );
} }
Argument::U64 => { Argument::U64 => {
full_log_msg.push_str( full_log_msg.push_str(
&u64::from_ne_bytes(attr.value.try_into().map_err(|_| ())?) &u64::from_ne_bytes(value.try_into().map_err(|_| ())?)
.format(last_hint.take())?, .format(last_hint.take())?,
); );
} }
Argument::Usize => { Argument::Usize => {
full_log_msg.push_str( full_log_msg.push_str(
&usize::from_ne_bytes(attr.value.try_into().map_err(|_| ())?) &usize::from_ne_bytes(value.try_into().map_err(|_| ())?)
.format(last_hint.take())?, .format(last_hint.take())?,
); );
} }
Argument::F32 => { Argument::F32 => {
full_log_msg.push_str( full_log_msg.push_str(
&f32::from_ne_bytes(attr.value.try_into().map_err(|_| ())?) &f32::from_ne_bytes(value.try_into().map_err(|_| ())?)
.format(last_hint.take())?, .format(last_hint.take())?,
); );
} }
Argument::F64 => { Argument::F64 => {
full_log_msg.push_str( full_log_msg.push_str(
&f64::from_ne_bytes(attr.value.try_into().map_err(|_| ())?) &f64::from_ne_bytes(value.try_into().map_err(|_| ())?)
.format(last_hint.take())?, .format(last_hint.take())?,
); );
} }
Argument::ArrU8Len6 => { Argument::ArrU8Len6 => {
let value: [u8; 6] = attr.value.try_into().map_err(|_| ())?; let value: [u8; 6] = value.try_into().map_err(|_| ())?;
full_log_msg.push_str(&value.format(last_hint.take())?); full_log_msg.push_str(&value.format(last_hint.take())?);
} }
Argument::ArrU8Len16 => { Argument::ArrU8Len16 => {
let value: [u8; 16] = attr.value.try_into().map_err(|_| ())?; let value: [u8; 16] = value.try_into().map_err(|_| ())?;
full_log_msg.push_str(&value.format(last_hint.take())?); full_log_msg.push_str(&value.format(last_hint.take())?);
} }
Argument::ArrU16Len8 => { Argument::ArrU16Len8 => {
let data: [u8; 16] = attr.value.try_into().map_err(|_| ())?; let data: [u8; 16] = value.try_into().map_err(|_| ())?;
let mut value: [u16; 8] = Default::default(); let mut value: [u16; 8] = Default::default();
for (i, s) in data.chunks_exact(2).enumerate() { for (i, s) in data.chunks_exact(2).enumerate() {
value[i] = ((s[1] as u16) << 8) | s[0] as u16; value[i] = ((s[1] as u16) << 8) | s[0] as u16;
} }
full_log_msg.push_str(&value.format(last_hint.take())?); full_log_msg.push_str(&value.format(last_hint.take())?);
} }
Argument::Str => match str::from_utf8(attr.value) { Argument::Bytes => {
full_log_msg.push_str(&value.format(last_hint.take())?);
}
Argument::Str => match str::from_utf8(value) {
Ok(v) => { Ok(v) => {
full_log_msg.push_str(v); full_log_msg.push_str(v);
} }
@ -505,7 +555,7 @@ fn log_buf(mut buf: &[u8], logger: &dyn Log) -> Result<(), ()> {
&Record::builder() &Record::builder()
.args(format_args!("{full_log_msg}")) .args(format_args!("{full_log_msg}"))
.target(target.ok_or(())?) .target(target.ok_or(())?)
.level(level) .level(level.ok_or(())?)
.module_path(module) .module_path(module)
.file(file) .file(file)
.line(line) .line(line)
@ -515,42 +565,32 @@ fn log_buf(mut buf: &[u8], logger: &dyn Log) -> Result<(), ()> {
Ok(()) Ok(())
} }
struct TagLenValue<'a, T: Pod> { fn try_read<T: Pod>(mut buf: &[u8]) -> Result<(T, &[u8], &[u8]), ()> {
tag: T, if buf.len() < mem::size_of::<T>() + mem::size_of::<LogValueLength>() {
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(()); return Err(());
} }
let tag = ptr::read_unaligned(buf.as_ptr() as *const T); let tag = unsafe { ptr::read_unaligned(buf.as_ptr() as *const T) };
buf = &buf[mem::size_of::<T>()..]; buf = &buf[mem::size_of::<T>()..];
let len = usize::from_ne_bytes(buf[..mem::size_of::<usize>()].try_into().unwrap()); let len =
buf = &buf[mem::size_of::<usize>()..]; LogValueLength::from_ne_bytes(buf[..mem::size_of::<LogValueLength>()].try_into().unwrap());
buf = &buf[mem::size_of::<LogValueLength>()..];
let len: usize = len.into();
if buf.len() < len { if buf.len() < len {
return Err(()); return Err(());
} }
Ok(( let (value, rest) = buf.split_at(len);
TagLenValue { Ok((tag, value, rest))
tag,
value: &buf[..len],
},
&buf[len..],
))
}
} }
#[cfg(test)] #[cfg(test)]
mod test { mod test {
use super::*; use super::*;
use aya_log_common::{write_record_header, WriteToBuf}; use aya_log_common::{write_record_header, WriteToBuf};
use log::logger; use log::{logger, Level};
fn new_log(args: usize) -> Result<(usize, Vec<u8>), ()> { fn new_log(args: usize) -> Result<(usize, Vec<u8>), ()> {
let mut buf = vec![0; 8192]; let mut buf = vec![0; 8192];
@ -569,14 +609,14 @@ mod test {
#[test] #[test]
fn test_str() { fn test_str() {
testing_logger::setup(); testing_logger::setup();
let (len, mut input) = new_log(1).unwrap(); let (mut len, mut input) = new_log(1).unwrap();
"test" len += "test".write(&mut input[len..]).unwrap();
.write(&mut input[len..])
.expect("could not write to the buffer"); _ = len;
let logger = logger(); let logger = logger();
let _ = log_buf(&input, logger); let () = log_buf(&input, logger).unwrap();
testing_logger::validate(|captured_logs| { testing_logger::validate(|captured_logs| {
assert_eq!(captured_logs.len(), 1); assert_eq!(captured_logs.len(), 1);
assert_eq!(captured_logs[0].body, "test"); assert_eq!(captured_logs[0].body, "test");
@ -589,13 +629,13 @@ mod test {
testing_logger::setup(); testing_logger::setup();
let (mut len, mut input) = new_log(2).unwrap(); let (mut len, mut input) = new_log(2).unwrap();
len += "hello " len += "hello ".write(&mut input[len..]).unwrap();
.write(&mut input[len..]) len += "test".write(&mut input[len..]).unwrap();
.expect("could not write to the buffer");
"test".write(&mut input[len..]).unwrap(); _ = len;
let logger = logger(); let logger = logger();
let _ = log_buf(&input, logger); let () = log_buf(&input, logger).unwrap();
testing_logger::validate(|captured_logs| { testing_logger::validate(|captured_logs| {
assert_eq!(captured_logs.len(), 1); assert_eq!(captured_logs.len(), 1);
assert_eq!(captured_logs[0].body, "hello test"); assert_eq!(captured_logs[0].body, "hello test");
@ -603,6 +643,49 @@ mod test {
}); });
} }
#[test]
fn test_bytes() {
testing_logger::setup();
let (mut len, mut input) = new_log(2).unwrap();
len += DisplayHint::LowerHex.write(&mut input[len..]).unwrap();
len += [0xde, 0xad].write(&mut input[len..]).unwrap();
_ = len;
let logger = logger();
let () = log_buf(&input, logger).unwrap();
testing_logger::validate(|captured_logs| {
assert_eq!(captured_logs.len(), 1);
assert_eq!(captured_logs[0].body, "dead");
assert_eq!(captured_logs[0].level, Level::Info);
});
}
#[test]
fn test_bytes_with_args() {
testing_logger::setup();
let (mut len, mut input) = new_log(5).unwrap();
len += DisplayHint::LowerHex.write(&mut input[len..]).unwrap();
len += [0xde, 0xad].write(&mut input[len..]).unwrap();
len += " ".write(&mut input[len..]).unwrap();
len += DisplayHint::UpperHex.write(&mut input[len..]).unwrap();
len += [0xbe, 0xef].write(&mut input[len..]).unwrap();
_ = len;
let logger = logger();
let () = log_buf(&input, logger).unwrap();
testing_logger::validate(|captured_logs| {
assert_eq!(captured_logs.len(), 1);
assert_eq!(captured_logs[0].body, "dead BEEF");
assert_eq!(captured_logs[0].level, Level::Info);
});
}
#[test] #[test]
fn test_display_hint_default() { fn test_display_hint_default() {
testing_logger::setup(); testing_logger::setup();
@ -610,10 +693,12 @@ mod test {
len += "default hint: ".write(&mut input[len..]).unwrap(); len += "default hint: ".write(&mut input[len..]).unwrap();
len += DisplayHint::Default.write(&mut input[len..]).unwrap(); len += DisplayHint::Default.write(&mut input[len..]).unwrap();
14.write(&mut input[len..]).unwrap(); len += 14.write(&mut input[len..]).unwrap();
_ = len;
let logger = logger(); let logger = logger();
let _ = log_buf(&input, logger); let () = log_buf(&input, logger).unwrap();
testing_logger::validate(|captured_logs| { testing_logger::validate(|captured_logs| {
assert_eq!(captured_logs.len(), 1); assert_eq!(captured_logs.len(), 1);
assert_eq!(captured_logs[0].body, "default hint: 14"); assert_eq!(captured_logs[0].body, "default hint: 14");
@ -628,10 +713,12 @@ mod test {
len += "lower hex: ".write(&mut input[len..]).unwrap(); len += "lower hex: ".write(&mut input[len..]).unwrap();
len += DisplayHint::LowerHex.write(&mut input[len..]).unwrap(); len += DisplayHint::LowerHex.write(&mut input[len..]).unwrap();
200.write(&mut input[len..]).unwrap(); len += 200.write(&mut input[len..]).unwrap();
_ = len;
let logger = logger(); let logger = logger();
let _ = log_buf(&input, logger); let () = log_buf(&input, logger).unwrap();
testing_logger::validate(|captured_logs| { testing_logger::validate(|captured_logs| {
assert_eq!(captured_logs.len(), 1); assert_eq!(captured_logs.len(), 1);
assert_eq!(captured_logs[0].body, "lower hex: c8"); assert_eq!(captured_logs[0].body, "lower hex: c8");
@ -646,10 +733,12 @@ mod test {
len += "upper hex: ".write(&mut input[len..]).unwrap(); len += "upper hex: ".write(&mut input[len..]).unwrap();
len += DisplayHint::UpperHex.write(&mut input[len..]).unwrap(); len += DisplayHint::UpperHex.write(&mut input[len..]).unwrap();
200.write(&mut input[len..]).unwrap(); len += 200.write(&mut input[len..]).unwrap();
_ = len;
let logger = logger(); let logger = logger();
let _ = log_buf(&input, logger); let () = log_buf(&input, logger).unwrap();
testing_logger::validate(|captured_logs| { testing_logger::validate(|captured_logs| {
assert_eq!(captured_logs.len(), 1); assert_eq!(captured_logs.len(), 1);
assert_eq!(captured_logs[0].body, "upper hex: C8"); assert_eq!(captured_logs[0].body, "upper hex: C8");
@ -665,10 +754,12 @@ mod test {
len += "ipv4: ".write(&mut input[len..]).unwrap(); len += "ipv4: ".write(&mut input[len..]).unwrap();
len += DisplayHint::Ipv4.write(&mut input[len..]).unwrap(); len += DisplayHint::Ipv4.write(&mut input[len..]).unwrap();
// 10.0.0.1 as u32 // 10.0.0.1 as u32
167772161u32.write(&mut input[len..]).unwrap(); len += 167772161u32.write(&mut input[len..]).unwrap();
_ = len;
let logger = logger(); let logger = logger();
let _ = log_buf(&input, logger); let () = log_buf(&input, logger).unwrap();
testing_logger::validate(|captured_logs| { testing_logger::validate(|captured_logs| {
assert_eq!(captured_logs.len(), 1); assert_eq!(captured_logs.len(), 1);
assert_eq!(captured_logs[0].body, "ipv4: 10.0.0.1"); assert_eq!(captured_logs[0].body, "ipv4: 10.0.0.1");
@ -688,10 +779,12 @@ mod test {
0x20, 0x01, 0x0d, 0xb8, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x01, 0x20, 0x01, 0x0d, 0xb8, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x01,
0x00, 0x01, 0x00, 0x01,
]; ];
ipv6_arr.write(&mut input[len..]).unwrap(); len += ipv6_arr.write(&mut input[len..]).unwrap();
_ = len;
let logger = logger(); let logger = logger();
let _ = log_buf(&input, logger); let () = log_buf(&input, logger).unwrap();
testing_logger::validate(|captured_logs| { testing_logger::validate(|captured_logs| {
assert_eq!(captured_logs.len(), 1); assert_eq!(captured_logs.len(), 1);
assert_eq!(captured_logs[0].body, "ipv6: 2001:db8::1:1"); assert_eq!(captured_logs[0].body, "ipv6: 2001:db8::1:1");
@ -710,10 +803,12 @@ mod test {
let ipv6_arr: [u16; 8] = [ let ipv6_arr: [u16; 8] = [
0x2001, 0x0db8, 0x0000, 0x0000, 0x0000, 0x0000, 0x0001, 0x0001, 0x2001, 0x0db8, 0x0000, 0x0000, 0x0000, 0x0000, 0x0001, 0x0001,
]; ];
ipv6_arr.write(&mut input[len..]).unwrap(); len += ipv6_arr.write(&mut input[len..]).unwrap();
_ = len;
let logger = logger(); let logger = logger();
let _ = log_buf(&input, logger); let () = log_buf(&input, logger).unwrap();
testing_logger::validate(|captured_logs| { testing_logger::validate(|captured_logs| {
assert_eq!(captured_logs.len(), 1); assert_eq!(captured_logs.len(), 1);
assert_eq!(captured_logs[0].body, "ipv6: 2001:db8::1:1"); assert_eq!(captured_logs[0].body, "ipv6: 2001:db8::1:1");
@ -730,10 +825,12 @@ mod test {
len += DisplayHint::LowerMac.write(&mut input[len..]).unwrap(); len += DisplayHint::LowerMac.write(&mut input[len..]).unwrap();
// 00:00:5e:00:53:af as byte array // 00:00:5e:00:53:af as byte array
let mac_arr: [u8; 6] = [0x00, 0x00, 0x5e, 0x00, 0x53, 0xaf]; let mac_arr: [u8; 6] = [0x00, 0x00, 0x5e, 0x00, 0x53, 0xaf];
mac_arr.write(&mut input[len..]).unwrap(); len += mac_arr.write(&mut input[len..]).unwrap();
_ = len;
let logger = logger(); let logger = logger();
let _ = log_buf(&input, logger); let () = log_buf(&input, logger).unwrap();
testing_logger::validate(|captured_logs| { testing_logger::validate(|captured_logs| {
assert_eq!(captured_logs.len(), 1); assert_eq!(captured_logs.len(), 1);
assert_eq!(captured_logs[0].body, "mac: 00:00:5e:00:53:af"); assert_eq!(captured_logs[0].body, "mac: 00:00:5e:00:53:af");
@ -750,10 +847,12 @@ mod test {
len += DisplayHint::UpperMac.write(&mut input[len..]).unwrap(); len += DisplayHint::UpperMac.write(&mut input[len..]).unwrap();
// 00:00:5E:00:53:AF as byte array // 00:00:5E:00:53:AF as byte array
let mac_arr: [u8; 6] = [0x00, 0x00, 0x5e, 0x00, 0x53, 0xaf]; let mac_arr: [u8; 6] = [0x00, 0x00, 0x5e, 0x00, 0x53, 0xaf];
mac_arr.write(&mut input[len..]).unwrap(); len += mac_arr.write(&mut input[len..]).unwrap();
_ = len;
let logger = logger(); let logger = logger();
let _ = log_buf(&input, logger); let () = log_buf(&input, logger).unwrap();
testing_logger::validate(|captured_logs| { testing_logger::validate(|captured_logs| {
assert_eq!(captured_logs.len(), 1); assert_eq!(captured_logs.len(), 1);
assert_eq!(captured_logs[0].body, "mac: 00:00:5E:00:53:AF"); assert_eq!(captured_logs[0].body, "mac: 00:00:5E:00:53:AF");

@ -590,8 +590,6 @@ mod test {
assert_eq!(fun.instructions[0].src_reg(), BPF_PSEUDO_MAP_FD as u8); assert_eq!(fun.instructions[0].src_reg(), BPF_PSEUDO_MAP_FD as u8);
assert_eq!(fun.instructions[0].imm, 1); assert_eq!(fun.instructions[0].imm, 1);
mem::forget(map);
} }
#[test] #[test]
@ -651,9 +649,6 @@ mod test {
assert_eq!(fun.instructions[1].src_reg(), BPF_PSEUDO_MAP_FD as u8); assert_eq!(fun.instructions[1].src_reg(), BPF_PSEUDO_MAP_FD as u8);
assert_eq!(fun.instructions[1].imm, 2); assert_eq!(fun.instructions[1].imm, 2);
mem::forget(map_1);
mem::forget(map_2);
} }
#[test] #[test]
@ -690,8 +685,6 @@ mod test {
assert_eq!(fun.instructions[0].src_reg(), BPF_PSEUDO_MAP_FD as u8); assert_eq!(fun.instructions[0].src_reg(), BPF_PSEUDO_MAP_FD as u8);
assert_eq!(fun.instructions[0].imm, 1); assert_eq!(fun.instructions[0].imm, 1);
mem::forget(map);
} }
#[test] #[test]
@ -751,8 +744,5 @@ mod test {
assert_eq!(fun.instructions[1].src_reg(), BPF_PSEUDO_MAP_FD as u8); assert_eq!(fun.instructions[1].src_reg(), BPF_PSEUDO_MAP_FD as u8);
assert_eq!(fun.instructions[1].imm, 2); assert_eq!(fun.instructions[1].imm, 2);
mem::forget(map_1);
mem::forget(map_2);
} }
} }

@ -17,6 +17,8 @@ pub fn test_log(ctx: ProbeContext) {
trace!(&ctx, "mac lc: {:mac}, mac uc: {:MAC}", mac, mac); trace!(&ctx, "mac lc: {:mac}, mac uc: {:MAC}", mac, mac);
let hex = 0x2f; let hex = 0x2f;
warn!(&ctx, "hex lc: {:x}, hex uc: {:X}", hex, hex); warn!(&ctx, "hex lc: {:x}, hex uc: {:X}", hex, hex);
let hex = [0xde, 0xad, 0xbe, 0xef].as_slice();
debug!(&ctx, "hex lc: {:x}, hex uc: {:X}", hex, hex);
} }
#[panic_handler] #[panic_handler]

@ -104,12 +104,12 @@ async fn log() {
// Call the function that the uprobe is attached to, so it starts logging. // Call the function that the uprobe is attached to, so it starts logging.
trigger_ebpf_program(); trigger_ebpf_program();
captured_logs.wait_expected_len(5).await; captured_logs.wait_expected_len(6).await;
let records = captured_logs let records = captured_logs
.lock() .lock()
.expect("Failed to acquire a lock for reading logs"); .expect("Failed to acquire a lock for reading logs");
assert_eq!(records.len(), 5); assert_eq!(records.len(), 6);
assert_eq!(records[0].body, "Hello from eBPF!"); assert_eq!(records[0].body, "Hello from eBPF!");
assert_eq!(records[0].level, Level::Debug); assert_eq!(records[0].level, Level::Debug);
@ -133,4 +133,8 @@ async fn log() {
assert_eq!(records[4].body, "hex lc: 2f, hex uc: 2F"); assert_eq!(records[4].body, "hex lc: 2f, hex uc: 2F");
assert_eq!(records[4].level, Level::Warn); assert_eq!(records[4].level, Level::Warn);
assert_eq!(records[4].target, "log"); assert_eq!(records[4].target, "log");
assert_eq!(records[5].body, "hex lc: deadbeef, hex uc: DEADBEEF");
assert_eq!(records[5].level, Level::Debug);
assert_eq!(records[5].target, "log");
} }

Loading…
Cancel
Save