Real world path finding oddities

[AnthonyRonning]

This may be hard to investigate remotely and parse all the data. But I've got about 10GB worth of log files from my continuous prober this month and I'm trying to hone in on path finding failures and why certain routes are being picked up or not.

I'm honing in on Wallet of Satoshi (035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226) as a reference and going through the Voltage Flow 2.0 (03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0) node.

They have a direct channel with each other. When I run a script that looks through the logs to find when it tries to probe a direct path from voltage -> wos whenever I target wos, the last entry I have goes back about 15 days:

2023-08-10 16:02:51.577 TRACE [lightning::routing::router:2248] Found a path back to us from the target with 2 hops contributing up to 109904500 msat:
 [                                                                                             
    PathBuildingHop {                                                                             
        node_id: NodeId(03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0),
        short_channel_id: Some(                                                                                                                                                
            880204138120806401,                                                                                                                                                                                                                                                
        ),                                                                                                                                                                                                                  
        total_fee_msat: 3500,                                                                                 
        next_hops_fee_msat: 3500,
        hop_use_fee_msat: 0,
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 0,                                                         
        path_penalty_msat: 31181,                                                                                                                                                                                                                                               
        path_htlc_minimum_msat: 1000,                                                                                
        cltv_expiry_delta: 0,                                                                                                                                                                                  
    },                                                                                                                                                                                                                                                                         
    PathBuildingHop {                                                                                                                                                                                                                     
        node_id: NodeId(035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226),                  
        short_channel_id: Some(                                                                                                                                                                                                                                            
            879148606984028160,                                                                                                                                        
        ),                                                                                                                                                                                                                   
        total_fee_msat: 3500,                                                                                                               
        next_hops_fee_msat: 0,                                                                                                                    
        hop_use_fee_msat: 0,                                                                                                                                                                                                                              
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 3500,                                                                                                                      
        path_penalty_msat: 24989,                                                                                                                                                   
        path_htlc_minimum_msat: 1000,                                                                                 
        cltv_expiry_delta: 34,                                                                                                                                                                                                                                  
    },                                                                                                                                                                                                                                                                         
]                                                                                                                                                                                                                                         
2023-08-10 16:02:51.577 TRACE [lightning::routing::router:2295] Disabling route candidate SCID 879148606984028160 for future path building iterations to
                                                avoid duplicates.

and that resulted in:

2023-08-10 16:02:53.676 INFO  [lightning::ln::onion_utils:579] Onion Error[from 03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0: temporary_channel_failure(0x1007)] Node indicated the outgoing channel is unable to handle the HTLC temporarily

After that, I never see it try to go that route when directly probing wos. However, it currently has 598148 sats of outbound from voltage -> wos. And there's plenty of times WoS is included in paths for probing others:

