Logging interface
[rust-lightning] / src / ln / channelmanager.rs
index af2e5e600993df37a2beac3925aa55dac2302ed5..0b6b1663ab47b508e527bd718c3b35d6b88252a1 100644 (file)
@@ -19,13 +19,14 @@ use ln::msgs;
 use ln::msgs::{HandleError,ChannelMessageHandler,MsgEncodable,MsgDecodable};
 use util::{byte_utils, events, internal_traits, rng};
 use util::sha2::Sha256;
+use util::chacha20poly1305rfc::ChaCha20;
+use util::logger::{Logger, Record};
 
 use crypto;
 use crypto::mac::{Mac,MacResult};
 use crypto::hmac::Hmac;
 use crypto::digest::Digest;
 use crypto::symmetriccipher::SynchronousStreamCipher;
-use crypto::chacha20::ChaCha20;
 
 use std::{ptr, mem};
 use std::collections::HashMap;
@@ -137,13 +138,15 @@ impl ChannelHolder {
                        by_id: &mut self.by_id,
                        short_to_id: &mut self.short_to_id,
                        next_forward: &mut self.next_forward,
-                       /// short channel id -> forward infos. Key of 0 means payments received
                        forward_htlcs: &mut self.forward_htlcs,
                        claimable_htlcs: &mut self.claimable_htlcs,
                }
        }
 }
 
+#[cfg(not(any(target_pointer_width = "32", target_pointer_width = "64")))]
+const ERR: () = "You need at least 32 bit pointers (well, usize, but we'll assume they're the same) for ChannelManager::latest_block_height";
+
 /// Manager which keeps track of a number of channels and sends messages to the appropriate
 /// channel, also tracking HTLC preimages and forwarding onion packets appropriately.
 /// Implements ChannelMessageHandler, handling the multi-channel parts and passing things through
@@ -157,13 +160,15 @@ pub struct ChannelManager {
 
        announce_channels_publicly: bool,
        fee_proportional_millionths: u32,
-       latest_block_height: AtomicUsize, //TODO: Compile-time assert this is at least 32-bits long
+       latest_block_height: AtomicUsize,
        secp_ctx: Secp256k1,
 
        channel_state: Mutex<ChannelHolder>,
        our_network_key: SecretKey,
 
        pending_events: Mutex<Vec<events::Event>>,
+
+       logger: Arc<Logger>,
 }
 
 const CLTV_EXPIRY_DELTA: u16 = 6 * 24 * 2; //TODO?
