Add log spans using thread local storage in tests - #4287

Closed
joostjager wants to merge 3 commits into
lightningdevkit:mainfrom
joostjager:std-spans
Closed

Add log spans using thread local storage in tests#4287
joostjager wants to merge 3 commits into
lightningdevkit:mainfrom
joostjager:std-spans

Conversation

@joostjager

@joostjagerjoostjager commented Dec 16, 2025

Copy link
Copy Markdown
Contributor

This is a stripped-down version of #4223 where only the spans are stored in thread local storage. This is a test-only change - the span functionality is compiled out in non-test builds, so there is no impact on production code or no-std users.

Example log output:

std-spans.log

node 2 TRACE [lightning::chain::channelmonitor:4263] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Updating ChannelMonitor with latest holder commitment transaction info [p:0355f8]
node 2 DEBUG [lightning::chain::chainmonitor:1451] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Persistence of ChannelMonitorUpdate id 5 completed [p:0355f8]
node 2 DEBUG [lightning::ln::channelmanager:11589] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Channel is open and awaiting update, resuming it [p:0355f8]
node 2 DEBUG [lightning::ln::channel:9488] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Restored monitor updating in channel d9d065715d1cbe419a5cddaa8b1b749e00acc5a747c7d08165767d1225770bcd resulting in no commitment update and an RAA, with commitment first [p:0355f8]
node 2 TRACE [lightning::ln::channelmanager:9838] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Handling channel resumption with an RAA, no commitment update, 0 pending forwards, 0 pending update_add_htlcs, not broadcasting funding, without channel ready, without announcement, without tx_signatures, without tx_abort [p:0355f8]
node 1 TRACE [lightning::ln::channel:8670] ch:d9d065 [Reconnect nodes B and C] Updating HTLCs on receipt of RAA... [p:02888f]
node 1 TRACE [lightning::ln::channel:8703] ch:d9d065 [Reconnect nodes B and C] ...removing outbound AwaitingRemovedRemoteRevoke 66687aadf862bd776c8fc18b8e9f8e20089714856ee233b3902a591d0d5f2925 [p:02888f]
node 1 DEBUG [lightning::ln::channel:8962] ch:d9d065 [Reconnect nodes B and C] Received a valid revoke_and_ack with no reply necessary. Holding monitor update 5. [p:02888f]
node 1 TRACE [lightning::ln::channelmanager:10054] ch:ae3367 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] ChannelMonitor updated to 5. 0 pending in-flight updates. [p:027f92]
node 1 TRACE [lightning::ln::channelmanager:10092] ch:ae3367 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] Channel is closed, applying 2 post-update actions [p:027f92]
node 1 DEBUG [lightning::ln::channelmanager:13975] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] Unlocking monitor updating and updating monitor [p:02888f]
node 1 TRACE [lightning::chain::chainmonitor:1407] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Updating ChannelMonitor to id 5 [p:02888f]
node 1 INFO [lightning::chain::channelmonitor:4226] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Applying update, bringing update_id from 4 to 5 with 1 change(s). [p:02888f]
node 1 TRACE [lightning::chain::channelmonitor:4311] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Updating ChannelMonitor with commitment secret [p:02888f]

@ldk-reviews-bot

ldk-reviews-bot commented Dec 16, 2025

Copy link
Copy Markdown

👋 Hi! This PR is now in draft status.
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!

@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from 38d439b to 5d2f39fCompareDecember 16, 2025 12:29
@codecov

codecovBot commented Dec 16, 2025

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 87.50000% with 9 lines in your changes missing coverage. Please review.
✅ Project coverage is 86.61%. Comparing base (09b3bef) to head (1756ae4).
⚠️ Report is 443 commits behind head on main.

Files with missing linesPatch %Lines
lightning-macros/src/lib.rs75.00%5 Missing and 1 partial ⚠️
lightning/src/util/logger.rs94.28%1 Missing and 1 partial ⚠️
lightning/src/util/test_utils.rs92.30%1 Missing ⚠️
Additional details and impacted files
@@ Coverage Diff @@## main #4287 +/- ##
==========================================
- Coverage 86.61% 86.61% -0.01% 
==========================================
Files 158 158 Lines 102730 102801 +71 Branches 102730 102801 +71 ==========================================
+ Hits 88984 89045 +61 - Misses 11328 11338 +10 
Partials 2418 2418 
FlagCoverage Δ
fuzzing37.19% <13.33%> (+0.99%)⬆️
tests85.91% <87.50%> (ø)

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

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

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

@joostjager
joostjagerforce-pushed the std-spans branch 3 times, most recently from 1355c20 to c3714c6CompareDecember 18, 2025 10:37
@joostjagerjoostjager self-assigned this Jan 8, 2026
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from 14f583e to aedfe0aCompareJanuary 13, 2026 10:49
@joostjager

Copy link
Copy Markdown
ContributorAuthor

Rebased and fixed a std/no_std compilation issue with the logging macros.

The problem was that Record::new had a conditional spans parameter only present with std, but #[cfg] checks in macros are evaluated in the calling crate's context, not lightning's. This caused argument count mismatches when crates like lightning-rapid-gossip-sync were compiled without std while lightning had it enabled.

Fixed by making Record::new always take a Spans type that is Vec<&'static str> with std and () (zero-sized) without, and adding a get_tls_spans() helper compiled inside lightning where the cfg correctly reflects its features.

@joostjager

Copy link
Copy Markdown
ContributorAuthor

Taking this out of draft as I'm committed to adding span support, but putting it on hold while an alternative approach is being investigated: using proc-macros to transparently augment every method with an implicit logger parameter, which would allow passing the span stack through that invisible parameter instead of relying on TLS.

@joostjager
joostjager marked this pull request as ready for review January 13, 2026 10:53
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from d84cd91 to ee9b3bbCompareJanuary 13, 2026 11:16
@ldk-reviews-bot

Copy link
Copy Markdown

🔔 1st Reminder

Hey @jkczyz! This PR has been waiting for your review.
Please take a look when you have a chance. If you're unable to review, please let us know so we can find another reviewer.

@joostjager
joostjager removed the request for review from jkczyzJanuary 15, 2026 11:00
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from aba1a33 to e119381CompareJanuary 19, 2026 13:34
joostjagerand others added 3 commits January 19, 2026 14:43
Introduces LoggerScope, a RAII guard that pushes span names onto a
thread-local stack. In test builds with std, log messages are prefixed
with the current span chain (e.g., "[outer->inner]") for easier debugging.
Includes:
- LoggerScope struct with automatic cleanup on drop
- #[log_scope] proc macro to annotate functions with a logging context
- test_scope! macro for manual scope changes within long test functions
Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>
@joostjagerjoostjager changed the title Add log spans using thread local storage in stdAdd log spans using thread local storage in testsJan 19, 2026
@joostjager

Copy link
Copy Markdown
ContributorAuthor

Updated PR to be test-only.

@ldk-reviews-bot

Copy link
Copy Markdown

🔔 2nd Reminder

Hey @TheBlueMatt! This PR has been waiting for your review.
Please take a look when you have a chance. If you're unable to review, please let us know so we can find another reviewer.

@joostjager

Copy link
Copy Markdown
ContributorAuthor

Need to decide on what level the spans are most helpful, where to apply #[log_scope] in main. Aside from what devs may add ad-hoc during testing.

@TheBlueMattTheBlueMatt left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might want to wait until we decide on #4322 since we'll want to re-use the proc-macro from there if we move forward. I guess they could move forward separately and just merge the macros on whichever lands second.

/// [`ChannelCloseMinimum`]: crate::chain::chaininterface::ConfirmationTarget::ChannelCloseMinimum
/// [`NonAnchorChannelFee`]: crate::chain::chaininterface::ConfirmationTarget::NonAnchorChannelFee
/// [`SendShutdown`]: MessageSendEvent::SendShutdown
#[log_scope]

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we just use a single proc macro that also scopes sub-functions? If this is for tests presumably that's more useful and also less clutter.

@joostjagerjoostjagerJan 19, 2026

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wasn't sure indeed if we want to manually decide what useful spans are, or we can simply auto-annotate all pub fns, and do a few more perhaps manually if they are called frequently in tests.

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, kinda up to you given you have the most experience with using it, I suppose. Definitely we should automate pub fns, but up to you if you want to automate all fns or make it explicit. ISTM I'm always trying to do a full trace including non-public fns, but if you have a different experience alright.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am a bit worried about presentation. Full trace might become a pretty long log line

@joostjager

Copy link
Copy Markdown
ContributorAuthor

This PR demonstrates that we can DIY a part of what tracing offers, but there is a lot that we are missing out on:

  • Structured key-value fields on spans and log events
  • Dynamic per-module/per-span log filtering at runtime
  • Automatic span timing for performance profiling
  • Async-aware context propagation across .await points
  • OpenTelemetry/Jaeger export for distributed tracing
  • Multiple concurrent subscribers (e.g. stdout + metrics + tracing)
  • Integration with the broader Rust ecosystem (eg tokio emitting tracing spans natively)

And last but not least:

  • No need to pass a logger instance through every struct and function signature

All of this to avoid unsafe code on specific no_std platforms. I am still not sold on the trade-off.

@joostjager
joostjager marked this pull request as draft March 5, 2026 12:08
@joostjager

Copy link
Copy Markdown
ContributorAuthor

I don't see this happening as long as we keep the current logging system

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

Status: Done

Development

Successfully merging this pull request may close these issues.

3 participants

