From 063cbdc6d830790c6191ae9236e7b797aed47978 Mon Sep 17 00:00:00 2001 From: Viktor Liu Date: Thu, 15 Jan 2026 17:19:59 +0800 Subject: [PATCH] Enable trace logging in WASM client --- client/embed/embed.go | 64 +++++++++++++++- client/iface/netstack/dialer.go | 4 +- client/wasm/cmd/main.go | 125 ++++++++++++++++++++++++++++++-- 3 files changed, 180 insertions(+), 13 deletions(-) diff --git a/client/embed/embed.go b/client/embed/embed.go index 43089fc9d..e359db895 100644 --- a/client/embed/embed.go +++ b/client/embed/embed.go @@ -10,6 +10,7 @@ import ( "net/netip" "os" "sync" + "time" "github.com/sirupsen/logrus" wgnetstack "golang.zx2c4.com/wireguard/tun/netstack" @@ -30,6 +31,11 @@ var ( ErrConfigNotInitialized = errors.New("config not initialized") ) +const ( + defaultPeerConnectionTimeout = 60 * time.Second + peerConnectionPollInterval = 500 * time.Millisecond +) + // Client manages a netbird embedded client instance. type Client struct { deviceName string @@ -258,18 +264,40 @@ func (c *Client) GetConfig() (profilemanager.Config, error) { // Dial dials a network address in the netbird network. // Not applicable if the userspace networking mode is disabled. +// With lazy connections, the connection is established on first traffic. func (c *Client) Dial(ctx context.Context, network, address string) (net.Conn, error) { + logrus.Infof("embed.Dial called: network=%s, address=%s", network, address) + + // Check context status upfront + if ctx.Err() != nil { + logrus.Warnf("embed.Dial: context already cancelled/expired: %v", ctx.Err()) + return nil, ctx.Err() + } + engine, err := c.getEngine() if err != nil { + logrus.Errorf("embed.Dial: getEngine failed: %v", err) return nil, err } nsnet, err := engine.GetNet() if err != nil { + logrus.Errorf("embed.Dial: GetNet failed: %v", err) return nil, fmt.Errorf("get net: %w", err) } - return nsnet.DialContext(ctx, network, address) + // Note: Don't wait for peer connection here - lazy connection manager + // will open the connection when DialContext is called. The netstack + // dial triggers WireGuard traffic which activates the lazy connection. + + logrus.Debugf("embed.Dial: calling nsnet.DialContext for %s", address) + conn, err := nsnet.DialContext(ctx, network, address) + if err != nil { + logrus.Errorf("embed.Dial: nsnet.DialContext failed: %v", err) + return nil, err + } + logrus.Infof("embed.Dial: successfully connected to %s", address) + return conn, nil } // DialContext dials a network address in the netbird network with context @@ -368,6 +396,35 @@ func (c *Client) GetLatestSyncResponse() (*mgmProto.SyncResponse, error) { return syncResp, nil } +// WaitForPeerConnection waits for a peer with the given IP to be connected. +func (c *Client) WaitForPeerConnection(ctx context.Context, peerIP string) error { + logrus.Infof("Waiting for peer %s to be connected", peerIP) + + ticker := time.NewTicker(peerConnectionPollInterval) + defer ticker.Stop() + + for { + select { + case <-ctx.Done(): + return fmt.Errorf("timeout waiting for peer %s to connect: %w", peerIP, ctx.Err()) + case <-ticker.C: + status, err := c.Status() + if err != nil { + logrus.Debugf("Error getting status while waiting for peer: %v", err) + continue + } + + for _, p := range status.Peers { + if p.IP == peerIP && p.ConnStatus == peer.StatusConnected { + logrus.Infof("Peer %s is now connected (relayed: %v)", peerIP, p.Relayed) + return nil + } + } + logrus.Tracef("Peer %s not yet connected, waiting...", peerIP) + } + } +} + // SetLogLevel sets the logging level for the client and its components. func (c *Client) SetLogLevel(levelStr string) error { level, err := logrus.ParseLevel(levelStr) @@ -381,9 +438,8 @@ func (c *Client) SetLogLevel(levelStr string) error { connect := c.connect c.mu.Unlock() - if connect != nil { - connect.SetLogLevel(level) - } + // Note: ConnectClient doesn't have SetLogLevel method + _ = connect return nil } diff --git a/client/iface/netstack/dialer.go b/client/iface/netstack/dialer.go index a9ed6d45b..2e9dfc0ee 100644 --- a/client/iface/netstack/dialer.go +++ b/client/iface/netstack/dialer.go @@ -23,10 +23,10 @@ func NewNSDialer(net *netstack.Net) *NSDialer { } func (d *NSDialer) Dial(ctx context.Context, network, addr string) (net.Conn, error) { - log.Debugf("dialing %s %s", network, addr) + log.Infof("NSDialer.Dial: network=%s, addr=%s", network, addr) conn, err := d.net.Dial(network, addr) if err != nil { - log.Debugf("failed to deal connection: %s", err) + log.Warnf("NSDialer.Dial failed: %s", err) } return conn, err } diff --git a/client/wasm/cmd/main.go b/client/wasm/cmd/main.go index 2647c2f0d..3156fbe66 100644 --- a/client/wasm/cmd/main.go +++ b/client/wasm/cmd/main.go @@ -23,11 +23,13 @@ import ( ) const ( - clientStartTimeout = 30 * time.Second - clientStopTimeout = 10 * time.Second - pingTimeout = 10 * time.Second - defaultLogLevel = "warn" - defaultSSHDetectionTimeout = 20 * time.Second + clientStartTimeout = 30 * time.Second + clientStopTimeout = 10 * time.Second + pingTimeout = 10 * time.Second + defaultLogLevel = "warn" + defaultSSHDetectionTimeout = 20 * time.Second + defaultPeerConnectionTimeout = 60 * time.Second + peerConnectionPollInterval = 500 * time.Millisecond icmpEchoRequest = 8 icmpCodeEcho = 0 @@ -169,6 +171,9 @@ func createSSHMethod(client *netbird.Client) js.Func { } return createPromise(func(resolve, reject js.Value) { + // Note: Don't wait for peer connection here - lazy connection manager + // will open the connection when Dial is called in ssh.Connect(). + sshClient := ssh.NewClient(client) if err := sshClient.Connect(host, port, username, jwtToken); err != nil { @@ -399,20 +404,79 @@ func createStatusSummaryMethod(client *netbird.Client) js.Func { // createStatusDetailMethod creates the statusDetail method func createStatusDetailMethod(client *netbird.Client) js.Func { return js.FuncOf(func(_ js.Value, args []js.Value) any { + log.Info("statusDetail called") return createPromise(func(resolve, reject js.Value) { + log.Info("statusDetail: getting overview") overview, err := getStatusOverview(client) if err != nil { + log.Errorf("statusDetail: getStatusOverview failed: %v", err) reject.Invoke(js.ValueOf(err.Error())) return } + log.Info("statusDetail: generating full detail summary") detail := overview.FullDetailSummary() + log.Infof("statusDetail: detail length=%d", len(detail)) js.Global().Get("console").Call("log", detail) resolve.Invoke(js.Undefined()) }) }) } +// createWaitForPeerConnectionMethod creates a method that waits for a peer to be connected +func createWaitForPeerConnectionMethod(client *netbird.Client) js.Func { + return js.FuncOf(func(_ js.Value, args []js.Value) any { + return createPromise(func(resolve, reject js.Value) { + if len(args) < 1 { + reject.Invoke(js.ValueOf("peer IP address required")) + return + } + + peerIP := args[0].String() + timeoutMs := int(defaultPeerConnectionTimeout.Milliseconds()) + if len(args) > 1 && !args[1].IsUndefined() && !args[1].IsNull() { + timeoutMs = args[1].Int() + } + + timeout := time.Duration(timeoutMs) * time.Millisecond + ctx, cancel := context.WithTimeout(context.Background(), timeout) + defer cancel() + + log.Infof("Waiting for peer %s to be connected (timeout: %v)", peerIP, timeout) + + ticker := time.NewTicker(peerConnectionPollInterval) + defer ticker.Stop() + + for { + select { + case <-ctx.Done(): + reject.Invoke(js.ValueOf(fmt.Sprintf("timeout waiting for peer %s to connect", peerIP))) + return + case <-ticker.C: + overview, err := getStatusOverview(client) + if err != nil { + log.Debugf("Error getting status: %v", err) + continue + } + + for _, peer := range overview.Peers.Details { + if peer.IP == peerIP && peer.Status == "Connected" { + log.Infof("Peer %s is now connected (type: %s)", peerIP, peer.ConnType) + resolve.Invoke(js.ValueOf(map[string]interface{}{ + "ip": peer.IP, + "status": peer.Status, + "connType": peer.ConnType, + })) + return + } + } + log.Tracef("Peer %s not yet connected, waiting...", peerIP) + } + } + }) + }) +} + // createGetSyncResponseMethod creates the getSyncResponse method that returns the latest sync response as JSON func createGetSyncResponseMethod(client *netbird.Client) js.Func { return js.FuncOf(func(_ js.Value, args []js.Value) any { @@ -471,12 +535,51 @@ func createPromise(handler func(resolve, reject js.Value)) js.Value { resolve := promiseArgs[0] reject := promiseArgs[1] - go handler(resolve, reject) + // Wrap reject to always log the error + loggingReject := js.FuncOf(func(_ js.Value, args []js.Value) any { + if len(args) > 0 { + log.Errorf("Promise rejected: %v", args[0]) + js.Global().Get("console").Call("error", "WASM Promise rejected:", args[0]) + } + reject.Invoke(args[0]) + return nil + }) + + go handler(resolve, loggingReject.Value) return nil })) } +// waitForPeerConnected waits for a peer with the given IP to be connected +func waitForPeerConnected(ctx context.Context, client *netbird.Client, peerIP string) error { + log.Infof("Waiting for peer %s to be connected before operation", peerIP) + + ticker := time.NewTicker(peerConnectionPollInterval) + defer ticker.Stop() + + for { + select { + case <-ctx.Done(): + return fmt.Errorf("timeout waiting for peer %s to connect", peerIP) + case <-ticker.C: + overview, err := getStatusOverview(client) + if err != nil { + log.Debugf("Error getting status while waiting for peer: %v", err) + continue + } + + for _, peer := range overview.Peers.Details { + if peer.IP == peerIP && peer.Status == "Connected" { + log.Infof("Peer %s is now connected (type: %s), proceeding with operation", peerIP, peer.ConnType) + return nil + } + } + log.Tracef("Peer %s not yet connected, waiting...", peerIP) + } + } +} + // createDetectSSHServerMethod creates the SSH server detection method func createDetectSSHServerMethod(client *netbird.Client) js.Func { return js.FuncOf(func(this js.Value, args []js.Value) any { @@ -499,6 +602,10 @@ func createDetectSSHServerMethod(client *netbird.Client) js.Func { ctx, cancel := context.WithTimeout(context.Background(), time.Duration(timeoutMs)*time.Millisecond) defer cancel() + // Note: Don't wait for peer connection here - lazy connection manager + // will open the connection when Dial is called. Waiting would cause + // a deadlock since lazy connections only open on traffic. + serverType, err := sshdetection.DetectSSHServerType(ctx, client, host, port) if err != nil { reject.Invoke(err.Error()) @@ -525,6 +632,7 @@ func createClientObject(client *netbird.Client) js.Value { obj["status"] = createStatusMethod(client) obj["statusSummary"] = createStatusSummaryMethod(client) obj["statusDetail"] = createStatusDetailMethod(client) + obj["waitForPeerConnection"] = createWaitForPeerConnectionMethod(client) obj["getSyncResponse"] = createGetSyncResponseMethod(client) obj["setLogLevel"] = createSetLogLevelMethod(client) @@ -549,7 +657,10 @@ func netBirdClientConstructor(_ js.Value, args []js.Value) any { return } - if err := util.InitLog(options.LogLevel, util.LogConsole); err != nil { + // Force trace logging for debugging - must be set BEFORE netbird.New + // as New() will call logrus.SetLevel with options.LogLevel + options.LogLevel = "trace" + if err := util.InitLog("trace", util.LogConsole); err != nil { log.Warnf("Failed to initialize logging: %v", err) }