rust-lightning icon indicating copy to clipboard operation
rust-lightning copied to clipboard

Add LoggerScope for a thread-local Logger instance

Open joostjager opened this issue 2 months ago • 10 comments

joostjager avatar Nov 13 '25 12:11 joostjager

👋 Hi! I see this is a draft PR. I'll wait to assign reviewers until you mark it as ready for review. Just convert it out of draft status when you're ready for review!

ldk-reviews-bot avatar Nov 13 '25 12:11 ldk-reviews-bot

Codecov Report

:x: Patch coverage is 84.96503% with 43 lines in your changes missing coverage. Please review. :white_check_mark: Project coverage is 89.34%. Comparing base (de384ff) to head (7dd7d6f).

Files with missing lines Patch % Lines
lightning/src/chain/channelmonitor.rs 83.33% 23 Missing :warning:
lightning/src/util/logger.rs 75.00% 3 Missing and 6 partials :warning:
lightning-macros/src/lib.rs 73.07% 6 Missing and 1 partial :warning:
lightning/src/chain/onchaintx.rs 91.11% 4 Missing :warning:
Additional details and impacted files
@@           Coverage Diff           @@
##             main    #4223   +/-   ##
=======================================
  Coverage   89.33%   89.34%           
=======================================
  Files         180      180           
  Lines      139042   139082   +40     
  Branches   139042   139082   +40     
=======================================
+ Hits       124219   124264   +45     
+ Misses      12196    12193    -3     
+ Partials     2627     2625    -2     
Flag Coverage Δ
fuzzing 36.04% <47.86%> (+0.07%) :arrow_up:
tests 88.70% <84.96%> (-0.01%) :arrow_down:

Flags with carried forward coverage won't be shown. Click here to find out more.

:umbrella: View full report in Codecov by Sentry.
:loudspeaker: Have feedback on the report? Share it here.

:rocket: New features to boost your workflow:
  • :snowflake: Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

codecov[bot] avatar Nov 13 '25 13:11 codecov[bot]

I played with this a bit, sadly Rust doesn't allow you to convert an arbitrary (?Sized) trait impl to dyn Trait (as it could lead to building a vtable that points to a type that has another vtable, which they could support by copying the vtable but do not). Thus, the real way to achieve this would be to convert the Deref<Target=Logger> bounds with Deref<Target=dyn Logger> (allowing us to simply deref the passed logger to get a dyn Logger). That's an annoying repetitive task so I asked claude to do it, but after fighting with it for a while it found that bounding on the dyn Logger results in objects that aren't Send/Sync making them not-multi-threaded, and then it immediately reset all its work and told me that I shouldn't want to do that:

The original design is actually more flexible and correct for Rust's type system. The generic bound doesn't prevent users from passing trait objects - it just doesn't require them, which is necessary for compatibility with different trait object variants.

(of course the log::Log trait is always Send + Sync-bounded to work around this issue). Luckily we have MaybeSend + MaybeSync for this purpose, so I made claude do that [1]. Anyway, once you get that far using the new LoggerScope is pretty doable (even in a trivial proc-macro [2], which could eventually push a scope onto the logger).

[1] https://git.bitcoin.ninja/?p=rust-lightning;a=shortlog;h=refs/heads/claude/2025-11-dyn-logger

[2]

/// Adds a logging scope at the top of a method.
#[proc_macro_attribute]
pub fn log_scope(_attrs: TokenStream, meth: TokenStream) -> TokenStream {
	let mut meth = if let Ok(parsed) = parse::<syn::ItemFn>(meth) {
		parsed
	} else {
		return (quote! {
			compile_error!("log_scope can only be set on methods")
		})
		.into();
	};
	let init_context = quote! { let _logging_context = crate::util::logger::LoggerScope::new(&*self.logger); };
	meth.block.stmts.insert(0, parse(init_context.into()).unwrap());
	quote! { #meth }.into()
}

TheBlueMatt avatar Nov 17 '25 02:11 TheBlueMatt

I've tried to make it work on top of your Maybe* commit, but failed. I can't get rid of

1066 |             let _scope = LoggerScope::new(&*self.logger); // DOES NOT WORK
     |                          ---------------- ^^^^^^^^^^^^^ doesn't have a size known at compile-time
     |                          |
     |                          required by a bound introduced by this call

First I thought you wanted to bound everything on dyn Logger to prevent the nested vtable, but that's not in your commit.

Proc macro for logger scope is interesting, and can indeed be extended with a node id in testing.

joostjager avatar Nov 17 '25 08:11 joostjager

The type passed to LoggerScope::new needs to change to take a &'a dyn Logger rather than taking a concrete Logger.

TheBlueMatt avatar Nov 17 '25 12:11 TheBlueMatt

I had tried that, but it didn't work. Same sized error. Pushed the commit. Maybe I am doing something wrong.

joostjager avatar Nov 17 '25 13:11 joostjager

I am wondering what the performance implications are of the logger scope. Just adding a node id in TLS would test-only, but storing the logger instance itself is production code that wouldn't be running if there was a global logger instead.

joostjager avatar Nov 17 '25 16:11 joostjager

I don't think its going to be material in either direct. Storing a dyn Logger in TLS shouldn't be more than like an extra 2 or 3 pointers (just 1 for the vtable, one for the self?) per thread. The existing logic was an extra ~1 pointer per logger object stored in various places (generally as Deref impls are usually just a single pointer). The dyn version requires jumping through the vtable indirection (and reading the vtable jump pointer from memory) so there's a tiny hit, but it shouldn't be substantial on any Real Hardware, really. TLS is a bit screwy on older rustc (and in C) on MacOS IIRC, but I assume by now that's all resolved.

TheBlueMatt avatar Nov 17 '25 16:11 TheBlueMatt

I had tried that, but it didn't work. Same sized error. Pushed the commit. Maybe I am doing something wrong.

Right, looks like claude just forgot to update the NetworkGraph logger bound to dyn.

TheBlueMatt avatar Nov 17 '25 19:11 TheBlueMatt

Oh, claude didn't update any of the references to dyn lol. Dumb LLMs just ignore half of what you tell them, I hadn't bothered to look at what it did, either. Anyway, gotta update all those bounds!

TheBlueMatt avatar Nov 17 '25 19:11 TheBlueMatt

With bound L: Deref<Target = dyn Logger + MaybeSend + MaybeSync> the code works indeed.

I started a bit of creative search/replace across the repo to do a sweeping conversion (https://github.com/lightningdevkit/rust-lightning/compare/main...joostjager:rust-lightning:dyn-logger?expand=0). Needs a bit more work.

It's probably not necessary for deciding on the direction we want to take this to.

joostjager avatar Nov 20 '25 15:11 joostjager

Sadly it seems that thread-local storage isn't compatible with no std. It's very unfortunate that I realized that only now that this PR is nearly finished. Spans can probably be implemented without thread-local storage, but getting rid of the logger parameters seems to be impossible. Even a global logger is problematic in no std because it requires the logger to be sync.

joostjager avatar Dec 04 '25 18:12 joostjager