@joostjager@ldk-reviews-bot@TheBlueMatt
, 'i'); if (__m === '*' || __re.test(location.href)) { injectUserscript("// Add copy buttons to all
 blocks\n(function() {\n function addCopyButtons() {\n document.querySelectorAll('pre code').forEach(function(codeBlock) {\n if (codeBlock.parentElement.hasAttribute('data-copy-added')) return;\n codeBlock.parentElement.setAttribute('data-copy-added', 'true');\n \n var btn = document.createElement('button');\n btn.textContent = 'Copy';\n btn.style.cssText = 'position:absolute;top:4px;right:4px;padding:2px 8px;font-size:11px;background:#4ecdc4;border:none;border-radius:4px;color:#1a1a2e;cursor:pointer;opacity:0.7;transition:opacity 0.2s;';\n btn.onmouseover = function() { this.style.opacity = '1'; };\n btn.onmouseout = function() { this.style.opacity = '0.7'; };\n btn.onclick = function() {\n navigator.clipboard.writeText(codeBlock.textContent).then(function() {\n btn.textContent = 'Copied!';\n setTimeout(function() { btn.textContent = 'Copy'; }, 1500);\n });\n };\n codeBlock.parentElement.style.position = 'relative';\n codeBlock.parentElement.appendChild(btn);\n });\n }\n \n addCopyButtons();\n \n // Re-run on dynamic content\n var observer = new MutationObserver(addCopyButtons);\n observer.observe(document.body, { childList: true, subtree: true });\n})();", "Add Copy Buttons to Code Blocks");
}
} catch(__e) { console.warn('[Userscript:Add Copy Buttons to Code Blocks]', __e); }
})();
(function(){
try {
var __m = "github.com";
var __re = new RegExp('^' + "github\\.com" + '
Skip to content

Add log spans using thread local storage in tests - #4287

Closed
joostjager wants to merge 3 commits into
lightningdevkit:mainfrom
joostjager:std-spans
Closed

Add log spans using thread local storage in tests#4287
joostjager wants to merge 3 commits into
lightningdevkit:mainfrom
joostjager:std-spans

Conversation

@joostjager

@joostjagerjoostjager commented Dec 16, 2025

Copy link
Copy Markdown
Contributor

This is a stripped-down version of #4223 where only the spans are stored in thread local storage. This is a test-only change - the span functionality is compiled out in non-test builds, so there is no impact on production code or no-std users.

Example log output:

std-spans.log

node 2 TRACE [lightning::chain::channelmonitor:4263] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Updating ChannelMonitor with latest holder commitment transaction info [p:0355f8]
node 2 DEBUG [lightning::chain::chainmonitor:1451] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Persistence of ChannelMonitorUpdate id 5 completed [p:0355f8]
node 2 DEBUG [lightning::ln::channelmanager:11589] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Channel is open and awaiting update, resuming it [p:0355f8]
node 2 DEBUG [lightning::ln::channel:9488] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Restored monitor updating in channel d9d065715d1cbe419a5cddaa8b1b749e00acc5a747c7d08165767d1225770bcd resulting in no commitment update and an RAA, with commitment first [p:0355f8]
node 2 TRACE [lightning::ln::channelmanager:9838] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Handling channel resumption with an RAA, no commitment update, 0 pending forwards, 0 pending update_add_htlcs, not broadcasting funding, without channel ready, without announcement, without tx_signatures, without tx_abort [p:0355f8]
node 1 TRACE [lightning::ln::channel:8670] ch:d9d065 [Reconnect nodes B and C] Updating HTLCs on receipt of RAA... [p:02888f]
node 1 TRACE [lightning::ln::channel:8703] ch:d9d065 [Reconnect nodes B and C] ...removing outbound AwaitingRemovedRemoteRevoke 66687aadf862bd776c8fc18b8e9f8e20089714856ee233b3902a591d0d5f2925 [p:02888f]
node 1 DEBUG [lightning::ln::channel:8962] ch:d9d065 [Reconnect nodes B and C] Received a valid revoke_and_ack with no reply necessary. Holding monitor update 5. [p:02888f]
node 1 TRACE [lightning::ln::channelmanager:10054] ch:ae3367 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] ChannelMonitor updated to 5. 0 pending in-flight updates. [p:027f92]
node 1 TRACE [lightning::ln::channelmanager:10092] ch:ae3367 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] Channel is closed, applying 2 post-update actions [p:027f92]
node 1 DEBUG [lightning::ln::channelmanager:13975] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] Unlocking monitor updating and updating monitor [p:02888f]
node 1 TRACE [lightning::chain::chainmonitor:1407] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Updating ChannelMonitor to id 5 [p:02888f]
node 1 INFO [lightning::chain::channelmonitor:4226] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Applying update, bringing update_id from 4 to 5 with 1 change(s). [p:02888f]
node 1 TRACE [lightning::chain::channelmonitor:4311] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Updating ChannelMonitor with commitment secret [p:02888f]

@ldk-reviews-bot

ldk-reviews-bot commented Dec 16, 2025

Copy link
Copy Markdown

👋 Hi! This PR is now in draft status.
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!

@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from 38d439b to 5d2f39fCompareDecember 16, 2025 12:29
@codecov

codecovBot commented Dec 16, 2025

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 87.50000% with 9 lines in your changes missing coverage. Please review.
✅ Project coverage is 86.61%. Comparing base (09b3bef) to head (1756ae4).
⚠️ Report is 443 commits behind head on main.

Files with missing linesPatch %Lines
lightning-macros/src/lib.rs75.00%5 Missing and 1 partial ⚠️
lightning/src/util/logger.rs94.28%1 Missing and 1 partial ⚠️
lightning/src/util/test_utils.rs92.30%1 Missing ⚠️
Additional details and impacted files
@@ Coverage Diff @@## main #4287 +/- ##
==========================================
- Coverage 86.61% 86.61% -0.01% 
==========================================
Files 158 158 Lines 102730 102801 +71 Branches 102730 102801 +71 ==========================================
+ Hits 88984 89045 +61 - Misses 11328 11338 +10 
Partials 2418 2418 
FlagCoverage Δ
fuzzing37.19% <13.33%> (+0.99%)⬆️
tests85.91% <87.50%> (ø)

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

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

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

@joostjager
joostjagerforce-pushed the std-spans branch 3 times, most recently from 1355c20 to c3714c6CompareDecember 18, 2025 10:37
@joostjagerjoostjager self-assigned this Jan 8, 2026
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from 14f583e to aedfe0aCompareJanuary 13, 2026 10:49
@joostjager

Copy link
Copy Markdown
ContributorAuthor

Rebased and fixed a std/no_std compilation issue with the logging macros.

The problem was that Record::new had a conditional spans parameter only present with std, but #[cfg] checks in macros are evaluated in the calling crate's context, not lightning's. This caused argument count mismatches when crates like lightning-rapid-gossip-sync were compiled without std while lightning had it enabled.

Fixed by making Record::new always take a Spans type that is Vec<&'static str> with std and () (zero-sized) without, and adding a get_tls_spans() helper compiled inside lightning where the cfg correctly reflects its features.

@joostjager

Copy link
Copy Markdown
ContributorAuthor

Taking this out of draft as I'm committed to adding span support, but putting it on hold while an alternative approach is being investigated: using proc-macros to transparently augment every method with an implicit logger parameter, which would allow passing the span stack through that invisible parameter instead of relying on TLS.

@joostjager
joostjager marked this pull request as ready for review January 13, 2026 10:53
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from d84cd91 to ee9b3bbCompareJanuary 13, 2026 11:16
@ldk-reviews-bot

Copy link
Copy Markdown

🔔 1st Reminder

Hey @jkczyz! This PR has been waiting for your review.
Please take a look when you have a chance. If you're unable to review, please let us know so we can find another reviewer.

@joostjager
joostjager removed the request for review from jkczyzJanuary 15, 2026 11:00
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from aba1a33 to e119381CompareJanuary 19, 2026 13:34
joostjagerand others added 3 commits January 19, 2026 14:43
Introduces LoggerScope, a RAII guard that pushes span names onto a
thread-local stack. In test builds with std, log messages are prefixed
with the current span chain (e.g., "[outer->inner]") for easier debugging.
Includes:
- LoggerScope struct with automatic cleanup on drop
- #[log_scope] proc macro to annotate functions with a logging context
- test_scope! macro for manual scope changes within long test functions
Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>
@joostjagerjoostjager changed the title Add log spans using thread local storage in stdAdd log spans using thread local storage in testsJan 19, 2026
@joostjager

Copy link
Copy Markdown
ContributorAuthor

Updated PR to be test-only.

@ldk-reviews-bot

Copy link
Copy Markdown

🔔 2nd Reminder

Hey @TheBlueMatt! This PR has been waiting for your review.
Please take a look when you have a chance. If you're unable to review, please let us know so we can find another reviewer.

@joostjager

Copy link
Copy Markdown
ContributorAuthor

Need to decide on what level the spans are most helpful, where to apply #[log_scope] in main. Aside from what devs may add ad-hoc during testing.

@TheBlueMattTheBlueMatt left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might want to wait until we decide on #4322 since we'll want to re-use the proc-macro from there if we move forward. I guess they could move forward separately and just merge the macros on whichever lands second.

/// [`ChannelCloseMinimum`]: crate::chain::chaininterface::ConfirmationTarget::ChannelCloseMinimum
/// [`NonAnchorChannelFee`]: crate::chain::chaininterface::ConfirmationTarget::NonAnchorChannelFee
/// [`SendShutdown`]: MessageSendEvent::SendShutdown
#[log_scope]

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we just use a single proc macro that also scopes sub-functions? If this is for tests presumably that's more useful and also less clutter.

@joostjagerjoostjagerJan 19, 2026

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wasn't sure indeed if we want to manually decide what useful spans are, or we can simply auto-annotate all pub fns, and do a few more perhaps manually if they are called frequently in tests.

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, kinda up to you given you have the most experience with using it, I suppose. Definitely we should automate pub fns, but up to you if you want to automate all fns or make it explicit. ISTM I'm always trying to do a full trace including non-public fns, but if you have a different experience alright.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am a bit worried about presentation. Full trace might become a pretty long log line

@joostjager

Copy link
Copy Markdown
ContributorAuthor

This PR demonstrates that we can DIY a part of what tracing offers, but there is a lot that we are missing out on:

  • Structured key-value fields on spans and log events
  • Dynamic per-module/per-span log filtering at runtime
  • Automatic span timing for performance profiling
  • Async-aware context propagation across .await points
  • OpenTelemetry/Jaeger export for distributed tracing
  • Multiple concurrent subscribers (e.g. stdout + metrics + tracing)
  • Integration with the broader Rust ecosystem (eg tokio emitting tracing spans natively)

And last but not least:

  • No need to pass a logger instance through every struct and function signature

All of this to avoid unsafe code on specific no_std platforms. I am still not sold on the trade-off.

@joostjager
joostjager marked this pull request as draft March 5, 2026 12:08
@joostjager

Copy link
Copy Markdown
ContributorAuthor

I don't see this happening as long as we keep the current logging system

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

Status: Done

Development

Successfully merging this pull request may close these issues.

3 participants

@joostjager@ldk-reviews-bot@TheBlueMatt
, 'i'); if (__m === '*' || __re.test(location.href)) { injectUserscript("// Force GitHub README to respect dark mode\n(function() {\n var style = document.createElement('style');\n style.textContent = '\n .markdown-body {\n color-scheme: dark light;\n }\n .markdown-body pre { background: #161b22 !important; }\n .markdown-body code { background: rgba(110, 118, 129, 0.4) !important; }\n .markdown-body table th, .markdown-body table td { border-color: #30363d !important; }\n .markdown-body img { background: #0d1117; }\n .markdown-body blockquote { border-left-color: #8b949e; }\n .markdown-body hr { border-color: #30363d; }\n ';\n document.head.appendChild(style);\n})();", "GitHub Dark Mode README Fix"); } } catch(__e) { console.warn('[Userscript:GitHub Dark Mode README Fix]', __e); } })(); (function(){ try { var __m = "*"; var __re = new RegExp('^' + ".*" + '
Skip to content

Add log spans using thread local storage in tests - #4287

Closed
joostjager wants to merge 3 commits into
lightningdevkit:mainfrom
joostjager:std-spans
Closed

Add log spans using thread local storage in tests#4287
joostjager wants to merge 3 commits into
lightningdevkit:mainfrom
joostjager:std-spans

Conversation

@joostjager

@joostjagerjoostjager commented Dec 16, 2025

Copy link
Copy Markdown
Contributor

This is a stripped-down version of #4223 where only the spans are stored in thread local storage. This is a test-only change - the span functionality is compiled out in non-test builds, so there is no impact on production code or no-std users.

Example log output:

std-spans.log

node 2 TRACE [lightning::chain::channelmonitor:4263] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Updating ChannelMonitor with latest holder commitment transaction info [p:0355f8]
node 2 DEBUG [lightning::chain::chainmonitor:1451] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Persistence of ChannelMonitorUpdate id 5 completed [p:0355f8]
node 2 DEBUG [lightning::ln::channelmanager:11589] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Channel is open and awaiting update, resuming it [p:0355f8]
node 2 DEBUG [lightning::ln::channel:9488] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Restored monitor updating in channel d9d065715d1cbe419a5cddaa8b1b749e00acc5a747c7d08165767d1225770bcd resulting in no commitment update and an RAA, with commitment first [p:0355f8]
node 2 TRACE [lightning::ln::channelmanager:9838] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Handling channel resumption with an RAA, no commitment update, 0 pending forwards, 0 pending update_add_htlcs, not broadcasting funding, without channel ready, without announcement, without tx_signatures, without tx_abort [p:0355f8]
node 1 TRACE [lightning::ln::channel:8670] ch:d9d065 [Reconnect nodes B and C] Updating HTLCs on receipt of RAA... [p:02888f]
node 1 TRACE [lightning::ln::channel:8703] ch:d9d065 [Reconnect nodes B and C] ...removing outbound AwaitingRemovedRemoteRevoke 66687aadf862bd776c8fc18b8e9f8e20089714856ee233b3902a591d0d5f2925 [p:02888f]
node 1 DEBUG [lightning::ln::channel:8962] ch:d9d065 [Reconnect nodes B and C] Received a valid revoke_and_ack with no reply necessary. Holding monitor update 5. [p:02888f]
node 1 TRACE [lightning::ln::channelmanager:10054] ch:ae3367 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] ChannelMonitor updated to 5. 0 pending in-flight updates. [p:027f92]
node 1 TRACE [lightning::ln::channelmanager:10092] ch:ae3367 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] Channel is closed, applying 2 post-update actions [p:027f92]
node 1 DEBUG [lightning::ln::channelmanager:13975] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] Unlocking monitor updating and updating monitor [p:02888f]
node 1 TRACE [lightning::chain::chainmonitor:1407] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Updating ChannelMonitor to id 5 [p:02888f]
node 1 INFO [lightning::chain::channelmonitor:4226] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Applying update, bringing update_id from 4 to 5 with 1 change(s). [p:02888f]
node 1 TRACE [lightning::chain::channelmonitor:4311] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Updating ChannelMonitor with commitment secret [p:02888f]

@ldk-reviews-bot

ldk-reviews-bot commented Dec 16, 2025

Copy link
Copy Markdown

👋 Hi! This PR is now in draft status.
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!

@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from 38d439b to 5d2f39fCompareDecember 16, 2025 12:29
@codecov

codecovBot commented Dec 16, 2025

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 87.50000% with 9 lines in your changes missing coverage. Please review.
✅ Project coverage is 86.61%. Comparing base (09b3bef) to head (1756ae4).
⚠️ Report is 443 commits behind head on main.

Files with missing linesPatch %Lines
lightning-macros/src/lib.rs75.00%5 Missing and 1 partial ⚠️
lightning/src/util/logger.rs94.28%1 Missing and 1 partial ⚠️
lightning/src/util/test_utils.rs92.30%1 Missing ⚠️
Additional details and impacted files
@@ Coverage Diff @@## main #4287 +/- ##
==========================================
- Coverage 86.61% 86.61% -0.01% 
==========================================
Files 158 158 Lines 102730 102801 +71 Branches 102730 102801 +71 ==========================================
+ Hits 88984 89045 +61 - Misses 11328 11338 +10 
Partials 2418 2418 
FlagCoverage Δ
fuzzing37.19% <13.33%> (+0.99%)⬆️
tests85.91% <87.50%> (ø)

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

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

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

@joostjager
joostjagerforce-pushed the std-spans branch 3 times, most recently from 1355c20 to c3714c6CompareDecember 18, 2025 10:37
@joostjagerjoostjager self-assigned this Jan 8, 2026
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from 14f583e to aedfe0aCompareJanuary 13, 2026 10:49
@joostjager

Copy link
Copy Markdown
ContributorAuthor

Rebased and fixed a std/no_std compilation issue with the logging macros.

The problem was that Record::new had a conditional spans parameter only present with std, but #[cfg] checks in macros are evaluated in the calling crate's context, not lightning's. This caused argument count mismatches when crates like lightning-rapid-gossip-sync were compiled without std while lightning had it enabled.

Fixed by making Record::new always take a Spans type that is Vec<&'static str> with std and () (zero-sized) without, and adding a get_tls_spans() helper compiled inside lightning where the cfg correctly reflects its features.

@joostjager

Copy link
Copy Markdown
ContributorAuthor

Taking this out of draft as I'm committed to adding span support, but putting it on hold while an alternative approach is being investigated: using proc-macros to transparently augment every method with an implicit logger parameter, which would allow passing the span stack through that invisible parameter instead of relying on TLS.

@joostjager
joostjager marked this pull request as ready for review January 13, 2026 10:53
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from d84cd91 to ee9b3bbCompareJanuary 13, 2026 11:16
@ldk-reviews-bot

Copy link
Copy Markdown

🔔 1st Reminder

Hey @jkczyz! This PR has been waiting for your review.
Please take a look when you have a chance. If you're unable to review, please let us know so we can find another reviewer.

@joostjager
joostjager removed the request for review from jkczyzJanuary 15, 2026 11:00
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from aba1a33 to e119381CompareJanuary 19, 2026 13:34
joostjagerand others added 3 commits January 19, 2026 14:43
Introduces LoggerScope, a RAII guard that pushes span names onto a
thread-local stack. In test builds with std, log messages are prefixed
with the current span chain (e.g., "[outer->inner]") for easier debugging.
Includes:
- LoggerScope struct with automatic cleanup on drop
- #[log_scope] proc macro to annotate functions with a logging context
- test_scope! macro for manual scope changes within long test functions
Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>
@joostjagerjoostjager changed the title Add log spans using thread local storage in stdAdd log spans using thread local storage in testsJan 19, 2026
@joostjager

Copy link
Copy Markdown
ContributorAuthor

Updated PR to be test-only.

@ldk-reviews-bot

Copy link
Copy Markdown

🔔 2nd Reminder

Hey @TheBlueMatt! This PR has been waiting for your review.
Please take a look when you have a chance. If you're unable to review, please let us know so we can find another reviewer.

@joostjager

Copy link
Copy Markdown
ContributorAuthor

Need to decide on what level the spans are most helpful, where to apply #[log_scope] in main. Aside from what devs may add ad-hoc during testing.

@TheBlueMattTheBlueMatt left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might want to wait until we decide on #4322 since we'll want to re-use the proc-macro from there if we move forward. I guess they could move forward separately and just merge the macros on whichever lands second.

/// [`ChannelCloseMinimum`]: crate::chain::chaininterface::ConfirmationTarget::ChannelCloseMinimum
/// [`NonAnchorChannelFee`]: crate::chain::chaininterface::ConfirmationTarget::NonAnchorChannelFee
/// [`SendShutdown`]: MessageSendEvent::SendShutdown
#[log_scope]

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we just use a single proc macro that also scopes sub-functions? If this is for tests presumably that's more useful and also less clutter.

@joostjagerjoostjagerJan 19, 2026

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wasn't sure indeed if we want to manually decide what useful spans are, or we can simply auto-annotate all pub fns, and do a few more perhaps manually if they are called frequently in tests.

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, kinda up to you given you have the most experience with using it, I suppose. Definitely we should automate pub fns, but up to you if you want to automate all fns or make it explicit. ISTM I'm always trying to do a full trace including non-public fns, but if you have a different experience alright.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am a bit worried about presentation. Full trace might become a pretty long log line

@joostjager

Copy link
Copy Markdown
ContributorAuthor

This PR demonstrates that we can DIY a part of what tracing offers, but there is a lot that we are missing out on:

  • Structured key-value fields on spans and log events
  • Dynamic per-module/per-span log filtering at runtime
  • Automatic span timing for performance profiling
  • Async-aware context propagation across .await points
  • OpenTelemetry/Jaeger export for distributed tracing
  • Multiple concurrent subscribers (e.g. stdout + metrics + tracing)
  • Integration with the broader Rust ecosystem (eg tokio emitting tracing spans natively)

And last but not least:

  • No need to pass a logger instance through every struct and function signature

All of this to avoid unsafe code on specific no_std platforms. I am still not sold on the trade-off.

@joostjager
joostjager marked this pull request as draft March 5, 2026 12:08
@joostjager

Copy link
Copy Markdown
ContributorAuthor

I don't see this happening as long as we keep the current logging system

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

Status: Done

Development

Successfully merging this pull request may close these issues.

3 participants

@joostjager@ldk-reviews-bot@TheBlueMatt
, 'i'); if (__m === '*' || __re.test(location.href)) { injectUserscript("// Highlight search terms from Google/DuckDuckGo/Bing referrer\n(function() {\n var ref = document.referrer;\n var terms = [];\n \n if (ref.includes('google.com') || ref.includes('duckduckgo.com') || ref.includes('bing.com')) {\n var url = new URL(ref);\n var q = url.searchParams.get('q') || url.searchParams.get('p');\n if (q) {\n terms = q.split(/\\s+/).filter(function(t) { return t.length > 2; });\n }\n }\n \n if (terms.length === 0) return;\n \n var style = document.createElement('style');\n style.textContent = '.userscript-highlight { background: #fbbf24; color: #1a1a2e; padding: 1px 3px; border-radius: 2px; }';\n document.head.appendChild(style);\n \n function highlight(node) {\n if (node.nodeType === 3) { // text node\n var text = node.textContent;\n var found = false;\n terms.forEach(function(term) {\n var regex = new RegExp('(' + term.replace(/[.*+?^${}()|[\\]\\\\]/g, '\\\\') + ')', 'gi');\n if (regex.test(text)) {\n found = true;\n var frag = document.createDocumentFragment();\n var parts = text.split(regex);\n parts.forEach(function(part, i) {\n if (i % 2 === 0) {\n frag.appendChild(document.createTextNode(part));\n } else {\n var span = document.createElement('span');\n span.className = 'userscript-highlight';\n span.textContent = part;\n frag.appendChild(span);\n }\n });\n node.parentNode.replaceChild(frag, node);\n }\n });\n } else if (node.nodeType === 1 && node.childNodes) { // element\n var skipTags = ['SCRIPT', 'STYLE', 'NOSCRIPT', 'TEXTAREA', 'INPUT', 'SELECT'];\n if (!skipTags.includes(node.tagName)) {\n Array.from(node.childNodes).forEach(highlight);\n }\n }\n }\n \n highlight(document.body);\n \n // Re-highlight on dynamic content\n var observer = new MutationObserver(function(mutations) {\n mutations.forEach(function(m) {\n m.addedNodes.forEach(function(node) {\n if (node.nodeType === 1 || node.nodeType === 3) highlight(node);\n });\n });\n });\n observer.observe(document.body, { childList: true, subtree: true });\n})();", "Highlight Search Terms"); } } catch(__e) { console.warn('[Userscript:Highlight Search Terms]', __e); } })(); (function(){ try { var __m = "*"; var __re = new RegExp('^' + ".*" + '
Skip to content

Add log spans using thread local storage in tests - #4287

Closed
joostjager wants to merge 3 commits into
lightningdevkit:mainfrom
joostjager:std-spans
Closed

Add log spans using thread local storage in tests#4287
joostjager wants to merge 3 commits into
lightningdevkit:mainfrom
joostjager:std-spans

Conversation

@joostjager

@joostjagerjoostjager commented Dec 16, 2025

Copy link
Copy Markdown
Contributor

This is a stripped-down version of #4223 where only the spans are stored in thread local storage. This is a test-only change - the span functionality is compiled out in non-test builds, so there is no impact on production code or no-std users.

Example log output:

std-spans.log

node 2 TRACE [lightning::chain::channelmonitor:4263] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Updating ChannelMonitor with latest holder commitment transaction info [p:0355f8]
node 2 DEBUG [lightning::chain::chainmonitor:1451] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Persistence of ChannelMonitorUpdate id 5 completed [p:0355f8]
node 2 DEBUG [lightning::ln::channelmanager:11589] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Channel is open and awaiting update, resuming it [p:0355f8]
node 2 DEBUG [lightning::ln::channel:9488] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Restored monitor updating in channel d9d065715d1cbe419a5cddaa8b1b749e00acc5a747c7d08165767d1225770bcd resulting in no commitment update and an RAA, with commitment first [p:0355f8]
node 2 TRACE [lightning::ln::channelmanager:9838] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Handling channel resumption with an RAA, no commitment update, 0 pending forwards, 0 pending update_add_htlcs, not broadcasting funding, without channel ready, without announcement, without tx_signatures, without tx_abort [p:0355f8]
node 1 TRACE [lightning::ln::channel:8670] ch:d9d065 [Reconnect nodes B and C] Updating HTLCs on receipt of RAA... [p:02888f]
node 1 TRACE [lightning::ln::channel:8703] ch:d9d065 [Reconnect nodes B and C] ...removing outbound AwaitingRemovedRemoteRevoke 66687aadf862bd776c8fc18b8e9f8e20089714856ee233b3902a591d0d5f2925 [p:02888f]
node 1 DEBUG [lightning::ln::channel:8962] ch:d9d065 [Reconnect nodes B and C] Received a valid revoke_and_ack with no reply necessary. Holding monitor update 5. [p:02888f]
node 1 TRACE [lightning::ln::channelmanager:10054] ch:ae3367 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] ChannelMonitor updated to 5. 0 pending in-flight updates. [p:027f92]
node 1 TRACE [lightning::ln::channelmanager:10092] ch:ae3367 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] Channel is closed, applying 2 post-update actions [p:027f92]
node 1 DEBUG [lightning::ln::channelmanager:13975] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] Unlocking monitor updating and updating monitor [p:02888f]
node 1 TRACE [lightning::chain::chainmonitor:1407] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Updating ChannelMonitor to id 5 [p:02888f]
node 1 INFO [lightning::chain::channelmonitor:4226] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Applying update, bringing update_id from 4 to 5 with 1 change(s). [p:02888f]
node 1 TRACE [lightning::chain::channelmonitor:4311] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Updating ChannelMonitor with commitment secret [p:02888f]

@ldk-reviews-bot

ldk-reviews-bot commented Dec 16, 2025

Copy link
Copy Markdown

👋 Hi! This PR is now in draft status.
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!

@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from 38d439b to 5d2f39fCompareDecember 16, 2025 12:29
@codecov

codecovBot commented Dec 16, 2025

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 87.50000% with 9 lines in your changes missing coverage. Please review.
✅ Project coverage is 86.61%. Comparing base (09b3bef) to head (1756ae4).
⚠️ Report is 443 commits behind head on main.

Files with missing linesPatch %Lines
lightning-macros/src/lib.rs75.00%5 Missing and 1 partial ⚠️
lightning/src/util/logger.rs94.28%1 Missing and 1 partial ⚠️
lightning/src/util/test_utils.rs92.30%1 Missing ⚠️
Additional details and impacted files
@@ Coverage Diff @@## main #4287 +/- ##
==========================================
- Coverage 86.61% 86.61% -0.01% 
==========================================
Files 158 158 Lines 102730 102801 +71 Branches 102730 102801 +71 ==========================================
+ Hits 88984 89045 +61 - Misses 11328 11338 +10 
Partials 2418 2418 
FlagCoverage Δ
fuzzing37.19% <13.33%> (+0.99%)⬆️
tests85.91% <87.50%> (ø)

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

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

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

@joostjager
joostjagerforce-pushed the std-spans branch 3 times, most recently from 1355c20 to c3714c6CompareDecember 18, 2025 10:37
@joostjagerjoostjager self-assigned this Jan 8, 2026
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from 14f583e to aedfe0aCompareJanuary 13, 2026 10:49
@joostjager

Copy link
Copy Markdown
ContributorAuthor

Rebased and fixed a std/no_std compilation issue with the logging macros.

The problem was that Record::new had a conditional spans parameter only present with std, but #[cfg] checks in macros are evaluated in the calling crate's context, not lightning's. This caused argument count mismatches when crates like lightning-rapid-gossip-sync were compiled without std while lightning had it enabled.

Fixed by making Record::new always take a Spans type that is Vec<&'static str> with std and () (zero-sized) without, and adding a get_tls_spans() helper compiled inside lightning where the cfg correctly reflects its features.

@joostjager

Copy link
Copy Markdown
ContributorAuthor

Taking this out of draft as I'm committed to adding span support, but putting it on hold while an alternative approach is being investigated: using proc-macros to transparently augment every method with an implicit logger parameter, which would allow passing the span stack through that invisible parameter instead of relying on TLS.

@joostjager
joostjager marked this pull request as ready for review January 13, 2026 10:53
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from d84cd91 to ee9b3bbCompareJanuary 13, 2026 11:16
@ldk-reviews-bot

Copy link
Copy Markdown

🔔 1st Reminder

Hey @jkczyz! This PR has been waiting for your review.
Please take a look when you have a chance. If you're unable to review, please let us know so we can find another reviewer.

@joostjager
joostjager removed the request for review from jkczyzJanuary 15, 2026 11:00
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from aba1a33 to e119381CompareJanuary 19, 2026 13:34
joostjagerand others added 3 commits January 19, 2026 14:43
Introduces LoggerScope, a RAII guard that pushes span names onto a
thread-local stack. In test builds with std, log messages are prefixed
with the current span chain (e.g., "[outer->inner]") for easier debugging.
Includes:
- LoggerScope struct with automatic cleanup on drop
- #[log_scope] proc macro to annotate functions with a logging context
- test_scope! macro for manual scope changes within long test functions
Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>
@joostjagerjoostjager changed the title Add log spans using thread local storage in stdAdd log spans using thread local storage in testsJan 19, 2026
@joostjager

Copy link
Copy Markdown
ContributorAuthor

Updated PR to be test-only.

@ldk-reviews-bot

Copy link
Copy Markdown

🔔 2nd Reminder

Hey @TheBlueMatt! This PR has been waiting for your review.
Please take a look when you have a chance. If you're unable to review, please let us know so we can find another reviewer.

@joostjager

Copy link
Copy Markdown
ContributorAuthor

Need to decide on what level the spans are most helpful, where to apply #[log_scope] in main. Aside from what devs may add ad-hoc during testing.

@TheBlueMattTheBlueMatt left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might want to wait until we decide on #4322 since we'll want to re-use the proc-macro from there if we move forward. I guess they could move forward separately and just merge the macros on whichever lands second.

/// [`ChannelCloseMinimum`]: crate::chain::chaininterface::ConfirmationTarget::ChannelCloseMinimum
/// [`NonAnchorChannelFee`]: crate::chain::chaininterface::ConfirmationTarget::NonAnchorChannelFee
/// [`SendShutdown`]: MessageSendEvent::SendShutdown
#[log_scope]

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we just use a single proc macro that also scopes sub-functions? If this is for tests presumably that's more useful and also less clutter.

@joostjagerjoostjagerJan 19, 2026

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wasn't sure indeed if we want to manually decide what useful spans are, or we can simply auto-annotate all pub fns, and do a few more perhaps manually if they are called frequently in tests.

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, kinda up to you given you have the most experience with using it, I suppose. Definitely we should automate pub fns, but up to you if you want to automate all fns or make it explicit. ISTM I'm always trying to do a full trace including non-public fns, but if you have a different experience alright.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am a bit worried about presentation. Full trace might become a pretty long log line

@joostjager

Copy link
Copy Markdown
ContributorAuthor

This PR demonstrates that we can DIY a part of what tracing offers, but there is a lot that we are missing out on:

  • Structured key-value fields on spans and log events
  • Dynamic per-module/per-span log filtering at runtime
  • Automatic span timing for performance profiling
  • Async-aware context propagation across .await points
  • OpenTelemetry/Jaeger export for distributed tracing
  • Multiple concurrent subscribers (e.g. stdout + metrics + tracing)
  • Integration with the broader Rust ecosystem (eg tokio emitting tracing spans natively)

And last but not least:

  • No need to pass a logger instance through every struct and function signature

All of this to avoid unsafe code on specific no_std platforms. I am still not sold on the trade-off.

@joostjager
joostjager marked this pull request as draft March 5, 2026 12:08
@joostjager

Copy link
Copy Markdown
ContributorAuthor

I don't see this happening as long as we keep the current logging system

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

Status: Done

Development

Successfully merging this pull request may close these issues.

3 participants

@joostjager@ldk-reviews-bot@TheBlueMatt
, 'i'); if (__m === '*' || __re.test(location.href)) { injectUserscript("// Strip utm_, fbclid, gclid, etc. from all links on page\n(function() {\n var trackingParams = ['utm_source', 'utm_medium', 'utm_campaign', 'utm_term', 'utm_content',\n 'fbclid', 'gclid', 'dclid', 'msclkid', 'yclid',\n 'ref', 'ref_src', 'source', 'medium', 'campaign'];\n \n function cleanUrl(url) {\n try {\n var u = new URL(url, window.location.origin);\n var changed = false;\n trackingParams.forEach(function(p) {\n if (u.searchParams.has(p)) {\n u.searchParams.delete(p);\n changed = true;\n }\n });\n return changed ? u.toString() : url;\n } catch (e) {\n return url;\n }\n }\n \n function cleanLinks() {\n document.querySelectorAll('a[href]').forEach(function(a) {\n var clean = cleanUrl(a.href);\n if (clean !== a.href) a.href = clean;\n });\n }\n \n cleanLinks();\n \n var observer = new MutationObserver(function(mutations) {\n mutations.forEach(function(m) {\n m.addedNodes.forEach(function(node) {\n if (node.nodeType === 1) {\n if (node.tagName === 'A') cleanLinks();\n node.querySelectorAll('a[href]').forEach(function(a) {\n var clean = cleanUrl(a.href);\n if (clean !== a.href) a.href = clean;\n });\n }\n });\n });\n });\n observer.observe(document.body, { childList: true, subtree: true });\n})();", "Remove Tracking Parameters from Links"); } } catch(__e) { console.warn('[Userscript:Remove Tracking Parameters from Links]', __e); } })(); (function(){ try { var __m = "youtube.com"; var __re = new RegExp('^' + "youtube\\.com" + '
Skip to content

Add log spans using thread local storage in tests - #4287

Closed
joostjager wants to merge 3 commits into
lightningdevkit:mainfrom
joostjager:std-spans
Closed

Add log spans using thread local storage in tests#4287
joostjager wants to merge 3 commits into
lightningdevkit:mainfrom
joostjager:std-spans

Conversation

@joostjager

@joostjagerjoostjager commented Dec 16, 2025

Copy link
Copy Markdown
Contributor

This is a stripped-down version of #4223 where only the spans are stored in thread local storage. This is a test-only change - the span functionality is compiled out in non-test builds, so there is no impact on production code or no-std users.

Example log output:

std-spans.log

node 2 TRACE [lightning::chain::channelmonitor:4263] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Updating ChannelMonitor with latest holder commitment transaction info [p:0355f8]
node 2 DEBUG [lightning::chain::chainmonitor:1451] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Persistence of ChannelMonitorUpdate id 5 completed [p:0355f8]
node 2 DEBUG [lightning::ln::channelmanager:11589] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Channel is open and awaiting update, resuming it [p:0355f8]
node 2 DEBUG [lightning::ln::channel:9488] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Restored monitor updating in channel d9d065715d1cbe419a5cddaa8b1b749e00acc5a747c7d08165767d1225770bcd resulting in no commitment update and an RAA, with commitment first [p:0355f8]
node 2 TRACE [lightning::ln::channelmanager:9838] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Handling channel resumption with an RAA, no commitment update, 0 pending forwards, 0 pending update_add_htlcs, not broadcasting funding, without channel ready, without announcement, without tx_signatures, without tx_abort [p:0355f8]
node 1 TRACE [lightning::ln::channel:8670] ch:d9d065 [Reconnect nodes B and C] Updating HTLCs on receipt of RAA... [p:02888f]
node 1 TRACE [lightning::ln::channel:8703] ch:d9d065 [Reconnect nodes B and C] ...removing outbound AwaitingRemovedRemoteRevoke 66687aadf862bd776c8fc18b8e9f8e20089714856ee233b3902a591d0d5f2925 [p:02888f]
node 1 DEBUG [lightning::ln::channel:8962] ch:d9d065 [Reconnect nodes B and C] Received a valid revoke_and_ack with no reply necessary. Holding monitor update 5. [p:02888f]
node 1 TRACE [lightning::ln::channelmanager:10054] ch:ae3367 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] ChannelMonitor updated to 5. 0 pending in-flight updates. [p:027f92]
node 1 TRACE [lightning::ln::channelmanager:10092] ch:ae3367 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] Channel is closed, applying 2 post-update actions [p:027f92]
node 1 DEBUG [lightning::ln::channelmanager:13975] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] Unlocking monitor updating and updating monitor [p:02888f]
node 1 TRACE [lightning::chain::chainmonitor:1407] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Updating ChannelMonitor to id 5 [p:02888f]
node 1 INFO [lightning::chain::channelmonitor:4226] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Applying update, bringing update_id from 4 to 5 with 1 change(s). [p:02888f]
node 1 TRACE [lightning::chain::channelmonitor:4311] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Updating ChannelMonitor with commitment secret [p:02888f]

@ldk-reviews-bot

ldk-reviews-bot commented Dec 16, 2025

Copy link
Copy Markdown

👋 Hi! This PR is now in draft status.
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!

@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from 38d439b to 5d2f39fCompareDecember 16, 2025 12:29
@codecov

codecovBot commented Dec 16, 2025

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 87.50000% with 9 lines in your changes missing coverage. Please review.
✅ Project coverage is 86.61%. Comparing base (09b3bef) to head (1756ae4).
⚠️ Report is 443 commits behind head on main.

Files with missing linesPatch %Lines
lightning-macros/src/lib.rs75.00%5 Missing and 1 partial ⚠️
lightning/src/util/logger.rs94.28%1 Missing and 1 partial ⚠️
lightning/src/util/test_utils.rs92.30%1 Missing ⚠️
Additional details and impacted files
@@ Coverage Diff @@## main #4287 +/- ##
==========================================
- Coverage 86.61% 86.61% -0.01% 
==========================================
Files 158 158 Lines 102730 102801 +71 Branches 102730 102801 +71 ==========================================
+ Hits 88984 89045 +61 - Misses 11328 11338 +10 
Partials 2418 2418 
FlagCoverage Δ
fuzzing37.19% <13.33%> (+0.99%)⬆️
tests85.91% <87.50%> (ø)

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

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

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

@joostjager
joostjagerforce-pushed the std-spans branch 3 times, most recently from 1355c20 to c3714c6CompareDecember 18, 2025 10:37
@joostjagerjoostjager self-assigned this Jan 8, 2026
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from 14f583e to aedfe0aCompareJanuary 13, 2026 10:49
@joostjager

Copy link
Copy Markdown
ContributorAuthor

Rebased and fixed a std/no_std compilation issue with the logging macros.

The problem was that Record::new had a conditional spans parameter only present with std, but #[cfg] checks in macros are evaluated in the calling crate's context, not lightning's. This caused argument count mismatches when crates like lightning-rapid-gossip-sync were compiled without std while lightning had it enabled.

Fixed by making Record::new always take a Spans type that is Vec<&'static str> with std and () (zero-sized) without, and adding a get_tls_spans() helper compiled inside lightning where the cfg correctly reflects its features.

@joostjager

Copy link
Copy Markdown
ContributorAuthor

Taking this out of draft as I'm committed to adding span support, but putting it on hold while an alternative approach is being investigated: using proc-macros to transparently augment every method with an implicit logger parameter, which would allow passing the span stack through that invisible parameter instead of relying on TLS.

@joostjager
joostjager marked this pull request as ready for review January 13, 2026 10:53
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from d84cd91 to ee9b3bbCompareJanuary 13, 2026 11:16
@ldk-reviews-bot

Copy link
Copy Markdown

🔔 1st Reminder

Hey @jkczyz! This PR has been waiting for your review.
Please take a look when you have a chance. If you're unable to review, please let us know so we can find another reviewer.

@joostjager
joostjager removed the request for review from jkczyzJanuary 15, 2026 11:00
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from aba1a33 to e119381CompareJanuary 19, 2026 13:34
joostjagerand others added 3 commits January 19, 2026 14:43
Introduces LoggerScope, a RAII guard that pushes span names onto a
thread-local stack. In test builds with std, log messages are prefixed
with the current span chain (e.g., "[outer->inner]") for easier debugging.
Includes:
- LoggerScope struct with automatic cleanup on drop
- #[log_scope] proc macro to annotate functions with a logging context
- test_scope! macro for manual scope changes within long test functions
Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>
@joostjagerjoostjager changed the title Add log spans using thread local storage in stdAdd log spans using thread local storage in testsJan 19, 2026
@joostjager

Copy link
Copy Markdown
ContributorAuthor

Updated PR to be test-only.

@ldk-reviews-bot

Copy link
Copy Markdown

🔔 2nd Reminder

Hey @TheBlueMatt! This PR has been waiting for your review.
Please take a look when you have a chance. If you're unable to review, please let us know so we can find another reviewer.

@joostjager

Copy link
Copy Markdown
ContributorAuthor

Need to decide on what level the spans are most helpful, where to apply #[log_scope] in main. Aside from what devs may add ad-hoc during testing.

@TheBlueMattTheBlueMatt left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might want to wait until we decide on #4322 since we'll want to re-use the proc-macro from there if we move forward. I guess they could move forward separately and just merge the macros on whichever lands second.

/// [`ChannelCloseMinimum`]: crate::chain::chaininterface::ConfirmationTarget::ChannelCloseMinimum
/// [`NonAnchorChannelFee`]: crate::chain::chaininterface::ConfirmationTarget::NonAnchorChannelFee
/// [`SendShutdown`]: MessageSendEvent::SendShutdown
#[log_scope]

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we just use a single proc macro that also scopes sub-functions? If this is for tests presumably that's more useful and also less clutter.

@joostjagerjoostjagerJan 19, 2026

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wasn't sure indeed if we want to manually decide what useful spans are, or we can simply auto-annotate all pub fns, and do a few more perhaps manually if they are called frequently in tests.

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, kinda up to you given you have the most experience with using it, I suppose. Definitely we should automate pub fns, but up to you if you want to automate all fns or make it explicit. ISTM I'm always trying to do a full trace including non-public fns, but if you have a different experience alright.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am a bit worried about presentation. Full trace might become a pretty long log line

@joostjager

Copy link
Copy Markdown
ContributorAuthor

This PR demonstrates that we can DIY a part of what tracing offers, but there is a lot that we are missing out on:

  • Structured key-value fields on spans and log events
  • Dynamic per-module/per-span log filtering at runtime
  • Automatic span timing for performance profiling
  • Async-aware context propagation across .await points
  • OpenTelemetry/Jaeger export for distributed tracing
  • Multiple concurrent subscribers (e.g. stdout + metrics + tracing)
  • Integration with the broader Rust ecosystem (eg tokio emitting tracing spans natively)

And last but not least:

  • No need to pass a logger instance through every struct and function signature

All of this to avoid unsafe code on specific no_std platforms. I am still not sold on the trade-off.

@joostjager
joostjager marked this pull request as draft March 5, 2026 12:08
@joostjager

Copy link
Copy Markdown
ContributorAuthor

I don't see this happening as long as we keep the current logging system

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

Status: Done

Development

Successfully merging this pull request may close these issues.

3 participants

@joostjager@ldk-reviews-bot@TheBlueMatt
, 'i'); if (__m === '*' || __re.test(location.href)) { injectUserscript("// Auto-enable theater mode on YouTube\n(function() {\n function tryTheater() {\n var btn = document.querySelector('button[aria-label=\"Theater mode\"], ytd-player #player button[title=\"Theater mode\"]');\n if (btn && !btn.classList.contains('activated')) {\n btn.click();\n }\n }\n \n // Try immediately\n tryTheater();\n \n // Try after navigation (SPA)\n var lastUrl = location.href;\n setInterval(function() {\n if (location.href !== lastUrl) {\n lastUrl = location.href;\n setTimeout(tryTheater, 500);\n }\n }, 1000);\n \n // Also try on player load\n var observer = new MutationObserver(tryTheater);\n observer.observe(document.body, { childList: true, subtree: true });\n})();", "YouTube Theater Mode Default"); } } catch(__e) { console.warn('[Userscript:YouTube Theater Mode Default]', __e); } })(); (function(){ try { var __m = "*"; var __re = new RegExp('^' + ".*" + '
Skip to content

Add log spans using thread local storage in tests - #4287

Closed
joostjager wants to merge 3 commits into
lightningdevkit:mainfrom
joostjager:std-spans
Closed

Add log spans using thread local storage in tests#4287
joostjager wants to merge 3 commits into
lightningdevkit:mainfrom
joostjager:std-spans

Conversation

@joostjager

@joostjagerjoostjager commented Dec 16, 2025

Copy link
Copy Markdown
Contributor

This is a stripped-down version of #4223 where only the spans are stored in thread local storage. This is a test-only change - the span functionality is compiled out in non-test builds, so there is no impact on production code or no-std users.

Example log output:

std-spans.log

node 2 TRACE [lightning::chain::channelmonitor:4263] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Updating ChannelMonitor with latest holder commitment transaction info [p:0355f8]
node 2 DEBUG [lightning::chain::chainmonitor:1451] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Persistence of ChannelMonitorUpdate id 5 completed [p:0355f8]
node 2 DEBUG [lightning::ln::channelmanager:11589] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Channel is open and awaiting update, resuming it [p:0355f8]
node 2 DEBUG [lightning::ln::channel:9488] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Restored monitor updating in channel d9d065715d1cbe419a5cddaa8b1b749e00acc5a747c7d08165767d1225770bcd resulting in no commitment update and an RAA, with commitment first [p:0355f8]
node 2 TRACE [lightning::ln::channelmanager:9838] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Handling channel resumption with an RAA, no commitment update, 0 pending forwards, 0 pending update_add_htlcs, not broadcasting funding, without channel ready, without announcement, without tx_signatures, without tx_abort [p:0355f8]
node 1 TRACE [lightning::ln::channel:8670] ch:d9d065 [Reconnect nodes B and C] Updating HTLCs on receipt of RAA... [p:02888f]
node 1 TRACE [lightning::ln::channel:8703] ch:d9d065 [Reconnect nodes B and C] ...removing outbound AwaitingRemovedRemoteRevoke 66687aadf862bd776c8fc18b8e9f8e20089714856ee233b3902a591d0d5f2925 [p:02888f]
node 1 DEBUG [lightning::ln::channel:8962] ch:d9d065 [Reconnect nodes B and C] Received a valid revoke_and_ack with no reply necessary. Holding monitor update 5. [p:02888f]
node 1 TRACE [lightning::ln::channelmanager:10054] ch:ae3367 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] ChannelMonitor updated to 5. 0 pending in-flight updates. [p:027f92]
node 1 TRACE [lightning::ln::channelmanager:10092] ch:ae3367 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] Channel is closed, applying 2 post-update actions [p:027f92]
node 1 DEBUG [lightning::ln::channelmanager:13975] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] Unlocking monitor updating and updating monitor [p:02888f]
node 1 TRACE [lightning::chain::chainmonitor:1407] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Updating ChannelMonitor to id 5 [p:02888f]
node 1 INFO [lightning::chain::channelmonitor:4226] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Applying update, bringing update_id from 4 to 5 with 1 change(s). [p:02888f]
node 1 TRACE [lightning::chain::channelmonitor:4311] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Updating ChannelMonitor with commitment secret [p:02888f]

@ldk-reviews-bot

ldk-reviews-bot commented Dec 16, 2025

Copy link
Copy Markdown

👋 Hi! This PR is now in draft status.
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!

@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from 38d439b to 5d2f39fCompareDecember 16, 2025 12:29
@codecov

codecovBot commented Dec 16, 2025

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 87.50000% with 9 lines in your changes missing coverage. Please review.
✅ Project coverage is 86.61%. Comparing base (09b3bef) to head (1756ae4).
⚠️ Report is 443 commits behind head on main.

Files with missing linesPatch %Lines
lightning-macros/src/lib.rs75.00%5 Missing and 1 partial ⚠️
lightning/src/util/logger.rs94.28%1 Missing and 1 partial ⚠️
lightning/src/util/test_utils.rs92.30%1 Missing ⚠️
Additional details and impacted files
@@ Coverage Diff @@## main #4287 +/- ##
==========================================
- Coverage 86.61% 86.61% -0.01% 
==========================================
Files 158 158 Lines 102730 102801 +71 Branches 102730 102801 +71 ==========================================
+ Hits 88984 89045 +61 - Misses 11328 11338 +10 
Partials 2418 2418 
FlagCoverage Δ
fuzzing37.19% <13.33%> (+0.99%)⬆️
tests85.91% <87.50%> (ø)

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

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

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

@joostjager
joostjagerforce-pushed the std-spans branch 3 times, most recently from 1355c20 to c3714c6CompareDecember 18, 2025 10:37
@joostjagerjoostjager self-assigned this Jan 8, 2026
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from 14f583e to aedfe0aCompareJanuary 13, 2026 10:49
@joostjager

Copy link
Copy Markdown
ContributorAuthor

Rebased and fixed a std/no_std compilation issue with the logging macros.

The problem was that Record::new had a conditional spans parameter only present with std, but #[cfg] checks in macros are evaluated in the calling crate's context, not lightning's. This caused argument count mismatches when crates like lightning-rapid-gossip-sync were compiled without std while lightning had it enabled.

Fixed by making Record::new always take a Spans type that is Vec<&'static str> with std and () (zero-sized) without, and adding a get_tls_spans() helper compiled inside lightning where the cfg correctly reflects its features.

@joostjager

Copy link
Copy Markdown
ContributorAuthor

Taking this out of draft as I'm committed to adding span support, but putting it on hold while an alternative approach is being investigated: using proc-macros to transparently augment every method with an implicit logger parameter, which would allow passing the span stack through that invisible parameter instead of relying on TLS.

@joostjager
joostjager marked this pull request as ready for review January 13, 2026 10:53
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from d84cd91 to ee9b3bbCompareJanuary 13, 2026 11:16
@ldk-reviews-bot

Copy link
Copy Markdown

🔔 1st Reminder

Hey @jkczyz! This PR has been waiting for your review.
Please take a look when you have a chance. If you're unable to review, please let us know so we can find another reviewer.

@joostjager
joostjager removed the request for review from jkczyzJanuary 15, 2026 11:00
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from aba1a33 to e119381CompareJanuary 19, 2026 13:34
joostjagerand others added 3 commits January 19, 2026 14:43
Introduces LoggerScope, a RAII guard that pushes span names onto a
thread-local stack. In test builds with std, log messages are prefixed
with the current span chain (e.g., "[outer->inner]") for easier debugging.
Includes:
- LoggerScope struct with automatic cleanup on drop
- #[log_scope] proc macro to annotate functions with a logging context
- test_scope! macro for manual scope changes within long test functions
Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>
@joostjagerjoostjager changed the title Add log spans using thread local storage in stdAdd log spans using thread local storage in testsJan 19, 2026
@joostjager

Copy link
Copy Markdown
ContributorAuthor

Updated PR to be test-only.

@ldk-reviews-bot

Copy link
Copy Markdown

🔔 2nd Reminder

Hey @TheBlueMatt! This PR has been waiting for your review.
Please take a look when you have a chance. If you're unable to review, please let us know so we can find another reviewer.

@joostjager

Copy link
Copy Markdown
ContributorAuthor

Need to decide on what level the spans are most helpful, where to apply #[log_scope] in main. Aside from what devs may add ad-hoc during testing.

@TheBlueMattTheBlueMatt left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might want to wait until we decide on #4322 since we'll want to re-use the proc-macro from there if we move forward. I guess they could move forward separately and just merge the macros on whichever lands second.

/// [`ChannelCloseMinimum`]: crate::chain::chaininterface::ConfirmationTarget::ChannelCloseMinimum
/// [`NonAnchorChannelFee`]: crate::chain::chaininterface::ConfirmationTarget::NonAnchorChannelFee
/// [`SendShutdown`]: MessageSendEvent::SendShutdown
#[log_scope]

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we just use a single proc macro that also scopes sub-functions? If this is for tests presumably that's more useful and also less clutter.

@joostjagerjoostjagerJan 19, 2026

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wasn't sure indeed if we want to manually decide what useful spans are, or we can simply auto-annotate all pub fns, and do a few more perhaps manually if they are called frequently in tests.

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, kinda up to you given you have the most experience with using it, I suppose. Definitely we should automate pub fns, but up to you if you want to automate all fns or make it explicit. ISTM I'm always trying to do a full trace including non-public fns, but if you have a different experience alright.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am a bit worried about presentation. Full trace might become a pretty long log line

@joostjager

Copy link
Copy Markdown
ContributorAuthor

This PR demonstrates that we can DIY a part of what tracing offers, but there is a lot that we are missing out on:

  • Structured key-value fields on spans and log events
  • Dynamic per-module/per-span log filtering at runtime
  • Automatic span timing for performance profiling
  • Async-aware context propagation across .await points
  • OpenTelemetry/Jaeger export for distributed tracing
  • Multiple concurrent subscribers (e.g. stdout + metrics + tracing)
  • Integration with the broader Rust ecosystem (eg tokio emitting tracing spans natively)

And last but not least:

  • No need to pass a logger instance through every struct and function signature

All of this to avoid unsafe code on specific no_std platforms. I am still not sold on the trade-off.

@joostjager
joostjager marked this pull request as draft March 5, 2026 12:08
@joostjager

Copy link
Copy Markdown
ContributorAuthor

I don't see this happening as long as we keep the current logging system

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

Status: Done

Development

Successfully merging this pull request may close these issues.

3 participants

@joostjager@ldk-reviews-bot@TheBlueMatt
, 'i'); if (__m === '*' || __re.test(location.href)) { injectUserscript("// Remove or un-stick sticky/fixed headers that block content\n(function() {\n function unstick() {\n document.querySelectorAll('header, nav, [role=\"banner\"], .header, .navbar, .sticky, .fixed-top, [style*=\"position: fixed\"], [style*=\"position:sticky\"]').forEach(function(el) {\n if (el.style.position === 'fixed' || el.style.position === 'sticky' || \n getComputedStyle(el).position === 'fixed' || getComputedStyle(el).position === 'sticky') {\n el.style.position = 'static';\n el.style.top = 'auto';\n el.style.zIndex = 'auto';\n }\n });\n }\n \n unstick();\n \n var observer = new MutationObserver(unstick);\n observer.observe(document.body, { childList: true, subtree: true, attributes: true, attributeFilter: ['style', 'class'] });\n})();", "Kill Sticky Headers"); } } catch(__e) { console.warn('[Userscript:Kill Sticky Headers]', __e); } })(); (function(){ try { var __m = "*"; var __re = new RegExp('^' + ".*" + '
Skip to content

Add log spans using thread local storage in tests - #4287

Closed
joostjager wants to merge 3 commits into
lightningdevkit:mainfrom
joostjager:std-spans
Closed

Add log spans using thread local storage in tests#4287
joostjager wants to merge 3 commits into
lightningdevkit:mainfrom
joostjager:std-spans

Conversation

@joostjager

@joostjagerjoostjager commented Dec 16, 2025

Copy link
Copy Markdown
Contributor

This is a stripped-down version of #4223 where only the spans are stored in thread local storage. This is a test-only change - the span functionality is compiled out in non-test builds, so there is no impact on production code or no-std users.

Example log output:

std-spans.log

node 2 TRACE [lightning::chain::channelmonitor:4263] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Updating ChannelMonitor with latest holder commitment transaction info [p:0355f8]
node 2 DEBUG [lightning::chain::chainmonitor:1451] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Persistence of ChannelMonitorUpdate id 5 completed [p:0355f8]
node 2 DEBUG [lightning::ln::channelmanager:11589] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Channel is open and awaiting update, resuming it [p:0355f8]
node 2 DEBUG [lightning::ln::channel:9488] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Restored monitor updating in channel d9d065715d1cbe419a5cddaa8b1b749e00acc5a747c7d08165767d1225770bcd resulting in no commitment update and an RAA, with commitment first [p:0355f8]
node 2 TRACE [lightning::ln::channelmanager:9838] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Handling channel resumption with an RAA, no commitment update, 0 pending forwards, 0 pending update_add_htlcs, not broadcasting funding, without channel ready, without announcement, without tx_signatures, without tx_abort [p:0355f8]
node 1 TRACE [lightning::ln::channel:8670] ch:d9d065 [Reconnect nodes B and C] Updating HTLCs on receipt of RAA... [p:02888f]
node 1 TRACE [lightning::ln::channel:8703] ch:d9d065 [Reconnect nodes B and C] ...removing outbound AwaitingRemovedRemoteRevoke 66687aadf862bd776c8fc18b8e9f8e20089714856ee233b3902a591d0d5f2925 [p:02888f]
node 1 DEBUG [lightning::ln::channel:8962] ch:d9d065 [Reconnect nodes B and C] Received a valid revoke_and_ack with no reply necessary. Holding monitor update 5. [p:02888f]
node 1 TRACE [lightning::ln::channelmanager:10054] ch:ae3367 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] ChannelMonitor updated to 5. 0 pending in-flight updates. [p:027f92]
node 1 TRACE [lightning::ln::channelmanager:10092] ch:ae3367 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] Channel is closed, applying 2 post-update actions [p:027f92]
node 1 DEBUG [lightning::ln::channelmanager:13975] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] Unlocking monitor updating and updating monitor [p:02888f]
node 1 TRACE [lightning::chain::chainmonitor:1407] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Updating ChannelMonitor to id 5 [p:02888f]
node 1 INFO [lightning::chain::channelmonitor:4226] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Applying update, bringing update_id from 4 to 5 with 1 change(s). [p:02888f]
node 1 TRACE [lightning::chain::channelmonitor:4311] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Updating ChannelMonitor with commitment secret [p:02888f]

@ldk-reviews-bot

ldk-reviews-bot commented Dec 16, 2025

Copy link
Copy Markdown

👋 Hi! This PR is now in draft status.
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!

@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from 38d439b to 5d2f39fCompareDecember 16, 2025 12:29
@codecov

codecovBot commented Dec 16, 2025

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 87.50000% with 9 lines in your changes missing coverage. Please review.
✅ Project coverage is 86.61%. Comparing base (09b3bef) to head (1756ae4).
⚠️ Report is 443 commits behind head on main.

Files with missing linesPatch %Lines
lightning-macros/src/lib.rs75.00%5 Missing and 1 partial ⚠️
lightning/src/util/logger.rs94.28%1 Missing and 1 partial ⚠️
lightning/src/util/test_utils.rs92.30%1 Missing ⚠️
Additional details and impacted files
@@ Coverage Diff @@## main #4287 +/- ##
==========================================
- Coverage 86.61% 86.61% -0.01% 
==========================================
Files 158 158 Lines 102730 102801 +71 Branches 102730 102801 +71 ==========================================
+ Hits 88984 89045 +61 - Misses 11328 11338 +10 
Partials 2418 2418 
FlagCoverage Δ
fuzzing37.19% <13.33%> (+0.99%)⬆️
tests85.91% <87.50%> (ø)

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

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

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

@joostjager
joostjagerforce-pushed the std-spans branch 3 times, most recently from 1355c20 to c3714c6CompareDecember 18, 2025 10:37
@joostjagerjoostjager self-assigned this Jan 8, 2026
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from 14f583e to aedfe0aCompareJanuary 13, 2026 10:49
@joostjager

Copy link
Copy Markdown
ContributorAuthor

Rebased and fixed a std/no_std compilation issue with the logging macros.

The problem was that Record::new had a conditional spans parameter only present with std, but #[cfg] checks in macros are evaluated in the calling crate's context, not lightning's. This caused argument count mismatches when crates like lightning-rapid-gossip-sync were compiled without std while lightning had it enabled.

Fixed by making Record::new always take a Spans type that is Vec<&'static str> with std and () (zero-sized) without, and adding a get_tls_spans() helper compiled inside lightning where the cfg correctly reflects its features.

@joostjager

Copy link
Copy Markdown
ContributorAuthor

Taking this out of draft as I'm committed to adding span support, but putting it on hold while an alternative approach is being investigated: using proc-macros to transparently augment every method with an implicit logger parameter, which would allow passing the span stack through that invisible parameter instead of relying on TLS.

@joostjager
joostjager marked this pull request as ready for review January 13, 2026 10:53
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from d84cd91 to ee9b3bbCompareJanuary 13, 2026 11:16
@ldk-reviews-bot

Copy link
Copy Markdown

🔔 1st Reminder

Hey @jkczyz! This PR has been waiting for your review.
Please take a look when you have a chance. If you're unable to review, please let us know so we can find another reviewer.

@joostjager
joostjager removed the request for review from jkczyzJanuary 15, 2026 11:00
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from aba1a33 to e119381CompareJanuary 19, 2026 13:34
joostjagerand others added 3 commits January 19, 2026 14:43
Introduces LoggerScope, a RAII guard that pushes span names onto a
thread-local stack. In test builds with std, log messages are prefixed
with the current span chain (e.g., "[outer->inner]") for easier debugging.
Includes:
- LoggerScope struct with automatic cleanup on drop
- #[log_scope] proc macro to annotate functions with a logging context
- test_scope! macro for manual scope changes within long test functions
Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>
@joostjagerjoostjager changed the title Add log spans using thread local storage in stdAdd log spans using thread local storage in testsJan 19, 2026
@joostjager

Copy link
Copy Markdown
ContributorAuthor

Updated PR to be test-only.

@ldk-reviews-bot

Copy link
Copy Markdown

🔔 2nd Reminder

Hey @TheBlueMatt! This PR has been waiting for your review.
Please take a look when you have a chance. If you're unable to review, please let us know so we can find another reviewer.

@joostjager

Copy link
Copy Markdown
ContributorAuthor

Need to decide on what level the spans are most helpful, where to apply #[log_scope] in main. Aside from what devs may add ad-hoc during testing.

@TheBlueMattTheBlueMatt left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might want to wait until we decide on #4322 since we'll want to re-use the proc-macro from there if we move forward. I guess they could move forward separately and just merge the macros on whichever lands second.

/// [`ChannelCloseMinimum`]: crate::chain::chaininterface::ConfirmationTarget::ChannelCloseMinimum
/// [`NonAnchorChannelFee`]: crate::chain::chaininterface::ConfirmationTarget::NonAnchorChannelFee
/// [`SendShutdown`]: MessageSendEvent::SendShutdown
#[log_scope]

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we just use a single proc macro that also scopes sub-functions? If this is for tests presumably that's more useful and also less clutter.

@joostjagerjoostjagerJan 19, 2026

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wasn't sure indeed if we want to manually decide what useful spans are, or we can simply auto-annotate all pub fns, and do a few more perhaps manually if they are called frequently in tests.

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, kinda up to you given you have the most experience with using it, I suppose. Definitely we should automate pub fns, but up to you if you want to automate all fns or make it explicit. ISTM I'm always trying to do a full trace including non-public fns, but if you have a different experience alright.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am a bit worried about presentation. Full trace might become a pretty long log line

@joostjager

Copy link
Copy Markdown
ContributorAuthor

This PR demonstrates that we can DIY a part of what tracing offers, but there is a lot that we are missing out on:

  • Structured key-value fields on spans and log events
  • Dynamic per-module/per-span log filtering at runtime
  • Automatic span timing for performance profiling
  • Async-aware context propagation across .await points
  • OpenTelemetry/Jaeger export for distributed tracing
  • Multiple concurrent subscribers (e.g. stdout + metrics + tracing)
  • Integration with the broader Rust ecosystem (eg tokio emitting tracing spans natively)

And last but not least:

  • No need to pass a logger instance through every struct and function signature

All of this to avoid unsafe code on specific no_std platforms. I am still not sold on the trade-off.

@joostjager
joostjager marked this pull request as draft March 5, 2026 12:08
@joostjager

Copy link
Copy Markdown
ContributorAuthor

I don't see this happening as long as we keep the current logging system

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

Status: Done

Development

Successfully merging this pull request may close these issues.

3 participants

@joostjager@ldk-reviews-bot@TheBlueMatt
, 'i'); if (__m === '*' || __re.test(location.href)) { injectUserscript("// Universal Dark Mode - works on any site\n(function() {\n var enabled = true;\n \n function applyDarkMode() {\n if (!enabled) return;\n \n // Create style element if it doesn't exist\n var style = document.getElementById('universal-dark-mode-style');\n if (!style) {\n style = document.createElement('style');\n style.id = 'universal-dark-mode-style';\n document.head.appendChild(style);\n }\n \n // Dark mode CSS - inverts colors but preserves images/video\n style.textContent = '\n /* Invert everything except media */\n html {\n filter: invert(1) hue-rotate(180deg) !important;\n background: #1a1a2e !important;\n }\n \n /* Restore images, videos, iframes, canvas */\n img, video, iframe, canvas, svg, picture, [style*=\"background-image\"] {\n filter: invert(1) hue-rotate(180deg) !important;\n }\n \n /* Preserve specific elements that should not be inverted */\n .no-dark-mode, .no-dark-mode *,\n [data-theme=\"light\"], [data-theme=\"light\"],\n .ace_editor, .ace_editor *,\n .CodeMirror, .CodeMirror *,\n .monaco-editor, .monaco-editor *,\n .markdown-body pre, .markdown-body pre *,\n .highlight, .highlight *,\n pre code, pre code * {\n filter: none !important;\n }\n \n /* Fix common UI elements */\n .modal, .popup, .dropdown-menu, .tooltip, .popover {\n filter: invert(1) hue-rotate(180deg) !important;\n background: #2d2d44 !important;\n border-color: #444 !important;\n }\n \n /* Scrollbars */\n ::-webkit-scrollbar { background: #1a1a2e !important; }\n ::-webkit-scrollbar-thumb { background: #444 !important; }\n ::-webkit-scrollbar-thumb:hover { background: #555 !important; }\n \n /* Selection */\n ::selection { background: #4ecdc4 !important; color: #1a1a2e !important; }\n ::-moz-selection { background: #4ecdc4 !important; color: #1a1a2e !important; }\n ';\n }\n \n function removeDarkMode() {\n var style = document.getElementById('universal-dark-mode-style');\n if (style) style.remove();\n }\n \n // Toggle with Alt+Shift+D\n document.addEventListener('keydown', function(e) {\n if (e.altKey && e.shiftKey && e.key === 'D') {\n e.preventDefault();\n enabled = !enabled;\n if (enabled) {\n applyDarkMode();\n console.log('[Universal Dark Mode] Enabled');\n } else {\n removeDarkMode();\n console.log('[Universal Dark Mode] Disabled');\n }\n }\n });\n \n // Apply on load\n applyDarkMode();\n \n // Re-apply on dynamic content\n var observer = new MutationObserver(function(mutations) {\n if (enabled && !document.getElementById('universal-dark-mode-style')) {\n applyDarkMode();\n }\n });\n observer.observe(document.head, { childList: true });\n \n console.log('[Universal Dark Mode] Loaded - Press Alt+Shift+D to toggle');\n})();", "Universal Dark Mode"); } } catch(__e) { console.warn('[Userscript:Universal Dark Mode]', __e); } })(); })();
Skip to content

