Logging interface #91

ariard · 2018-07-26T01:13:21Z

Implement error, warn, info, debug and trace macros, internally calling
an instance of Logger, and passing it to every main structures
Issue #54

ariard · 2018-07-26T01:14:34Z

Still early work, need to add more comments and a test part, but want your thinking about it. Mainly, it s a lightweight copy of crate log, without a global logger, and less features. Maybe there is still to much stuff, and I'll prune more if needed.
Need also to test the conditional compilation part, to check that format_args! doesn t pop if it isn't necessary.

ariard · 2018-07-26T02:05:04Z

travis failures because I need to add Logger to test, working on that

yuntai · 2018-07-26T03:33:20Z

Could it be worth exploring to use static ref Logger instead of passing around Arc<Logger>?

TheBlueMatt · 2018-07-26T03:36:27Z

Then the client has to set it and you have to use unsafe every time you want to read from it, no? Arcs aren't too bad if they're not copied often.

…

On July 26, 2018 3:33:21 AM UTC, yuntai ***@***.***> wrote: Could it be worth exploring to use `static ref Logger` instead of passing around `Arc<Logger>`? -- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: #91 (comment)

TheBlueMatt

Awesome, looks cool!

TheBlueMatt · 2018-07-26T18:46:25Z

src/util/logger.rs

+}
+
+/// A trait encapsulating the operations required of a logger
+pub trait Logger: Sync + Send {


This needs to be full-pub somehow, so I presume the macros and this need to be in a separate module?

ariard · 2018-07-28T19:03:56Z

Updated, currently you need to pass self to each macro call because of Rust hygienic macro. This isn't awesome but that's the Rust way for now rust-lang/rust#39922.
In this commit, you have a one-time setting of a max debug level at compilation and a per-logger setting. Per-logger has to be inferior to global.
Still need to comment more and clean warnings and some scopes.

ariard · 2018-07-28T19:07:15Z

d2ab686 rebased

ariard · 2018-07-29T00:45:01Z

Should build + rebase

TheBlueMatt

This is really awesome work, thanks! It does seem to me to be a bit overengineered, though. It looks like there's about three ways to filter log messages (client-side, build-time, and via the filter stuff). I originally suggested supporting build-time to avoid performance issues with formatting strings and passing them to the user for every debug message, but if you can encapsulate that in the object passed to the client, it seems like there should be pretty low overhead for something like that, so maybe we can just always call into the client and let them filter as they see fit? If it becomes an issue maybe we can template our types based on the logger type so LLVM can inline the call?

TheBlueMatt · 2018-07-30T21:13:38Z

src/util/logger.rs

+	)
+}
+
+macro_rules! warn {


Can you make these names a little less generic if we're gonna use them all over the crate? Like log_debug instead of debug, at least?

TheBlueMatt · 2018-07-30T21:16:46Z

src/util/logger.rs

+
+/// An enum representing the available verbosity level filters of the logger.
+#[derive(Copy, Eq, Debug, Hash)]
+pub enum LevelFilter {


It seems way overdesigned to have a filter API like this where our log logic does the filtering. Seems much simpler to me to just call into the logger for every log message and let the client filter it how they see fit? Would cut out a ton of code here, no?

TheBlueMatt · 2018-07-30T21:18:10Z

src/util/logger.rs

+#[derive(Clone,Debug)]
+pub struct Record<'a> {
+	metadata: Metadata<'a>,
+	args: fmt::Arguments<'a>,


Oh this is cool! If we have this do we need features to disable logging of low-level messages? Most of the reason I suggested having a feature was to avoid calling format!() for every debug message even when its just going to be discarded as that can be a performance issue in some applications, but it looks like maybe that wouldn't be an issue with this?

ariard · 2018-07-31T23:34:40Z

Instead of relaying on static variable for global filtering, I added conditional compilation directly in macro, same effect with less code. Based on playing with rustc linking flags of dead code, it prunes useless call to logger in macro body. It doesn't speed up compile-time as macro expanding is handled earlier, but it's a little decrease in binary size.
Digging into format_args, in fact most of the overhead is at run-time, at compile-time it's only parses the templates strings, places the Arguments values and check argument types. Formatting is only handled by writer at runtime.
So with this design, you have 2 filtering, one a build time and one per-logger. Per-logger can't be superior at build time, code isn't built. Client-side filtering let you manage the performance hit as you want, you have metadata to decide on it.

ariard · 2018-07-31T23:41:28Z

I cut the filter API, at first I was dubious to let it for already existents logger implementations being backward compatible with us, but well I've already cut too much for this being right.
Tell me for comments and also I can disable warning with macros.

TheBlueMatt

I still think this is a bit overengineered, but I'm getting increasingly excited to start using it...I'm tired of maintaining a patch that adds a ton of println!()s everywhere :p.

TheBlueMatt · 2018-08-01T01:12:47Z

src/util/logger.rs

+	}
+}
+
+impl FromStr for Level {


Can we just not implement FromStr for Level? I'm not sure who would ever really need that, and it adds a whole Err type and associated impls.

TheBlueMatt · 2018-08-01T01:27:25Z

Cargo.toml

@@ -15,6 +15,11 @@ build = "build.rs"
 # Supports tracking channels with a non-bitcoin chain hashes. Currently enables all kinds of fun DoS attacks.
 non_bitcoin_chain_hash_routing = []
 fuzztarget = ["secp256k1/fuzztarget", "bitcoin/fuzztarget"]
+max_level_error = []


My point about overhead was more a question of "would someone care about the peroformance hit of this" - the reason to have the conditional compilation is that the act of doing the format!() itself can often be nontrivial, especially when you're running at something like trace, but because rust lets us do format_args!() without actually doing the full format!() unless the client actually wants to write out the line to their log, the overhead of doing a log call that gets dropped should be pretty low (mostly the indirect call through the Arc, but given we're doing a ton of crypto anyway so what's some indirect calls, which theoretically we could get dropped by templating if we needed to in the future). All that said, having the options isn't many lines of code, so I don't feel so strongly anymore.

Still, if we do want to keep the features, I'd think its more intuitive to have them go the other way - default to call the user's Logger for everything TRACE and up, and let the user turn things off at compile-time if they want to opt into it.

TheBlueMatt · 2018-08-01T01:31:07Z

src/util/test_utils.rs


 use bitcoin::blockdata::transaction::Transaction;

 use secp256k1::PublicKey;

 use std::sync::{Arc,Mutex};
 use std::{mem};
+use std::fmt::Write;
+use std::cell::RefCell;


This is unused.

TheBlueMatt · 2018-08-01T01:31:11Z

src/util/test_utils.rs


 use bitcoin::blockdata::transaction::Transaction;

 use secp256k1::PublicKey;

 use std::sync::{Arc,Mutex};
 use std::{mem};
+use std::fmt::Write;


This is unused.

TheBlueMatt · 2018-08-01T01:31:22Z

src/util/logger.rs

+use std::str::FromStr;
+use std::sync::Arc;
+
+use std::ascii::AsciiExt;


This appears unused now?

TheBlueMatt · 2018-08-01T01:32:23Z

src/util/logger.rs

+	}
+}
+
+#[allow(dead_code)]