@@ -209,7 +214,7 @@ impl ChannelManager {
        /// fee_proportional_millionths is an optional fee to charge any payments routed through us.
        /// Non-proportional fees are fixed according to our risk using the provided fee estimator.
        /// panics if channel_value_satoshis is >= `MAX_FUNDING_SATOSHIS`!
-       pub fn new(our_network_key: SecretKey, fee_proportional_millionths: u32, announce_channels_publicly: bool, network: Network, feeest: Arc<FeeEstimator>, monitor: Arc<ManyChannelMonitor>, chain_monitor: Arc<ChainWatchInterface>, tx_broadcaster: Arc<BroadcasterInterface>) -> Result<Arc<ChannelManager>, secp256k1::Error> {
+       pub fn new(our_network_key: SecretKey, fee_proportional_millionths: u32, announce_channels_publicly: bool, network: Network, feeest: Arc<FeeEstimator>, monitor: Arc<ManyChannelMonitor>, chain_monitor: Arc<ChainWatchInterface>, tx_broadcaster: Arc<BroadcasterInterface>, logger: Arc<Logger>) -> Result<Arc<ChannelManager>, secp256k1::Error> {
                let secp_ctx = Secp256k1::new();
 
                let res = Arc::new(ChannelManager {
@@ -234,6 +239,8 @@ impl ChannelManager {
                        our_network_key,
 
                        pending_events: Mutex::new(Vec::new()),
+
+                       logger,
                });
                let weak_res = Arc::downgrade(&res);
                res.chain_monitor.register_listener(weak_res);
@@ -268,7 +275,7 @@ impl ChannelManager {
                        }
                };
 
-               let channel = Channel::new_outbound(&*self.fee_estimator, chan_keys, their_network_key, channel_value_satoshis, self.announce_channels_publicly, user_id);
+               let channel = Channel::new_outbound(&*self.fee_estimator, chan_keys, their_network_key, channel_value_satoshis, self.announce_channels_publicly, user_id, Arc::clone(&self.logger));
                let res = channel.get_open_channel(self.genesis_hash.clone(), &*self.fee_estimator)?;
                let mut channel_state = self.channel_state.lock().unwrap();
                match channel_state.by_id.insert(channel.channel_id(), channel) {
@@ -388,7 +395,7 @@ impl ChannelManager {
                let mut chan = {
                        let mut channel_state_lock = self.channel_state.lock().unwrap();
                        let channel_state = channel_state_lock.borrow_parts();
-                       if let Some(mut chan) = channel_state.by_id.remove(channel_id) {
+                       if let Some(chan) = channel_state.by_id.remove(channel_id) {
                                if let Some(short_id) = chan.get_short_channel_id() {
                                        channel_state.short_to_id.remove(&short_id);
                                }
@@ -764,6 +771,7 @@ impl ChannelManager {
        /// Call this upon creation of a funding transaction for the given channel.
        /// Panics if a funding transaction has already been provided for this channel.
        pub fn funding_transaction_generated(&self, temporary_channel_id: &[u8; 32], funding_txo: OutPoint) {
+
                macro_rules! add_pending_event {
                        ($event: expr) => {
                                {
@@ -782,12 +790,12 @@ impl ChannelManager {
                                                        (chan, funding_msg.0, funding_msg.1)
                                                },
                                                Err(e) => {
+                                                       log_error!(self, "Got bad signatures: {}!", e.err);
                                                        mem::drop(channel_state);
-                                                       add_pending_event!(events::Event::DisconnectPeer {
+                                                       add_pending_event!(events::Event::HandleError {
                                                                node_id: chan.get_their_node_id(),
-                                                               msg: if let Some(msgs::ErrorAction::DisconnectPeer { msg } ) = e.action { msg } else { None },
+                                                               action: e.action,
                                                        });
-
                                                        return;
                                                },
                                        }
@@ -878,7 +886,7 @@ impl ChannelManager {
                                        if !add_htlc_msgs.is_empty() {
                                                let (commitment_msg, monitor) = match forward_chan.send_commitment() {
                                                        Ok(res) => res,
-                                                       Err(_) => {
+                                                       Err(_e) => {
                                                                //TODO: Handle...this is bad!
                                                                continue;
                                                        },
@@ -1002,6 +1010,7 @@ impl ChannelManager {
                                                }
 
                                                let mut pending_events = self.pending_events.lock().unwrap();
+                                               //TODO: replace by HandleError ? UpdateFailHTLC in handle_update_add_htlc need also to build a CommitmentSigned
                                                pending_events.push(events::Event::SendFailHTLC {
                                                        node_id,
                                                        msg: msg,
@@ -1135,14 +1144,16 @@ impl ChainListener for ChannelManager {
                let mut new_events = Vec::new();
                let mut failed_channels = Vec::new();
                {
-                       let mut channel_state = self.channel_state.lock().unwrap();
-                       let mut short_to_ids_to_insert = Vec::new();
-                       let mut short_to_ids_to_remove = Vec::new();
+                       let mut channel_lock = self.channel_state.lock().unwrap();
+                       let channel_state = channel_lock.borrow_parts();
+                       let short_to_id = channel_state.short_to_id;
                        channel_state.by_id.retain(|_, channel| {
-                               if let Some(funding_locked) = channel.block_connected(header, height, txn_matched, indexes_of_txn_matched) {
+                               let chan_res = channel.block_connected(header, height, txn_matched, indexes_of_txn_matched);
+                               if let Ok(Some(funding_locked)) = chan_res {
                                        let announcement_sigs = match self.get_announcement_sigs(channel) {
                                                Ok(res) => res,
-                                               Err(_e) => {
+                                               Err(e) => {
+                                                       log_error!(self, "Got error handling message: {}!", e.err);
                                                        //TODO: push e on events and blow up the channel (it has bad keys)
                                                        return true;
                                                }
@@ -1152,14 +1163,22 @@ impl ChainListener for ChannelManager {
                                                msg: funding_locked,
                                                announcement_sigs: announcement_sigs
                                        });
-                                       short_to_ids_to_insert.push((channel.get_short_channel_id().unwrap(), channel.channel_id()));
+                                       short_to_id.insert(channel.get_short_channel_id().unwrap(), channel.channel_id());
+                               } else if let Err(e) = chan_res {
+                                       new_events.push(events::Event::HandleError {
+                                               node_id: channel.get_their_node_id(),
+                                               action: e.action,
+                                       });
+                                       if channel.is_shutdown() {
+                                               return false;
+                                       }
                                }
                                if let Some(funding_txo) = channel.get_funding_txo() {
                                        for tx in txn_matched {
                                                for inp in tx.input.iter() {
                                                        if inp.prev_hash == funding_txo.txid && inp.prev_index == funding_txo.index as u32 {
                                                                if let Some(short_id) = channel.get_short_channel_id() {
-                                                                       short_to_ids_to_remove.push(short_id);
+                                                                       short_to_id.remove(&short_id);
                                                                }
                                                                // It looks like our counterparty went on-chain. We go ahead and
                                                                // broadcast our latest local state as well here, just in case its
@@ -1175,9 +1194,9 @@ impl ChainListener for ChannelManager {
                                                }
                                        }
                                }
-                               if channel.channel_monitor().would_broadcast_at_height(height) {
+                               if channel.is_funding_initiated() && channel.channel_monitor().would_broadcast_at_height(height) {
                                        if let Some(short_id) = channel.get_short_channel_id() {
-                                               short_to_ids_to_remove.push(short_id);
+                                               short_to_id.remove(&short_id);
                                        }
                                        failed_channels.push(channel.force_shutdown());
                                        // If would_broadcast_at_height() is true, the channel_monitor will broadcast
@@ -1193,12 +1212,6 @@ impl ChainListener for ChannelManager {
                                }
                                true
                        });
-                       for to_remove in short_to_ids_to_remove {
-                               channel_state.short_to_id.remove(&to_remove);
-                       }
-                       for to_insert in short_to_ids_to_insert {
-                               channel_state.short_to_id.insert(to_insert.0, to_insert.1);
-                       }
                }
                for failure in failed_channels.drain(..) {
                        self.finish_force_close_channel(failure);
@@ -1261,13 +1274,13 @@ impl ChannelMessageHandler for ChannelManager {
 
                let chan_keys = if cfg!(feature = "fuzztarget") {
                        ChannelKeys {
-                               funding_key:               SecretKey::from_slice(&self.secp_ctx, &[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]).unwrap(),
-                               revocation_base_key:       SecretKey::from_slice(&self.secp_ctx, &[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]).unwrap(),
-                               payment_base_key:          SecretKey::from_slice(&self.secp_ctx, &[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]).unwrap(),
-                               delayed_payment_base_key:  SecretKey::from_slice(&self.secp_ctx, &[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]).unwrap(),
-                               htlc_base_key:             SecretKey::from_slice(&self.secp_ctx, &[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]).unwrap(),
-                               channel_close_key:         SecretKey::from_slice(&self.secp_ctx, &[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]).unwrap(),
-                               channel_monitor_claim_key: SecretKey::from_slice(&self.secp_ctx, &[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]).unwrap(),
+                               funding_key:               SecretKey::from_slice(&self.secp_ctx, &[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0]).unwrap(),
+                               revocation_base_key:       SecretKey::from_slice(&self.secp_ctx, &[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 2, 0]).unwrap(),
+                               payment_base_key:          SecretKey::from_slice(&self.secp_ctx, &[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 3, 0]).unwrap(),
+                               delayed_payment_base_key:  SecretKey::from_slice(&self.secp_ctx, &[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 4, 0]).unwrap(),
+                               htlc_base_key:             SecretKey::from_slice(&self.secp_ctx, &[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 5, 0]).unwrap(),
+                               channel_close_key:         SecretKey::from_slice(&self.secp_ctx, &[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 6, 0]).unwrap(),
+                               channel_monitor_claim_key: SecretKey::from_slice(&self.secp_ctx, &[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 7, 0]).unwrap(),
                                commitment_seed: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0],
                        }
                } else {
@@ -1279,7 +1292,7 @@ impl ChannelMessageHandler for ChannelManager {
                        }
                };
 
-               let channel = Channel::new_from_req(&*self.fee_estimator, chan_keys, their_node_id.clone(), msg, 0, false, self.announce_channels_publicly)?;
+               let channel = Channel::new_from_req(&*self.fee_estimator, chan_keys, their_node_id.clone(), msg, 0, false, self.announce_channels_publicly, Arc::clone(&self.logger))?;
                let accept_msg = channel.get_accept_channel()?;
                channel_state.by_id.insert(channel.channel_id(), channel);
                Ok(accept_msg)
@@ -1628,20 +1641,14 @@ impl ChannelMessageHandler for ChannelManager {
                // destination. That's OK since those nodes are probably busted or trying to do network
                // mapping through repeated loops. In either case, we want them to stop talking to us, so
                // we send permanent_node_failure.
-               match &claimable_htlcs_entry {
-                       &hash_map::Entry::Occupied(ref e) => {
-                               let mut acceptable_cycle = false;
-                               match e.get() {
-                                       &PendingOutboundHTLC::OutboundRoute { .. } => {
-                                               acceptable_cycle = pending_forward_info.short_channel_id == 0;
-                                       },
-                                       _ => {},
-                               }
-                               if !acceptable_cycle {
-                                       return_err!("Payment looped through us twice", 0x4000 | 0x2000 | 2, &[0;0]);
-                               }
-                       },
-                       _ => {},
+               if let &hash_map::Entry::Occupied(ref e) = &claimable_htlcs_entry {
+                       let mut acceptable_cycle = false;
+                       if let &PendingOutboundHTLC::OutboundRoute { .. } = e.get() {
+                               acceptable_cycle = pending_forward_info.short_channel_id == 0;
+                       }
+                       if !acceptable_cycle {
+                               return_err!("Payment looped through us twice", 0x4000 | 0x2000 | 2, &[0;0]);
+                       }
                }
 
                let (source_short_channel_id, res) = match channel_state.by_id.get_mut(&msg.channel_id) {
@@ -1692,22 +1699,16 @@ impl ChannelMessageHandler for ChannelManager {
                // is broken, we may have enough info to get our own money!
                self.claim_funds_internal(msg.payment_preimage.clone(), false);
 
-               let monitor = {
-                       let mut channel_state = self.channel_state.lock().unwrap();
-                       match channel_state.by_id.get_mut(&msg.channel_id) {
-                               Some(chan) => {
-                                       if chan.get_their_node_id() != *their_node_id {
-                                               return Err(HandleError{err: "Got a message for a channel from the wrong node!", action: None})
-                                       }
-                                       chan.update_fulfill_htlc(&msg)?
-                               },
-                               None => return Err(HandleError{err: "Failed to find corresponding channel", action: None})
-                       }
-               };
-               if let Err(_e) = self.monitor.add_update_monitor(monitor.get_funding_txo().unwrap(), monitor) {
-                       unimplemented!();
+               let mut channel_state = self.channel_state.lock().unwrap();
+               match channel_state.by_id.get_mut(&msg.channel_id) {
+                       Some(chan) => {
+                               if chan.get_their_node_id() != *their_node_id {
+                                       return Err(HandleError{err: "Got a message for a channel from the wrong node!", action: None})
+                               }
+                               chan.update_fulfill_htlc(&msg)
+                       },
+                       None => return Err(HandleError{err: "Failed to find corresponding channel", action: None})
                }
-               Ok(())
        }
 
        fn handle_update_fail_htlc(&self, their_node_id: &PublicKey, msg: &msgs::UpdateFailHTLC) -> Result<Option<msgs::HTLCFailChannelUpdate>, HandleError> {
@@ -1977,6 +1978,7 @@ mod tests {
        use ln::msgs::{MsgEncodable,ChannelMessageHandler,RoutingMessageHandler};
        use util::test_utils;
        use util::events::{Event, EventsProvider};
+       use util::logger::Logger;
 
        use bitcoin::util::hash::Sha256dHash;
        use bitcoin::blockdata::block::{Block, BlockHeader};
@@ -2502,10 +2504,9 @@ mod tests {
                                        {
                                                let mut added_monitors = $node.chan_monitor.added_monitors.lock().unwrap();
                                                if $last_node {
-                                                       assert_eq!(added_monitors.len(), 1);
+                                                       assert_eq!(added_monitors.len(), 0);
                                                } else {
-                                                       assert_eq!(added_monitors.len(), 2);
-                                                       assert!(added_monitors[0].0 != added_monitors[1].0);
+                                                       assert_eq!(added_monitors.len(), 1);
                                                }
                                                added_monitors.clear();
                                        }
@@ -2692,10 +2693,11 @@ mod tests {
                let mut nodes = Vec::new();
                let mut rng = thread_rng();
                let secp_ctx = Secp256k1::new();
+               let logger: Arc<Logger> = Arc::new(test_utils::TestLogger::new());
 
                for _ in 0..node_count {
                        let feeest = Arc::new(test_utils::TestFeeEstimator { sat_per_kw: 253 });
-                       let chain_monitor = Arc::new(chaininterface::ChainWatchInterfaceUtil::new());
+                       let chain_monitor = Arc::new(chaininterface::ChainWatchInterfaceUtil::new(Arc::clone(&logger)));
                        let tx_broadcaster = Arc::new(test_utils::TestBroadcaster{txn_broadcasted: Mutex::new(Vec::new())});
                        let chan_monitor = Arc::new(test_utils::TestChannelMonitor::new(chain_monitor.clone(), tx_broadcaster.clone()));
                        let node_id = {
@@ -2703,8 +2705,8 @@ mod tests {
                                rng.fill_bytes(&mut key_slice);
                                SecretKey::from_slice(&secp_ctx, &key_slice).unwrap()
                        };
-                       let node = ChannelManager::new(node_id.clone(), 0, true, Network::Testnet, feeest.clone(), chan_monitor.clone(), chain_monitor.clone(), tx_broadcaster.clone()).unwrap();
-                       let router = Router::new(PublicKey::from_secret_key(&secp_ctx, &node_id).unwrap());
+                       let node = ChannelManager::new(node_id.clone(), 0, true, Network::Testnet, feeest.clone(), chan_monitor.clone(), chain_monitor.clone(), tx_broadcaster.clone(), Arc::clone(&logger)).unwrap();
+                       let router = Router::new(PublicKey::from_secret_key(&secp_ctx, &node_id).unwrap(), Arc::clone(&logger));
                        nodes.push(Node { feeest, chain_monitor, tx_broadcaster, chan_monitor, node_id, node, router });
                }