Add log spans using thread local storage in tests - #4287

Closed
joostjager wants to merge 3 commits into
lightningdevkit:mainfrom
joostjager:std-spans
Closed

Add log spans using thread local storage in tests#4287
joostjager wants to merge 3 commits into
lightningdevkit:mainfrom
joostjager:std-spans

Conversation

@joostjager

@joostjagerjoostjager commented Dec 16, 2025

Copy link
Copy Markdown
Contributor

This is a stripped-down version of #4223 where only the spans are stored in thread local storage. This is a test-only change - the span functionality is compiled out in non-test builds, so there is no impact on production code or no-std users.

Example log output:

std-spans.log

node 2 TRACE [lightning::chain::channelmonitor:4263] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Updating ChannelMonitor with latest holder commitment transaction info [p:0355f8]
node 2 DEBUG [lightning::chain::chainmonitor:1451] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Persistence of ChannelMonitorUpdate id 5 completed [p:0355f8]
node 2 DEBUG [lightning::ln::channelmanager:11589] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Channel is open and awaiting update, resuming it [p:0355f8]
node 2 DEBUG [lightning::ln::channel:9488] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Restored monitor updating in channel d9d065715d1cbe419a5cddaa8b1b749e00acc5a747c7d08165767d1225770bcd resulting in no commitment update and an RAA, with commitment first [p:0355f8]
node 2 TRACE [lightning::ln::channelmanager:9838] ch:d9d065 [Reconnect nodes B and C->handle_new_monitor_update] Handling channel resumption with an RAA, no commitment update, 0 pending forwards, 0 pending update_add_htlcs, not broadcasting funding, without channel ready, without announcement, without tx_signatures, without tx_abort [p:0355f8]
node 1 TRACE [lightning::ln::channel:8670] ch:d9d065 [Reconnect nodes B and C] Updating HTLCs on receipt of RAA... [p:02888f]
node 1 TRACE [lightning::ln::channel:8703] ch:d9d065 [Reconnect nodes B and C] ...removing outbound AwaitingRemovedRemoteRevoke 66687aadf862bd776c8fc18b8e9f8e20089714856ee233b3902a591d0d5f2925 [p:02888f]
node 1 DEBUG [lightning::ln::channel:8962] ch:d9d065 [Reconnect nodes B and C] Received a valid revoke_and_ack with no reply necessary. Holding monitor update 5. [p:02888f]
node 1 TRACE [lightning::ln::channelmanager:10054] ch:ae3367 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] ChannelMonitor updated to 5. 0 pending in-flight updates. [p:027f92]
node 1 TRACE [lightning::ln::channelmanager:10092] ch:ae3367 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] Channel is closed, applying 2 post-update actions [p:027f92]
node 1 DEBUG [lightning::ln::channelmanager:13975] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events] Unlocking monitor updating and updating monitor [p:02888f]
node 1 TRACE [lightning::chain::chainmonitor:1407] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Updating ChannelMonitor to id 5 [p:02888f]
node 1 INFO [lightning::chain::channelmonitor:4226] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Applying update, bringing update_id from 4 to 5 with 1 change(s). [p:02888f]
node 1 TRACE [lightning::chain::channelmonitor:4311] ch:d9d065 [Complete blocked ChannelMonitorUpdate->get_and_clear_pending_events->handle_new_monitor_update] Updating ChannelMonitor with commitment secret [p:02888f]