2023-08-21 21:32:27.571 TRACE [lightning::ln::peer_handler:1579] Received message Pong(Pong { byteslen: 0 }) from 03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0                                                                                                                                                                  
2023-08-21 21:32:27.591 TRACE [lightning::routing::router:2248]                                                                                                                                                                                                                                                                                       
Found a path back to us from the target with 7 hops contributing up to 24742875 msat:                                                                                                                                                                                                                                                                 
 [                                                                                                                                                                                                                                                                                                                                                    
    PathBuildingHop {                                                                                                                                                                                                                                                                                                                                 
        node_id: NodeId(03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0),                                                                                                                                                                                                                                                          
        short_channel_id: Some(                                                                                                                                                                                                                                                                                                                       
            880350373213634560,                                                                                                                                                                                                                                                                                                                       
        ),                                                                                                                                                                                                                                                                                                                                            
        total_fee_msat: 10847,                                                                                                                                                                                                                                                                                                                        
        next_hops_fee_msat: 10847,                                                                                                                                                                                                                                                                                                                    
        hop_use_fee_msat: 0,                                                                                                                                                                                                                                                                                                                          
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 0,                                                                                                                                                                                                                                                                                  
        path_penalty_msat: 42211,                                                                                                                                                                                                                                                                                                                     
        path_htlc_minimum_msat: 4000,                                                                                                                                                                                                                                                                                                                 
        cltv_expiry_delta: 0,                                                                                                                                                                                                                                                                                                                         
    },                                                                                                                                                                                                                                                                                                                                                
    PathBuildingHop {
        node_id: NodeId(035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226),
        short_channel_id: Some(
            879148606984028160,
        ),
        total_fee_msat: 10847,
        next_hops_fee_msat: 9600,
        hop_use_fee_msat: 1247,
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 0,
        path_penalty_msat: 39267,
        path_htlc_minimum_msat: 4000,
        cltv_expiry_delta: 34,
    },
    PathBuildingHop {
        node_id: NodeId(037bba3fec931587fa28061ca522c962491ab1e98c30836e9dd5d011895823d8ad),
        short_channel_id: Some(
            807730928654024705,
        ),
        total_fee_msat: 9600,
        next_hops_fee_msat: 7125,
        hop_use_fee_msat: 2475,
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 0,
        path_penalty_msat: 32879,
        path_htlc_minimum_msat: 3000,
        cltv_expiry_delta: 40,
    },
    PathBuildingHop {

2023-08-21 21:38:00.994 TRACE [lightning::routing::router:2175] Starting main path collection loop with 25 nodes pre-filled from first/last hops.                                                                                                                                                                                          [656/27780]
2023-08-21 21:38:01.056 TRACE [lightning::routing::router:2248]                                                                                                                                                                                                                                                                                       
Found a path back to us from the target with 8 hops contributing up to 49498750 msat:                                                                                                                                                                                                                                                                 
 [                                                                                                                                                                                                                                                                                                                                                    
    PathBuildingHop {                                                                                                                                                                                                                                                                                                                                 
        node_id: NodeId(03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0),                                                                                                                                                                                                                                                          
        short_channel_id: Some(                                                                                                                                                                                                                                                                                                                       
            880350373213634560,                                                                                                                                                                                                                                                                                                                       
        ),                                                                                                                                                                                                                                                                                                                                            
        total_fee_msat: 9685,                                                                                                                                                                                                                                                                                                                         
        next_hops_fee_msat: 9685,                                                                                                                                                                                                                                                                                                                     
        hop_use_fee_msat: 0,                                                                                                                                                                                                                                                                                                                          
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 0,                                                                                                                                                                                                                                                                                  
        path_penalty_msat: 62717,                                                                                                                                                                                                                                                                                                                     
        path_htlc_minimum_msat: 3000,                                                                                                                                                                                                                                                                                                                 
        cltv_expiry_delta: 0,                                                                                                                                                                                                                                                                                                                         
    },                                                                                                                                                                                                                                                                                                                                                
    PathBuildingHop {                                                                                                                                                                                                                                                                                                                                 
        node_id: NodeId(035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226),                                                                                                                                                                                                                                                          
        short_channel_id: Some(                                                                                                                                                                                                                                                                                                                       
            879148606984028160,                                                                                                                                                                                                                                                                                                                       
        ),
        total_fee_msat: 9685,
        next_hops_fee_msat: 8190,
        hop_use_fee_msat: 1495,
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 0,
        path_penalty_msat: 58829,
        path_htlc_minimum_msat: 3000,
        cltv_expiry_delta: 34,
    },
    PathBuildingHop {
        node_id: NodeId(02d8a1d22732b1e2097ddb074bc15b3d14234ea5a0655df2997a67255df5c74765),
        short_channel_id: Some(
            800811702060318721,
        ),
        total_fee_msat: 8190,
        next_hops_fee_msat: 3240,
        hop_use_fee_msat: 4950,
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 0,
        path_penalty_msat: 46048,
        path_htlc_minimum_msat: 2000,
        cltv_expiry_delta: 40,
    },          

and occasional successful probes and routing failure errors I get from wos:

                                                             
2023-08-20 19:47:24.293 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect                                                                         
2023-08-20 19:47:30.016 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect                                                                         
2023-08-20 19:50:27.710 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect                                                                         
2023-08-20 19:53:12.998 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect                                                                         
2023-08-20 20:23:59.648 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: unknown_next_peer(0x400a)] Node indicated the outbound channel is not found for the specified short_channel_id in the onion packet                                                                
2023-08-20 20:29:38.504 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: temporary_channel_failure(0x1007)] Node indicated the outgoing channel is unable to handle the HTLC temporarily                                                                                   
2023-08-20 20:30:08.006 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: temporary_channel_failure(0x1007)] Node indicated the outgoing channel is unable to handle the HTLC temporarily                                                                                   
2023-08-20 20:45:01.084 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: temporary_channel_failure(0x1007)] Node indicated the outgoing channel is unable to handle the HTLC temporarily                                                                                   
2023-08-20 20:45:28.994 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: temporary_channel_failure(0x1007)] Node indicated the outgoing channel is unable to handle the HTLC temporarily                                                                                   
2023-08-20 20:45:31.870 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: temporary_channel_failure(0x1007)] Node indicated the outgoing channel is unable to handle the HTLC temporarily                                                                                   
2023-08-21 02:56:56.489 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect                                                                         
2023-08-21 02:57:31.463 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect                                                                         
2023-08-21 02:58:24.927 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect                                                                         
2023-08-21 02:59:01.451 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect                                                                         
2023-08-21 02:59:30.147 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect                                                                         
2023-08-21 03:03:54.687 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: temporary_channel_failure(0x1007)] Node indicated the outgoing channel is unable to handle the HTLC temporarily                                                                                   
2023-08-21 06:54:32.743 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect                                                                         
2023-08-21 17:36:45.154 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-21 17:38:04.295 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-21 17:41:48.273 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-21 17:45:53.221 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-21 17:48:01.423 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-22 03:46:00.901 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-22 03:46:36.029 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-22 03:48:23.268 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-22 03:48:44.260 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-22 03:49:19.871 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-22 11:34:29.031 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: temporary_channel_failure(0x1007)] Node indicated the outgoing channel is unable to handle the HTLC temporarily
2023-08-22 11:44:47.370 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-22 17:55:56.885 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: unknown_next_peer(0x400a)] Node indicated the outbound channel is not found for the specified short_channel_id in the onion packet
2023-08-22 20:43:45.708 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-25 10:01:01.262 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-25 13:17:31.636 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-25 13:17:40.593 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-25 13:18:02.927 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-25 13:18:27.787 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-25 13:18:38.822 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-25 14:20:24.492 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-25 14:21:00.181 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-25 14:22:19.980 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-25 14:22:58.070 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-25 14:23:21.749 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-25 15:40:01.737 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-25 15:40:05.591 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-25 17:10:55.464 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect
2023-08-25 17:11:07.923 INFO  [lightning::ln::onion_utils:579] Onion Error[from 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226: incorrect_or_unknown_payment_details(0x400f)] The final node indicated the payment hash is unknown or amount is incorrect

