zecfoundation
/
zcashd
mirror of https://github.com/ZcashFoundation/zcashd.git
1
0
Fork 0
Code Issues Projects Releases Wiki Activity

Auto merge of #4657 - str4d:tracing-fields, r=str4d 

Add support for logging fields in spans and events

Field values must be pointers to C strings, which in practice means that they
cannot be formatted inline (as the pointer must remain valid across the FFI).
This might be improved by future iterations of the macros.

`LogPrint()` is also moved to the DEBUG level, leaving `LogPrintf()` at INFO.
This commit is contained in:
Homu 2020-08-17 16:23:58 +00:00
parent c2f991db5b 5ca852ba41
commit 940fe0b3be
8 changed files with 253 additions and 23 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

34
contrib/debian/copyright
View File

@ -126,6 +126,15 @@ Files: src/crypto/ctaes/*
Copyright: Copyright (c) 2016 Pieter Wuille
License: Expat
Files: src/rust/include/tracing.h
src/rust/src/tracing_ffi.rs
Copyright: Copyright (c) 2020 Jack Grigg
License: Expat
Files: src/rust/include/tracing/map.h
Copyright: Copyright (c) 2012 William Swanson
License: Expat-with-advertising-clause
Files: src/secp256k1/*
Copyright: Copyright (c) 2013 Pieter Wuille
License: Expat
@ -1237,3 +1246,28 @@ License: GPLv3-or-later-with-Autoconf-exception
Comment:
The "special exception" is extended to the versions of files covered by
this license that are distributed with this software.
License: Expat-with-advertising-clause
Permission is hereby granted, free of charge, to any person
obtaining a copy of this software and associated documentation
files (the "Software"), to deal in the Software without
restriction, including without limitation the rights to use, copy,
modify, merge, publish, distribute, sublicense, and/or sell copies
of the Software, and to permit persons to whom the Software is
furnished to do so, subject to the following conditions:
The above copyright notice and this permission notice shall be
included in all copies or substantial portions of the Software.
THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS BE LIABLE FOR ANY
CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF
CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION
WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
Except as contained in this notice, the names of the authors or
their institutions shall not be used in advertising or otherwise to
promote the sale, use or other dealings in this Software without
prior written authorization from the authors.

23
src/main.cpp
View File

@ -3235,11 +3235,24 @@ void static UpdateTip(CBlockIndex *pindexNew, const CChainParams& chainParams) {
nTimeBestReceived = GetTime();
mempool.AddTransactionsUpdated(1);
LogPrintf("%s: new best=%s height=%d bits=%d log2_work=%.8g tx=%lu date=%s progress=%f cache=%.1fMiB(%utx)\n", __func__,
chainActive.Tip()->GetBlockHash().ToString(), chainActive.Height(), chainActive.Tip()->nBits,
log(chainActive.Tip()->nChainWork.getdouble())/log(2.0), (unsigned long)chainActive.Tip()->nChainTx,
DateTimeStrFormat("%Y-%m-%d %H:%M:%S", chainActive.Tip()->GetBlockTime()),
Checkpoints::GuessVerificationProgress(chainParams.Checkpoints(), chainActive.Tip()), pcoinsTip->DynamicMemoryUsage() * (1.0 / (1<<20)), pcoinsTip->GetCacheSize());
auto hash = tfm::format("%s", chainActive.Tip()->GetBlockHash().ToString());
auto height = tfm::format("%d", chainActive.Height());
auto bits = tfm::format("%d", chainActive.Tip()->nBits);
auto log2_work = tfm::format("%.8g", log(chainActive.Tip()->nChainWork.getdouble())/log(2.0));
auto tx = tfm::format("%lu", (unsigned long)chainActive.Tip()->nChainTx);
auto date = DateTimeStrFormat("%Y-%m-%d %H:%M:%S", chainActive.Tip()->GetBlockTime());
auto progress = tfm::format("%f", Checkpoints::GuessVerificationProgress(chainParams.Checkpoints(), chainActive.Tip()));
auto cache = tfm::format("%.1fMiB(%utx)", pcoinsTip->DynamicMemoryUsage() * (1.0 / (1<<20)), pcoinsTip->GetCacheSize());
TracingInfo("main", "UpdateTip: new best",
"hash", hash.c_str(),
"height", height.c_str(),
"bits", bits.c_str(),
"log2_work", log2_work.c_str(),
"tx", tx.c_str(),
"date", date.c_str(),
"progress", progress.c_str(),
"cache", cache.c_str());
cvBlockChange.notify_all();
}

7
src/net.cpp
View File

@ -2108,7 +2108,12 @@ CNode::CNode(SOCKET hSocketIn, const CAddress& addrIn, const std::string& addrNa
nPingUsecTime = 0;
fPingQueued = false;
nMinPingUsecTime = std::numeric_limits<int64_t>::max();
span = TracingSpan("info", "net", "CNode");
if (fLogIPs) {
span = TracingSpanFields("info", "net", "CNode", "addr", addrName.c_str());
} else {
span = TracingSpan("info", "net", "CNode");
}
auto spanGuard = span.Enter();
{

52
src/rust/include/tracing.h
View File

@ -6,6 +6,7 @@
#define TRACING_INCLUDE_H_
#include "rust/types.h"
#include "tracing/map.h"
#include <stddef.h>
#include <stdint.h>
@ -67,7 +68,10 @@ typedef struct TracingSpanGuard TracingSpanGuard;
/// Creates a span for a callsite.
///
/// The span must be freed when it goes out of scope.
TracingSpanHandle* tracing_span_create(const TracingCallsite* callsite);
TracingSpanHandle* tracing_span_create(
const TracingCallsite* callsite,
const char* const* field_values,
size_t fields_len);
/// Clones the given span.
///
@ -103,6 +107,19 @@ void tracing_log(
// Helper macros
//
#define MAP_PAIR_LIST0(f, x, y, peek, ...) f(x, y) MAP_LIST_NEXT(peek, MAP_PAIR_LIST1)(f, peek, __VA_ARGS__)
#define MAP_PAIR_LIST1(f, x, y, peek, ...) f(x, y) MAP_LIST_NEXT(peek, MAP_PAIR_LIST0)(f, peek, __VA_ARGS__)
/// Applies the function macro `f` to each pair of the remaining parameters and
/// inserts commas between the results.
#define MAP_PAIR_LIST(f, ...) EVAL(MAP_PAIR_LIST1(f, __VA_ARGS__, ()()(), ()()(), ()()(), 0))
#define T_FIELD_NAME(x, y) x
#define T_FIELD_VALUE(x, y) y
#define T_FIELD_NAMES(...) MAP_PAIR_LIST(T_FIELD_NAME, __VA_ARGS__)
#define T_FIELD_VALUES(...) MAP_PAIR_LIST(T_FIELD_VALUE, __VA_ARGS__)
#define T_DOUBLEESCAPE(a) #a
#define T_ESCAPEQUOTE(a) T_DOUBLEESCAPE(a)
@ -202,7 +219,7 @@ public:
Span() : inner(nullptr, tracing_span_free) {}
/// Use the `TracingSpan` macro instead of calling this constructor directly.
Span(const TracingCallsite* callsite) : inner(tracing_span_create(callsite), tracing_span_free) {}
Span(const TracingCallsite* callsite, const char* const* field_values, size_t fields_len) : inner(tracing_span_create(callsite, field_values, fields_len), tracing_span_free) {}
Span(Span& span) : inner(std::move(span.inner)) {}
Span(const Span& span) : inner(tracing_span_clone(span.inner.get()), tracing_span_free) {}
@ -243,9 +260,31 @@ public:
/// strings.
#define TracingSpan(level, target, name) ([&] { \
static constexpr const char* const FIELDS[] = {}; \
const char* T_VALUES[] = {}; \
static TracingCallsite* CALLSITE = \
T_CALLSITE(name, target, level, FIELDS, true); \
return tracing::Span(CALLSITE); \
return tracing::Span( \
CALLSITE, T_VALUES, T_ARRLEN(T_VALUES)); \
}())
/// Expands to a `tracing::Span` object which is used to record a span.
/// The `Span::Enter` method on that object records that the span has been
/// entered, and returns a RAII guard object, which will exit the span when
/// dropped.
///
/// Arguments: (level, target, name, key, value[, key2, value2, ...])
///
/// level, target, name, and all keys MUST be static constants, and MUST be
/// valid UTF-8 strings.
#define TracingSpanFields(level, target, name, ...) ([&] { \
static constexpr const char* const FIELDS[] = \
{T_FIELD_NAMES(__VA_ARGS__)}; \
const char* T_VALUES[] = \
{T_FIELD_VALUES(__VA_ARGS__)}; \
static TracingCallsite* CALLSITE = \
T_CALLSITE(name, target, level, FIELDS, true); \
return tracing::Span( \
CALLSITE, T_VALUES, T_ARRLEN(T_VALUES)); \
}())
#endif
@ -256,11 +295,12 @@ public:
/// Constructs a new event.
///
/// level and target MUST be static constants, and MUST be valid UTF-8 strings.
#define TracingLog(level, target, message) \
#define TracingLog(level, target, ...) \
do { \
static constexpr const char* const FIELDS[] = \
{"message"}; \
const char* T_VALUES[] = {message}; \
{T_FIELD_NAMES("message", __VA_ARGS__)}; \
const char* T_VALUES[] = \
{T_FIELD_VALUES("message", __VA_ARGS__)}; \
static TracingCallsite* CALLSITE = T_CALLSITE( \
"event " __FILE__ ":" T_ESCAPEQUOTE(__LINE__), \
target, level, FIELDS, false); \

70
src/rust/include/tracing/map.h Normal file
View File

@ -0,0 +1,70 @@
/*
* Copyright (C) 2012 William Swanson
*
* Permission is hereby granted, free of charge, to any person
* obtaining a copy of this software and associated documentation
* files (the "Software"), to deal in the Software without
* restriction, including without limitation the rights to use, copy,
* modify, merge, publish, distribute, sublicense, and/or sell copies
* of the Software, and to permit persons to whom the Software is
* furnished to do so, subject to the following conditions:
*
* The above copyright notice and this permission notice shall be
* included in all copies or substantial portions of the Software.
*
* THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
* EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
* MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
* NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS BE LIABLE FOR ANY
* CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF
* CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION
* WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
*
* Except as contained in this notice, the names of the authors or
* their institutions shall not be used in advertising or otherwise to
* promote the sale, use or other dealings in this Software without
* prior written authorization from the authors.
*/
#ifndef MAP_H_INCLUDED
#define MAP_H_INCLUDED
#define EVAL0(...) __VA_ARGS__
#define EVAL1(...) EVAL0(EVAL0(EVAL0(__VA_ARGS__)))
#define EVAL2(...) EVAL1(EVAL1(EVAL1(__VA_ARGS__)))
#define EVAL3(...) EVAL2(EVAL2(EVAL2(__VA_ARGS__)))
#define EVAL4(...) EVAL3(EVAL3(EVAL3(__VA_ARGS__)))
#define EVAL(...) EVAL4(EVAL4(EVAL4(__VA_ARGS__)))
#define MAP_END(...)
#define MAP_OUT
#define MAP_COMMA ,
#define MAP_GET_END2() 0, MAP_END
#define MAP_GET_END1(...) MAP_GET_END2
#define MAP_GET_END(...) MAP_GET_END1
#define MAP_NEXT0(test, next, ...) next MAP_OUT
#define MAP_NEXT1(test, next) MAP_NEXT0(test, next, 0)
#define MAP_NEXT(test, next) MAP_NEXT1(MAP_GET_END test, next)
#define MAP0(f, x, peek, ...) f(x) MAP_NEXT(peek, MAP1)(f, peek, __VA_ARGS__)
#define MAP1(f, x, peek, ...) f(x) MAP_NEXT(peek, MAP0)(f, peek, __VA_ARGS__)
#define MAP_LIST_NEXT1(test, next) MAP_NEXT0(test, MAP_COMMA next, 0)
#define MAP_LIST_NEXT(test, next) MAP_LIST_NEXT1(MAP_GET_END test, next)
#define MAP_LIST0(f, x, peek, ...) f(x) MAP_LIST_NEXT(peek, MAP_LIST1)(f, peek, __VA_ARGS__)
#define MAP_LIST1(f, x, peek, ...) f(x) MAP_LIST_NEXT(peek, MAP_LIST0)(f, peek, __VA_ARGS__)
/**
* Applies the function macro `f` to each of the remaining parameters.
*/
#define MAP(f, ...) EVAL(MAP1(f, __VA_ARGS__, ()()(), ()()(), ()()(), 0))
/**
* Applies the function macro `f` to each of the remaining parameters and
* inserts commas between the results.
*/
#define MAP_LIST(f, ...) EVAL(MAP_LIST1(f, __VA_ARGS__, ()()(), ()()(), ()()(), 0))
#endif

