-
Notifications
You must be signed in to change notification settings - Fork 421
Log structured peer, channel and hash fields #4217
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Conversation
|
👋 Thanks for assigning @valentinewallace as a reviewer! |
5bae991 to
bf104c0
Compare
bf104c0 to
9491fa7
Compare
44dec3f to
2f6b50a
Compare
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #4217 +/- ##
==========================================
- Coverage 89.36% 89.33% -0.03%
==========================================
Files 180 180
Lines 138369 138341 -28
Branches 138369 138341 -28
==========================================
- Hits 123652 123587 -65
- Misses 12114 12135 +21
- Partials 2603 2619 +16
Flags with carried forward coverage won't be shown. Click here to find out more. ☔ View full report in Codecov by Sentry. 🚀 New features to boost your workflow:
|
2f6b50a to
f2483eb
Compare
61b1780 to
3506f92
Compare
TheBlueMatt
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LGTM, needs rebase though.
As a preparatory step for unifying test log output.
Makes sure that 4 and 5 character log levels line up.
Now that we have Display implemented on Record, the various test logger implementations can make use of that.
3506f92 to
2febae0
Compare
|
Rebased |
2febae0 to
e76d564
Compare
e76d564 to
73ea256
Compare
valentinewallace
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I would prefer putting the peer and payment hash at the end of the log, at least in test output. I work on a laptop somewhat regularly and this change pushes the actual log content very far to the side, particularly since the payment_hash field doesn't seem to be set the vast majority of the time.
We could also maybe do this in addition:
diff --git a/lightning/src/ln/functional_test_utils.rs b/lightning/src/ln/functional_test_utils.rs
index 643c1825f..a0cd881f1 100644
--- a/lightning/src/ln/functional_test_utils.rs
+++ b/lightning/src/ln/functional_test_utils.rs
@@ -4360,7 +4360,7 @@ pub fn create_chanmon_cfgs_with_legacy_keys(
let tx_broadcaster = test_utils::TestBroadcaster::new(Network::Testnet);
let fee_estimator = test_utils::TestFeeEstimator::new(253);
let chain_source = test_utils::TestChainSource::new(Network::Testnet);
- let logger = test_utils::TestLogger::with_id(format!("node {}", i));
+ let logger = test_utils::TestLogger::with_id(format!("n{}", i));
let persister = test_utils::TestPersister::new();
let seed = [i as u8; 32];
let keys_manager = if predefined_keys_ids.is_some() {
diff --git a/lightning/src/util/test_utils.rs b/lightning/src/util/test_utils.rs
index 5f408a9e8..d414b980f 100644
--- a/lightning/src/util/test_utils.rs
+++ b/lightning/src/util/test_utils.rs
@@ -1698,7 +1698,7 @@ impl TestLogger {
impl Logger for TestLogger {
fn log(&self, record: Record) {
- let s = format!("{:<6} {}", self.id, record);
+ let s = format!("{:<2} {}", self.id, record);
#[cfg(ldk_bench)]
{
// When benchmarking, we don't actually want to print logs, but we do want to format| entry.insert(channel); | ||
| } else { | ||
| log_trace!(logger, | ||
| "Preferring counterparty {} channel {} (SCID {:?}, {} msats) over {} (SCID {:?}, {} msats) for invoice route hints", |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The word "over" got deleted, may need to tweak the log slightly to keep the original meaning as well
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Reverted these two log lines. As they are making a comparison, it may be a bit weird to rely on the structured field only.
In some tests, the nodes are called 'alice' and 'bob', so we'd need to change that to 'a' and 'b' perhaps? Maybe just one character is also sufficient. Starting everyline with |
73ea256 to
e069743
Compare
|
🔔 1st Reminder Hey @TheBlueMatt! This PR has been waiting for your review. |
3f2926c to
1e1df23
Compare
|
Applied the smaller suggestions https://github.com/lightningdevkit/rust-lightning/compare/73ea2568a2f4ab6f2e3809a2acf07ad111cad231~1..65f7f7f and added a fixup commit to differentiate output between test and prod. Single-char node ids I didn't do yet because we also have longer ids. |
Previously, log messages often included the channel ID both in the message text and in the structured `channel_id` field. This led to redundant information and made it difficult to quickly identify which log lines pertain to a given channel, as the ID could appear in different positions or sometimes not at all. This change removes the channel ID from the message in all cases where it is already present in the structured field. A test run was used to verify that the structured field always appeared in these log calls. Some exceptions remain—for example, calls where the structured field contains a temporary channel ID and the message contains the final ID were left unchanged.
1e1df23 to
a21fd62
Compare
|
Reminder: if rebasing on top of #4224, chan ids can be removed. |
TheBlueMatt
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Feel free to squash imo
valentinewallace
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LGTM, feel free to squash
Since most log messages no longer include the channel ID in their text, this commit updates the test logger to output the structured channel ID instead. The ID is truncated for readability. Similarly peer id and payment hash are logged. Co-authored-by: Matt Corallo <[email protected]>
a21fd62 to
053933b
Compare
|
Squashed without changes |
valentinewallace
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This has the side effect of reducing the rustfmt vertical-ness of many logs within the code👌
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The format! can go away and can be inlined into the log_err now that this differs from what we put in APIError::ChannelUnavailable below.
| }; | ||
| log_trace!(logger, "Forwarding HTLC from SCID {} with payment_hash {} and next hop SCID {} over {} channel {} with corresponding peer {}", | ||
| prev_outbound_scid_alias, &payment_hash, short_chan_id, channel_description, optimal_channel.context.channel_id(), &counterparty_node_id); | ||
| log_trace!(logger, "Forwarding HTLC from SCID {} with payment_hash {} and next hop SCID {} over {} with corresponding peer {}", |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
We now also log peer so no need for that either (plus corresponding should have been removed).
| log_trace!(logger, "Forwarding HTLC from SCID {} with payment_hash {} and next hop SCID {} over {} with corresponding peer {}", | |
| log_trace!(logger, "Forwarding HTLC from SCID {} with payment_hash {} and next hop SCID {} over {}", |
| Some(msg.channel_id), | ||
| None | ||
| ), | ||
| "Handling Shutdown event in peer_handler for node {}", |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
There's plenty of room to remove node_ids in various places.
|
I intentionally left removal of redundant node ids and payment hashes for a follow up. Wanted to land this first. |
This PR improves channel ID logging consistency and clarity.
Removes redundant channel ID text from log messages where the ID is already included as a structured field. This reduces duplication and makes it easier to filter logs by channel. De-duplication of peer and payment hash is left for a follow up.
Adds a
Displayimplementation for logRecords that outputs the structured fields. The fields are truncated to six (hex) characters for readability. In tests, the layout is changed slightly to accommodate for narrower terminal windows.Together, these changes standardize how channel IDs, peers and payment hashes appear in logs and make them easier to parse and analyze.
Example output (prod):
Example output (test):