---

Now on the mutiny wallet side: whenver I pull in the remote scorer and make a 10k payment (note, that we do not attempt to probe this low, the minimum is about ~30k sats), then I see my router build that path:

2023-08-25 19:05:38.740 TRACE [lightning::routing::router:1648] Building path from payee node id 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226 to payer 03818a6060cb899d52258a7c12c57e754b625391e2fea1f81d3c2b221e0ecb7222 for value 10000000 msat.
2023-08-25 19:05:38.746 TRACE [lightning::routing::router:2175] Starting main path collection loop with 1982 nodes pre-filled from first/last hops.
2023-08-25 19:05:38.836 TRACE [lightning::routing::router:2248] Found a path back to us from the target with 2 hops contributing up to 10000000 msat: 
 [
    PathBuildingHop {
        node_id: NodeId(03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0),
        short_channel_id: Some(
            882907837178052609,
        ),
        total_fee_msat: 1100,
        next_hops_fee_msat: 1100,
        hop_use_fee_msat: 0,
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 0,
        path_penalty_msat: 7921,
        path_htlc_minimum_msat: 1000,
        cltv_expiry_delta: 0,
    },
    PathBuildingHop {
        node_id: NodeId(035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226),
        short_channel_id: Some(
            879148606984028160,
        ),
        total_fee_msat: 1100,
        next_hops_fee_msat: 0,
        hop_use_fee_msat: 0,
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 1100,
        path_penalty_msat: 5540,
        path_htlc_minimum_msat: 1000,
        cltv_expiry_delta: 34,
    },
]

However, when I immediately try 100k to wos from mutiny, it doesn't attempt to pick up that path, the first one is:

035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226 to payer 03818a6060cb899d52258a7c12c57e754b625391e2fea1f81d3c2b221e0ecb7222 for value 100000000 msat.
2023-08-25 19:09:13.191 TRACE [lightning::routing::router:2175] Starting main path collection loop with 1957 nodes pre-filled from first/last hops.
2023-08-25 19:09:13.353 TRACE [lightning::routing::router:2248] Found a path back to us from the target with 3 hops contributing up to 100000000 msat: 
 [
    PathBuildingHop {
        node_id: NodeId(03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0),
        short_channel_id: Some(
            882907837178052609,
        ),
        total_fee_msat: 3100,
        next_hops_fee_msat: 3100,
        hop_use_fee_msat: 0,
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 0,
        path_penalty_msat: 17442,
        path_htlc_minimum_msat: 2000,
        cltv_expiry_delta: 0,
    },
    PathBuildingHop {
        node_id: NodeId(030a58b8653d32b99200a2334cfe913e51dc7d155aa0116c176657a4f1722677a3),
        short_channel_id: Some(
            872723061011382273,
        ),
        total_fee_msat: 3100,
        next_hops_fee_msat: 1100,
        hop_use_fee_msat: 2000,
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 0,
        path_penalty_msat: 11628,
        path_htlc_minimum_msat: 2000,
        cltv_expiry_delta: 34,
    },
    PathBuildingHop {
        node_id: NodeId(035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226),
        short_channel_id: Some(
            883547752890302465,
        ),
        total_fee_msat: 1100,
        next_hops_fee_msat: 0,
        hop_use_fee_msat: 0,
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 1100,
        path_penalty_msat: 5814,
        path_htlc_minimum_msat: 1000,
        cltv_expiry_delta: 80,
    },
]

And the rest of the routes are even longer and none of them succeed. I immediately asked voltage what their outbound to WoS was and it was 600k.

---

So to summarize, my observations is that the router is not trying to pick up direct 2 hop paths very often anymore with WoS, or at least none after the temporarily_channel_failure message the last time it tried to make a 2 hop path to the target.

Mutiny will pull down the remote scorer and still try the 2 hop path for ~10k sats, but for 100k sats it never attempts to construct the 2 hop path. If it would have, it would have succeeded on the first try. So something leaves me to believe that the channel is not being picked up anymore for higher amounts and I'm not sure why.

Could something look less ideal about that route or is it the fact that the scorer saved the temporary_channel_failure with that SCID and it's being excluded? Note that our prober only excludes SCID's when calling find_route in a while loop for each unique instance of probe amount & probe target. IE, when it has a new amount target / node target, it resets the SCID's to exclude when we call find_route.

Our prober's find_routes method if it helps (note that mutiny does not use this, it just tries to pay invoice with the prober's scorer):

