feat: improve logging

packages/autopeering/discover/manager.go

@@ -202,8 +202,8 @@ func (m *manager) peerToReverify() *mpeer {
 }
 
 // updatePeer moves the peer with the given ID to the front of the list of managed peers.
-// It returns true if a peer was bumped or false if there was no peer with that id
-func (m *manager) updatePeer(update *peer.Peer) bool {
+// It returns 0 if there was no peer with that id, otherwise the verifiedCount of the updated peer is returned.
+func (m *manager) updatePeer(update *peer.Peer) uint {
 	id := update.ID()
 	for i, p := range m.active {
 		if p.ID() == id {
@@ -217,11 +217,10 @@ func (m *manager) updatePeer(update *peer.Peer) bool {
 				verifiedCount: p.verifiedCount + 1,
 				lastNewPeers:  p.lastNewPeers,
 			}
-
-			return true
+			return p.verifiedCount + 1
 		}
 	}
-	return false
+	return 0
 }
 
 func (m *manager) addReplacement(p *mpeer) bool {
@@ -289,7 +288,11 @@ func (m *manager) addVerifiedPeer(p *peer.Peer) bool {
 	defer m.mutex.Unlock()
 
 	// if already in the list, move it to the front
-	if m.updatePeer(p) {
+	if v := m.updatePeer(p); v > 0 {
+		// trigger the event only for the first time the peer is updated
+		if v == 1 {
+			Events.PeerDiscovered.Trigger(&DiscoveredEvent{Peer: p})
+		}
 		return false
 	}
 

packages/autopeering/peer/peer.go

@@ -2,6 +2,7 @@ package peer
 
 import (
 	"crypto/ed25519"
+	"encoding/base64"
 	"errors"
 	"fmt"
 	"net/url"
@@ -50,7 +51,7 @@ func (p *Peer) Services() service.Service {
 func (p *Peer) String() string {
 	u := url.URL{
 		Scheme: "peer",
-		User:   url.User(fmt.Sprintf("%x", p.publicKey)),
+		User:   url.User(base64.StdEncoding.EncodeToString(p.PublicKey())),
 		Host:   p.Address(),
 	}
 	return u.String()

plugins/analysis/client/plugin.go

 package client
 
 import (
-	"encoding/hex"
 	"net"
 	"time"
 
@@ -57,15 +56,19 @@ func Run(plugin *node.Plugin) {
 func getEventDispatchers(conn *network.ManagedConnection) *EventDispatchers {
 	return &EventDispatchers{
 		AddNode: func(nodeId []byte) {
+			log.Debugw("AddNode", "nodeId", nodeId)
 			_, _ = conn.Write((&addnode.Packet{NodeId: nodeId}).Marshal())
 		},
 		RemoveNode: func(nodeId []byte) {
+			log.Debugw("RemoveNode", "nodeId", nodeId)
 			_, _ = conn.Write((&removenode.Packet{NodeId: nodeId}).Marshal())
 		},
 		ConnectNodes: func(sourceId []byte, targetId []byte) {
+			log.Debugw("ConnectNodes", "sourceId", sourceId, "targetId", targetId)
 			_, _ = conn.Write((&connectnodes.Packet{SourceId: sourceId, TargetId: targetId}).Marshal())
 		},
 		DisconnectNodes: func(sourceId []byte, targetId []byte) {
+			log.Debugw("DisconnectNodes", "sourceId", sourceId, "targetId", targetId)
 			_, _ = conn.Write((&disconnectnodes.Packet{SourceId: sourceId, TargetId: targetId}).Marshal())
 		},
 	}
@@ -83,27 +86,22 @@ func setupHooks(plugin *node.Plugin, conn *network.ManagedConnection, eventDispa
 	// define hooks ////////////////////////////////////////////////////////////////////////////////////////////////////
 
 	onDiscoverPeer := events.NewClosure(func(ev *discover.DiscoveredEvent) {
-		log.Info("onDiscoverPeer: " + hex.EncodeToString(ev.Peer.ID().Bytes()))
 		eventDispatchers.AddNode(ev.Peer.ID().Bytes())
 	})
 
 	onDeletePeer := events.NewClosure(func(ev *discover.DeletedEvent) {
-		log.Info("onDeletePeer: " + hex.EncodeToString(ev.Peer.ID().Bytes()))
 		eventDispatchers.RemoveNode(ev.Peer.ID().Bytes())
 	})
 
 	onAddAcceptedNeighbor := events.NewClosure(func(ev *selection.PeeringEvent) {
-		log.Info("onAddAcceptedNeighbor: " + hex.EncodeToString(ev.Peer.ID().Bytes()) + " - " + hex.EncodeToString(local.GetInstance().ID().Bytes()))
 		eventDispatchers.ConnectNodes(ev.Peer.ID().Bytes(), local.GetInstance().ID().Bytes())
 	})
 
 	onRemoveNeighbor := events.NewClosure(func(ev *selection.DroppedEvent) {
-		log.Info("onRemoveNeighbor: " + hex.EncodeToString(ev.DroppedID.Bytes()) + " - " + hex.EncodeToString(local.GetInstance().ID().Bytes()))
 		eventDispatchers.DisconnectNodes(ev.DroppedID.Bytes(), local.GetInstance().ID().Bytes())
 	})
 
 	onAddChosenNeighbor := events.NewClosure(func(ev *selection.PeeringEvent) {
-		log.Info("onAddChosenNeighbor: " + hex.EncodeToString(local.GetInstance().ID().Bytes()) + " - " + hex.EncodeToString(ev.Peer.ID().Bytes()))
 		eventDispatchers.ConnectNodes(local.GetInstance().ID().Bytes(), ev.Peer.ID().Bytes())
 	})
 

plugins/autopeering/autopeering.go

@@ -96,7 +96,7 @@ func start(shutdownSignal <-chan struct{}) {
 		defer Selection.Close()
 	}
 
-	log.Infof("Auto Peering server started: ID=%x, address=%s", local.GetInstance().ID(), srv.LocalAddr())
+	log.Infof("Auto Peering started: address=%s", srv.LocalAddr())
 
 	<-shutdownSignal
 	log.Info("Stopping Auto Peering server ...")

plugins/autopeering/local/local.go

@@ -3,7 +3,6 @@ package local
 import (
 	"fmt"
 	"io/ioutil"
-	"log"
 	"net"
 	"net/http"
 	"strconv"
@@ -20,33 +19,47 @@ var (
 )
 
 func configureLocal() *peer.Local {
+	log := logger.NewLogger("Local")
+
 	ip := net.ParseIP(parameter.NodeConfig.GetString(CFG_ADDRESS))
 	if ip == nil {
 		log.Fatalf("Invalid IP address: %s", parameter.NodeConfig.GetString(CFG_ADDRESS))
 	}
 	if ip.IsUnspecified() {
-		myIp, err := getMyIP()
+		log.Info("Querying public IP ...")
+		myIp, err := getPublicIP(isIPv4(ip))
 		if err != nil {
-			log.Fatalf("Could not query public IP: %v", err)
+			log.Fatalf("Error querying public IP: %s", err)
 		}
 		ip = myIp
+		log.Infof("Public IP queried: address=%s", ip.String())
 	}
 
 	port := strconv.Itoa(parameter.NodeConfig.GetInt(CFG_PORT))
 
 	// create a new local node
-	db := peer.NewPersistentDB(logger.NewLogger("local"))
+	db := peer.NewPersistentDB(log)
 
 	local, err := peer.NewLocal("udp", net.JoinHostPort(ip.String(), port), db)
 	if err != nil {
-		log.Fatalf("NewLocal: %v", err)
+		log.Fatalf("Error creating local: %s", err)
 	}
+	log.Infof("Initialized local: %v", local)
 
 	return local
 }
 
-func getMyIP() (net.IP, error) {
-	url := "https://api.ipify.org?format=text"
+func isIPv4(ip net.IP) bool {
+	return ip.To4() != nil
+}
+
+func getPublicIP(ipv4 bool) (net.IP, error) {
+	var url string
+	if ipv4 {
+		url = "https://api.ipify.org"
+	} else {
+		url = "https://api6.ipify.org"
+	}
 	resp, err := http.Get(url)
 	if err != nil {
 		return nil, err

plugins/autopeering/plugin.go

@@ -3,6 +3,7 @@ package autopeering
 import (
 	"github.com/iotaledger/goshimmer/packages/autopeering/discover"
 	"github.com/iotaledger/goshimmer/packages/autopeering/peer"
+	"github.com/iotaledger/goshimmer/packages/autopeering/selection"
 	"github.com/iotaledger/goshimmer/packages/gossip"
 	"github.com/iotaledger/hive.go/daemon"
 	"github.com/iotaledger/hive.go/events"
@@ -37,6 +38,19 @@ func configureEvents() {
 	}))
 
 	discover.Events.PeerDiscovered.Attach(events.NewClosure(func(ev *discover.DiscoveredEvent) {
-		log.Info("new peer discovered: " + ev.Peer.Address() + " / " + ev.Peer.ID().String())
+		log.Infof("Discovered: %s / %s", ev.Peer.Address(), ev.Peer.ID())
+	}))
+	discover.Events.PeerDeleted.Attach(events.NewClosure(func(ev *discover.DeletedEvent) {
+		log.Infof("Removed offline: %s / %s", ev.Peer.Address(), ev.Peer.ID())
+	}))
+
+	selection.Events.OutgoingPeering.Attach(events.NewClosure(func(ev *selection.PeeringEvent) {
+		log.Infof("Peering chosen: %s / %s", ev.Peer.Address(), ev.Peer.ID())
+	}))
+	selection.Events.IncomingPeering.Attach(events.NewClosure(func(ev *selection.PeeringEvent) {
+		log.Infof("Peering accepted: %s / %s", ev.Peer.Address(), ev.Peer.ID())
+	}))
+	selection.Events.Dropped.Attach(events.NewClosure(func(ev *selection.DroppedEvent) {
+		log.Infof("Peering dropped: %s", ev.DroppedID)
 	}))
 }

plugins/cli/plugin.go

@@ -45,7 +45,7 @@ func parseParameters() {
 }
 
 func LoadConfig() {
-	if err := parameter.FetchConfig(true); err != nil {
+	if err := parameter.FetchConfig(false); err != nil {
 		panic(err)
 	}
 	parseParameters()
@@ -56,7 +56,6 @@ func LoadConfig() {
 }
 
 func configure(ctx *node.Plugin) {
-
 	fmt.Println("  _____ _   _ ________  ______  ___ ___________ ")
 	fmt.Println(" /  ___| | | |_   _|  \\/  ||  \\/  ||  ___| ___ \\")
 	fmt.Println(" \\ `--.| |_| | | | | .  . || .  . || |__ | |_/ /")
@@ -64,6 +63,7 @@ func configure(ctx *node.Plugin) {
 	fmt.Println(" /\\__/ / | | |_| |_| |  | || |  | || |___| |\\ \\ ")
 	fmt.Printf(" \\____/\\_| |_/\\___/\\_|  |_/\\_|  |_/\\____/\\_| \\_| fullnode %s", AppVersion)
 	fmt.Println()
+	fmt.Println()
 
 	ctx.Node.Logger.Info("Loading plugins ...")
 }