FFI wrapper around tracing crate

The tracing crate is initialized with an optional log path, and will
either start a background thread for non-blocking log writing, or write
directly to standard output with ANSI encoding.

C preprocessor macros are used to emulate the Rust macros natively
provided by the tracing crate. They handle the creation of static
tracing callsites, and ensure that the correct file and line number
information is used for each logging site.
This commit is contained in:
Jack Grigg 2020-07-11 00:42:26 +12:00
parent e6a52fa9c8
commit e04da74957
5 changed files with 582 additions and 0 deletions

1
Cargo.lock generated
View File

@ -484,6 +484,7 @@ dependencies = [
"rand_core",
"tracing",
"tracing-appender",
"tracing-core",
"tracing-subscriber",
"zcash_history",
"zcash_primitives",

View File

@ -29,6 +29,7 @@ pairing = "0.16"
lazy_static = "1"
rand_core = "0.5.1"
tracing = "0.1"
tracing-core = "0.1"
tracing-appender = "0.1"
zcash_history = "0.2"
zcash_primitives = "0.2"

119
src/rust/include/tracing.h Normal file
View File

@ -0,0 +1,119 @@
// Copyright (c) 2020 Jack Grigg
// Distributed under the MIT software license, see the accompanying
// file COPYING or https://www.opensource.org/licenses/mit-license.php .
#ifndef TRACING_INCLUDE_H_
#define TRACING_INCLUDE_H_
#include <stdint.h>
#ifdef __cplusplus
extern "C" {
#endif
#ifdef WIN32
typedef uint16_t codeunit;
#else
typedef uint8_t codeunit;
#endif
struct TracingHandle;
typedef struct TracingHandle TracingHandle;
/// Initializes the tracing crate, returning a handle for the logging
/// component. The handle must be freed to close the logging component.
///
/// If log_path is NULL, logging is sent to standard output.
TracingHandle* tracing_init(
const codeunit* log_path,
size_t log_path_len,
bool log_timestamps);
/// Frees a tracing handle returned from `tracing_init`;
void tracing_free(TracingHandle* handle);
struct TracingCallsite;
typedef struct TracingCallsite TracingCallsite;
/// Creates a tracing callsite.
///
/// You should usually call the `TracingLog` macro (or one of the helper
/// macros such as `TracingInfo`) instead of calling this directly.
///
/// This MUST ONLY be called to assign a `static void*`, and all string
/// arguments MUST be `static const char*`.
TracingCallsite* tracing_callsite(
const char* name,
const char* target,
const char* level,
const char* file,
uint32_t line,
const char** fields,
size_t fields_len,
bool is_span);
/// Logs a message for a callsite.
///
/// You should usually call the `TracingLog` macro (or one of the helper
/// macros such as `TracingInfo`) instead of calling this directly.
void tracing_log(
const TracingCallsite* callsite,
const char** field_values,
size_t fields_len);
#ifdef __cplusplus
}
#endif
//
// Helper macros
//
#define T_DOUBLEESCAPE(a) #a
#define T_ESCAPEQUOTE(a) T_DOUBLEESCAPE(a)
// Computes the length of the given array. This is COUNT_OF from Chromium.
#define T_ARRLEN(x) ((sizeof(x) / sizeof(0 [x])) / ((size_t)(!(sizeof(x) % sizeof(0 [x])))))
// Constructs a tracing callsite.
//
// name, target, and fields MUST be static constants, and the output of this
// macro MUST be stored as a static void*.
#define T_CALLSITE(name, target, level, fields, is_span) \
tracing_callsite( \
name, \
target, \
level, \
__FILE__, \
__LINE__, \
fields, \
T_ARRLEN(fields), \
is_span)
//
// Events
//
/// Constructs a new event.
#define TracingLog(level, target, message) \
do { \
static const char* NAME = \
"event " __FILE__ ":" T_ESCAPEQUOTE(__LINE__); \
static const char* FIELDS[] = {"message"}; \
const char* T_VALUES[] = {message}; \
static TracingCallsite* CALLSITE = \
T_CALLSITE(NAME, target, level, FIELDS, false); \
tracing_log(CALLSITE, T_VALUES, T_ARRLEN(T_VALUES)); \
} while (0)
/// Constructs an event at the error level.
#define TracingError(...) TracingLog("error", __VA_ARGS__)
/// Constructs an event at the warn level.
#define TracingWarn(...) TracingLog("warn", __VA_ARGS__)
/// Constructs an event at the info level.
#define TracingInfo(...) TracingLog("info", __VA_ARGS__)
/// Constructs an event at the debug level.
#define TracingDebug(...) TracingLog("debug", __VA_ARGS__)
/// Constructs an event at the trace level.
#define TracingTrace(...) TracingLog("trace", __VA_ARGS__)
#endif // TRACING_INCLUDE_H_

View File

@ -67,6 +67,8 @@ use zcash_proofs::{
use zcash_history::{Entry as MMREntry, NodeData as MMRNodeData, Tree as MMRTree};
mod tracing_ffi;
#[cfg(test)]
mod tests;

459
src/rust/src/tracing_ffi.rs Normal file
View File

@ -0,0 +1,459 @@
use libc::c_char;
use std::ffi::CStr;
use std::path::Path;
use std::slice;
use std::str;
use std::sync::atomic::{AtomicUsize, Ordering};
use tracing::{
callsite::{Callsite, Identifier},
field::{FieldSet, Value},
level_enabled,
metadata::Kind,
subscriber::Interest,
Event, Metadata,
};
use tracing_appender::non_blocking::WorkerGuard;
use tracing_core::Once;
#[cfg(not(target_os = "windows"))]
use std::ffi::OsStr;
#[cfg(not(target_os = "windows"))]
use std::os::unix::ffi::OsStrExt;
#[cfg(target_os = "windows")]
use std::ffi::OsString;
#[cfg(target_os = "windows")]
use std::os::windows::ffi::OsStringExt;
pub struct TracingHandle {
_file_guard: Option<WorkerGuard>,
}
#[no_mangle]
pub extern "C" fn tracing_init(
#[cfg(not(target_os = "windows"))] log_path: *const u8,
#[cfg(target_os = "windows")] log_path: *const u16,
log_path_len: usize,
log_timestamps: bool,
) -> *mut TracingHandle {
if log_path.is_null() {
tracing_init_stdout(log_timestamps)
} else {
let log_path = unsafe { slice::from_raw_parts(log_path, log_path_len) };
#[cfg(not(target_os = "windows"))]
let log_path = Path::new(OsStr::from_bytes(log_path));
#[cfg(target_os = "windows")]
let log_path = Path::new(OsString::from_wide(log_path));
tracing_init_file(log_path, log_timestamps)
}
}
fn tracing_init_stdout(log_timestamps: bool) -> *mut TracingHandle {
let builder = tracing_subscriber::fmt().with_ansi(true);
if log_timestamps {
builder.init();
} else {
builder.without_time().init();
}
Box::into_raw(Box::new(TracingHandle { _file_guard: None }))
}
fn tracing_init_file(log_path: &Path, log_timestamps: bool) -> *mut TracingHandle {
let file_appender =
tracing_appender::rolling::never(log_path.parent().unwrap(), log_path.file_name().unwrap());
let (non_blocking, file_guard) = tracing_appender::non_blocking(file_appender);
let builder = tracing_subscriber::fmt()
.with_ansi(false)
.with_writer(non_blocking);
if log_timestamps {
builder.init();
} else {
builder.without_time().init();
}
Box::into_raw(Box::new(TracingHandle {
_file_guard: Some(file_guard),
}))
}
#[no_mangle]
pub extern "C" fn tracing_free(handle: *mut TracingHandle) {
drop(unsafe { Box::from_raw(handle) });
}
pub struct FfiCallsite {
interest: AtomicUsize,
meta: Option<Metadata<'static>>,
registration: Once,
fields: Vec<&'static str>,
}
impl FfiCallsite {
fn new(fields: Vec<&'static str>) -> Self {
FfiCallsite {
interest: AtomicUsize::new(0),
meta: None,
registration: Once::new(),
fields,
}
}
#[inline(always)]
fn is_enabled(&self) -> bool {
let interest = self.interest();
if interest.is_always() {
return true;
}
if interest.is_never() {
return false;
}
tracing::dispatcher::get_default(|current| current.enabled(self.metadata()))
}
#[inline(always)]
pub fn register(&'static self) {
self.registration
.call_once(|| tracing::callsite::register(self));
}
#[inline(always)]
fn interest(&self) -> Interest {
match self.interest.load(Ordering::Relaxed) {
0 => Interest::never(),
2 => Interest::always(),
_ => Interest::sometimes(),
}
}
}
impl Callsite for FfiCallsite {
fn set_interest(&self, interest: Interest) {
let interest = match () {
_ if interest.is_never() => 0,
_ if interest.is_always() => 2,
_ => 1,
};
self.interest.store(interest, Ordering::SeqCst);
}
#[inline(always)]
fn metadata(&self) -> &Metadata<'static> {
self.meta.as_ref().unwrap()
}
}
#[no_mangle]
pub extern "C" fn tracing_callsite(
name: *const c_char,
target: *const c_char,
level: *const c_char,
file: *const c_char,
line: u32,
fields: *const *const c_char,
fields_len: usize,
is_span: bool,
) -> *mut FfiCallsite {
let name = unsafe { CStr::from_ptr(name) }.to_str().unwrap();
let target = unsafe { CStr::from_ptr(target) }.to_str().unwrap();
let level = unsafe { CStr::from_ptr(level) }.to_str().unwrap();
let file = unsafe { CStr::from_ptr(file) }.to_str().unwrap();
let fields = unsafe { slice::from_raw_parts(fields, fields_len) };
let fields = fields
.iter()
.map(|&p| unsafe { CStr::from_ptr(p) })
.map(|cs| cs.to_str())
.collect::<Result<Vec<_>, _>>()
.unwrap();
let level = level.parse().unwrap();
// We immediately convert the new callsite into a pointer to erase lifetime
// information. The caller MUST ensure that the callsite is stored statically.
let site = Box::into_raw(Box::new(FfiCallsite::new(fields)));
let site_ref = unsafe { &*site };
let meta: Metadata<'static> = Metadata::new(
name,
target,
level,
Some(file),
Some(line),
None,
FieldSet::new(&site_ref.fields, Identifier(site_ref)),
if is_span { Kind::SPAN } else { Kind::EVENT },
);
unsafe { &mut *site }.meta = Some(meta);
site_ref.register();
site
}
macro_rules! repeat {
(1, $val:expr) => {
[$val]
};
(2, $val:expr) => {
[$val, $val]
};
(3, $val:expr) => {
[$val, $val, $val]
};
(4, $val:expr) => {
[$val, $val, $val, $val]
};
(5, $val:expr) => {
[$val, $val, $val, $val, $val]
};
(6, $val:expr) => {
[$val, $val, $val, $val, $val, $val]
};
(7, $val:expr) => {
[$val, $val, $val, $val, $val, $val, $val]
};
(8, $val:expr) => {
[$val, $val, $val, $val, $val, $val, $val, $val]
};
(9, $val:expr) => {
[$val, $val, $val, $val, $val, $val, $val, $val, $val]
};
(10, $val:expr) => {
[$val, $val, $val, $val, $val, $val, $val, $val, $val, $val]
};
(11, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
]
};
(12, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
]
};
(13, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
]
};
(14, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
]
};
(15, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val,
]
};
(16, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val,
]
};
(17, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val,
]
};
(18, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val, $val,
]
};
(19, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val, $val, $val,
]
};
(20, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val, $val, $val, $val,
]
};
(21, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val, $val, $val, $val, $val,
]
};
(22, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val, $val, $val, $val, $val, $val,
]
};
(23, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val, $val, $val, $val, $val, $val, $val,
]
};
(24, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
]
};
(25, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
]
};
(26, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
]
};
(27, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
]
};
(28, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
]
};
(29, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val,
]
};
(30, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val,
]
};
(31, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val,
]
};
(32, $val:expr) => {
[
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val, $val,
$val, $val, $val, $val,
]
};
}
#[no_mangle]
pub extern "C" fn tracing_log(
callsite: *const FfiCallsite,
field_values: *const *const c_char,
fields_len: usize,
) {
let callsite = unsafe { &*callsite };
let field_values = unsafe { slice::from_raw_parts(field_values, fields_len) };
let meta = callsite.metadata();
assert!(meta.is_event());
if level_enabled!(*meta.level()) {
if callsite.is_enabled() {
/// Dispatch the event.
///
/// We wrap this in a function so that we can use `?` to collect and raise
/// UTF-8 errors without allocating. We use a function instead of a closure
/// so that we can force it to be inlined.
#[inline(always)]
fn dispatch_event(
meta: &'static Metadata,
field_values: &[*const c_char],
) -> Result<(), str::Utf8Error> {
let mut fi = meta.fields().iter();
let mut vi = field_values
.iter()
.map(|&p| unsafe { CStr::from_ptr(p) })
.map(|cs| cs.to_str());
macro_rules! dispatch {
($n:tt) => {
Event::dispatch(
meta,
&meta.fields().value_set(&repeat!(
$n,
(
&fi.next().unwrap(),
Some(&vi.next().unwrap()? as &dyn Value)
)
)),
)
};
}
// https://github.com/tokio-rs/tracing/issues/782 might help improve things here.
match field_values.len() {
1 => dispatch!(1),
2 => dispatch!(2),
3 => dispatch!(3),
4 => dispatch!(4),
5 => dispatch!(5),
6 => dispatch!(6),
7 => dispatch!(7),
8 => dispatch!(8),
9 => dispatch!(9),
10 => dispatch!(10),
11 => dispatch!(11),
12 => dispatch!(12),
13 => dispatch!(13),
14 => dispatch!(14),
15 => dispatch!(15),
16 => dispatch!(16),
17 => dispatch!(17),
18 => dispatch!(18),
19 => dispatch!(19),
20 => dispatch!(20),
21 => dispatch!(21),
22 => dispatch!(22),
23 => dispatch!(23),
24 => dispatch!(24),
25 => dispatch!(25),
26 => dispatch!(26),
27 => dispatch!(27),
28 => dispatch!(28),
29 => dispatch!(29),
30 => dispatch!(30),
31 => dispatch!(31),
32 => dispatch!(32),
_ => unimplemented!(),
}
Ok(())
}
if let Err(e) = dispatch_event(meta, field_values) {
tracing::error!(
"{}: Field value was not valid UTF-8: {}",
callsite.metadata().name(),
e
);
}
}
}
}