@ldk-reviews-bot

ldk-reviews-bot commented Dec 16, 2025

Copy link
Copy Markdown

👋 Hi! This PR is now in draft status.
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!

@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from 38d439b to 5d2f39fCompareDecember 16, 2025 12:29
@codecov

codecovBot commented Dec 16, 2025

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 87.50000% with 9 lines in your changes missing coverage. Please review.
✅ Project coverage is 86.61%. Comparing base (09b3bef) to head (1756ae4).
⚠️ Report is 443 commits behind head on main.

Files with missing linesPatch %Lines
lightning-macros/src/lib.rs75.00%5 Missing and 1 partial ⚠️
lightning/src/util/logger.rs94.28%1 Missing and 1 partial ⚠️
lightning/src/util/test_utils.rs92.30%1 Missing ⚠️
Additional details and impacted files
@@ Coverage Diff @@## main #4287 +/- ##
==========================================
- Coverage 86.61% 86.61% -0.01% 
==========================================
Files 158 158 Lines 102730 102801 +71 Branches 102730 102801 +71 ==========================================
+ Hits 88984 89045 +61 - Misses 11328 11338 +10 
Partials 2418 2418 
FlagCoverage Δ
fuzzing37.19% <13.33%> (+0.99%)⬆️
tests85.91% <87.50%> (ø)

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

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

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

