Skip to content

Simplify and expand logging in is_resolving_htlc_output #283

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.

Sign up for GitHub

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

Merged
merged 3 commits into from
Jan 9, 2019
Merged

Simplify and expand logging in is_resolving_htlc_output #283

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
c9df4bd
Fix multi-remote-HTLC-claim preimage learning
TheBlueMatt Jan 6, 2019
bf96c80
Fix source name in is_resolving_htlc_output
TheBlueMatt Jan 7, 2019
90ce971
Simplify and expand logging in is_resolving_htlc_output
TheBlueMatt Jan 6, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion fuzz/fuzz_targets/full_stack_target.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -853,6 +853,6 @@ mod tests {
assert_eq!(log_entries.get(&("lightning::ln::peer_handler".to_string(), "Handling UpdateHTLCs event in peer_handler for node 030200000000000000000000000000000000000000000000000000000000000000 with 1 adds, 0 fulfills, 0 fails for channel 3f00000000000000000000000000000000000000000000000000000000000000".to_string())), Some(&3)); // 7
assert_eq!(log_entries.get(&("lightning::ln::peer_handler".to_string(), "Handling UpdateHTLCs event in peer_handler for node 030000000000000000000000000000000000000000000000000000000000000000 with 0 adds, 1 fulfills, 0 fails for channel 3d00000000000000000000000000000000000000000000000000000000000000".to_string())), Some(&1)); // 8
assert_eq!(log_entries.get(&("lightning::ln::peer_handler".to_string(), "Handling UpdateHTLCs event in peer_handler for node 030000000000000000000000000000000000000000000000000000000000000000 with 0 adds, 0 fulfills, 1 fails for channel 3d00000000000000000000000000000000000000000000000000000000000000".to_string())), Some(&2)); // 9
assert_eq!(log_entries.get(&("lightning::ln::channelmonitor".to_string(), "Input spending 00000000000000000000000000000000000000000000000000000000000000fb:0 resolves HTLC with payment hash ff00000000000000000000000000000000000000000000000000000000000000 from remote commitment tx".to_string())), Some(&1)); // 10
assert_eq!(log_entries.get(&("lightning::ln::channelmonitor".to_string(), "Input spending remote commitment tx (00000000000000000000000000000000000000000000000000000000000000fb:0) in 0000000000000000000000000000000000000000000000000000000000000042 resolves outbound HTLC with payment hash ff00000000000000000000000000000000000000000000000000000000000000 with timeout".to_string())), Some(&1)); // 10
}
}
72 changes: 49 additions & 23 deletions src/ln/channelmonitor.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1747,10 +1747,13 @@ impl ChannelMonitor {
for tx in txn.iter() {
broadcaster.broadcast_transaction(tx);
}
let mut updated = self.is_resolving_htlc_output(tx);
if updated.len() > 0 {
htlc_updated.append(&mut updated);
}
}
// While all commitment/HTLC-Success/HTLC-Timeout transactions have one input, HTLCs
// can also be resolved in a few other ways which can have more than one output. Thus,
// we call is_resolving_htlc_output here outside of the tx.input.len() == 1 check.
let mut updated = self.is_resolving_htlc_output(tx);
if updated.len() > 0 {
htlc_updated.append(&mut updated);
}
}
if let Some(ref cur_local_tx) = self.current_local_signed_commitment_tx {
Expand Down Expand Up @@ -1833,22 +1836,48 @@ impl ChannelMonitor {

'outer_loop: for input in &tx.input {
let mut payment_data = None;
let revocation_sig_claim = (input.witness.len() == 3 && input.witness[2].len() == OFFERED_HTLC_SCRIPT_WEIGHT && input.witness[1].len() == 33)
|| (input.witness.len() == 3 && input.witness[2].len() == ACCEPTED_HTLC_SCRIPT_WEIGHT && input.witness[1].len() == 33);
let accepted_preimage_claim = input.witness.len() == 5 && input.witness[4].len() == ACCEPTED_HTLC_SCRIPT_WEIGHT;
let offered_preimage_claim = input.witness.len() == 3 && input.witness[2].len() == OFFERED_HTLC_SCRIPT_WEIGHT;

macro_rules! log_claim {
($source: expr, $local_tx: expr, $outbound_htlc: expr, $payment_hash: expr, $source_avail: expr) => {
// We found the output in question, but aren't failing it backwards
// as we have no corresponding source. This implies either it is an
// inbound HTLC or an outbound HTLC on a revoked transaction.
if ($local_tx && revocation_sig_claim) ||
($outbound_htlc && !$source_avail && (accepted_preimage_claim || offered_preimage_claim)) {
log_error!(self, "Input spending {} ({}:{}) in {} resolves {} HTLC with payment hash {} with {}!",
$source, input.previous_output.txid, input.previous_output.vout, tx.txid(),
if $outbound_htlc { "outbound" } else { "inbound" }, log_bytes!($payment_hash.0),
if revocation_sig_claim { "revocation sig" } else { "preimage claim after we'd passed the HTLC resolution back" });
} else {
log_info!(self, "Input spending {} ({}:{}) in {} resolves {} HTLC with payment hash {} with {}",
$source, input.previous_output.txid, input.previous_output.vout, tx.txid(),
if $outbound_htlc { "outbound" } else { "inbound" }, log_bytes!($payment_hash.0),
if revocation_sig_claim { "revocation sig" } else if accepted_preimage_claim || offered_preimage_claim { "preimage" } else { "timeout" });
}
}
}

macro_rules! scan_commitment {
($htlc_outputs: expr, $htlc_sources: expr, $source: expr) => {
($htlc_outputs: expr, $htlc_sources: expr, $source: expr, $local_tx: expr) => {
for &(ref payment_hash, ref source, ref vout) in $htlc_sources.iter() {
if &Some(input.previous_output.vout) == vout {
log_trace!(self, "Input spending {}:{} resolves HTLC with payment hash {} from {}", input.previous_output.txid, input.previous_output.vout, log_bytes!(payment_hash.0), $source);
log_claim!($source, $local_tx, true, payment_hash, true);
// We have a resolution of an HTLC either from one of our latest
// local commitment transactions or an unrevoked remote commitment
// transaction. This implies we either learned a preimage, the HTLC
// has timed out, or we screwed up. In any case, we should now
// resolve the source HTLC with the original sender.
payment_data = Some((source.clone(), *payment_hash));
}
}
if payment_data.is_none() {
for htlc_output in $htlc_outputs {
if input.previous_output.vout == htlc_output.transaction_output_index && !htlc_output.offered {
log_info!(self, "Input spending {}:{} in {} resolves inbound HTLC with timeout from {}", input.previous_output.txid, input.previous_output.vout, tx.txid(), $source);
continue 'outer_loop;
} else if input.previous_output.vout == htlc_output.transaction_output_index && tx.lock_time > 0 {
log_info!(self, "Input spending {}:{} in {} resolves offered HTLC with HTLC-timeout from {}", input.previous_output.txid, input.previous_output.vout, tx.txid(), $source);
if input.previous_output.vout == htlc_output.transaction_output_index {
log_claim!($source, $local_tx, $local_tx == htlc_output.offered, htlc_output.payment_hash, false);
continue 'outer_loop;
}
}
Expand All @@ -1860,32 +1889,29 @@ impl ChannelMonitor {
if input.previous_output.txid == current_local_signed_commitment_tx.txid {
scan_commitment!(current_local_signed_commitment_tx.htlc_outputs.iter().map(|&(ref a, _, _)| a),
current_local_signed_commitment_tx.htlc_sources,
"our latest local commitment tx");
"our latest local commitment tx", true);
}
}
if let Some(ref prev_local_signed_commitment_tx) = self.prev_local_signed_commitment_tx {
if input.previous_output.txid == prev_local_signed_commitment_tx.txid {
scan_commitment!(prev_local_signed_commitment_tx.htlc_outputs.iter().map(|&(ref a, _, _)| a),
prev_local_signed_commitment_tx.htlc_sources,
"our latest local commitment tx");
"our previous local commitment tx", true);
}
}
if let Some(&(ref htlc_outputs, ref htlc_sources)) = self.remote_claimable_outpoints.get(&input.previous_output.txid) {
scan_commitment!(htlc_outputs, htlc_sources, "remote commitment tx");
scan_commitment!(htlc_outputs, htlc_sources, "remote commitment tx", false);
}

// If tx isn't solving htlc output from local/remote commitment tx and htlc isn't outbound we don't need
// to broadcast solving backward
// Check that scan_commitment, above, decided there is some source worth relaying an
// HTLC resolution backwards to and figure out whether we learned a preimage from it.
if let Some((source, payment_hash)) = payment_data {
let mut payment_preimage = PaymentPreimage([0; 32]);
if (input.witness.len() == 3 && input.witness[2].len() == OFFERED_HTLC_SCRIPT_WEIGHT && input.witness[1].len() == 33)
|| (input.witness.len() == 3 && input.witness[2].len() == ACCEPTED_HTLC_SCRIPT_WEIGHT && input.witness[1].len() == 33) {
log_error!(self, "Remote used revocation sig to take a {} HTLC output at index {} from commitment_tx {}", if input.witness[2].len() == OFFERED_HTLC_SCRIPT_WEIGHT { "offered" } else { "accepted" }, input.previous_output.vout, input.previous_output.txid);
} else if input.witness.len() == 5 && input.witness[4].len() == ACCEPTED_HTLC_SCRIPT_WEIGHT {
payment_preimage.0.copy_from_slice(&tx.input[0].witness[3]);
if accepted_preimage_claim {
payment_preimage.0.copy_from_slice(&input.witness[3]);
htlc_updated.push((source, Some(payment_preimage), payment_hash));
} else if input.witness.len() == 3 && input.witness[2].len() == OFFERED_HTLC_SCRIPT_WEIGHT {
payment_preimage.0.copy_from_slice(&tx.input[0].witness[1]);
} else if offered_preimage_claim {
payment_preimage.0.copy_from_slice(&input.witness[1]);
htlc_updated.push((source, Some(payment_preimage), payment_hash));
} else {
htlc_updated.push((source, None, payment_hash));
Expand Down
121 changes: 74 additions & 47 deletions src/ln/functional_tests.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2648,14 +2648,15 @@ fn test_htlc_on_chain_success() {
// Test that in case of an unilateral close onchain, we detect the state of output thanks to
// ChainWatchInterface and pass the preimage backward accordingly. So here we test that ChannelManager is
// broadcasting the right event to other nodes in payment path.
// We test with two HTLCs simultaneously as that was not handled correctly in the past.
// A --------------------> B ----------------------> C (preimage)
// First, C should claim the HTLC output via HTLC-Success when its own latest local
// First, C should claim the HTLC outputs via HTLC-Success when its own latest local
// commitment transaction was broadcast.
// Then, B should learn the preimage from said transactions, attempting to claim backwards
// towards B.
// B should be able to claim via preimage if A then broadcasts its local tx.
// Finally, when A sees B's latest local commitment transaction it should be able to claim
// the HTLC output via the preimage it learned (which, once confirmed should generate a
// the HTLC outputs via the preimage it learned (which, once confirmed should generate a
// PaymentSent event).

let nodes = create_network(3);
Expand All @@ -2669,6 +2670,7 @@ fn test_htlc_on_chain_success() {
send_payment(&nodes[0], &vec!(&nodes[1], &nodes[2])[..], 8000000);

let (our_payment_preimage, _payment_hash) = route_payment(&nodes[0], &vec!(&nodes[1], &nodes[2]), 3000000);
let (our_payment_preimage_2, _payment_hash_2) = route_payment(&nodes[0], &vec!(&nodes[1], &nodes[2]), 3000000);
let header = BlockHeader { version: 0x20000000, prev_blockhash: Default::default(), merkle_root: Default::default(), time: 42, bits: 42, nonce: 42};

// Broadcast legit commitment tx from C on B's chain
Expand All @@ -2677,7 +2679,8 @@ fn test_htlc_on_chain_success() {
assert_eq!(commitment_tx.len(), 1);
check_spends!(commitment_tx[0], chan_2.3.clone());
nodes[2].node.claim_funds(our_payment_preimage);
check_added_monitors!(nodes[2], 1);
nodes[2].node.claim_funds(our_payment_preimage_2);
check_added_monitors!(nodes[2], 2);
let updates = get_htlc_update_msgs!(nodes[2], nodes[1].node.get_our_node_id());
assert!(updates.update_add_htlcs.is_empty());
assert!(updates.update_fail_htlcs.is_empty());
Expand All @@ -2686,22 +2689,28 @@ fn test_htlc_on_chain_success() {

nodes[2].chain_monitor.block_connected_with_filtering(&Block { header, txdata: vec![commitment_tx[0].clone()]}, 1);
check_closed_broadcast!(nodes[2]);
let node_txn = nodes[2].tx_broadcaster.txn_broadcasted.lock().unwrap().clone(); // ChannelManager : 1 (commitment tx), ChannelMonitor : 2 (2 * HTLC-Success tx)
assert_eq!(node_txn.len(), 3);
assert_eq!(node_txn[1], commitment_tx[0]);
assert_eq!(node_txn[0], node_txn[2]);
let node_txn = nodes[2].tx_broadcaster.txn_broadcasted.lock().unwrap().clone(); // ChannelManager : 1 (commitment tx), ChannelMonitor : 4 (2*2 * HTLC-Success tx)
assert_eq!(node_txn.len(), 5);
assert_eq!(node_txn[0], node_txn[3]);
assert_eq!(node_txn[1], node_txn[4]);
assert_eq!(node_txn[2], commitment_tx[0]);
check_spends!(node_txn[0], commitment_tx[0].clone());
check_spends!(node_txn[1], commitment_tx[0].clone());
assert_eq!(node_txn[0].input[0].witness.clone().last().unwrap().len(), ACCEPTED_HTLC_SCRIPT_WEIGHT);
assert_eq!(node_txn[1].input[0].witness.clone().last().unwrap().len(), ACCEPTED_HTLC_SCRIPT_WEIGHT);
assert!(node_txn[0].output[0].script_pubkey.is_v0_p2wsh()); // revokeable output
assert!(node_txn[1].output[0].script_pubkey.is_v0_p2wsh()); // revokeable output
assert_eq!(node_txn[0].lock_time, 0);
assert_eq!(node_txn[1].lock_time, 0);

// Verify that B's ChannelManager is able to extract preimage from HTLC Success tx and pass it backward
nodes[1].chain_monitor.block_connected_with_filtering(&Block { header, txdata: node_txn}, 1);
let events = nodes[1].node.get_and_clear_pending_msg_events();
{
let mut added_monitors = nodes[1].chan_monitor.added_monitors.lock().unwrap();
assert_eq!(added_monitors.len(), 1);
assert_eq!(added_monitors.len(), 2);
assert_eq!(added_monitors[0].0.txid, chan_1.3.txid());
assert_eq!(added_monitors[1].0.txid, chan_1.3.txid());
added_monitors.clear();
}
assert_eq!(events.len(), 2);
Expand All @@ -2719,25 +2728,45 @@ fn test_htlc_on_chain_success() {
},
_ => panic!("Unexpected event"),
};
{
// nodes[1] now broadcasts its own local state as a fallback, suggesting an alternate
// commitment transaction with a corresponding HTLC-Timeout transaction, as well as a
// timeout-claim of the output that nodes[2] just claimed via success.
let mut node_txn = nodes[1].tx_broadcaster.txn_broadcasted.lock().unwrap(); // ChannelManager : 2 (commitment tx, HTLC-Timeout tx), ChannelMonitor : 1 (timeout tx) * 2 (block-rescan)
assert_eq!(node_txn.len(), 4);
assert_eq!(node_txn[0], node_txn[3]);
check_spends!(node_txn[0], commitment_tx[0].clone());
assert_eq!(node_txn[0].input[0].witness.clone().last().unwrap().len(), ACCEPTED_HTLC_SCRIPT_WEIGHT);
assert_ne!(node_txn[0].lock_time, 0);
assert!(node_txn[0].output[0].script_pubkey.is_v0_p2wpkh()); // direct payment
check_spends!(node_txn[1], chan_2.3.clone());
check_spends!(node_txn[2], node_txn[1].clone());
assert_eq!(node_txn[1].input[0].witness.clone().last().unwrap().len(), 71);
assert_eq!(node_txn[2].input[0].witness.clone().last().unwrap().len(), OFFERED_HTLC_SCRIPT_WEIGHT);
assert!(node_txn[2].output[0].script_pubkey.is_v0_p2wsh()); // revokeable output
assert_ne!(node_txn[2].lock_time, 0);
node_txn.clear();
}
macro_rules! check_tx_local_broadcast {
($node: expr, $htlc_offered: expr, $commitment_tx: expr, $chan_tx: expr) => { {
// ChannelManager : 3 (commitment tx, 2*HTLC-Timeout tx), ChannelMonitor : 2 (timeout tx) * 2 (block-rescan)
let mut node_txn = $node.tx_broadcaster.txn_broadcasted.lock().unwrap();
assert_eq!(node_txn.len(), 7);
assert_eq!(node_txn[0], node_txn[5]);
assert_eq!(node_txn[1], node_txn[6]);
check_spends!(node_txn[0], $commitment_tx.clone());
check_spends!(node_txn[1], $commitment_tx.clone());
assert_ne!(node_txn[0].lock_time, 0);
assert_ne!(node_txn[1].lock_time, 0);
if $htlc_offered {
assert_eq!(node_txn[0].input[0].witness.last().unwrap().len(), OFFERED_HTLC_SCRIPT_WEIGHT);
assert_eq!(node_txn[1].input[0].witness.last().unwrap().len(), OFFERED_HTLC_SCRIPT_WEIGHT);
assert!(node_txn[0].output[0].script_pubkey.is_v0_p2wsh()); // revokeable output
assert!(node_txn[1].output[0].script_pubkey.is_v0_p2wsh()); // revokeable output
} else {
assert_eq!(node_txn[0].input[0].witness.last().unwrap().len(), ACCEPTED_HTLC_SCRIPT_WEIGHT);
assert_eq!(node_txn[1].input[0].witness.last().unwrap().len(), ACCEPTED_HTLC_SCRIPT_WEIGHT);
assert!(node_txn[0].output[0].script_pubkey.is_v0_p2wpkh()); // direct payment
assert!(node_txn[1].output[0].script_pubkey.is_v0_p2wpkh()); // direct payment
}
check_spends!(node_txn[2], $chan_tx.clone());
check_spends!(node_txn[3], node_txn[2].clone());
check_spends!(node_txn[4], node_txn[2].clone());
assert_eq!(node_txn[2].input[0].witness.last().unwrap().len(), 71);
assert_eq!(node_txn[3].input[0].witness.last().unwrap().len(), OFFERED_HTLC_SCRIPT_WEIGHT);
assert_eq!(node_txn[4].input[0].witness.last().unwrap().len(), OFFERED_HTLC_SCRIPT_WEIGHT);
assert!(node_txn[3].output[0].script_pubkey.is_v0_p2wsh()); // revokeable output
assert!(node_txn[4].output[0].script_pubkey.is_v0_p2wsh()); // revokeable output
assert_ne!(node_txn[3].lock_time, 0);
assert_ne!(node_txn[4].lock_time, 0);
node_txn.clear();
} }
}
// nodes[1] now broadcasts its own local state as a fallback, suggesting an alternate
// commitment transaction with a corresponding HTLC-Timeout transactions, as well as a
// timeout-claim of the output that nodes[2] just claimed via success.
check_tx_local_broadcast!(nodes[1], false, commitment_tx[0], chan_2.3);

// Broadcast legit commitment tx from A on B's chain
// Broadcast preimage tx by B on offered output from A commitment tx on A's chain
Expand All @@ -2749,7 +2778,9 @@ fn test_htlc_on_chain_success() {
assert_eq!(node_txn.len(), 3);
assert_eq!(node_txn[0], node_txn[2]);
check_spends!(node_txn[0], commitment_tx[0].clone());
assert_eq!(node_txn[0].input[0].witness.clone().last().unwrap().len(), OFFERED_HTLC_SCRIPT_WEIGHT);
assert_eq!(node_txn[0].input.len(), 2);
assert_eq!(node_txn[0].input[0].witness.last().unwrap().len(), OFFERED_HTLC_SCRIPT_WEIGHT);
assert_eq!(node_txn[0].input[1].witness.last().unwrap().len(), OFFERED_HTLC_SCRIPT_WEIGHT);
assert_eq!(node_txn[0].lock_time, 0);
assert!(node_txn[0].output[0].script_pubkey.is_v0_p2wpkh()); // direct payment
check_spends!(node_txn[1], chan_1.3.clone());
Expand All @@ -2761,26 +2792,22 @@ fn test_htlc_on_chain_success() {
nodes[0].chain_monitor.block_connected_with_filtering(&Block { header, txdata: vec![commitment_tx[0].clone(), node_txn[0].clone()] }, 1);
check_closed_broadcast!(nodes[0]);
let events = nodes[0].node.get_and_clear_pending_events();
assert_eq!(events.len(), 1);
match events[0] {
Event::PaymentSent { payment_preimage } => {
assert_eq!(payment_preimage, our_payment_preimage);
},
_ => panic!("Unexpected event"),
assert_eq!(events.len(), 2);
let mut first_claimed = false;
for event in events {
match event {
Event::PaymentSent { payment_preimage } => {
if payment_preimage == our_payment_preimage {
assert!(!first_claimed);
first_claimed = true;
} else {
assert_eq!(payment_preimage, our_payment_preimage_2);
}
},
_ => panic!("Unexpected event"),
}
}
let node_txn = nodes[0].tx_broadcaster.txn_broadcasted.lock().unwrap().clone(); // ChannelManager : 2 (commitment tx, HTLC-Timeout tx), ChannelMonitor : 1 (HTLC-Timeout tx) * 2 (block-rescan)
assert_eq!(node_txn.len(), 4);
assert_eq!(node_txn[0], node_txn[3]);
check_spends!(node_txn[0], commitment_tx[0].clone());
assert_eq!(node_txn[0].input[0].witness.clone().last().unwrap().len(), OFFERED_HTLC_SCRIPT_WEIGHT);
assert_ne!(node_txn[0].lock_time, 0);
assert!(node_txn[0].output[0].script_pubkey.is_v0_p2wsh()); // revokeable output
check_spends!(node_txn[1], chan_1.3.clone());
check_spends!(node_txn[2], node_txn[1].clone());
assert_eq!(node_txn[1].input[0].witness.clone().last().unwrap().len(), 71);
assert_eq!(node_txn[2].input[0].witness.clone().last().unwrap().len(), OFFERED_HTLC_SCRIPT_WEIGHT);
assert!(node_txn[2].output[0].script_pubkey.is_v0_p2wsh()); // revokeable output
assert_ne!(node_txn[2].lock_time, 0);
check_tx_local_broadcast!(nodes[0], true, commitment_tx[0], chan_1.3);
}

#[test]
Expand Down