wgengine: start network logger in Userspace.Reconfig (#5908)

If the wgcfg.Config is specified with network logging arguments,
then Userspace.Reconfig starts up an asynchronous network logger,
which is shutdown either upon Userspace.Close or when Userspace.Reconfig
is called again without network logging or route arguments.

Signed-off-by: Joe Tsai <joetsai@digital-static.net>

cmd/tailscaled/depaware.txt

@@ -240,7 +240,7 @@ tailscale.com/cmd/tailscaled dependencies: (generated by github.com/tailscale/de
         tailscale.com/net/tsdial                                     from tailscale.com/control/controlclient+
      💣 tailscale.com/net/tshttpproxy                                from tailscale.com/control/controlclient+
         tailscale.com/net/tstun                                      from tailscale.com/net/dns+
-        tailscale.com/net/tunstats                                   from tailscale.com/net/tstun
+        tailscale.com/net/tunstats                                   from tailscale.com/net/tstun+
         tailscale.com/paths                                          from tailscale.com/ipn/ipnlocal+
         tailscale.com/portlist                                       from tailscale.com/ipn/ipnlocal
         tailscale.com/safesocket                                     from tailscale.com/client/tailscale+
@@ -297,6 +297,7 @@ tailscale.com/cmd/tailscaled dependencies: (generated by github.com/tailscale/de
         tailscale.com/wgengine/filter                                from tailscale.com/control/controlclient+
      💣 tailscale.com/wgengine/magicsock                             from tailscale.com/ipn/ipnlocal+
         tailscale.com/wgengine/monitor                               from tailscale.com/control/controlclient+
+        tailscale.com/wgengine/netlog                                from tailscale.com/wgengine
         tailscale.com/wgengine/netstack                              from tailscale.com/cmd/tailscaled+
         tailscale.com/wgengine/router                                from tailscale.com/ipn/ipnlocal+
         tailscale.com/wgengine/wgcfg                                 from tailscale.com/ipn/ipnlocal+

wgengine/netlog/logger.go

@@ -44,9 +44,7 @@ type Device interface {
 type Logger struct {
 	mu sync.Mutex
 
-	nodeID   logtail.PrivateID
+	logger *logtail.Logger
-	domainID logtail.PrivateID
-	logger   *logtail.Logger
 
 	addrs    map[netip.Addr]bool
 	prefixes map[netip.Prefix]bool
@@ -67,11 +65,11 @@ var testClient *http.Client
 // Startup starts an asynchronous network logger that monitors
 // statistics for the provided tun device.
 // The provided cfg is used to classify the types of connections.
-func (nl *Logger) Startup(nodeID, domainID logtail.PrivateID, tun Device, cfg *router.Config) error {
+func (nl *Logger) Startup(nodeID, domainID logtail.PrivateID, tun Device) error {
 	nl.mu.Lock()
 	defer nl.mu.Unlock()
 	if nl.logger != nil {
-		return fmt.Errorf("network logger already running for %v", nl.nodeID.Public())
+		return fmt.Errorf("network logger already running for %v", nl.logger.PrivateID().Public())
 	}
 
 	httpc := &http.Client{Transport: logpolicy.NewLogtailTransport(logtail.DefaultHost)}
@@ -99,8 +97,6 @@ func (nl *Logger) Startup(nodeID, domainID logtail.PrivateID, tun Device, cfg *r
 	}, log.Printf)
 	nl.logger = logger
 
-	nl.addrs, nl.prefixes = makeRouteMaps(cfg)
-
 	ctx, cancel := context.WithCancel(context.Background())
 	nl.cancel = cancel
 	nl.group.Go(func() error {
@@ -228,6 +224,7 @@ func (nl *Logger) ReconfigRoutes(cfg *router.Config) {
 
 // Shutdown shuts down the network logger.
 // This attempts to flush out all pending log messages.
+// Even if an error is returned, the logger is still shut down.
 func (nl *Logger) Shutdown(ctx context.Context) error {
 	nl.mu.Lock()
 	defer nl.mu.Unlock()
@@ -240,8 +237,6 @@ func (nl *Logger) Shutdown(ctx context.Context) error {
 	nl.mu.Lock()
 	err := nl.logger.Shutdown(ctx)
 
-	nl.nodeID = logtail.PrivateID{}
-	nl.domainID = logtail.PrivateID{}
 	nl.logger = nil
 	nl.addrs = nil
 	nl.prefixes = nil

wgengine/netlog/logger_test.go

@@ -59,7 +59,7 @@ func TestResourceCheck(t *testing.T) {
 	var l Logger
 	var d fakeDevice
 	for i := 0; i < 10; i++ {
-		must.Do(l.Startup(logtail.PrivateID{}, logtail.PrivateID{}, &d, &router.Config{}))
+		must.Do(l.Startup(logtail.PrivateID{}, logtail.PrivateID{}, &d))
 		l.ReconfigRoutes(&router.Config{})
 		must.Do(l.Shutdown(context.Background()))
 		c.Assert(d.toggled, qt.Equals, 2*(i+1))

wgengine/userspace.go

@@ -6,6 +6,7 @@ package wgengine
 
 import (
 	"bufio"
+	"context"
 	crand "crypto/rand"
 	"errors"
 	"fmt"
@@ -48,6 +49,7 @@ import (
 	"tailscale.com/wgengine/filter"
 	"tailscale.com/wgengine/magicsock"
 	"tailscale.com/wgengine/monitor"
+	"tailscale.com/wgengine/netlog"
 	"tailscale.com/wgengine/router"
 	"tailscale.com/wgengine/wgcfg"
 	"tailscale.com/wgengine/wgint"
@@ -84,6 +86,10 @@ const (
 // status (as long as there's activity). See docs on its use below.
 const statusPollInterval = 1 * time.Minute
 
+// networkLoggerUploadTimeout is the maximum timeout to wait when
+// shutting down the network logger as it uploads the last network log messages.
+const networkLoggerUploadTimeout = 5 * time.Second
+
 type userspaceEngine struct {
 	logf              logger.Logf
 	wgLogger          *wglog.Logger //a wireguard-go logging wrapper
@@ -145,6 +151,9 @@ type userspaceEngine struct {
 	// value of the ICMP identifer and sequence number concatenated.
 	icmpEchoResponseCallback map[uint32]func()
 
+	// networkLogger logs statistics about network connections.
+	networkLogger netlog.Logger
+
 	// Lock ordering: magicsock.Conn.mu, wgLock, then mu.
 }
 
@@ -872,6 +881,12 @@ func (e *userspaceEngine) Reconfig(cfg *wgcfg.Config, routerCfg *router.Config,
 	if !engineChanged && !routerChanged && listenPort == e.magicConn.LocalPort() && !isSubnetRouterChanged {
 		return ErrNoChanges
 	}
+	newLogIDs := cfg.NetworkLogging
+	oldLogIDs := e.lastCfgFull.NetworkLogging
+	netLogIDsNowValid := !newLogIDs.NodeID.IsZero() && !newLogIDs.DomainID.IsZero()
+	netLogIDsWasValid := !oldLogIDs.NodeID.IsZero() && !oldLogIDs.DomainID.IsZero()
+	netLogIDsChanged := netLogIDsNowValid && netLogIDsWasValid && newLogIDs != oldLogIDs
+	netLogRunning := netLogIDsNowValid && !routerCfg.Equal(&router.Config{})
 
 	// TODO(bradfitz,danderson): maybe delete this isDNSIPOverTailscale
 	// field and delete the resolver.ForwardLinkSelector hook and
@@ -921,8 +936,31 @@ func (e *userspaceEngine) Reconfig(cfg *wgcfg.Config, routerCfg *router.Config,
 		return err
 	}
 
+	// Shutdown the network logger because the IDs changed.
+	// Let it be started back up by subsequent logic.
+	if netLogIDsChanged && e.networkLogger.Running() {
+		e.logf("wgengine: Reconfig: shutting down network logger")
+		ctx, cancel := context.WithTimeout(context.Background(), networkLoggerUploadTimeout)
+		defer cancel()
+		if err := e.networkLogger.Shutdown(ctx); err != nil {
+			e.logf("wgengine: Reconfig: error shutting down network logger: %v", err)
+		}
+	}
+
+	// Startup the network logger.
+	// Do this before configuring the router so that we capture initial packets.
+	if netLogRunning && !e.networkLogger.Running() {
+		nid := cfg.NetworkLogging.NodeID
+		tid := cfg.NetworkLogging.DomainID
+		e.logf("wgengine: Reconfig: starting up network logger (node:%s tailnet:%s)", nid.Public(), tid.Public())
+		if err := e.networkLogger.Startup(nid, tid, e.tundev); err != nil {
+			e.logf("wgengine: Reconfig: error starting up network logger: %v", err)
+		}
+	}
+
 	if routerChanged {
 		e.logf("wgengine: Reconfig: configuring router")
+		e.networkLogger.ReconfigRoutes(routerCfg)
 		err := e.router.Set(routerCfg)
 		health.SetRouterHealth(err)
 		if err != nil {
@@ -939,6 +977,18 @@ func (e *userspaceEngine) Reconfig(cfg *wgcfg.Config, routerCfg *router.Config,
 		}
 	}
 
+	// Shutdown the network logger.
+	// Do this after configuring the router so that we capture final packets.
+	// This attempts to flush out any log messages and may block.
+	if !netLogRunning && e.networkLogger.Running() {
+		e.logf("wgengine: Reconfig: shutting down network logger")
+		ctx, cancel := context.WithTimeout(context.Background(), networkLoggerUploadTimeout)
+		defer cancel()
+		if err := e.networkLogger.Shutdown(ctx); err != nil {
+			e.logf("wgengine: Reconfig: error shutting down network logger: %v", err)
+		}
+	}
+
 	if isSubnetRouterChanged && e.birdClient != nil {
 		e.logf("wgengine: Reconfig: configuring BIRD")
 		var err error
@@ -1092,6 +1142,12 @@ func (e *userspaceEngine) Close() {
 		e.birdClient.Close()
 	}
 	close(e.waitCh)
+
+	ctx, cancel := context.WithTimeout(context.Background(), networkLoggerUploadTimeout)
+	defer cancel()
+	if err := e.networkLogger.Shutdown(ctx); err != nil {
+		e.logf("wgengine: Close: error shutting down network logger: %v", err)
+	}
 }
 
 func (e *userspaceEngine) Wait() {