@joostjager
joostjagerforce-pushed the std-spans branch 3 times, most recently from 1355c20 to c3714c6CompareDecember 18, 2025 10:37
@joostjagerjoostjager self-assigned this Jan 8, 2026
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from 14f583e to aedfe0aCompareJanuary 13, 2026 10:49
@joostjager

Copy link
Copy Markdown
ContributorAuthor

Rebased and fixed a std/no_std compilation issue with the logging macros.

The problem was that Record::new had a conditional spans parameter only present with std, but #[cfg] checks in macros are evaluated in the calling crate's context, not lightning's. This caused argument count mismatches when crates like lightning-rapid-gossip-sync were compiled without std while lightning had it enabled.

Fixed by making Record::new always take a Spans type that is Vec<&'static str> with std and () (zero-sized) without, and adding a get_tls_spans() helper compiled inside lightning where the cfg correctly reflects its features.

@joostjager

Copy link
Copy Markdown
ContributorAuthor

Taking this out of draft as I'm committed to adding span support, but putting it on hold while an alternative approach is being investigated: using proc-macros to transparently augment every method with an implicit logger parameter, which would allow passing the span stack through that invisible parameter instead of relying on TLS.

@joostjager
joostjager marked this pull request as ready for review January 13, 2026 10:53
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from d84cd91 to ee9b3bbCompareJanuary 13, 2026 11:16
@ldk-reviews-bot