fn find_routes(
	destination_node: PublicKey, amount: u64, channel_manager: &ChannelManager,
	network: &NetworkGraph, logger: &FilesystemLogger,
	scorer: Arc<Mutex<ProbabilisticScorer<Arc<NetworkGraph>, Arc<FilesystemLogger>>>>,
	previously_failed_channels: Vec<u64>,
) -> Result<Route, LightningError> {
	let our_node_pubkey = channel_manager.get_our_node_id();
	let our_channels = channel_manager.list_usable_channels().to_owned();

	let payment_params = PaymentParameters {
		payee: Payee::Clear {
			node_id: destination_node,
			route_hints: vec![],
			features: None,
			final_cltv_expiry_delta: 40,
		},
		expiry_time: None,
		max_total_cltv_expiry_delta: DEFAULT_MAX_TOTAL_CLTV_EXPIRY_DELTA,
		max_path_count: DEFAULT_MAX_PATH_COUNT,
		max_channel_saturation_power_of_half: 2,
		previously_failed_channels,
	};
	let route_params = RouteParameters { payment_params, final_value_msat: amount * 1_000 };

	let random_bytes = rand::thread_rng().gen::<[u8; 32]>();
	find_route(
		&our_node_pubkey,
		&route_params,
		network,
		Some(our_channels.iter().collect::<Vec<_>>().as_slice()),
		logger,
		&scorer.lock().unwrap(),
		&scoring_params(),
		&random_bytes,
	)
}

Happy to provide my scorer logs if you want all 10GB of it and my scripts that I used to parse it. Also my scorer is available if there's anything useful there for parsing it somehow. This was working great, but something over the last week or two has caused payment reliability to go down a lot and it could be related to these oddities. I'm tempted to blow away the prober's scorer (or reset it after every day) and let it refill the scorer again from a fresh one.

[TheBlueMatt]

This is awesome, thanks! Can you dump the estimated liquidity range on the channel in question with https://docs.rs/lightning/latest/lightning/routing/scoring/struct.ProbabilisticScorerUsingTime.html#method.estimated_channel_liquidity_range and the historical probabilities with https://docs.rs/lightning/latest/lightning/routing/scoring/struct.ProbabilisticScorerUsingTime.html#method.historical_estimated_channel_liquidity_probabilities ? Alternatively, just hit https://docs.rs/lightning/latest/lightning/routing/scoring/struct.ProbabilisticScorerUsingTime.html#method.debug_log_liquidity_stats and paste the (huge) log somewhere.

[AnthonyRonning]

2023-08-25 23:03:02.445 INFO  [ldk_sample::cli:374] Scorer estimated_channel_liquidity_range for nodeid 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226 and scid 879148606984028160: min: 0 - max: 5939910119
2023-08-25 23:03:02.445 INFO  [ldk_sample::cli:398] Scorer historical_estimated_channel_liquidity_probabilities for nodeid 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226 and scid 879148606984028160: lower: [19976, 0, 0, 0, 0, 0, 0, 0] - upper: [11747, 832, 0, 0, 6774, 0, 0, 0]

I wish I could understand what the docs meant about all of these values. Maybe the docs make sense to someone that understands the whole buckets / probability / statistics stuff but I don't understand it. Is this good? Accurate? Do I need to probe it more or does it have good data?

[TheBlueMatt]

Hmm, I'd love suggestions on doc improvements, its not super wildly complicated - the top line you got from the liquidity range is our minimum and maximum estimate for the liquidity in the channel in the given direction. We think we can send at least the minimum amount out over this channel in the given direction, and we think we cannot send more than the maximum. These bounds decay every (default) 6 hours.

The buckets are just the history of those minimum and maximum bounds with much less decay - the lower bound buckets show that we've never thought the lower bound was anything other than the bottom octile (all the other buckets are zeros). The upper bound buckets show that we've thought the upper bound was at a few different places, which we assign probability of 6774/19353 (35%) that the upper bound is in the 5th octile, 832/19353 (4%) that the upper bound is in the second octile, and 11747/19353 (60%) that the upper bound is in the bottom octile. Obviously the maximum being in the bottom octile implies we can't send any reasonable amount of funds (a full octile is pretty coarse, we want to improve that in 117), so we're kinda skiddish about using this channel.

Now, why 60% of our upper-bound estimates are in the bottom octile when you say that we only had one substantial failure I don't fully understand - it may be that this scorer goes back further in time and we didn't like the channel before now (the buckets largely only decay slowly with new data, not with time), or there's some bug in filling out the buckets (though I'm not aware of one, at least the code post-#2176 I've spent a lot of time with the scorer and would be fairly surprised by that).

All that said, broadly, we're not at all confident in our fee parameters. They're a bit haphazard and based on some rough guesses and seem to mostly work okay, but they absolutely need to be tuned depending on where you are in the network and what kind of liquidity is available where - without worrying about the amount vs non-amount multipliers, there's 3 parameters that matter base_penalty* is "penalty every time we have to take a hop", liquidity_penalty* is "penalty based on only the lower and upper bound that decays fast", historical_liquidity* is "penalty based on the buckets and a long-horizon view of the liquidity bounds".

