Improve logging

Cargo.lock

@@ -600,9 +600,9 @@ dependencies = [
 
 [[package]]
 name = "syn"
-version = "1.0.45"
+version = "1.0.48"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "ea9c5432ff16d6152371f808fb5a871cd67368171b09bb21b43df8e4a47a3556"
+checksum = "cc371affeffc477f42a221a1e4297aedcea33d47d19b61455588bd9d8f6b19ac"
 dependencies = [
  "proc-macro2",
  "quote",

src/cloud.rs

@@ -270,7 +270,10 @@ impl<D: Device, P: Protocol, S: Socket, TS: TimeSource> GenericCloud<D, P, S, TS
     pub fn connect<Addr: ToSocketAddrs + fmt::Debug + Clone>(&mut self, addr: Addr) -> Result<(), Error> {
         let addrs = resolve(&addr)?.into_iter().map(mapped_addr).collect::<Vec<_>>();
         for addr in &addrs {
-            if self.own_addresses.contains(addr) || self.peers.contains_key(addr) {
+            if self.own_addresses.contains(addr)
+                || self.peers.contains_key(addr)
+                || self.pending_inits.contains_key(addr)
+            {
                 return Ok(())
             }
         }
@@ -353,7 +356,7 @@ impl<D: Device, P: Protocol, S: Socket, TS: TimeSource> GenericCloud<D, P, S, TS
             }
         }
         for addr in del {
-            info!("Forgot peer: {}", addr_nice(addr));
+            info!("Forgot peer {} due to timeout", addr_nice(addr));
             self.peers.remove(&addr);
             self.table.remove_claims(addr);
             self.connect_sock(addr)?; // Try to reconnect
@@ -608,6 +611,7 @@ impl<D: Device, P: Protocol, S: Socket, TS: TimeSource> GenericCloud<D, P, S, TS
 
     fn remove_peer(&mut self, addr: SocketAddr) {
         if let Some(_peer) = self.peers.remove(&addr) {
+            info!("Closing connection to {}", addr_nice(addr));
             self.table.remove_claims(addr);
         }
     }
@@ -701,20 +705,28 @@ impl<D: Device, P: Protocol, S: Socket, TS: TimeSource> GenericCloud<D, P, S, TS
     }
 
     pub fn handle_net_message(&mut self, src: SocketAddr, data: &mut MsgBuffer) -> Result<(), Error> {
+        let src = mapped_addr(src);
         debug!("Received {} bytes from {}", data.len(), src);
         let msg_result = if let Some(init) = self.pending_inits.get_mut(&src) {
             init.handle_message(data)
         } else if is_init_message(data.message()) {
             let mut init = self.crypto.peer_instance(self.create_node_info());
             let msg_result = init.handle_message(data);
-            if msg_result.is_ok() {
+            match msg_result {
-                self.pending_inits.insert(src, init);
+                Ok(res) => {
+                    self.pending_inits.insert(src, init);
+                    Ok(res)
+                }
+                Err(err) => {
+                    debug!("Init error from {}: {}", src, err);
+                    info!("Ignoring invalid init message from peer {}", addr_nice(src));
+                    return Ok(())
+                }
             }
-            msg_result
         } else if let Some(peer) = self.peers.get_mut(&src) {
             peer.crypto.handle_message(data)
         } else {
-            error!("Received non-init message from unknown peer {}", addr_nice(src));
+            info!("Ignoring non-init message from unknown peer {}", addr_nice(src));
             return Ok(())
         };
         match msg_result {
@@ -737,10 +749,12 @@ impl<D: Device, P: Protocol, S: Socket, TS: TimeSource> GenericCloud<D, P, S, TS
         let src = try_fail!(self.socket.receive(buffer), "Failed to read from network socket: {}");
         self.traffic.count_in_traffic(src, buffer.len());
         if let Err(e) = self.handle_net_message(src, buffer) {
-            error!("Error: {}", e);
             if let Error::CryptoInit(_) = e {
-                info!("Closing pending connection to {} due to error", addr_nice(src));
+                debug!("Crypto init error: {}", e);
+                info!("Closing pending connection to {} due to error in crypto init", addr_nice(src));
                 self.pending_inits.remove(&src);
+            } else {
+                error!("Error: {}", e);
             }
         }
     }

src/crypto/core.rs

@@ -174,7 +174,7 @@ impl CryptoCore {
         tag_space.clone_from_slice(tag.as_ref());
     }
 
-    fn decrypt_with_key<'a>(key: &mut CryptoKey, nonce: Nonce, data_and_tag: &'a mut [u8]) -> Result<(), Error> {
+    fn decrypt_with_key(key: &mut CryptoKey, nonce: Nonce, data_and_tag: &mut [u8]) -> Result<(), Error> {
         if nonce < key.min_nonce {
             return Err(Error::Crypto("Old nonce rejected"))
         }

src/crypto/init.rs

@@ -82,6 +82,7 @@ pub const CLOSING: u8 = 5;
 pub const SALTED_NODE_ID_HASH_LEN: usize = 20;
 pub type SaltedNodeIdHash = [u8; SALTED_NODE_ID_HASH_LEN];
 
+
 #[allow(clippy::large_enum_variant)]
 pub enum InitMsg {
     Ping {
@@ -561,6 +562,7 @@ impl<P: Payload> InitState<P> {
             })
             .max_by(|(_, s1), (_, s2)| if s1 < s2 { cmp::Ordering::Less } else { cmp::Ordering::Greater });
         if let Some(algo) = algo {
+            debug!("Init: best algorithm is {:?} with speed {}", algo.0, algo.1);
             Ok(Some(algo))
         } else {
             Err(Error::CryptoInit("No common algorithms"))

src/port_forwarding.rs

@@ -39,7 +39,7 @@ mod internal {
                     return None
                 }
             };
-            info!("Port-forwarding: found router at {}", gateway.addr);
+            debug!("Port-forwarding: found router at {}", gateway.addr);
             let internal_addr = SocketAddrV4::new(get_internal_ip(), port);
             // Query the external address
             let external_ip = match gateway.get_external_ip() {
@@ -50,9 +50,10 @@ mod internal {
                 }
             };
             if let Ok((port, timeout)) = Self::get_any_forwarding(&gateway, internal_addr, port) {
-                info!("Port-forwarding: external IP is {}", external_ip);
+                debug!("Port-forwarding: external IP is {}", external_ip);
                 let external_addr = SocketAddrV4::new(external_ip, port);
-                info!("Port-forwarding: successfully activated port forward on {}, timeout: {}", external_addr, timeout);
+                debug!("Port-forwarding has timeout {}", timeout);
+                info!("Port-forwarding: successfully activated port forward on {}", external_addr);
                 let next_extension =
                     if timeout > 0 { Some(SystemTimeSource::now() + Time::from(timeout) - 60) } else { None };
                 Some(PortForwarding { internal_addr, external_addr, gateway, next_extension })
@@ -78,11 +79,12 @@ mod internal {
                     return Ok(a)
                 }
             }
+            warn!("Failed to activate port forwarding");
             Err(())
         }
 
         fn get_forwarding(gateway: &Gateway, addr: SocketAddrV4, port: u16) -> Result<(u16, u32), ()> {
-            info!("Trying external port {}", port);
+            debug!("Trying external port {}", port);
             if port == 0 {
                 match gateway.add_any_port(PortMappingProtocol::UDP, addr, LEASE_TIME, DESCRIPTION) {
                     Ok(port) => Ok((port, LEASE_TIME)),
@@ -90,13 +92,13 @@ mod internal {
                         match gateway.add_any_port(PortMappingProtocol::UDP, addr, 0, DESCRIPTION) {
                             Ok(port) => Ok((port, 0)),
                             Err(err) => {
-                                error!("Port-forwarding: failed to activate port forwarding: {}", err);
+                                debug!("Port-forwarding: failed to activate port forwarding: {}", err);
                                 Err(())
                             }
                         }
                     }
                     Err(err) => {
-                        error!("Port-forwarding: failed to activate port forwarding: {}", err);
+                        debug!("Port-forwarding: failed to activate port forwarding: {}", err);
                         Err(())
                     }
                 }
@@ -108,13 +110,13 @@ mod internal {
                         match gateway.add_port(PortMappingProtocol::UDP, port, addr, 0, DESCRIPTION) {
                             Ok(()) => Ok((port, 0)),
                             Err(err) => {
-                                error!("Port-forwarding: failed to activate port forwarding: {}", err);
+                                debug!("Port-forwarding: failed to activate port forwarding: {}", err);
                                 Err(())
                             }
                         }
                     }
                     Err(err) => {
-                        error!("Port-forwarding: failed to activate port forwarding: {}", err);
+                        debug!("Port-forwarding: failed to activate port forwarding: {}", err);
                         Err(())
                     }
                 }
@@ -137,7 +139,7 @@ mod internal {
                 DESCRIPTION
             ) {
                 Ok(()) => debug!("Port-forwarding: extended port forwarding"),
-                Err(err) => error!("Port-forwarding: failed to extend port forwarding: {}", err)
+                Err(err) => debug!("Port-forwarding: failed to extend port forwarding: {}", err)
             };
             self.next_extension = Some(SystemTimeSource::now() + Time::from(LEASE_TIME) - 60);
         }
@@ -145,7 +147,7 @@ mod internal {
         fn deactivate(&self) {
             match self.gateway.remove_port(PortMappingProtocol::UDP, self.external_addr.port()) {
                 Ok(()) => info!("Port-forwarding: successfully deactivated port forwarding"),
-                Err(err) => error!("Port-forwarding: failed to deactivate port forwarding: {}", err)
+                Err(err) => debug!("Port-forwarding: failed to deactivate port forwarding: {}", err)
             }
         }
     }