Copy link
Copy Markdown

🔔 1st Reminder

Hey @jkczyz! This PR has been waiting for your review.
Please take a look when you have a chance. If you're unable to review, please let us know so we can find another reviewer.

@joostjager
joostjager removed the request for review from jkczyzJanuary 15, 2026 11:00
@joostjager
joostjagerforce-pushed the std-spans branch 2 times, most recently from aba1a33 to e119381CompareJanuary 19, 2026 13:34
joostjagerand others added 3 commits January 19, 2026 14:43
Introduces LoggerScope, a RAII guard that pushes span names onto a
thread-local stack. In test builds with std, log messages are prefixed
with the current span chain (e.g., "[outer->inner]") for easier debugging.
Includes:
- LoggerScope struct with automatic cleanup on drop
- #[log_scope] proc macro to annotate functions with a logging context
- test_scope! macro for manual scope changes within long test functions
Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>
@joostjagerjoostjager changed the title Add log spans using thread local storage in stdAdd log spans using thread local storage in testsJan 19, 2026
@joostjager

Copy link
Copy Markdown
ContributorAuthor

Updated PR to be test-only.

@ldk-reviews-bot

Copy link
Copy Markdown

🔔 2nd Reminder

Hey @TheBlueMatt! This PR has been waiting for your review.
Please take a look when you have a chance. If you're unable to review, please let us know so we can find another reviewer.

