From e6e070b2e5a3bb6a6f041d66c8d6af590c03dc57 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zolt=C3=A1n=20Papp?= Date: Wed, 26 Feb 2025 12:38:09 +0100 Subject: [PATCH] Add log lines --- client/internal/conn_mgr.go | 8 ++- client/internal/peer/conn.go | 104 +++++++++++++++++------------------ 2 files changed, 58 insertions(+), 54 deletions(-) diff --git a/client/internal/conn_mgr.go b/client/internal/conn_mgr.go index 7f620209e..ed6fbf01b 100644 --- a/client/internal/conn_mgr.go +++ b/client/internal/conn_mgr.go @@ -80,6 +80,7 @@ func (e *ConnMgr) AddPeerConn(peerKey string, conn *peer.Conn) (exists bool) { log.Errorf("failed to add peer to lazyconn manager: %v", err) conn.Open() } + conn.Log.Infof("peer added to lazy conn manager") return } @@ -94,6 +95,7 @@ func (e *ConnMgr) OnSignalMsg(peerKey string) (*peer.Conn, bool) { } if ok := e.lazyConnMgr.RemovePeer(peerKey); ok { + conn.Log.Infof("removed peer from lazy conn manager") conn.Open() } return conn, true @@ -101,15 +103,17 @@ func (e *ConnMgr) OnSignalMsg(peerKey string) (*peer.Conn, bool) { func (e *ConnMgr) RemovePeerConn(peerKey string) { conn, ok := e.peerStore.Remove(peerKey) - if ok { - conn.Close() + if !ok { + return } + defer conn.Close() if e.lazyConnMgr == nil { return } e.lazyConnMgr.RemovePeer(peerKey) + conn.Log.Infof("removed peer from lazy conn manager") } func (e *ConnMgr) Close() { diff --git a/client/internal/peer/conn.go b/client/internal/peer/conn.go index 4bec27964..638437763 100644 --- a/client/internal/peer/conn.go +++ b/client/internal/peer/conn.go @@ -83,7 +83,7 @@ type ConnConfig struct { } type Conn struct { - log *log.Entry + Log *log.Entry mu sync.Mutex ctx context.Context ctxCancel context.CancelFunc @@ -127,7 +127,7 @@ func NewConn(engineCtx context.Context, config ConnConfig, statusRecorder *Statu connLog := log.WithField("peer", config.Key) var conn = &Conn{ - log: connLog, + Log: connLog, ctx: ctx, ctxCancel: ctxCancel, config: config, @@ -169,7 +169,7 @@ func NewConn(engineCtx context.Context, config ConnConfig, statusRecorder *Statu // todo: prevent double open func (conn *Conn) Open() { conn.semaphore.Add(conn.ctx) - conn.log.Debugf("open connection to peer") + conn.Log.Infof("open connection to peer") conn.mu.Lock() defer conn.mu.Unlock() @@ -184,7 +184,7 @@ func (conn *Conn) Open() { } err := conn.statusRecorder.UpdatePeerState(peerState) if err != nil { - conn.log.Warnf("error while updating the state err: %v", err) + conn.Log.Warnf("error while updating the state err: %v", err) } go conn.startHandshakeAndReconnect(conn.ctx) @@ -196,7 +196,7 @@ func (conn *Conn) startHandshakeAndReconnect(ctx context.Context) { err := conn.handshaker.sendOffer() if err != nil { - conn.log.Errorf("failed to send initial offer: %v", err) + conn.Log.Errorf("failed to send initial offer: %v", err) } go conn.guard.Start(ctx) @@ -208,11 +208,11 @@ func (conn *Conn) Close() { conn.mu.Lock() defer conn.mu.Unlock() - conn.log.Infof("close peer connection") + conn.Log.Infof("close peer connection") conn.ctxCancel() if !conn.opened { - conn.log.Debugf("ignore close connection to peer") + conn.Log.Debugf("ignore close connection to peer") return } @@ -223,7 +223,7 @@ func (conn *Conn) Close() { if conn.wgProxyRelay != nil { err := conn.wgProxyRelay.CloseConn() if err != nil { - conn.log.Errorf("failed to close wg proxy for relay: %v", err) + conn.Log.Errorf("failed to close wg proxy for relay: %v", err) } conn.wgProxyRelay = nil } @@ -231,13 +231,13 @@ func (conn *Conn) Close() { if conn.wgProxyICE != nil { err := conn.wgProxyICE.CloseConn() if err != nil { - conn.log.Errorf("failed to close wg proxy for ice: %v", err) + conn.Log.Errorf("failed to close wg proxy for ice: %v", err) } conn.wgProxyICE = nil } if err := conn.removeWgPeer(); err != nil { - conn.log.Errorf("failed to remove wg endpoint: %v", err) + conn.Log.Errorf("failed to remove wg endpoint: %v", err) } conn.freeUpConnID() @@ -252,7 +252,7 @@ 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.Log.Debugf("OnRemoteAnswer, status ICE: %s, status relay: %s", conn.statusICE, conn.statusRelay) return conn.handshaker.OnRemoteAnswer(answer) } @@ -279,7 +279,7 @@ 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.Log.Debugf("OnRemoteOffer, on status ICE: %s, status Relay: %s", conn.statusICE, conn.statusRelay) return conn.handshaker.OnRemoteOffer(offer) } @@ -308,21 +308,21 @@ func (conn *Conn) onICEConnectionIsReady(priority ConnPriority, iceConnInfo ICEC return } - if remoteConnNil(conn.log, iceConnInfo.RemoteConn) { - conn.log.Errorf("remote ICE connection is nil") + if remoteConnNil(conn.Log, iceConnInfo.RemoteConn) { + conn.Log.Errorf("remote ICE connection is nil") return } // this never should happen, because Relay is the lower priority and ICE always close the deprecated connection before upgrade // todo consider to remove this check if conn.currentConnPriority > priority { - conn.log.Infof("current connection priority (%s) is higher than the new one (%s), do not upgrade connection", conn.currentConnPriority, priority) + conn.Log.Infof("current connection priority (%s) is higher than the new one (%s), do not upgrade connection", conn.currentConnPriority, priority) conn.statusICE.Set(StatusConnected) conn.updateIceState(iceConnInfo) return } - conn.log.Infof("set ICE to active connection") + conn.Log.Infof("set ICE to active connection") var ( ep *net.UDPAddr @@ -332,7 +332,7 @@ func (conn *Conn) onICEConnectionIsReady(priority ConnPriority, iceConnInfo ICEC if iceConnInfo.RelayedOnLocal { wgProxy, err = conn.newProxy(iceConnInfo.RemoteConn) if err != nil { - conn.log.Errorf("failed to add turn net.Conn to local proxy: %v", err) + conn.Log.Errorf("failed to add turn net.Conn to local proxy: %v", err) return } ep = wgProxy.EndpointAddr() @@ -348,7 +348,7 @@ func (conn *Conn) onICEConnectionIsReady(priority ConnPriority, iceConnInfo ICEC } if err := conn.runBeforeAddPeerHooks(ep.IP); err != nil { - conn.log.Errorf("Before add peer hook failed: %v", err) + conn.Log.Errorf("Before add peer hook failed: %v", err) } conn.workerRelay.DisableWgWatcher() @@ -380,26 +380,26 @@ func (conn *Conn) onICEStateDisconnected() { return } - conn.log.Tracef("ICE connection state changed to disconnected") + conn.Log.Tracef("ICE connection state changed to disconnected") if conn.wgProxyICE != nil { if err := conn.wgProxyICE.CloseConn(); err != nil { - conn.log.Warnf("failed to close deprecated wg proxy conn: %v", err) + conn.Log.Warnf("failed to close deprecated wg proxy conn: %v", err) } } // switch back to relay connection if conn.isReadyToUpgrade() { - conn.log.Infof("ICE disconnected, set Relay to active connection") + conn.Log.Infof("ICE disconnected, set Relay to active connection") conn.wgProxyRelay.Work() if err := conn.configureWGEndpoint(conn.wgProxyRelay.EndpointAddr()); err != nil { - conn.log.Errorf("failed to switch to relay conn: %v", err) + conn.Log.Errorf("failed to switch to relay conn: %v", err) } conn.workerRelay.EnableWgWatcher(conn.ctx) conn.currentConnPriority = connPriorityRelay } else { - conn.log.Infof("ICE disconnected, do not switch to Relay. Reset priority to: %s", connPriorityNone.String()) + conn.Log.Infof("ICE disconnected, do not switch to Relay. Reset priority to: %s", connPriorityNone.String()) conn.currentConnPriority = connPriorityNone } @@ -418,7 +418,7 @@ func (conn *Conn) onICEStateDisconnected() { err := conn.statusRecorder.UpdatePeerICEStateToDisconnected(peerState) if err != nil { - conn.log.Warnf("unable to set peer's state to disconnected ice, got error: %v", err) + conn.Log.Warnf("unable to set peer's state to disconnected ice, got error: %v", err) } } @@ -428,23 +428,23 @@ func (conn *Conn) onRelayConnectionIsReady(rci RelayConnInfo) { if conn.ctx.Err() != nil { if err := rci.relayedConn.Close(); err != nil { - conn.log.Warnf("failed to close unnecessary relayed connection: %v", err) + conn.Log.Warnf("failed to close unnecessary relayed connection: %v", err) } return } - conn.log.Debugf("Relay connection has been established, setup the WireGuard") + conn.Log.Debugf("Relay connection has been established, setup the WireGuard") wgProxy, err := conn.newProxy(rci.relayedConn) if err != nil { - conn.log.Errorf("failed to add relayed net.Conn to local proxy: %v", err) + conn.Log.Errorf("failed to add relayed net.Conn to local proxy: %v", err) return } - conn.log.Infof("created new wgProxy for relay connection: %s", wgProxy.EndpointAddr().String()) + conn.Log.Infof("created new wgProxy for relay connection: %s", wgProxy.EndpointAddr().String()) if conn.iceP2PIsActive() { - conn.log.Debugf("do not switch to relay because current priority is: %s", conn.currentConnPriority.String()) + conn.Log.Debugf("do not switch to relay because current priority is: %s", conn.currentConnPriority.String()) conn.setRelayedProxy(wgProxy) conn.statusRelay.Set(StatusConnected) conn.updateRelayStatus(rci.relayedConn.RemoteAddr().String(), rci.rosenpassPubKey) @@ -452,15 +452,15 @@ func (conn *Conn) onRelayConnectionIsReady(rci RelayConnInfo) { } if err := conn.runBeforeAddPeerHooks(wgProxy.EndpointAddr().IP); err != nil { - conn.log.Errorf("Before add peer hook failed: %v", err) + conn.Log.Errorf("Before add peer hook failed: %v", err) } wgProxy.Work() if err := conn.configureWGEndpoint(wgProxy.EndpointAddr()); err != nil { if err := wgProxy.CloseConn(); err != nil { - conn.log.Warnf("Failed to close relay connection: %v", err) + conn.Log.Warnf("Failed to close relay connection: %v", err) } - conn.log.Errorf("Failed to update WireGuard peer configuration: %v", err) + conn.Log.Errorf("Failed to update WireGuard peer configuration: %v", err) return } conn.workerRelay.EnableWgWatcher(conn.ctx) @@ -470,7 +470,7 @@ func (conn *Conn) onRelayConnectionIsReady(rci RelayConnInfo) { conn.statusRelay.Set(StatusConnected) conn.setRelayedProxy(wgProxy) conn.updateRelayStatus(rci.relayedConn.RemoteAddr().String(), rci.rosenpassPubKey) - conn.log.Infof("start to communicate with peer via relay") + conn.Log.Infof("start to communicate with peer via relay") conn.doOnConnected(rci.rosenpassPubKey, rci.rosenpassAddr) } @@ -482,12 +482,12 @@ func (conn *Conn) onRelayDisconnected() { return } - conn.log.Debugf("relay connection is disconnected") + conn.Log.Debugf("relay connection is disconnected") if conn.currentConnPriority == connPriorityRelay { - conn.log.Debugf("clean up WireGuard config") + conn.Log.Debugf("clean up WireGuard config") if err := conn.removeWgPeer(); err != nil { - conn.log.Errorf("failed to remove wg endpoint: %v", err) + conn.Log.Errorf("failed to remove wg endpoint: %v", err) } } @@ -509,7 +509,7 @@ func (conn *Conn) onRelayDisconnected() { ConnStatusUpdate: time.Now(), } if err := conn.statusRecorder.UpdatePeerRelayedStateToDisconnected(peerState); err != nil { - conn.log.Warnf("unable to save peer's state to Relay disconnected, got error: %v", err) + conn.Log.Warnf("unable to save peer's state to Relay disconnected, got error: %v", err) } } @@ -517,9 +517,9 @@ func (conn *Conn) listenGuardEvent(ctx context.Context) { for { select { case <-conn.guard.Reconnect: - conn.log.Debugf("send offer to peer") + conn.Log.Debugf("send offer to peer") if err := conn.handshaker.SendOffer(); err != nil { - conn.log.Errorf("failed to send offer: %v", err) + conn.Log.Errorf("failed to send offer: %v", err) } case <-ctx.Done(): return @@ -549,7 +549,7 @@ func (conn *Conn) updateRelayStatus(relayServerAddr string, rosenpassPubKey []by err := conn.statusRecorder.UpdatePeerRelayedState(peerState) if err != nil { - conn.log.Warnf("unable to save peer's Relay state, got error: %v", err) + conn.Log.Warnf("unable to save peer's Relay state, got error: %v", err) } } @@ -568,7 +568,7 @@ func (conn *Conn) updateIceState(iceConnInfo ICEConnInfo) { err := conn.statusRecorder.UpdatePeerICEState(peerState) if err != nil { - conn.log.Warnf("unable to save peer's ICE state, got error: %v", err) + conn.Log.Warnf("unable to save peer's ICE state, got error: %v", err) } } @@ -586,10 +586,10 @@ func (conn *Conn) setStatusToDisconnected() { if err != nil { // pretty common error because by that time Engine can already remove the peer and status won't be available. // todo rethink status updates - conn.log.Debugf("error while updating peer's state, err: %v", err) + conn.Log.Debugf("error while updating peer's state, err: %v", err) } if err := conn.statusRecorder.UpdateWireGuardPeerState(conn.config.Key, configurer.WGStats{}); err != nil { - conn.log.Debugf("failed to reset wireguard stats for peer: %s", err) + conn.Log.Debugf("failed to reset wireguard stats for peer: %s", err) } } @@ -677,7 +677,7 @@ func (conn *Conn) freeUpConnID() { if conn.connIDRelay != "" { for _, hook := range conn.afterRemovePeerHooks { if err := hook(conn.connIDRelay); err != nil { - conn.log.Errorf("After remove peer hook failed: %v", err) + conn.Log.Errorf("After remove peer hook failed: %v", err) } } conn.connIDRelay = "" @@ -686,7 +686,7 @@ func (conn *Conn) freeUpConnID() { if conn.connIDICE != "" { for _, hook := range conn.afterRemovePeerHooks { if err := hook(conn.connIDICE); err != nil { - conn.log.Errorf("After remove peer hook failed: %v", err) + conn.Log.Errorf("After remove peer hook failed: %v", err) } } conn.connIDICE = "" @@ -694,7 +694,7 @@ func (conn *Conn) freeUpConnID() { } func (conn *Conn) newProxy(remoteConn net.Conn) (wgproxy.Proxy, error) { - conn.log.Debugf("setup proxied WireGuard connection") + conn.Log.Debugf("setup proxied WireGuard connection") udpAddr := &net.UDPAddr{ IP: conn.config.WgConfig.AllowedIps[0].Addr().AsSlice(), Port: conn.config.WgConfig.WgListenPort, @@ -702,7 +702,7 @@ func (conn *Conn) newProxy(remoteConn net.Conn) (wgproxy.Proxy, error) { wgProxy := conn.config.WgConfig.WgInterface.GetProxy() if err := wgProxy.AddTurnConn(conn.ctx, udpAddr, remoteConn); err != nil { - conn.log.Errorf("failed to add turn net.Conn to local proxy: %v", err) + conn.Log.Errorf("failed to add turn net.Conn to local proxy: %v", err) return nil, err } return wgProxy, nil @@ -721,10 +721,10 @@ func (conn *Conn) removeWgPeer() error { } func (conn *Conn) handleConfigurationFailure(err error, wgProxy wgproxy.Proxy) { - conn.log.Warnf("Failed to update wg peer configuration: %v", err) + conn.Log.Warnf("Failed to update wg peer configuration: %v", err) if wgProxy != nil { if ierr := wgProxy.CloseConn(); ierr != nil { - conn.log.Warnf("Failed to close wg proxy: %v", ierr) + conn.Log.Warnf("Failed to close wg proxy: %v", ierr) } } if conn.wgProxyRelay != nil { @@ -734,16 +734,16 @@ func (conn *Conn) handleConfigurationFailure(err error, wgProxy wgproxy.Proxy) { func (conn *Conn) logTraceConnState() { if conn.workerRelay.IsRelayConnectionSupportedWithPeer() { - conn.log.Tracef("connectivity guard check, relay state: %s, ice state: %s", conn.statusRelay, conn.statusICE) + conn.Log.Tracef("connectivity guard check, relay state: %s, ice state: %s", conn.statusRelay, conn.statusICE) } else { - conn.log.Tracef("connectivity guard check, ice state: %s", conn.statusICE) + conn.Log.Tracef("connectivity guard check, ice state: %s", conn.statusICE) } } func (conn *Conn) setRelayedProxy(proxy wgproxy.Proxy) { if conn.wgProxyRelay != nil { if err := conn.wgProxyRelay.CloseConn(); err != nil { - conn.log.Warnf("failed to close deprecated wg proxy conn: %v", err) + conn.Log.Warnf("failed to close deprecated wg proxy conn: %v", err) } } conn.wgProxyRelay = proxy