sendnrw/netbird
2
0
Fork 0
mirror of https://github.com/netbirdio/netbird.git synced 2026-04-20 09:16:40 +00:00
Code Issues Packages Projects Releases Wiki Activity

Add log lines

Browse Source
This commit is contained in:
Zoltán Papp
2025-02-26 12:38:09 +01:00
parent f898904fa8
commit e6e070b2e5
2 changed files with 58 additions and 54 deletions
Download Patch File Download Diff File Expand all files Collapse all files

104
client/internal/peer/conn.go
View File

@@ -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