73
src/rust/src/tracing_ffi.rs
View File

@ -295,6 +295,9 @@ pub extern "C" fn tracing_callsite(
}
macro_rules! repeat {
(0, $val:expr) => {
[]
};
(1, $val:expr) => {
[$val]
};
@ -460,14 +463,77 @@ macro_rules! repeat {
}
#[no_mangle]
pub extern "C" fn tracing_span_create(callsite: *const FfiCallsite) -> *mut Span {
pub extern "C" fn tracing_span_create(
callsite: *const FfiCallsite,
field_values: *const *const c_char,
fields_len: usize,
) -> *mut Span {
let callsite = unsafe { &*callsite };
let field_values = unsafe { slice::from_raw_parts(field_values, fields_len) };
let meta = callsite.metadata();
assert!(meta.is_span());
let span = if level_enabled!(*meta.level()) && callsite.is_enabled() {
Span::new(meta, &meta.fields().value_set(&[]))
let mut fi = meta.fields().iter();
let mut vi = field_values
.iter()
.map(|&p| unsafe { CStr::from_ptr(p) })
.map(|cs| cs.to_string_lossy());
use tracing::field::display;
macro_rules! new_span {
($n:tt) => {
Span::new(
meta,
&meta.fields().value_set(&repeat!(
$n,
(
&fi.next().unwrap(),
Some(&display(vi.next().unwrap().as_ref()) as &dyn Value)
)
)),
)
};
}
// https://github.com/tokio-rs/tracing/issues/782 might help improve things here.
match field_values.len() {
0 => new_span!(0),
1 => new_span!(1),
2 => new_span!(2),
3 => new_span!(3),
4 => new_span!(4),
5 => new_span!(5),
6 => new_span!(6),
7 => new_span!(7),
8 => new_span!(8),
9 => new_span!(9),
10 => new_span!(10),
11 => new_span!(11),
12 => new_span!(12),
13 => new_span!(13),
14 => new_span!(14),
15 => new_span!(15),
16 => new_span!(16),
17 => new_span!(17),
18 => new_span!(18),
19 => new_span!(19),
20 => new_span!(20),
21 => new_span!(21),
22 => new_span!(22),
23 => new_span!(23),
24 => new_span!(24),
25 => new_span!(25),
26 => new_span!(26),
27 => new_span!(27),
28 => new_span!(28),
29 => new_span!(29),
30 => new_span!(30),
31 => new_span!(31),
32 => new_span!(32),
_ => unimplemented!(),
}
} else {
Span::none()
};
@ -522,6 +588,7 @@ pub extern "C" fn tracing_log(
.map(|&p| unsafe { CStr::from_ptr(p) })
.map(|cs| cs.to_string_lossy());
use tracing::field::display;
macro_rules! dispatch {
($n:tt) => {
Event::dispatch(
@ -530,7 +597,7 @@ pub extern "C" fn tracing_log(
$n,
(
&fi.next().unwrap(),
Some(&vi.next().unwrap().as_ref() as &dyn Value)
Some(&display(vi.next().unwrap().as_ref()) as &dyn Value)
)
)),
)

4
src/util.cpp
View File

@ -230,10 +230,10 @@ std::string LogConfigFilter()
std::set<std::string> setCategories(categories.begin(), categories.end());
if (setCategories.count(string("")) != 0 || setCategories.count(string("1")) != 0) {
// Turn on the firehose!
filter = "info";
filter = "debug";
} else {
for (auto category : setCategories) {
filter += "," + category + "=info";
filter += "," + category + "=debug";
}
}

13
src/util.h
View File

@ -79,17 +79,18 @@ std::string LogConfigFilter();
/** Return true if log accepts specified category */
bool LogAcceptCategory(const char* category);
#define LogPrintf(...) LogPrint(NULL, __VA_ARGS__)
/** Print to debug.log with level INFO and category "main". */
#define LogPrintf(...) LogPrintInner("info", "main", __VA_ARGS__)
/** Print to debug.log if -debug=category switch is given OR category is NULL. */
#define LogPrint(category, ...) do { \
/** Print to debug.log with level DEBUG. */
#define LogPrint(category, ...) LogPrintInner("debug", category, __VA_ARGS__)
#define LogPrintInner(level, category, ...) do { \
std::string T_MSG = tfm::format(__VA_ARGS__); \
if (!T_MSG.empty() && T_MSG[T_MSG.size()-1] == '\n') { \
T_MSG.erase(T_MSG.size()-1); \
} \
TracingInfo( \
category == NULL ? "main" : category, \
T_MSG.c_str()); \
TracingLog(level, category, T_MSG.c_str()); \
} while(0)
#define LogError(category, ...) ([&]() { \