From 4591a4f8327cfd00d452da0063960d9013bb4f78 Mon Sep 17 00:00:00 2001 From: Jack Grigg Date: Fri, 7 Aug 2020 21:17:09 +0100 Subject: [PATCH 1/7] tracing: Add MAP macro Source: https://github.com/swansontec/map-macro License: X11 Also updates contrib/debian/copyright for recent license additions. --- contrib/debian/copyright | 34 +++++++++++++++++ src/rust/include/tracing/map.h | 70 ++++++++++++++++++++++++++++++++++ 2 files changed, 104 insertions(+) create mode 100644 src/rust/include/tracing/map.h diff --git a/contrib/debian/copyright b/contrib/debian/copyright index 39290b6fd..fee8739b6 100644 --- a/contrib/debian/copyright +++ b/contrib/debian/copyright @@ -124,6 +124,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: X11 + Files: src/secp256k1/* Copyright: Copyright (c) 2013 Pieter Wuille License: Expat @@ -1235,3 +1244,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: X11 + 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. diff --git a/src/rust/include/tracing/map.h b/src/rust/include/tracing/map.h new file mode 100644 index 000000000..acd5018e3 --- /dev/null +++ b/src/rust/include/tracing/map.h @@ -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 From 31ba572811f698a1951c15c3630043318a98dae3 Mon Sep 17 00:00:00 2001 From: Jack Grigg Date: Fri, 7 Aug 2020 21:17:09 +0100 Subject: [PATCH 2/7] tracing: Add support for event fields --- src/rust/include/tracing.h | 21 ++++++++++++++++++--- 1 file changed, 18 insertions(+), 3 deletions(-) diff --git a/src/rust/include/tracing.h b/src/rust/include/tracing.h index 89bd87c4a..3764d5066 100644 --- a/src/rust/include/tracing.h +++ b/src/rust/include/tracing.h @@ -6,6 +6,7 @@ #define TRACING_INCLUDE_H_ #include "rust/types.h" +#include "tracing/map.h" #include #include @@ -103,6 +104,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) @@ -256,11 +270,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); \ From d1e0087bd5df116e22709feec13162ec72bfb425 Mon Sep 17 00:00:00 2001 From: Jack Grigg Date: Fri, 7 Aug 2020 21:41:29 +0100 Subject: [PATCH 3/7] tracing: Add support for span fields --- src/rust/include/tracing.h | 31 +++++++++++++++-- src/rust/src/tracing_ffi.rs | 69 +++++++++++++++++++++++++++++++++++-- 2 files changed, 95 insertions(+), 5 deletions(-) diff --git a/src/rust/include/tracing.h b/src/rust/include/tracing.h index 3764d5066..63ccc5988 100644 --- a/src/rust/include/tracing.h +++ b/src/rust/include/tracing.h @@ -68,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. /// @@ -216,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) {} @@ -257,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 diff --git a/src/rust/src/tracing_ffi.rs b/src/rust/src/tracing_ffi.rs index 2f7ecf731..fb810ab09 100644 --- a/src/rust/src/tracing_ffi.rs +++ b/src/rust/src/tracing_ffi.rs @@ -270,6 +270,9 @@ pub extern "C" fn tracing_callsite( } macro_rules! repeat { + (0, $val:expr) => { + [] + }; (1, $val:expr) => { [$val] }; @@ -435,14 +438,76 @@ 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()); + + macro_rules! new_span { + ($n:tt) => { + Span::new( + meta, + &meta.fields().value_set(&repeat!( + $n, + ( + &fi.next().unwrap(), + Some(&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() }; From f54f9d5e06c60918afc88d919913b4ce9fe78348 Mon Sep 17 00:00:00 2001 From: Jack Grigg Date: Tue, 11 Aug 2020 01:06:34 +0100 Subject: [PATCH 4/7] tracing: Format field values with Display This removes the surrounding double quotes from logged field values. --- src/rust/src/tracing_ffi.rs | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/rust/src/tracing_ffi.rs b/src/rust/src/tracing_ffi.rs index fb810ab09..f3eb9a15f 100644 --- a/src/rust/src/tracing_ffi.rs +++ b/src/rust/src/tracing_ffi.rs @@ -456,6 +456,7 @@ pub extern "C" fn tracing_span_create( .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( @@ -464,7 +465,7 @@ pub extern "C" fn tracing_span_create( $n, ( &fi.next().unwrap(), - Some(&vi.next().unwrap().as_ref() as &dyn Value) + Some(&display(vi.next().unwrap().as_ref()) as &dyn Value) ) )), ) @@ -562,6 +563,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( @@ -570,7 +572,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) ) )), ) From c9879d2f9659a9bdf69cf0b5fa5d4c7f74eff501 Mon Sep 17 00:00:00 2001 From: Jack Grigg Date: Tue, 11 Aug 2020 01:56:32 +0100 Subject: [PATCH 5/7] Add fields to logging in CNode and UpdateTip --- src/main.cpp | 23 ++++++++++++++++++----- src/net.cpp | 7 ++++++- 2 files changed, 24 insertions(+), 6 deletions(-) diff --git a/src/main.cpp b/src/main.cpp index 206f81c1d..ac32f0a3f 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -3232,11 +3232,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(); } diff --git a/src/net.cpp b/src/net.cpp index 067678c6b..40b5a6e46 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -2108,7 +2108,12 @@ CNode::CNode(SOCKET hSocketIn, const CAddress& addrIn, const std::string& addrNa nPingUsecTime = 0; fPingQueued = false; nMinPingUsecTime = std::numeric_limits::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(); { From 81446deef2534bee0ff4c2e825b707805552d9c0 Mon Sep 17 00:00:00 2001 From: Jack Grigg Date: Tue, 11 Aug 2020 02:10:42 +0100 Subject: [PATCH 6/7] util: Use DEBUG level for LogPrint(), leaving INFO for LogPrintf() --- src/util.cpp | 4 ++-- src/util.h | 13 +++++++------ 2 files changed, 9 insertions(+), 8 deletions(-) diff --git a/src/util.cpp b/src/util.cpp index dc0ecd0ff..df0311e7c 100644 --- a/src/util.cpp +++ b/src/util.cpp @@ -230,10 +230,10 @@ std::string LogConfigFilter() std::set 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"; } } diff --git a/src/util.h b/src/util.h index 60e7dd258..9e41b53b2 100644 --- a/src/util.h +++ b/src/util.h @@ -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, ...) ([&]() { \ From 5ca852ba41b112499475529a3825e219e6465c6c Mon Sep 17 00:00:00 2001 From: str4d Date: Tue, 18 Aug 2020 02:00:24 +1200 Subject: [PATCH 7/7] debian: Rename X11 to Expat-with-advertising-clause in copyright The X11 license specifically mentions the X Consortium as the party that the no-advertising clause applies to. Co-authored-by: Daira Hopwood --- contrib/debian/copyright | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/contrib/debian/copyright b/contrib/debian/copyright index fee8739b6..b1dc579e8 100644 --- a/contrib/debian/copyright +++ b/contrib/debian/copyright @@ -131,7 +131,7 @@ License: Expat Files: src/rust/include/tracing/map.h Copyright: Copyright (c) 2012 William Swanson -License: X11 +License: Expat-with-advertising-clause Files: src/secp256k1/* Copyright: Copyright (c) 2013 Pieter Wuille @@ -1245,7 +1245,7 @@ Comment: The "special exception" is extended to the versions of files covered by this license that are distributed with this software. -License: X11 +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