Can you just add a few sample logs in obvious places and remove the allow(dead_code)s? That way we can see it works and no need for bending over backwards here.

TheBlueMatt · 2018-08-01T01:33:31Z

src/util/logger.rs

+
+#[allow(dead_code)]
+impl Level {
+	fn from_usize(u: usize) -> Option<Level> {


Same here - if you remove from_str can probably remove from_usize as well.

TheBlueMatt · 2018-08-01T01:35:10Z

src/util/logger.rs

+/// A trait encapsulating the operations required of a logger
+pub trait Logger: Sync + Send {
+	/// Enable the logger with a maximum log level
+	fn enable(&mut self, level: Level);


Why does this (and flush, and level) need to be present? I think that's all client-side stuff that a library doesn't really need to concern itself with?

I'm still unsure why we'd need a third way to limit the log level (which this appears to be?).

ariard · 2018-08-01T03:24:05Z

Updated, reverse the logic for filtering, but I think it's fine to keep the 2 ways as you can have multiples loggers, each with its level policy and you want some global setting, without having to update each one. Also cut down the useless stuff and throw sample logs in some places (trying to find others ones)

ariard · 2018-08-12T01:01:44Z

Right, no need of enable in the API, let it be implemented client-side. Rebased

TheBlueMatt · 2018-08-14T14:15:57Z

Cargo.toml

@@ -15,6 +15,11 @@ build = "build.rs"
 # Supports tracking channels with a non-bitcoin chain hashes. Currently enables all kinds of fun DoS attacks.
 non_bitcoin_chain_hash_routing = []
 fuzztarget = ["secp256k1/fuzztarget", "bitcoin/fuzztarget"]
+max_level_off = []


Can we make these a bit more descriptive (eg "disable_log_level_X")? Also, these need to be documented somewhere (I guess in the docs for Logger?).

TheBlueMatt · 2018-08-14T14:16:47Z

src/ln/channel.rs

@@ -1176,6 +1184,7 @@ impl Channel {
 		let (remote_initial_commitment_tx, our_signature) = match self.funding_created_signature(&msg.signature) {
 			Ok(res) => res,
 			Err(e) => {
+				log_error!(self, "Got error handling message {}", e.err);


Oops, log_error probably shouldn't be used for things remote peers can trivially trigger (eg a failed HTLC, we could use it for things where a channel had a confirmed transaction but something resulted in it being closed due to error), but, in general, we should try to keep log_error "DoS-resistant" and have some docs indicating that its safe to use and a remote peer cannot trivially fill up a client's disk using it.

TheBlueMatt · 2018-08-14T14:17:01Z

src/util/logger.rs

+
+static LOG_LEVEL_NAMES: [&'static str; 6] = ["OFF", "ERROR", "WARN", "INFO", "DEBUG", "TRACE"];
+
+static LEVEL_PARSE_ERROR: &'static str =


This appears unused now?

TheBlueMatt · 2018-08-14T14:17:12Z

src/util/logger.rs

+	Trace,
+}
+
+impl Clone for Level {


Can't this just be derived?

TheBlueMatt · 2018-08-14T14:17:44Z

src/util/logger.rs

+pub struct Record<'a> {
+	metadata: Metadata<'a>,
+	args: fmt::Arguments<'a>,
+	module_path: Option<&'a str>,


Why is this (and the below two additional vars) an Option? It seems like its always available (and should always be available), no?

TheBlueMatt · 2018-08-14T14:19:41Z

src/util/logger.rs

+}
+
+macro_rules! log_internal {
+	($self: ident, target: $target:expr, $lvl:expr, $($arg:tt)+) => (


Why do we accept a $target here when we always are called without it until we call outselves? Can't we just drop the indirection?

Yes my mistake. Legacy design let you opt out using different pattern-matching of the macro. But in fact it's up to the implementation if it doesn't want to bother with additional infos

TheBlueMatt · 2018-08-14T14:20:52Z

src/util/logger.rs

+
+	#[test]
+	fn test_logging_macros() {
+		let mut logger = TestLogger::new();


Hmm, would be nice if this actually checked that logs were generated, but not a big deal wither way.

Yeah at first, I wawed to pipe the output or implement Write trait on a wrapper giving it the output of format_args! but not sure if it worth the hurdle. For me, it's testing that format_args! and stdout works well.

TheBlueMatt · 2018-08-14T14:21:24Z

src/util/test_utils.rs

+
+impl Logger for TestLogger {
+	fn log(&self, record: &Record) {
+		if self.level >= record.metadata().level() {


Hmm, maybe just always log the record since output isnt printed unless the test fails anyway? Could skip the enable() function then, too.

TheBlueMatt · 2018-08-14T14:22:50Z

src/util/mod.rs

+
+#[cfg(not(feature = "fuzztarget"))]
+#[macro_use]
+pub(crate) mod logger;


The Logger trait needs to be always-pub, but the macros for logging should probably be pub(crate). I guess they need to be separated out into different mods?

TheBlueMatt · 2018-08-14T14:24:07Z

src/util/mod.rs

@@ -12,3 +12,12 @@ pub use self::rng::reset_rng_state;

 #[cfg(test)]
 pub(crate) mod test_utils;
+#[cfg(feature = "fuzztarget")]


Hmm, the Logger thing is simple enough I figure fuzz can impl its own test logger (which it can tune to enable logging info only when running in test so that it doesn't slow down the fuzzer too much).

ariard · 2018-08-16T22:08:24Z

Updated and rebased. I cleaned the useless stuff as Metadata and others which were legacy design due to copy from log crate.

ariard · 2018-08-16T22:15:08Z

src/util/test_utils.rs

+
+impl Logger for TestLogger {
+	fn log(&self, record: &Record) {
+		if self.level >= record.level() {


Maybe worth it to let it as an example for future logger implementers ?

TheBlueMatt

Just gonna merge, will fix the two comments here later as logs are added.

TheBlueMatt · 2018-08-16T22:46:33Z

src/util/logger.rs

+
+	/// The message body.
+	#[inline]
+	pub fn args(&self) -> &fmt::Arguments<'a> {


Why not just make the vars in Record pub (with docs) and not worry about accessors?

TheBlueMatt · 2018-08-16T22:49:43Z

src/util/macro_logger.rs

+	($self: ident, $lvl:expr, $($arg:tt)+) => (
+		&$self.logger.log(&Record::new($lvl, format_args!($($arg)+), module_path!(), file!(), line!()));
+	);
+	($self: ident, $lvl:expr, $($arg:tt)+) => (log_internal!($self, $lvl, $($arg)+))


Looks like this comment wasn't addressed: #91 (comment)

Implement error, warn, info, debug and trace macros, internally calling an instance of Logger, and passing it to every main structures Build-time or client-side filtering. Issue lightningdevkit#54

TheBlueMatt reviewed Jul 26, 2018

View reviewed changes

ariard force-pushed the logging_interface branch from 6736566 to e5c6c54 Compare July 28, 2018 18:57

ariard force-pushed the logging_interface branch from e5c6c54 to d2ab686 Compare July 28, 2018 19:06

ariard force-pushed the logging_interface branch from d2ab686 to 3356d6e Compare July 29, 2018 00:44

ariard force-pushed the logging_interface branch from 3356d6e to 36273c9 Compare July 29, 2018 21:28

TheBlueMatt reviewed Jul 30, 2018

View reviewed changes

ariard force-pushed the logging_interface branch from 36273c9 to 2f9b8a7 Compare July 31, 2018 23:24

TheBlueMatt reviewed Aug 1, 2018

View reviewed changes

ariard force-pushed the logging_interface branch from 2f9b8a7 to 51482c5 Compare August 1, 2018 03:20

ariard force-pushed the logging_interface branch from 51482c5 to f97ef28 Compare August 12, 2018 00:56

TheBlueMatt reviewed Aug 14, 2018

View reviewed changes

ariard force-pushed the logging_interface branch 2 times, most recently from 932c81c to b1a1d3d Compare August 16, 2018 22:06

ariard commented Aug 16, 2018

View reviewed changes

TheBlueMatt reviewed Aug 16, 2018

View reviewed changes

ariard force-pushed the logging_interface branch 2 times, most recently from 951e7d5 to 19c84c5 Compare August 17, 2018 00:01

Logging interface

0029f04

Implement error, warn, info, debug and trace macros, internally calling an instance of Logger, and passing it to every main structures Build-time or client-side filtering. Issue lightningdevkit#54

ariard force-pushed the logging_interface branch from 19c84c5 to 0029f04 Compare August 17, 2018 00:01

TheBlueMatt merged commit 1a9ef40 into lightningdevkit:master Aug 17, 2018

TheBlueMatt mentioned this pull request Aug 20, 2018

Logging Interface #54

Closed

ariard deleted the logging_interface branch August 27, 2018 22:29


		static LOG_LEVEL_NAMES: [&'static str; 6] = ["OFF", "ERROR", "WARN", "INFO", "DEBUG", "TRACE"];

		static LEVEL_PARSE_ERROR: &'static str =

Logging interface #91

Logging interface #91

Conversation

ariard commented Jul 26, 2018

ariard commented Jul 26, 2018

ariard commented Jul 26, 2018

yuntai commented Jul 26, 2018

TheBlueMatt commented Jul 26, 2018 via email

TheBlueMatt left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ariard commented Jul 28, 2018 • edited Loading

ariard commented Jul 28, 2018

ariard commented Jul 29, 2018

TheBlueMatt left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ariard commented Jul 31, 2018 • edited Loading

ariard commented Jul 31, 2018

TheBlueMatt left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ariard commented Aug 1, 2018

ariard commented Aug 12, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ariard commented Aug 16, 2018

Choose a reason for hiding this comment

TheBlueMatt left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ariard commented Jul 28, 2018 •

edited

Loading

ariard commented Jul 31, 2018 •

edited

Loading