[ariard]

They have a direct channel with each other.

I have no idea if our scoring historical buckets are robust enough in the case of non-announced parallel channels between wos and voltage: https://fc22.ifca.ai/preproceedings/132.pdf, where minimum / maximum bounds could be mingled. IIRC, BOLT4 is loose on message errors returned for routing-hops selected forward channels, disrespecting onion’s payload scid.

[TheBlueMatt]

Indeed, we don't consider directly the case when two nodes have multiple channels between them (is that true in this case?), but I don't expect it to be a substantial issue - because most nodes forward over substitute channels when there's not enough liquidity on the channel selected in the onion it would result in us overestimating the available liquidity (which is...kinda right?), but the issue here describes a potential under-estimation.

[jkczyz]

There may be a bug in update_history_buckets when the decay is computed. That method is called from one of the three methods signifying success or failure for a channel, but those methods may have already modified last_updated. Thus, the decay calculation is wrong.

set_min_liquidity_msat and set_max_liquidity_msat should really update the buckets before updating last_updated. Looks like I introduced this in e448686.

[jkczyz]

Drafted #2530 but need to write a test still.

[TheBlueMatt]

Mmm, good catch! That said, I doubt that's having an impact here, the default no_updates_half_life is 14 days, so we'd only be materially impacted if we haven't seen fresh data for a channel for a few months, then get several updates which are very different from our past data (but not a ton of updates, cause those would have overwritten the past data anyway).

[AnthonyRonning]

Now, why 60% of our upper-bound estimates are in the bottom octile when you say that we only had one substantial failure I don't fully understand - it may be that this scorer goes back further in time and we didn't like the channel before now

That's correct that it wasn't the only time it didn't like that channel. There was more times it had that similar problem but I was surprised it just stopped after ~14 days. Especiallly since that channel is still included in paths to other destinations but not when it is direct from voltage -> wos.

It has started to pick up that channel again as a direct hop, so maybe that should be lowered, if that 14 day value is indeed why it wasn't picked up? I'm wondering if this sort of scoring algorithm is appropriate for continuous probers. I appreciate explaining it more here but I'm really not picking up on the logic. Is there any resources out there about this concept that might be able to explain the theory more?

The other thing I've been curious about is where the blame falls under this scenario:

path 1:
 node_id: 03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0, short_channel_id: 880204138120806401, fee_msat: 1861, cltv_expiry_delta: 34
 node_id: 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226, short_channel_id: 879148606984028160, fee_msat: 86168750, cltv_expiry_delta: 40
 blinded_tail: None

...

2023-08-27 23:43:37.138 INFO  [lightning::ln::onion_utils:579] Onion Error[from 03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0: temporary_channel_failure(0x1007)] Node indicated the outgoing channel is unable to handle the HTLC temporarily
2023-08-27 23:43:37.138 TRACE [lightning::ln::outbound_payment:1306] Failing outbound payment HTLC with payment_hash 48fd2e1d929e1538b5c41da0c5f4c2836d7d3f3619b2f8243da8df8df3a99746
2023-08-27 23:43:37.138 TRACE [lightning::ln::channelmanager:3063] Generating channel update for channel aca11b3b47b54e83bf40cf7b2f2100ebad6cf84dab079980aa47eadebbb750d3
2023-08-27 23:43:37.138 TRACE [lightning_background_processor:645] Persisting ChannelManager...
2023-08-27 23:43:37.149 TRACE [lightning_background_processor:645] Done persisting ChannelManager.
2023-08-27 23:43:37.149 TRACE [lightning::routing::scoring:1269] Scoring path through to SCID 880204138120806401 as having failed at 86168750 msat
2023-08-27 23:43:37.149 WARN  [lightning::routing::scoring:1279] Payment failed at the first hop - we do not attempt to learn channel info in such cases as we can directly observe local state.
	Because we know the local state, we should generally not see failures here - this may be an indication that your channel peer on channel 880204138120806401 is broken and you may wish to close the channel.
2023-08-27 23:43:37.149 DEBUG [lightning::routing::scoring:1299] Not able to penalize channel with SCID 880204138120806401 as we do not have graph info for it (likely a route-hint last-hop).

If 03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0 gives temporary_channel_failure then it should mean that SCID 879148606984028160 is the problem, not 880204138120806401.

[TheBlueMatt]

Especiallly since that channel is still included in paths to other destinations but not when it is direct from voltage -> wos.

This I do find very confusing - the algorithm should not care whether its going to wos or past wos, the "cost" to get to wos is always the same...Can you attach the scorer? Assuming its exactly "one path goes through wos, another calculated with the exact same data/parameters goes to wos but avoids the same channel" I'd really like to look into it.

It has started to pick up that channel again as a direct hop, so maybe that should be lowered, if that 14 day value is indeed why it wasn't picked up?

No, the 14 day value doesn't kick in unless the channel is never tried at all. More likely you're seeing it tried now cause we've learned by trying to pay through the channel (not to wos) that we can use the channel and it has some liquidity.

The historical data is...historical, it isn't really designed to have any time component at all, though if you're concerned about stale data you could turn the 14 day parameter down to around 1, or 6 hours.