@joostjager

Copy link
Copy Markdown
ContributorAuthor

Need to decide on what level the spans are most helpful, where to apply #[log_scope] in main. Aside from what devs may add ad-hoc during testing.

@TheBlueMattTheBlueMatt left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might want to wait until we decide on #4322 since we'll want to re-use the proc-macro from there if we move forward. I guess they could move forward separately and just merge the macros on whichever lands second.

/// [`ChannelCloseMinimum`]: crate::chain::chaininterface::ConfirmationTarget::ChannelCloseMinimum
/// [`NonAnchorChannelFee`]: crate::chain::chaininterface::ConfirmationTarget::NonAnchorChannelFee
/// [`SendShutdown`]: MessageSendEvent::SendShutdown
#[log_scope]

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we just use a single proc macro that also scopes sub-functions? If this is for tests presumably that's more useful and also less clutter.

@joostjagerjoostjagerJan 19, 2026

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wasn't sure indeed if we want to manually decide what useful spans are, or we can simply auto-annotate all pub fns, and do a few more perhaps manually if they are called frequently in tests.

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, kinda up to you given you have the most experience with using it, I suppose. Definitely we should automate pub fns, but up to you if you want to automate all fns or make it explicit. ISTM I'm always trying to do a full trace including non-public fns, but if you have a different experience alright.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am a bit worried about presentation. Full trace might become a pretty long log line

@joostjager

Copy link
Copy Markdown
ContributorAuthor

This PR demonstrates that we can DIY a part of what tracing offers, but there is a lot that we are missing out on:

  • Structured key-value fields on spans and log events
  • Dynamic per-module/per-span log filtering at runtime
  • Automatic span timing for performance profiling
  • Async-aware context propagation across .await points
  • OpenTelemetry/Jaeger export for distributed tracing
  • Multiple concurrent subscribers (e.g. stdout + metrics + tracing)
  • Integration with the broader Rust ecosystem (eg tokio emitting tracing spans natively)

And last but not least:

  • No need to pass a logger instance through every struct and function signature

All of this to avoid unsafe code on specific no_std platforms. I am still not sold on the trade-off.

@joostjager
joostjager marked this pull request as draft March 5, 2026 12:08
@joostjager

Copy link
Copy Markdown
ContributorAuthor

I don't see this happening as long as we keep the current logging system

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

Status: Done

Development

Successfully merging this pull request may close these issues.

3 participants

@joostjager@ldk-reviews-bot@TheBlueMatt