Improve logging of pathfinding behavior #2011

Sharmalm · 2023-02-05T17:24:58Z

This pull request is for issue #1646.Please review my PR. :)

codecov-commenter · 2023-02-05T17:44:59Z

Codecov Report

Patch coverage has no change and project coverage change: -0.02 ⚠️

Comparison is base (12d799e) 91.15% compared to head (4364e18) 91.13%.

❗ Current head 4364e18 differs from pull request most recent head 34d21dc. Consider uploading reports for the commit 34d21dc to get more accurate results

📣 This organization is not using Codecov’s GitHub App Integration. We recommend you install it so Codecov can continue to function properly for your repositories. Learn more

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #2011      +/-   ##
==========================================
- Coverage   91.15%   91.13%   -0.02%     
==========================================
  Files         101      101              
  Lines       48868    48769      -99     
  Branches    48868    48769      -99     
==========================================
- Hits        44544    44445      -99     
  Misses       4324     4324

Impacted Files	Coverage Δ
lightning/src/routing/router.rs	`94.69% <ø> (-0.11%)`	⬇️

... and 24 files with indirect coverage changes

Help us with your feedback. Take ten seconds to tell us how you rate us. Have a feature suggestion? Share it here.

☔ View full report in Codecov by Sentry.
📢 Do you have feedback about the report comment? Let us know in this issue.

tnull

Thank you for having a go at this! Here are some initial comments.

tnull · 2023-02-06T14:25:24Z

lightning/src/routing/router.rs