I appreciate explaining it more here but I'm really not picking up on the logic. Is there any resources out there about this concept that might be able to explain the theory more?

There is no logic lol. There's not great research on scoring in lightning outside of Rene's work (which is great but really a first-step, by itself - which is basically the LDK scorer with the historical_liquidity_penalty* set to zero - its really not very good) and "whatever other lightning implementations are doing". Indeed, the current 0.0.116 scorer is not super great, but my tests of #2176 (and another PR that I have prep'd for on top based on the insight from the new changes in LND) work pretty decent in my probing tests. Not great, cause lightning sucks, but pretty decent :).

If 03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0 gives temporary_channel_failure then it should mean that SCID 879148606984028160 is the problem, not 880204138120806401.

Is it possible you're hitting ElementsProject/lightning#6200 ?

[AnthonyRonning]

Here's a zip with the scorer I saved off earlier today. Though it's after it started including wos into it's direct 2 hop path again. I didn't save it off on friday, that could have been useful.

scorer.zip

I've reset the scorer and will let it run over night. I'll see if it is any better.

Is it possible you're hitting ElementsProject/lightning#6200 ?

Maybe, I do see this log:

2023-08-27 23:42:43.991 TRACE [lightning::ln::onion_utils:481] Failure provided features a channel update without type prefix. Deprecated, but allowing for now.
2023-08-27 23:42:43.991 INFO  [lightning::ln::onion_utils:579] Onion Error[from 03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0: temporary_channel_failure(0x1007)] Node indicated the outgoing channel is unable to handle the HTLC temporarily

and this one too:

2023-08-27 23:42:45.521 INFO  [lightning::ln::onion_utils:521] Node provided a channel_update for which it was not authoritative, ignoring.
2023-08-27 23:42:45.521 INFO  [lightning::ln::onion_utils:579] Onion Error[from 03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0: temporary_channel_failure(0x1007)] Node indicated the outgoing channel is unable to handle the HTLC temporarily

[AnthonyRonning]

Going through some user submitted logs. Below we have a user that can't even route 25 or 10 sats across a few hops. With this one, it's full of immediate RouteNotFound issues, which I'm going to call a false positive because it's not even attempting to try something different. It's full of attempted payments from 10k sats all the way down to 10, mostly attempting for WoS and another node. It's always the same paths being selected. Most of the time it does not event attempt to route:

