wgengine, wgengine/router: add a bunch of (temporary?) engine creation logging

Trying to debug what's slow on a user's machine.

Updates #785

wgengine/router/router_windows.go

@@ -6,10 +6,10 @@
 
 import (
 	"fmt"
-	"log"
 	"os/exec"
 	"sync"
 	"syscall"
+	"time"
 
 	winipcfg "github.com/tailscale/winipcfg-go"
 	"github.com/tailscale/wireguard-go/device"
@@ -27,7 +27,8 @@ type winRouter struct {
 	dns                 *dns.Manager
 
 	mu             sync.Mutex
-	firewallRuleIP string // the IP rule exists for, or "" if rule doesn't exist
+	firewallRuleIP string // the IP rule exists for, or "" when rule is deleted
+	didRemove      bool
 }
 
 func newUserspaceRouter(logf logger.Logf, wgdev *device.Device, tundev tun.Device) (Router, error) {
@@ -39,7 +40,7 @@ func newUserspaceRouter(logf logger.Logf, wgdev *device.Device, tundev tun.Devic
 	nativeTun := tundev.(*tun.NativeTun)
 	guid := nativeTun.GUID().String()
 	mconfig := dns.ManagerConfig{
-		Logf:          logf,
+		Logf:          logger.WithPrefix(logf, "dns: "),
 		InterfaceName: guid,
 	}
 
@@ -56,10 +57,13 @@ func (r *winRouter) Up() error {
 	r.removeFirewallAcceptRule()
 
 	var err error
+	t0 := time.Now()
 	r.routeChangeCallback, err = monitorDefaultRoutes(r.nativeTun)
+	d := time.Since(t0).Round(time.Millisecond)
 	if err != nil {
-		log.Fatalf("MonitorDefaultRoutes: %v", err)
+		return fmt.Errorf("monitorDefaultRoutes, after %v: %v", d, err)
 	}
+	r.logf("monitorDefaultRoutes done after %v", d)
 	return nil
 }
 
@@ -69,14 +73,24 @@ func (r *winRouter) Up() error {
 //
 // So callers should ignore its error for now.
 func (r *winRouter) removeFirewallAcceptRule() error {
+	t0 := time.Now()
+
 	r.mu.Lock()
 	defer r.mu.Unlock()
 
+	if r.firewallRuleIP == "" && r.didRemove {
+		// Already done.
+		return nil
+	}
 	r.firewallRuleIP = ""
+	r.didRemove = true
 
 	cmd := exec.Command("netsh", "advfirewall", "firewall", "delete", "rule", "name=Tailscale-In", "dir=in")
 	cmd.SysProcAttr = &syscall.SysProcAttr{HideWindow: true}
-	return cmd.Run()
+	err := cmd.Run()
+	d := time.Since(t0).Round(time.Millisecond)
+	r.logf("after %v, removed firewall rule (wasPresent=%v)", d, err == nil)
+	return err
 }
 
 // addFirewallAcceptRule adds a firewall rule to allow all incoming

wgengine/userspace.go

@@ -141,15 +141,6 @@ type EngineConfig struct {
 	Fake bool
 }
 
-type Loggify struct {
-	f logger.Logf
-}
-
-func (l *Loggify) Write(b []byte) (int, error) {
-	l.f(string(b))
-	return len(b), nil
-}
-
 func NewFakeUserspaceEngine(logf logger.Logf, listenPort uint16) (Engine, error) {
 	logf("Starting userspace wireguard engine (FAKE tuntap device).")
 	conf := EngineConfig{
@@ -258,7 +249,7 @@ func newUserspaceEngineAdvanced(conf EngineConfig) (_ Engine, reterr error) {
 
 	// flags==0 because logf is already nested in another logger.
 	// The outer one can display the preferred log prefixes, etc.
-	dlog := log.New(&Loggify{logf}, "", 0)
+	dlog := logger.StdLogger(logf)
 	logger := device.Logger{
 		Debug: dlog,
 		Info:  dlog,
@@ -309,6 +300,7 @@ func newUserspaceEngineAdvanced(conf EngineConfig) (_ Engine, reterr error) {
 	}
 
 	// wgdev takes ownership of tundev, will close it when closed.
+	e.logf("Creating wireguard device...")
 	e.wgdev = device.NewDevice(e.tundev, opts)
 	defer func() {
 		if reterr != nil {
@@ -318,6 +310,7 @@ func newUserspaceEngineAdvanced(conf EngineConfig) (_ Engine, reterr error) {
 
 	// Pass the underlying tun.(*NativeDevice) to the router:
 	// routers do not Read or Write, but do access native interfaces.
+	e.logf("Creating router...")
 	e.router, err = conf.RouterGen(logf, e.wgdev, e.tundev.Unwrap())
 	if err != nil {
 		e.magicConn.Close()
@@ -344,7 +337,9 @@ func newUserspaceEngineAdvanced(conf EngineConfig) (_ Engine, reterr error) {
 		}
 	}()
 
+	e.logf("Bringing wireguard device up...")
 	e.wgdev.Up()
+	e.logf("Bringing router up...")
 	if err := e.router.Up(); err != nil {
 		e.magicConn.Close()
 		e.wgdev.Close()
@@ -354,17 +349,22 @@ func newUserspaceEngineAdvanced(conf EngineConfig) (_ Engine, reterr error) {
 	// a no-op settings here.
 	// TODO(bradfitz): counter-point: it tests the router implementation early
 	// to see if any part of it might fail.
+	e.logf("Clearing router settings...")
 	if err := e.router.Set(nil); err != nil {
 		e.magicConn.Close()
 		e.wgdev.Close()
 		return nil, err
 	}
+	e.logf("Starting link monitor...")
 	e.linkMon.Start()
+	e.logf("Starting magicsock...")
 	e.magicConn.Start()
 
+	e.logf("Starting resolver...")
 	e.resolver.Start()
 	go e.pollResolver()
 
+	e.logf("Engine created.")
 	return e, nil
 }