@@ -1270,6 +1270,12 @@ where L::Target: Logger {
 					// around again with a higher amount.
 					if !contributes_sufficient_value || exceeds_max_path_length ||
 						exceeds_cltv_delta_limit || payment_failed_on_this_channel {
+						if let Some(first_hops) = first_hops {    // for only first hop it will log feedback
+							for hop in first_hops {           
+								let _channel_id = hop.channel_id;


You probably want to log via the short_channel_id rather than the channel_id to maintain uniformity with other logging outputs.

tnull · 2023-02-06T14:28:42Z

lightning/src/routing/router.rs

+							for hop in first_hops {           
+								let _channel_id = hop.channel_id;
+							}
+						 	log_trace!(logger, "first Hop is excluded because unfulfilling condition"); 


Would be nice to know a) what hop was excluded and b) why exactly it was excluded. To this end it might make sense to break up the ORed bools above into individual else if statements.

tnull · 2023-02-06T14:33:05Z

lightning/src/routing/router.rs

@@ -1270,6 +1270,12 @@ where L::Target: Logger {
 					// around again with a higher amount.
 					if !contributes_sufficient_value || exceeds_max_path_length ||
 						exceeds_cltv_delta_limit || payment_failed_on_this_channel {
+						if let Some(first_hops) = first_hops {    // for only first hop it will log feedback
+							for hop in first_hops {           


With this you're logging every single first hop, independently of whether it was excluded or not. You rather should just log the current candidate if it matches one of the first hops.

where to find find current candidate in this code :)

where to find find current candidate in this code :)

$candidate

tnull · 2023-02-06T14:34:14Z

lightning/src/routing/router.rs

@@ -1270,6 +1270,12 @@ where L::Target: Logger {
 					// around again with a higher amount.
 					if !contributes_sufficient_value || exceeds_max_path_length ||
 						exceeds_cltv_delta_limit || payment_failed_on_this_channel {
+						if let Some(first_hops) = first_hops {    // for only first hop it will log feedback


If you'd use first_hop_targets rather than first_hops, there would be no need for this unwrapping.

@tnull But first_hop_targets doesn't have short_channel_id field.

Yes it does. It is a HashMap from PublicKey to ChannelDetails and the latter has short_channel_id.

Sharmalm · 2023-02-06T15:37:24Z

OK

TheBlueMatt · 2023-02-10T17:13:48Z

Looks like CI is failing due to a unknown-item error.

Sharmalm · 2023-02-11T10:04:26Z

Looks like CI is failing due to a unknown-item error.

But it build's successfully on my device

Sharmalm · 2023-02-11T15:10:51Z

Hey, how can I fix the CI error even though it builds successfully on my device?

tnull · 2023-02-15T01:43:51Z

lightning/src/routing/router.rs

-						let our_node_id = NodeId::from_pubkey(&our_node_pubkey);
-						let target = first_hop_targets.get(&NodeId::from_pubkey(&our_node_pubkey)).unwrap(); 
+						let empty_vec: Vec<&ChannelDetails> = Vec::new();
+						let target = match first_hop_targets.get(&NodeId::from_pubkey(&our_node_pubkey)) {


I think you're looking for

Suggested change

let target = match first_hop_targets.get(&NodeId::from_pubkey(&our_node_pubkey)) {

if let Some(targets) = first_hop_targets.get(&NodeId::from_pubkey(&our_node_pubkey)) {

and then can just move the for inside? An alternative would be to use .unwrap_or(Vec::new()) or similar.

tnull · 2023-02-15T01:48:25Z

lightning/src/routing/router.rs

-								if short_channel_id == short_channel_id_target {
-        							log_trace!(logger, "first Hop of node id {our_node_id} is excluded due to a failed requirement.");
+								if short_channel_id == short_channel_id_target { // short_channel_id is hop id of candidate.
+									if !contributes_sufficient_value {


I don't think we should replicate checking on the individual bools here, rather we can just break the big if above, no? Likely we also want to create the is_first_hop bool before that so that we can reuse it in all variants.

TheBlueMatt · 2023-02-15T20:47:48Z

lightning/src/routing/router.rs

@@ -1243,6 +1243,25 @@ where L::Target: Logger {
 					// around again with a higher amount.
 					if !contributes_sufficient_value || exceeds_max_path_length ||
 						exceeds_cltv_delta_limit || payment_failed_on_this_channel {
+						let mut is_first_hop = true;
+						if let Some(target) = first_hop_targets.get(&NodeId::from_pubkey(&our_node_pubkey)){


Have you tested this somehow? I don't think our node key can ever be in first_hop_targets. Maybe try writing a test for exactly one of the cases here and see if you can get it to hit one of your new logs.

rust-lightning/lightning/src/routing/router.rs

Line 1080 in 30b9d9f

.entry(NodeId::from_pubkey(&chan.counterparty.node_id))

@TheBlueMatt , NodeId is the Key of the Hashmap first_hop_targets here ,right?.

Have you tested this somehow? I don't think our node key can ever be in first_hop_targets. Maybe try writing a test for exactly one of the cases here and see if you can get it to hit one of your new logs.

Hey @TheBlueMatt , I don't know how to use test. How should I approach writing tests :)

Start by looking at how the existing tests work and select one that does something similar and copy/modify it.

Start by looking at how the existing tests work and select one that does something similar and copy/modify it.

Please help me with test functions. I can't find any similar test functions of logging.

TheBlueMatt · 2023-02-21T21:48:32Z

lightning/src/routing/router.rs

+						let mut is_first_hop = true;
+						// if let Some(target) = first_hop_targets.get(&NodeId::from_pubkey(&our_node_pubkey)) {
+						for (key ,value) in &first_hop_targets {
+							if (key == &NodeId::from_pubkey(&our_node_pubkey)) { 


You're still comparing a first_hop_targets key to our_node_id which will never succeed, thus all of this is dead code. You need to use something else here.

TheBlueMatt

Nice! Glad you got test coverage working.

TheBlueMatt · 2023-03-20T19:55:49Z

lightning/src/routing/router.rs

@@ -1296,6 +1296,25 @@ where L::Target: Logger {
 					// around again with a higher amount.
 					if !contributes_sufficient_value || exceeds_max_path_length ||
 						exceeds_cltv_delta_limit || payment_failed_on_this_channel {
+
+						let mut is_first_hop = true;
+						for (key , _channel) in &first_hop_targets {


You don't need to loop here, you can just do first_hop_targets.get(&$dest_node_id) with an if let Some... or match. That should also let you drop the is_first_hop variable.

TheBlueMatt · 2023-03-20T19:58:46Z

lightning/src/routing/router.rs

+							if key == &$dest_node_id {
+								if is_first_hop && !contributes_sufficient_value {
+        								log_trace!(logger, "First Hop {} is excluded due to insufficient value", short_channel_id);
+


You can drop the blank lines here, and note that some lines have whitespace at the end, which would be nice to remove. Finally, note that some lines are indented by spaces followed by tabs, which should be replaced by all tabs. All of these issues will be highlighted by doing git show or git diff-tree -U3 locally, depending on your terminal config.

TheBlueMatt · 2023-03-20T19:59:07Z

lightning/src/routing/router.rs

+    									log_trace!(logger, "First Hop {} is excluded beacause it was failed previously" , short_channel_id);
+    								}
+    								is_first_hop = false;			
+    							} // commit


What does // commit mean?

Oh, it means nothing. I write // commit in the line where I update the code.

TheBlueMatt · 2023-03-20T20:01:05Z

lightning/src/routing/router.rs

+        	// Retrieve the log message from TestLogger
+    		let lines = logger.lines.lock().unwrap();
+		let mut log_output = String::new();
+		for ((module, file), line) in &*lines {


You don't have to iterate over the lines here, you can just do logger.assert_log_contains("routing:;router", "First Hop 3 is excluded due to insufficient value", 1);

Sharmalm · 2023-03-21T07:16:57Z

Nice! Glad you got test coverage working.

Hey , But this test has been failing.

TheBlueMatt · 2023-03-22T02:14:44Z

Hey , But this test has been failing.

Ah, I didn't try to run it. So if you want to get some first-hops rejected, you should probably at least have Some first_hops at all - your current get_route call passes a None for first_hops, so your code definitely wont run :). Try adding a first hop that fails to be used that connects from a random public key (which you use as the sender) to somewhere in the network graph being used.

Sharmalm · 2023-03-22T09:27:14Z

Hey , But this test has been failing.

Ah, I didn't try to run it. So if you want to get some first-hops rejected, you should probably at least have Some first_hops at all - your current get_route call passes a None for first_hops, so your code definitely wont run :). Try adding a first hop that fails to be used that connects from a random public key (which you use as the sender) to somewhere in the network graph being used.

It means I have to make a first_hops that can't route the payment in the test function ,and then test it right?

TheBlueMatt · 2023-03-24T18:16:45Z

Right, your new logging is all about first_hops, so you definitely need to have some to hit the new code :)

TheBlueMatt · 2023-07-08T20:02:53Z

Any desire to pick this back up?

Sharmalm · 2023-07-10T06:17:16Z

apologies for break on my PR , i have been busy in university exam and internship. I will resume working on it in some time :)

tnull · 2023-07-24T07:12:07Z

Closing this as it has been superseded by #2436.

Sharmalm and others added 6 commits February 4, 2023 23:18

first commit

9073b8d

second commit

02dddb4

original

0312c2b

first logging

3cdb8ed

Merge remote-tracking branch 'origin/main'

b6ac4ec

fifth commit

cfe611a

Sharmalm marked this pull request as ready for review February 5, 2023 17:47

third commit

5bd7708

tnull reviewed Feb 6, 2023

View reviewed changes

Sharmalm and others added 2 commits February 9, 2023 23:36

fourth commit

87eef3f

Merge branch 'lightningdevkit:main' into main

bb6c7f6

Sharmalm and others added 3 commits February 11, 2023 15:38

Merge branch 'lightningdevkit:main' into main

aef2aa6

sixth commit

4a2c289

seventh commit

a8781ca

Sharmalm requested a review from tnull February 13, 2023 06:18

Sharmalm and others added 2 commits February 15, 2023 00:10

eight commit

0e5e8a6

Merge branch 'lightningdevkit:main' into main

3240053

tnull reviewed Feb 15, 2023

View reviewed changes

Sharmalm and others added 2 commits February 15, 2023 15:17

Merge branch 'lightningdevkit:main' into main

b913098

ninth

8d2a85d

TheBlueMatt reviewed Feb 15, 2023

View reviewed changes

Sharmalm and others added 3 commits February 20, 2023 15:27

Merge branch 'lightningdevkit:main' into main

fe93ed8

access hashmap

6da0e06

Merge remote-tracking branch 'origin/main'

78dbb77

TheBlueMatt reviewed Feb 21, 2023

View reviewed changes

Sharmalm and others added 6 commits February 25, 2023 00:51

Merge branch 'lightningdevkit:main' into main

0be98f5

Merge branch 'lightningdevkit:main' into main

c830123

improving hashmap conditions

9bc34a1

Merge remote-tracking branch 'refs/remotes/origin/main'

1969bb7

Merge branch 'lightningdevkit:main' into main

7febd5b

correction

4364e18

tnull mentioned this pull request Mar 7, 2023

Improve logging of pathfinding behavior #1646

Closed

Sharmalm and others added 3 commits March 16, 2023 13:44

Merge branch 'lightningdevkit:main' into main

34d21dc

test function

592f615

Merge remote-tracking branch 'refs/remotes/origin/main'

c633d31

TheBlueMatt reviewed Mar 20, 2023

View reviewed changes

tnull closed this Jul 24, 2023

	let target = match first_hop_targets.get(&NodeId::from_pubkey(&our_node_pubkey)) {
	if let Some(targets) = first_hop_targets.get(&NodeId::from_pubkey(&our_node_pubkey)) {

Improve logging of pathfinding behavior #2011

Improve logging of pathfinding behavior #2011

Conversation

Sharmalm commented Feb 5, 2023 • edited Loading

codecov-commenter commented Feb 5, 2023 • edited Loading

Codecov Report

tnull left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Sharmalm Feb 8, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Sharmalm Feb 8, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Sharmalm commented Feb 6, 2023

TheBlueMatt commented Feb 10, 2023

Sharmalm commented Feb 11, 2023 • edited Loading

Sharmalm commented Feb 11, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Sharmalm Feb 16, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Sharmalm Feb 20, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

TheBlueMatt left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

TheBlueMatt Mar 20, 2023 • edited Loading

Choose a reason for hiding this comment

Sharmalm commented Mar 21, 2023 • edited Loading

TheBlueMatt commented Mar 22, 2023

Sharmalm commented Mar 22, 2023

TheBlueMatt commented Mar 24, 2023

TheBlueMatt commented Jul 8, 2023

Sharmalm commented Jul 10, 2023

tnull commented Jul 24, 2023

Sharmalm commented Feb 5, 2023 •

edited

Loading

codecov-commenter commented Feb 5, 2023 •

edited

Loading

Sharmalm Feb 8, 2023 •

edited

Loading

Sharmalm Feb 8, 2023 •

edited

Loading

Sharmalm commented Feb 11, 2023 •

edited

Loading

Sharmalm Feb 16, 2023 •

edited

Loading

Sharmalm Feb 20, 2023 •

edited

Loading

TheBlueMatt Mar 20, 2023 •

edited

Loading

Sharmalm commented Mar 21, 2023 •

edited

Loading