:13.599 TRACE [lightning::routing::router:1561] Searching for a route from payer XXX to payee node id 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226 with MPP and 1 first hops overriding the network graph
:13.599 TRACE [lightning::routing::router:1648] Building path from payee node id XXX to payer XXX for value 25000 msat.
:13.605 TRACE [lightning::routing::router:2175] Starting main path collection loop with 1966 nodes pre-filled from first/last hops.
:13.682 TRACE [lightning::routing::router:2248] Found a path back to us from the target with 2 hops contributing up to 19426 msat: 
 [
    PathBuildingHop {
        node_id: NodeId(03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0),
        short_channel_id: Some(
            XXX,
        ),
        total_fee_msat: 1000,
        next_hops_fee_msat: 1000,
        hop_use_fee_msat: 0,
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 0,
        path_penalty_msat: 4034,
        path_htlc_minimum_msat: 1000,
        cltv_expiry_delta: 0,
    },
    PathBuildingHop {
        node_id: NodeId(035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226),
        short_channel_id: Some(
            879148606984028160,
        ),
        total_fee_msat: 1000,
        next_hops_fee_msat: 0,
        hop_use_fee_msat: 0,
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 1000,
        path_penalty_msat: 2034,
        path_htlc_minimum_msat: 1000,
        cltv_expiry_delta: 34,
    },
]
:13.684 TRACE [lightning::routing::router:2175] Starting main path collection loop with 1966 nodes pre-filled from first/last hops.
:13.709 TRACE [lightning::routing::router:2321] Ignoring first hop with SCID XXX due to insufficient value contribution.
:13.754 TRACE [lightning::routing::router:2175] Starting main path collection loop with 1966 nodes pre-filled from first/last hops.
:13.781 TRACE [lightning::routing::router:2321] Ignoring first hop with SCID XXX due to insufficient value contribution.
:13.831 TRACE [lightning::routing::router:2345] Have now collected 19426 msat (seeking 75000 msat) in paths. Last path loop did not find a new path.
:13.831 TRACE [lightning::routing::router:2366] Ignored 650 candidate hops due to insufficient value contribution, 0 due to path length limit, 84 due to CLTV delta limit, 0 due to previous payment failure. Total: 734 ignored candidates.
:13.896 ERROR [mutiny_core::node:1027] failed to make payment: Sending(RouteNotFound)
:13.896 DEBUG [mutiny_core::node:1030] current channel details: [ChannelDetails { channel_id: [94, 35, 78, 12, 81, 148, 64, 51, 201, 198, 3, 56, 16, 196, 83, 33, 110, 107, 12, 167, 212, 120, 105, 75, 140, 169, 191, 165, 182, 13, 13, 189], counterparty: ChannelCounterparty { node_id: PublicKey(f0e18eca0f86800041211951fbbbabdbb7743995059d12a4219b00b4fb43faaec9a0af987303533cdaa9a57b32494716c973a7a53696dd46367cb483a5fa46e6), features: [162, 105, 10, 10, 0, 160, 8], unspendable_punishment_reserve: 1000, forwarding_info: Some(CounterpartyForwardingInfo { fee_base_msat: 1000, fee_proportional_millionths: 10, cltv_expiry_delta: 34 }), outbound_htlc_minimum_msat: Some(0), outbound_htlc_maximum_msat: Some(47784000) }, funding_txo: Some(OutPoint { txid: bd0d0db6a5bfa98c4b6978d4a70c6b6e2153c4103803c6c9334094510c4e235e, index: 0 }), channel_type: Some([0, 16]), short_channel_id: Some(XXX), outbound_scid_alias: Some(848051119597355015), inbound_scid_alias: None, channel_value_satoshis: 49276, unspendable_punishment_reserve: Some(492), user_channel_id: 233175328073315463806461395567577423746, feerate_sat_per_1000_weight: Some(3250), balance_msat: 6336426, outbound_capacity_msat: 5844426, next_outbound_htlc_limit_msat: 20426, next_outbound_htlc_minimum_msat: 0, inbound_capacity_msat: 41939574, confirmations_required: Some(3), confirmations: Some(6022), force_close_spend_delay: Some(144), is_outbound: true, is_channel_ready: true, channel_shutdown_state: Some(NotShuttingDown), is_usable: true, is_public: false, inbound_htlc_minimum_msat: Some(1), inbound_htlc_maximum_msat: Some(47784000), config: Some(ChannelConfig { forwarding_fee_proportional_millionths: 0, forwarding_fee_base_msat: 1000, cltv_expiry_delta: 72, max_dust_htlc_exposure: FixedLimitMsat(20000000), force_close_avoidance_max_fee_satoshis: 1000, accept_underpaying_htlcs: false }) }]
...
...
...
:48.257 TRACE [lightning::routing::router:1561] Searching for a route from payer XXX to payee node id 03d506016e3e0e540ac26d557a412520ea24990ca9405d410c24122f648752b830 with MPP and 1 first hops overriding the network graph
:48.257 TRACE [lightning::routing::router:1648] Building path from payee node id 03d506016e3e0e540ac26d557a412520ea24990ca9405d410c24122f648752b830 to payer XXX for value 100000 msat.
:48.257 TRACE [lightning::routing::router:2175] Starting main path collection loop with 28 nodes pre-filled from first/last hops.
:48.363 TRACE [lightning::routing::router:2248] Found a path back to us from the target with 3 hops contributing up to 19425 msat: 
 [
    PathBuildingHop {
        node_id: NodeId(03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0),
        short_channel_id: Some(
            XXX,
        ),
        total_fee_msat: 1001,
        next_hops_fee_msat: 1001,
        hop_use_fee_msat: 0,
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 0,
        path_penalty_msat: 6006,
        path_htlc_minimum_msat: 2000,
        cltv_expiry_delta: 0,
    },
    PathBuildingHop {
        node_id: NodeId(024bfaf0cabe7f874fd33ebf7c6f4e5385971fc504ef3f492432e9e3ec77e1b5cf),
        short_channel_id: Some(
            874825327293497345,
        ),
        total_fee_msat: 1001,
        next_hops_fee_msat: 0,
        hop_use_fee_msat: 1001,
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 0,
        path_penalty_msat: 4006,
        path_htlc_minimum_msat: 2000,
        cltv_expiry_delta: 34,
    },
    PathBuildingHop {
        node_id: NodeId(03d506016e3e0e540ac26d557a412520ea24990ca9405d410c24122f648752b830),
        short_channel_id: Some(
            819268104266317824,
        ),
        total_fee_msat: 0,
        next_hops_fee_msat: 0,
        hop_use_fee_msat: 0,
        total_fee_msat - (next_hops_fee_msat + hop_use_fee_msat): 0,
        path_penalty_msat: 2003,
        path_htlc_minimum_msat: 1000,
        cltv_expiry_delta: 40,
    },
]
:48.363 TRACE [lightning::routing::router:2295] Disabling route candidate SCID 874825327293497345 for future path building iterations to
						avoid duplicates.
