[client] Set info logs (#3504)

collect and log connection stats per peer every 10 minutes

README.md

@@ -12,7 +12,7 @@
        <img src="https://img.shields.io/badge/license-BSD--3-blue" />
      </a> 
     <br>
-    <a href="https://join.slack.com/t/netbirdio/shared_invite/zt-2utg2ncdz-W7LEB6toRBLE1Jca37dYpg">
+    <a href="https://join.slack.com/t/netbirdio/shared_invite/zt-31rofwmxc-27akKd0Le0vyRpBcwXkP0g">
         <img src="https://img.shields.io/badge/slack-@netbird-red.svg?logo=slack"/>
      </a>  
      <br>
@@ -29,13 +29,13 @@
   <br/>
   See <a href="https://netbird.io/docs/">Documentation</a>
   <br/>
-   Join our <a href="https://join.slack.com/t/netbirdio/shared_invite/zt-2utg2ncdz-W7LEB6toRBLE1Jca37dYpg">Slack channel</a>
+   Join our <a href="https://join.slack.com/t/netbirdio/shared_invite/zt-31rofwmxc-27akKd0Le0vyRpBcwXkP0g">Slack channel</a>
   <br/>
  
 </strong>
 <br>
-<a href="https://netbird.io/webinars/achieve-zero-trust-access-to-k8s?utm_source=github&utm_campaign=2502%20-%20webinar%20-%20How%20to%20Achieve%20Zero%20Trust%20Access%20to%20Kubernetes%20-%20Effortlessly&utm_medium=github">
+<a href="https://github.com/netbirdio/kubernetes-operator">
-    Webinar: Securely Access Kubernetes without Port Forwarding and Jump Hosts
+    New: NetBird Kubernetes Operator
   </a> 
 </p>
 

client/anonymize/anonymize.go

@@ -26,7 +26,7 @@ type Anonymizer struct {
 }
 
 func DefaultAddresses() (netip.Addr, netip.Addr) {
-	// 192.51.100.0, 100::
+	// 198.51.100.0, 100::
 	return netip.AddrFrom4([4]byte{198, 51, 100, 0}), netip.AddrFrom16([16]byte{0x01})
 }
 

client/internal/peer/conn.go

@@ -114,6 +114,9 @@ type Conn struct {
 
 	guard     *guard.Guard
 	semaphore *semaphoregroup.SemaphoreGroup
+
+	// debug purpose
+	dumpState *stateDump
 }
 
 // NewConn creates a new not opened Conn to the remote peer.
@@ -140,7 +143,7 @@ func NewConn(engineCtx context.Context, config ConnConfig, statusRecorder *Statu
 	}
 
 	ctrl := isController(config)
-	conn.workerRelay = NewWorkerRelay(connLog, ctrl, config, conn, relayManager)
+	conn.workerRelay = NewWorkerRelay(connLog, ctrl, config, conn, relayManager, conn.dumpState)
 
 	relayIsSupportedLocally := conn.workerRelay.RelayIsSupportedLocally()
 	workerICE, err := NewWorkerICE(ctx, connLog, config, conn, signaler, iFaceDiscover, statusRecorder, relayIsSupportedLocally)
@@ -160,6 +163,8 @@ func NewConn(engineCtx context.Context, config ConnConfig, statusRecorder *Statu
 
 	go conn.handshaker.Listen()
 
+	conn.dumpState = newStateDump(connLog)
+	go conn.dumpState.Start(ctx)
 	return conn, nil
 }
 
@@ -193,6 +198,7 @@ func (conn *Conn) startHandshakeAndReconnect(ctx context.Context) {
 	defer conn.semaphore.Done(conn.ctx)
 	conn.waitInitialRandomSleepTime(ctx)
 
+	conn.dumpState.SendOffer()
 	err := conn.handshaker.sendOffer()
 	if err != nil {
 		conn.log.Errorf("failed to send initial offer: %v", err)
@@ -251,12 +257,14 @@ func (conn *Conn) Close() {
 // OnRemoteAnswer handles an offer from the remote peer and returns true if the message was accepted, false otherwise
 // doesn't block, discards the message if connection wasn't ready
 func (conn *Conn) OnRemoteAnswer(answer OfferAnswer) bool {
-	conn.log.Debugf("OnRemoteAnswer, status ICE: %s, status relay: %s", conn.statusICE, conn.statusRelay)
+	conn.dumpState.RemoteAnswer()
+	conn.log.Infof("OnRemoteAnswer, status ICE: %s, status relay: %s", conn.statusICE, conn.statusRelay)
 	return conn.handshaker.OnRemoteAnswer(answer)
 }
 
 // OnRemoteCandidate Handles ICE connection Candidate provided by the remote peer.
 func (conn *Conn) OnRemoteCandidate(candidate ice.Candidate, haRoutes route.HAMap) {
+	conn.dumpState.RemoteCandidate()
 	conn.workerICE.OnRemoteCandidate(candidate, haRoutes)
 }
 
@@ -278,7 +286,8 @@ func (conn *Conn) SetOnDisconnected(handler func(remotePeer string)) {
 }
 
 func (conn *Conn) OnRemoteOffer(offer OfferAnswer) bool {
-	conn.log.Debugf("OnRemoteOffer, on status ICE: %s, status Relay: %s", conn.statusICE, conn.statusRelay)
+	conn.dumpState.RemoteOffer()
+	conn.log.Infof("OnRemoteOffer, on status ICE: %s, status Relay: %s", conn.statusICE, conn.statusRelay)
 	return conn.handshaker.OnRemoteOffer(offer)
 }
 
@@ -322,6 +331,7 @@ func (conn *Conn) onICEConnectionIsReady(priority ConnPriority, iceConnInfo ICEC
 	}
 
 	conn.log.Infof("set ICE to active connection")
+	conn.dumpState.P2PConnected()
 
 	var (
 		ep      *net.UDPAddr
@@ -329,6 +339,7 @@ func (conn *Conn) onICEConnectionIsReady(priority ConnPriority, iceConnInfo ICEC
 		err     error
 	)
 	if iceConnInfo.RelayedOnLocal {
+		conn.dumpState.NewLocalProxy()
 		wgProxy, err = conn.newProxy(iceConnInfo.RemoteConn)
 		if err != nil {
 			conn.log.Errorf("failed to add turn net.Conn to local proxy: %v", err)
@@ -390,6 +401,7 @@ func (conn *Conn) onICEStateDisconnected() {
 	// switch back to relay connection
 	if conn.isReadyToUpgrade() {
 		conn.log.Infof("ICE disconnected, set Relay to active connection")
+		conn.dumpState.SwitchToRelay()
 		conn.wgProxyRelay.Work()
 
 		if err := conn.configureWGEndpoint(conn.wgProxyRelay.EndpointAddr()); err != nil {
@@ -432,6 +444,7 @@ func (conn *Conn) onRelayConnectionIsReady(rci RelayConnInfo) {
 		return
 	}
 
+	conn.dumpState.RelayConnected()
 	conn.log.Debugf("Relay connection has been established, setup the WireGuard")
 
 	wgProxy, err := conn.newProxy(rci.relayedConn)
@@ -439,6 +452,7 @@ func (conn *Conn) onRelayConnectionIsReady(rci RelayConnInfo) {
 		conn.log.Errorf("failed to add relayed net.Conn to local proxy: %v", err)
 		return
 	}
+	conn.dumpState.NewLocalProxy()
 
 	conn.log.Infof("created new wgProxy for relay connection: %s", wgProxy.EndpointAddr().String())
 
@@ -481,10 +495,10 @@ func (conn *Conn) onRelayDisconnected() {
 		return
 	}
 
-	conn.log.Debugf("relay connection is disconnected")
+	conn.log.Infof("relay connection is disconnected")
 
 	if conn.currentConnPriority == connPriorityRelay {
-		conn.log.Debugf("clean up WireGuard config")
+		conn.log.Infof("clean up WireGuard config")
 		if err := conn.removeWgPeer(); err != nil {
 			conn.log.Errorf("failed to remove wg endpoint: %v", err)
 		}
@@ -516,7 +530,8 @@ func (conn *Conn) listenGuardEvent(ctx context.Context) {
 	for {
 		select {
 		case <-conn.guard.Reconnect:
-			conn.log.Debugf("send offer to peer")
+			conn.log.Infof("send offer to peer")
+			conn.dumpState.SendOffer()
 			if err := conn.handshaker.SendOffer(); err != nil {
 				conn.log.Errorf("failed to send offer: %v", err)
 			}

client/internal/peer/handshaker.go

@@ -76,19 +76,19 @@ func (h *Handshaker) AddOnNewOfferListener(offer func(remoteOfferAnswer *OfferAn
 
 func (h *Handshaker) Listen() {
 	for {
-		h.log.Debugf("wait for remote offer confirmation")
+		h.log.Info("wait for remote offer confirmation")
 		remoteOfferAnswer, err := h.waitForRemoteOfferConfirmation()
 		if err != nil {
 			var connectionClosedError *ConnectionClosedError
 			if errors.As(err, &connectionClosedError) {
-				h.log.Tracef("stop handshaker")
+				h.log.Info("exit from handshaker")
 				return
 			}
 			h.log.Errorf("failed to received remote offer confirmation: %s", err)
 			continue
 		}
 
-		h.log.Debugf("received connection confirmation, running version %s and with remote WireGuard listen port %d", remoteOfferAnswer.Version, remoteOfferAnswer.WgListenPort)
+		h.log.Infof("received connection confirmation, running version %s and with remote WireGuard listen port %d", remoteOfferAnswer.Version, remoteOfferAnswer.WgListenPort)
 		for _, listener := range h.onNewOfferListeners {
 			go listener(remoteOfferAnswer)
 		}
@@ -108,7 +108,7 @@ func (h *Handshaker) OnRemoteOffer(offer OfferAnswer) bool {
 	case h.remoteOffersCh <- offer:
 		return true
 	default:
-		h.log.Debugf("OnRemoteOffer skipping message because is not ready")
+		h.log.Warnf("OnRemoteOffer skipping message because is not ready")
 		// connection might not be ready yet to receive so we ignore the message
 		return false
 	}
@@ -131,8 +131,7 @@ func (h *Handshaker) waitForRemoteOfferConfirmation() (*OfferAnswer, error) {
 	select {
 	case remoteOfferAnswer := <-h.remoteOffersCh:
 		// received confirmation from the remote peer -> ready to proceed
-		err := h.sendAnswer()
+		if err := h.sendAnswer(); err != nil {
-		if err != nil {
 			return nil, err
 		}
 		return &remoteOfferAnswer, nil
@@ -168,7 +167,7 @@ func (h *Handshaker) sendOffer() error {
 }
 
 func (h *Handshaker) sendAnswer() error {
-	h.log.Debugf("sending answer")
+	h.log.Infof("sending answer")
 	uFrag, pwd := h.ice.GetLocalUserCredentials()
 
 	answer := OfferAnswer{

client/internal/peer/state_dump.go

@@ -0,0 +1,112 @@
+package peer
+
+import (
+	"context"
+	"sync"
+	"time"
+
+	log "github.com/sirupsen/logrus"
+)
+
+type stateDump struct {
+	log *log.Entry
+
+	sentOffer       int
+	remoteOffer     int
+	remoteAnswer    int
+	remoteCandidate int
+	p2pConnected    int
+	switchToRelay   int
+	wgCheckSuccess  int
+	relayConnected  int
+	localProxies    int
+
+	mu sync.Mutex
+}
+
+func newStateDump(log *log.Entry) *stateDump {
+	return &stateDump{
+		log: log,
+	}
+}
+
+func (s *stateDump) Start(ctx context.Context) {
+	ticker := time.NewTicker(10 * time.Minute)
+	defer ticker.Stop()
+
+	for {
+		select {
+		case <-ticker.C:
+			s.dumpState()
+		case <-ctx.Done():
+			return
+		}
+	}
+}
+
+func (s *stateDump) RemoteOffer() {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+	s.remoteOffer++
+}
+
+func (s *stateDump) RemoteCandidate() {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+	s.remoteCandidate++
+}
+
+func (s *stateDump) SendOffer() {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+	s.sentOffer++
+}
+
+func (s *stateDump) dumpState() {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	s.log.Infof("Dump stat: SentOffer: %d, RemoteOffer: %d, RemoteAnswer: %d, RemoteCandidate: %d, P2PConnected: %d, SwitchToRelay: %d, WGCheckSuccess: %d, RelayConnected: %d, LocalProxies: %d",
+		s.sentOffer, s.remoteOffer, s.remoteAnswer, s.remoteCandidate, s.p2pConnected, s.switchToRelay, s.wgCheckSuccess, s.relayConnected, s.localProxies)
+}
+
+func (s *stateDump) RemoteAnswer() {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+	s.remoteAnswer++
+}
+
+func (s *stateDump) P2PConnected() {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	s.p2pConnected++
+}
+
+func (s *stateDump) SwitchToRelay() {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	s.switchToRelay++
+}
+
+func (s *stateDump) WGcheckSuccess() {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	s.wgCheckSuccess++
+}
+
+func (s *stateDump) RelayConnected() {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	s.relayConnected++
+}
+
+func (s *stateDump) NewLocalProxy() {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	s.localProxies++
+}

client/internal/peer/wg_watcher.go

@@ -27,6 +27,7 @@ type WGWatcher struct {
 	log           *log.Entry
 	wgIfaceStater WGInterfaceStater
 	peerKey       string
+	stateDump     *stateDump
 
 	ctx       context.Context
 	ctxCancel context.CancelFunc
@@ -34,11 +35,12 @@ type WGWatcher struct {
 	waitGroup sync.WaitGroup
 }
 
-func NewWGWatcher(log *log.Entry, wgIfaceStater WGInterfaceStater, peerKey string) *WGWatcher {
+func NewWGWatcher(log *log.Entry, wgIfaceStater WGInterfaceStater, peerKey string, stateDump *stateDump) *WGWatcher {
 	return &WGWatcher{
 		log:           log,
 		wgIfaceStater: wgIfaceStater,
 		peerKey:       peerKey,
+		stateDump:     stateDump,
 	}
 }
 
@@ -105,6 +107,7 @@ func (w *WGWatcher) periodicHandshakeCheck(ctx context.Context, ctxCancel contex
 
 			resetTime := time.Until(handshake.Add(checkPeriod))
 			timer.Reset(resetTime)
+			w.stateDump.WGcheckSuccess()
 
 			w.log.Debugf("WireGuard watcher reset timer: %v", resetTime)
 		case <-ctx.Done():

client/internal/peer/wg_watcher_test.go

@@ -43,7 +43,7 @@ func TestWGWatcher_EnableWgWatcher(t *testing.T) {
 
 	mlog := log.WithField("peer", "tet")
 	mocWgIface := &MocWgIface{}
-	watcher := NewWGWatcher(mlog, mocWgIface, "")
+	watcher := NewWGWatcher(mlog, mocWgIface, "", newStateDump(mlog))
 
 	ctx, cancel := context.WithCancel(context.Background())
 	defer cancel()
@@ -72,7 +72,7 @@ func TestWGWatcher_ReEnable(t *testing.T) {
 
 	mlog := log.WithField("peer", "tet")
 	mocWgIface := &MocWgIface{}
-	watcher := NewWGWatcher(mlog, mocWgIface, "")
+	watcher := NewWGWatcher(mlog, mocWgIface, "", newStateDump(mlog))
 
 	ctx, cancel := context.WithCancel(context.Background())
 	defer cancel()

client/internal/peer/worker_relay.go

@@ -33,14 +33,14 @@ type WorkerRelay struct {
 	wgWatcher *WGWatcher
 }
 
-func NewWorkerRelay(log *log.Entry, ctrl bool, config ConnConfig, conn *Conn, relayManager relayClient.ManagerService) *WorkerRelay {
+func NewWorkerRelay(log *log.Entry, ctrl bool, config ConnConfig, conn *Conn, relayManager relayClient.ManagerService, stateDump *stateDump) *WorkerRelay {
 	r := &WorkerRelay{
 		log:          log,
 		isController: ctrl,
 		config:       config,
 		conn:         conn,
 		relayManager: relayManager,
-		wgWatcher:    NewWGWatcher(log, config.WgConfig.WgInterface, config.Key),
+		wgWatcher:    NewWGWatcher(log, config.WgConfig.WgInterface, config.Key, stateDump),
 	}
 	return r
 }

client/server/debug.go

@@ -53,7 +53,7 @@ The files in this bundle have been anonymized to protect sensitive information.
 
 IP Addresses
 
-IPv4 addresses are replaced with addresses starting from 192.51.100.0
+IPv4 addresses are replaced with addresses starting from 198.51.100.0
 IPv6 addresses are replaced with addresses starting from 100::
 
 IP addresses from non public ranges and well known addresses are not anonymized (e.g. 8.8.8.8, 100.64.0.0/10, addresses starting with 192.168., 172.16., 10., etc.).

client/server/network.go

@@ -36,8 +36,13 @@ func (s *Server) ListNetworks(context.Context, *proto.ListNetworksRequest) (*pro
 		return nil, fmt.Errorf("not connected")
 	}
 
-	routesMap := engine.GetRouteManager().GetClientRoutesWithNetID()
+	routeMgr := engine.GetRouteManager()
-	routeSelector := engine.GetRouteManager().GetRouteSelector()
+	if routeMgr == nil {
+		return nil, fmt.Errorf("no route manager")
+	}
+
+	routesMap := routeMgr.GetClientRoutesWithNetID()
+	routeSelector := routeMgr.GetRouteSelector()
 
 	var routes []*selectRoute
 	for id, rt := range routesMap {
@@ -123,6 +128,10 @@ func (s *Server) SelectNetworks(_ context.Context, req *proto.SelectNetworksRequ
 	}
 
 	routeManager := engine.GetRouteManager()
+	if routeManager == nil {
+		return nil, fmt.Errorf("no route manager")
+	}
+
 	routeSelector := routeManager.GetRouteSelector()
 	if req.GetAll() {
 		routeSelector.SelectAllRoutes()
@@ -165,6 +174,10 @@ func (s *Server) DeselectNetworks(_ context.Context, req *proto.SelectNetworksRe
 	}
 
 	routeManager := engine.GetRouteManager()
+	if routeManager == nil {
+		return nil, fmt.Errorf("no route manager")
+	}
+
 	routeSelector := routeManager.GetRouteSelector()
 	if req.GetAll() {
 		routeSelector.DeselectAllRoutes()

management/server/http/handlers/networks/handler.go

@@ -289,7 +289,7 @@ func (h *handler) collectIDsInNetwork(ctx context.Context, accountID, userID, ne
 }
 
 func (h *handler) generateNetworkResponse(networks []*types.Network, routers map[string][]*routerTypes.NetworkRouter, resourceIDs map[string][]string, groups map[string]*nbtypes.Group, account *nbtypes.Account) []*api.Network {
-	var networkResponse []*api.Network
+	networkResponse := make([]*api.Network, 0, len(networks))
 	for _, network := range networks {
 		routerIDs, peerCounter := getRouterIDs(network, routers, groups)
 		policyIDs := account.GetPoliciesAppliedInNetwork(network.ID)

management/server/http/handlers/networks/resources_handler.go

@@ -89,7 +89,7 @@ func (h *resourceHandler) getAllResourcesInAccount(w http.ResponseWriter, r *htt
 
 	grpsInfoMap := groups.ToGroupsInfoMap(grps, 0)
 
-	var resourcesResponse []*api.NetworkResource
+	resourcesResponse := make([]*api.NetworkResource, 0, len(resources))
 	for _, resource := range resources {
 		resourcesResponse = append(resourcesResponse, resource.ToAPIResponse(grpsInfoMap[resource.ID]))
 	}

management/server/http/handlers/networks/routers_handler.go

@@ -48,7 +48,7 @@ func (h *routersHandler) getAllRouters(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	var routersResponse []*api.NetworkRouter
+	routersResponse := make([]*api.NetworkRouter, 0, len(routers))
 	for _, router := range routers {
 		routersResponse = append(routersResponse, router.ToAPIResponse())
 	}