Simplify and expand logging in is_resolving_htlc_output 2019-01-htlc-resolution-log
authorMatt Corallo <git@bluematt.me>
Sun, 6 Jan 2019 22:01:29 +0000 (17:01 -0500)
committerMatt Corallo <git@bluematt.me>
Wed, 9 Jan 2019 04:03:07 +0000 (23:03 -0500)
This clarifies all the conditions we can hit and also ensures they
are all logged in a clear and consistent manner.

fuzz/fuzz_targets/full_stack_target.rs
src/ln/channelmonitor.rs

index a9ee47c806676da76e19acd1d1c7cf6dd71b3c6e..21acf2777911a4dcbddec033313639d9cf6e98b8 100644 (file)
@@ -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
        }
 }
index 04b324e2222ae892974206ec9a39c41401c9980e..ea3e279213c88cca40a7e3fa5c800828fbc20f12 100644 (file)
@@ -1836,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;
                                                        }
                                                }
@@ -1863,31 +1889,28 @@ 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 previous 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 {
+                               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 {
+                               } else if offered_preimage_claim {
                                        payment_preimage.0.copy_from_slice(&input.witness[1]);
                                        htlc_updated.push((source, Some(payment_preimage), payment_hash));
                                } else {