:48.363 TRACE [lightning::routing::router:2175] Starting main path collection loop with 28 nodes pre-filled from first/last hops.
:48.405 TRACE [lightning::routing::router:2321] Ignoring first hop with SCID XXX due to insufficient value contribution.
:48.434 TRACE [lightning::routing::router:2175] Starting main path collection loop with 28 nodes pre-filled from first/last hops.
:48.477 TRACE [lightning::routing::router:2321] Ignoring first hop with SCID XXX due to insufficient value contribution.
:48.505 TRACE [lightning::routing::router:2345] Have now collected 19425 msat (seeking 300000 msat) in paths. Last path loop did not find a new path.
:48.505 TRACE [lightning::routing::router:2366] Ignored 682 candidate hops due to insufficient value contribution, 0 due to path length limit, 133 due to CLTV delta limit, 0 due to previous payment failure. Total: 815 ignored candidates.
:48.552 ERROR [mutiny_core::node:1027] failed to make payment: Sending(RouteNotFound)
:48.552 DEBUG [mutiny_core::node:1030] current channel details: [ChannelDetails { channel_id: [94, 35, 78, 12, 81, 148, 64, 51, 201, 198, 3, 56, 16, 196, 83, 33, 110, 107, 12, 167, 212, 120, 105, 75, 140, 169, 191, 165, 182, 13, 13, 189], counterparty: ChannelCounterparty { node_id: PublicKey(f0e18eca0f86800041211951fbbbabdbb7743995059d12a4219b00b4fb43faaec9a0af987303533cdaa9a57b32494716c973a7a53696dd46367cb483a5fa46e6), features: [162, 105, 10, 10, 0, 160, 8], unspendable_punishment_reserve: 1000, forwarding_info: Some(CounterpartyForwardingInfo { fee_base_msat: 1000, fee_proportional_millionths: 10, cltv_expiry_delta: 34 }), outbound_htlc_minimum_msat: Some(0), outbound_htlc_maximum_msat: Some(47784000) }, funding_txo: Some(OutPoint { txid: bd0d0db6a5bfa98c4b6978d4a70c6b6e2153c4103803c6c9334094510c4e235e, index: 0 }), channel_type: Some([0, 16]), short_channel_id: Some(XXX), outbound_scid_alias: Some(848051119597355015), inbound_scid_alias: None, channel_value_satoshis: 49276, unspendable_punishment_reserve: Some(492), user_channel_id: 233175328073315463806461395567577423746, feerate_sat_per_1000_weight: Some(3250), balance_msat: 6336426, outbound_capacity_msat: 5844426, next_outbound_htlc_limit_msat: 20426, next_outbound_htlc_minimum_msat: 0, inbound_capacity_msat: 41939574, confirmations_required: Some(3), confirmations: Some(6023), force_close_spend_delay: Some(144), is_outbound: true, is_channel_ready: true, channel_shutdown_state: Some(NotShuttingDown), is_usable: true, is_public: false, inbound_htlc_minimum_msat: Some(1), inbound_htlc_maximum_msat: Some(47784000), config: Some(ChannelConfig { forwarding_fee_proportional_millionths: 0, forwarding_fee_base_msat: 1000, cltv_expiry_delta: 72, max_dust_htlc_exposure: FixedLimitMsat(20000000), force_close_avoidance_max_fee_satoshis: 1000, accept_underpaying_htlcs: false }) }]

And when it does actually attempt, it seems to succeed, there's a dozen of these:

:22.412 TRACE [lightning::routing::router:2345] Have now collected 1500000 msat (seeking 1500000 msat) in paths. Last path loop found a new path.
:22.412 TRACE [lightning::routing::router:2366] Ignored 330 candidate hops due to insufficient value contribution, 0 due to path length limit, 102 due to CLTV delta limit, 0 due to previous payment failure. Total: 432 ignored candidates.
:22.412 INFO  [lightning::routing::router:2494] Got route: path 0:
 node_id: 03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0, short_channel_id: XXX, fee_msat: 1005, cltv_expiry_delta: 34
 node_id: 035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226, short_channel_id: 879148606984028160, fee_msat: 500000, cltv_expiry_delta: 80
 blinded_tail: None

:22.412 TRACE [lightning::ln::channelmanager:3107] Attempting to send payment for path with next hop XXX
:22.413 DEBUG [lightning::ln::channel:5182] Pushing new outbound HTLC for 501005 msat to peer
...
...
...
:25.127 TRACE [lightning::routing::scoring:1308] Scoring path through SCID 879148606984028160 as having succeeded at 500000 msat.
:25.127 DEBUG [lightning::routing::scoring:1326] Not able to learn for channel with SCID XXX as we do not have graph info for it (likely a route-hint last-hop).
:25.127 DEBUG [lightning::routing::scoring:1178] Subtracting 500000 from max liquidity of SCID 879148606984028160, towards NodeId(035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226) (setting it to 47198750)
:25.127 TRACE [mutiny_core::background:543] Persisting scorer after update
:25.189 DEBUG [mutiny_core::event:375] EVENT: PaymentPathSuccessful, ignored

If you'd like these logs in full, I can send them out of band. It's dozens of attempts to withdraw and a very painful experience for the user.

This user did get hit with this, so I'm not sure if that makes a difference at all: lightningdevkit/rapid-gossip-sync-server#45

I need to go through much more user submitted logs to find some more correlations but similar things have been happening to select users. I'm very puzzled why it just stops caring about trying to find other routes or even attempting the routes at all.

[TheBlueMatt]

With this one, it's full of immediate RouteNotFound issues, which I'm going to call a false positive because it's not even attempting to try something different.

This is lightningdevkit/rapid-gossip-sync-server#45, I don't think its (immediately) related to scoring at all.

[TheBlueMatt]

Maybe, I do see this log:

Heh, no, that's ElementsProject/lightning#6214 🤦 But confirmed they're running CLN, so we're probably hitting both issues.