fix: demo branch fixes

contracts/contracts/sbtc-registry.clar

@@ -73,10 +73,6 @@
 ;; stored to avoid replay
 (define-map aggregate-pubkeys (buff 33) bool)
 
-;; Data structure to store the current signer set,
-;; stored to avoid replay
-(define-map multi-sig-address principal bool)
-
 ;; Data structure to store the active protocol contracts
 (define-map protocol-contracts principal bool)
 (map-set protocol-contracts .sbtc-bootstrap-signers true)
@@ -304,8 +300,6 @@
     (try! (is-protocol-caller))
     ;; Check that the aggregate pubkey is not already in the map
     (asserts! (map-insert aggregate-pubkeys new-aggregate-pubkey true) ERR_AGG_PUBKEY_REPLAY)
-    ;; Check that the new address (multi-sig) is not already in the map
-    (asserts! (map-insert multi-sig-address new-address true) ERR_MULTI_SIG_REPLAY)
     ;; Update the current signer set
     (var-set current-signer-set new-keys)
     ;; Update the current multi-sig address

contracts/tests/clarigen-types.ts

@@ -1116,11 +1116,6 @@ export const contracts = {
         },
         boolean
       >,
-      multiSigAddress: {
-        name: "multi-sig-address",
-        key: "principal",
-        value: "bool",
-      } as TypedAbiMap<string, boolean>,
       protocolContracts: {
         name: "protocol-contracts",
         key: "principal",

signer/Cargo.toml

@@ -48,7 +48,7 @@ tokio = { workspace = true, features = ["signal", "macros", "rt-multi-thread"] }
 tokio-stream.workspace = true
 tracing.workspace = true
 tracing-attributes.workspace = true
-tracing-subscriber.workspace = true
+tracing-subscriber = { workspace = true }
 url.workspace = true
 # wsts.workspace = true
 wsts = { git = "https://github.com/Trust-Machines/wsts.git", rev = "ebd7d7775ad5e44cdbf4f5c1fb468bdf6c467265" }

signer/src/emily_client.rs

@@ -323,6 +323,7 @@ impl EmilyInteract for EmilyClient {
     async fn set_chainstate(&self, chainstate: Chainstate) -> Result<Chainstate, Error> {
         chainstate_api::set_chainstate(&self.config, chainstate)
             .await
+            .inspect_err(|e| tracing::info!(?e, "Error for set_chainstate"))
             .map_err(EmilyClientError::AddChainstateEntry)
             .map_err(Error::EmilyApi)
     }

signer/src/main.rs

@@ -7,6 +7,7 @@ use axum::routing::post;
 use axum::Router;
 use cfg_if::cfg_if;
 use clap::Parser;
+use clap::ValueEnum;
 use signer::api;
 use signer::api::ApiState;
 use signer::bitcoin::rpc::BitcoinCoreClient;
@@ -28,6 +29,12 @@ use signer::transaction_signer;
 use signer::util::ApiFallbackClient;
 use tokio::signal;
 
+#[derive(Debug, Clone, Copy, ValueEnum)]
+enum LogOutputFormat {
+    Json,
+    Pretty,
+}
+
 /// Command line arguments for the signer.
 #[derive(Debug, Parser)]
 #[clap(name = "sBTC Signer")]
@@ -41,22 +48,30 @@ struct SignerArgs {
     /// pending migrations to the database on startup.
     #[clap(long)]
     migrate_db: bool,
+
+    #[clap(short = 'o', long = "output-format", default_value = "pretty")]
+    output_format: Option<LogOutputFormat>,
 }
 
 #[tokio::main]
 #[tracing::instrument(name = "signer")]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
-    // Initialize logging
-    // TODO(497): The whole logging thing should be revisited. We should support
-    //   enabling different layers, i.e. for pretty console, for opentelem, etc.
-    //sbtc::logging::setup_logging("info,signer=debug", false);
-    let _ = tracing_subscriber::fmt()
-        .with_env_filter(tracing_subscriber::EnvFilter::from_default_env())
-        .try_init();
-
     // Parse the command line arguments.
     let args = SignerArgs::parse();
 
+    // Initialize logging
+    let tracing_filter = tracing_subscriber::EnvFilter::from_default_env();
+    if let Some(LogOutputFormat::Json) = args.output_format {
+        tracing_subscriber::fmt()
+            .json()
+            .with_env_filter(tracing_filter)
+            .init();
+    } else {
+        tracing_subscriber::fmt()
+            .with_env_filter(tracing_filter)
+            .init();
+    }
+
     // Load the configuration file and/or environment variables.
     let settings = Settings::new(args.config)?;
 
@@ -279,7 +294,7 @@ async fn run_transaction_signer(ctx: impl Context) -> Result<(), Error> {
         network,
         context: ctx.clone(),
         context_window: 10000,
-        threshold: 2,
+        threshold: config.signer.bootstrap_signatures_required.into(),
         rng: rand::thread_rng(),
         signer_private_key: config.signer.private_key,
         wsts_state_machines: HashMap::new(),
@@ -290,17 +305,18 @@ async fn run_transaction_signer(ctx: impl Context) -> Result<(), Error> {
 
 /// Run the transaction coordinator event-loop.
 async fn run_transaction_coordinator(ctx: impl Context) -> Result<(), Error> {
-    let private_key = ctx.config().signer.private_key;
+    let config = ctx.config().clone();
+    let private_key = config.signer.private_key;
     let network = P2PNetwork::new(&ctx);
 
     let coord = transaction_coordinator::TxCoordinatorEventLoop {
         network,
         context: ctx,
         context_window: 10000,
         private_key,
-        signing_round_max_duration: Duration::from_secs(15),
-        threshold: 2,
-        dkg_max_duration: Duration::from_secs(15),
+        signing_round_max_duration: Duration::from_secs(30),
+        threshold: config.signer.bootstrap_signatures_required,
+        dkg_max_duration: Duration::from_secs(120),
         sbtc_contracts_deployed: false,
         is_epoch3: false,
     };

signer/src/network/libp2p/event_loop.rs

@@ -2,8 +2,9 @@ use std::sync::Arc;
 use std::time::Duration;
 
 use futures::StreamExt;
+use libp2p::multiaddr::Protocol;
 use libp2p::swarm::SwarmEvent;
-use libp2p::{gossipsub, identify, mdns, Swarm};
+use libp2p::{gossipsub, identify, kad, mdns, Multiaddr, Swarm};
 use tokio::sync::Mutex;
 
 use crate::codec::{Decode, Encode};
@@ -95,7 +96,7 @@ pub async fn run(ctx: &impl Context, swarm: Arc<Mutex<Swarm<SignerBehavior>>>) {
                         tracing::warn!(%listener_id, %error, "Listener error");
                     }
                     SwarmEvent::Dialing { peer_id, connection_id } => {
-                        tracing::info!(peer_id = ?peer_id, %connection_id, "Dialing peer");
+                        tracing::trace!(?peer_id, %connection_id, "Dialing peer");
                     }
                     SwarmEvent::ConnectionEstablished { endpoint, peer_id, .. } => {
                         if !ctx.state().current_signer_set().is_allowed_peer(&peer_id) {
@@ -105,25 +106,25 @@ pub async fn run(ctx: &impl Context, swarm: Arc<Mutex<Swarm<SignerBehavior>>>) {
                         }
                         tracing::info!(%peer_id, ?endpoint, "Connected to peer");
                     }
-                    SwarmEvent::ConnectionClosed { peer_id, cause, .. } => {
-                        tracing::info!(%peer_id, ?cause, "Connection closed");
+                    SwarmEvent::ConnectionClosed { peer_id, cause, endpoint, .. } => {
+                        tracing::trace!(%peer_id, ?cause, ?endpoint, "Connection closed");
                     }
                     SwarmEvent::IncomingConnection { local_addr, send_back_addr, .. } => {
-                        tracing::debug!(%local_addr, %send_back_addr, "Incoming connection");
+                        tracing::trace!(%local_addr, %send_back_addr, "Incoming connection");
                     }
                     SwarmEvent::Behaviour(SignerBehaviorEvent::Ping(ping)) => {
                         tracing::trace!("ping received: {:?}", ping);
                     }
-                    SwarmEvent::OutgoingConnectionError { connection_id, error, .. } => {
-                        tracing::warn!(%connection_id, %error, "outgoing connection error");
+                    SwarmEvent::OutgoingConnectionError { connection_id, error, peer_id } => {
+                        tracing::trace!(%connection_id, %error, ?peer_id, "outgoing connection error");
                     }
                     SwarmEvent::IncomingConnectionError {
                         local_addr,
                         send_back_addr,
                         error,
                         ..
                     } => {
-                        tracing::warn!(%local_addr, %send_back_addr, %error, "incoming connection error");
+                        tracing::trace!(%local_addr, %send_back_addr, %error, "incoming connection error");
                     }
                     SwarmEvent::NewExternalAddrCandidate { address } => {
                         tracing::debug!(%address, "New external address candidate");
@@ -135,19 +136,53 @@ pub async fn run(ctx: &impl Context, swarm: Arc<Mutex<Swarm<SignerBehavior>>>) {
                         tracing::debug!(%address, "External address expired");
                     }
                     SwarmEvent::NewExternalAddrOfPeer { peer_id, address } => {
-                        tracing::debug!(%peer_id, %address, "New external address of peer");
+                        if swarm.listeners().any(|addr| addr == &address) {
+                            tracing::debug!(%peer_id, %address, "ignoring our own external address");
+                        } else {
+                            tracing::debug!(%peer_id, %address, "New external address of peer");
+                            let kad_addr = strip_peer_id(&address);
+                            tracing::debug!(%peer_id, %kad_addr, "Adding address to kademlia");
+                            swarm
+                                .behaviour_mut()
+                                .kademlia
+                                .add_address(&peer_id, kad_addr);
+                        }
+                    }
+                    SwarmEvent::Behaviour(SignerBehaviorEvent::Kademlia(event)) => {
+                        handle_kademlia_event(event);
+                    }
+                    SwarmEvent::Behaviour(SignerBehaviorEvent::AutonatClient(event)) => {
+                        tracing::debug!(
+                            tested_addr = ?event.tested_addr,
+                            server = ?event.server,
+                            result = ?event.result,
+                            "autonat client event"
+                        );
+                    }
+                    SwarmEvent::Behaviour(SignerBehaviorEvent::AutonatServer(event)) => {
+                        tracing::debug!(
+                            all_addrs = ?event.all_addrs,
+                            tested_addr = ?event.tested_addr,
+                            client = ?event.client,
+                            result = ?event.result,
+                            "autonat server event"
+                        );
                     }
                     // The derived `SwarmEvent` is marked as #[non_exhaustive], so we must have a
                     // catch-all.
-                    _ => tracing::trace!("unhandled swarm event"),
+                    event => tracing::trace!(?event, "unhandled swarm event"),
                 }
             }
 
             // Drain the outbox and publish the messages to the network.
             let outbox = outbox.lock().await.drain(..).collect::<Vec<_>>();
             for payload in outbox {
-                tracing::info!("publishing message");
                 let msg_id = payload.id();
+                tracing::trace!(
+                    message_id = hex::encode(msg_id),
+                    msg = %payload,
+                    "publishing message"
+                );
 
                 // Attempt to encode the message payload into bytes
                 // using the signer codec.
@@ -187,17 +222,49 @@ pub async fn run(ctx: &impl Context, swarm: Arc<Mutex<Swarm<SignerBehavior>>>) {
         }
     };
 
+    let log = async {
+        loop {
+            tokio::time::sleep(Duration::from_secs(60)).await;
+            let swarm = swarm.lock().await;
+            let peers = swarm.connected_peers().collect::<Vec<_>>();
+            tracing::debug!(?peers, "connected peers");
+        }
+    };
+
     tokio::select! {
         _ = term.wait_for_shutdown() => {
             tracing::info!("libp2p received a termination signal; stopping the libp2p swarm");
         },
         _ = poll_outbound => {},
         _ = poll_swarm => {},
+        _ = log => {},
     }
 
     tracing::info!("libp2p event loop terminated");
 }
 
+fn handle_kademlia_event(event: kad::Event) {
+    match event {
+        kad::Event::RoutingUpdated {
+            peer,
+            is_new_peer,
+            addresses,
+            bucket_range,
+            old_peer,
+        } => {
+            tracing::debug!(
+                %peer,
+                is_new_peer,
+                ?addresses,
+                ?bucket_range,
+                ?old_peer,
+                "kademlia routing table updated"
+            );
+        }
+        _ => tracing::trace!(?event, "kademlia event"),
+    }
+}
+
 fn handle_mdns_event(swarm: &mut Swarm<SignerBehavior>, ctx: &impl Context, event: mdns::Event) {
     use mdns::Event;
 
@@ -239,19 +306,18 @@ fn handle_mdns_event(swarm: &mut Swarm<SignerBehavior>, ctx: &impl Context, even
 
 fn handle_identify_event(
     swarm: &mut Swarm<SignerBehavior>,
-    ctx: &impl Context,
+    _: &impl Context,
     event: identify::Event,
 ) {
     use identify::Event;
 
     match event {
         Event::Received { peer_id, info, .. } => {
-            if !ctx.state().current_signer_set().is_allowed_peer(&peer_id) {
-                tracing::debug!(%peer_id, "ignoring identify message from unknown peer");
-                return;
-            }
-            tracing::debug!(%peer_id, "Received identify message from peer; adding to confirmed external addresses");
-            swarm.add_external_address(info.observed_addr.clone());
+            tracing::debug!(%peer_id, ?info, "Received identify message from peer");
+            swarm
+                .behaviour_mut()
+                .kademlia
+                .add_address(&peer_id, strip_peer_id(&info.observed_addr));
         }
         Event::Pushed { connection_id, peer_id, info } => {
             tracing::trace!(%connection_id, %peer_id, ?info, "Pushed identify message to peer");
@@ -275,21 +341,24 @@ fn handle_gossipsub_event(
     match event {
         Event::Message {
             propagation_source: peer_id,
-            message_id: id,
             message,
+            ..
         } => {
             if !ctx.state().current_signer_set().is_allowed_peer(&peer_id) {
                 tracing::warn!(%peer_id, "ignoring message from unknown peer");
                 return;
             }
 
-            tracing::trace!(local_peer_id = %swarm.local_peer_id(), %peer_id,
-                "Got message: '{}' with id: {id} from peer: {peer_id}",
-                hex::encode(&message.data),
-            );
-
             Msg::decode(message.data.as_slice())
                 .map(|msg| {
+                    tracing::trace!(
+                        local_peer_id = %swarm.local_peer_id(),
+                        %peer_id,
+                        message_id = hex::encode(msg.id()),
+                        %msg,
+                        "received message",
+                    );
+
                     let _ = ctx.get_signal_sender()
                         .send(P2PEvent::MessageReceived(msg).into())
                         .map_err(|error| {
@@ -311,3 +380,32 @@ fn handle_gossipsub_event(
         }
     }
 }
+
+/// For a multiaddr that ends with a peer id, this strips this suffix. Rust-libp2p
+/// only supports dialing to an address without providing the peer id.
+fn strip_peer_id(addr: &Multiaddr) -> Multiaddr {
+    let mut new_addr = Multiaddr::empty();
+    for protocol in addr.iter().take_while(|p| !matches!(p, Protocol::P2p(_))) {
+        new_addr.push(protocol);
+    }
+    new_addr
+}
+
+#[cfg(test)]
+mod tests {
+    use std::str::FromStr;
+
+    use super::*;
+
+    #[test]
+    fn test_strip_peer_id() {
+        let endpoint =
+            "/ip4/198.51.100.0/tcp/4242/p2p/QmYyQSo1c1Ym7orWxLYvCrM2EmxFTANf8wXmmE7DWjhx5N";
+        let addr = Multiaddr::from_str(endpoint).unwrap();
+
+        let stripped = strip_peer_id(&addr);
+
+        let stripped_str = "/ip4/198.51.100.0/tcp/4242";
+        assert_eq!(stripped.to_string(), stripped_str);
+    }
+}