cmd/tailscaled, util/winutil: log Windows service diagnostics when the wintun device fails to install

I added new functions to winutil to obtain the state of a service and all
its depedencies, serialize them to JSON, and write them to a Logf.

When tstun.New returns a wrapped ERROR_DEVICE_NOT_AVAILABLE, we know that wintun
installation failed. We then log the service graph rooted at "NetSetupSvc".
We are interested in that specific service because network devices will not
install if that service is not running.

Updates https://github.com/tailscale/tailscale/issues/5531

Signed-off-by: Aaron Klotz <[email protected]>

cmd/derper/depaware.txt

@@ -107,6 +107,8 @@ tailscale.com/cmd/derper dependencies: (generated by github.com/tailscale/depawa
   LD    golang.org/x/sys/unix                                        from github.com/jsimonetti/rtnetlink/internal/unix+
    W    golang.org/x/sys/windows                                     from golang.org/x/sys/windows/registry+
    W    golang.org/x/sys/windows/registry                            from golang.zx2c4.com/wireguard/windows/tunnel/winipcfg+
+   W    golang.org/x/sys/windows/svc                                 from golang.org/x/sys/windows/svc/mgr+
+   W    golang.org/x/sys/windows/svc/mgr                             from tailscale.com/util/winutil
         golang.org/x/text/secure/bidirule                            from golang.org/x/net/idna
         golang.org/x/text/transform                                  from golang.org/x/text/secure/bidirule+
         golang.org/x/text/unicode/bidi                               from golang.org/x/net/idna+

cmd/tailscale/depaware.txt

@@ -135,6 +135,8 @@ tailscale.com/cmd/tailscale dependencies: (generated by github.com/tailscale/dep
   LD    golang.org/x/sys/unix                                        from tailscale.com/net/netns+
    W    golang.org/x/sys/windows                                     from golang.org/x/sys/windows/registry+
    W    golang.org/x/sys/windows/registry                            from golang.zx2c4.com/wireguard/windows/tunnel/winipcfg+
+   W    golang.org/x/sys/windows/svc                                 from golang.org/x/sys/windows/svc/mgr+
+   W    golang.org/x/sys/windows/svc/mgr                             from tailscale.com/util/winutil
         golang.org/x/text/secure/bidirule                            from golang.org/x/net/idna
         golang.org/x/text/transform                                  from golang.org/x/text/secure/bidirule+
         golang.org/x/text/unicode/bidi                               from golang.org/x/net/idna+

cmd/tailscaled/depaware.txt

@@ -342,7 +342,7 @@ tailscale.com/cmd/tailscaled dependencies: (generated by github.com/tailscale/de
    W    golang.org/x/sys/windows/registry                            from golang.org/x/sys/windows/svc/eventlog+
    W    golang.org/x/sys/windows/svc                                 from golang.org/x/sys/windows/svc/mgr+
    W    golang.org/x/sys/windows/svc/eventlog                        from tailscale.com/cmd/tailscaled
-   W    golang.org/x/sys/windows/svc/mgr                             from tailscale.com/cmd/tailscaled
+   W    golang.org/x/sys/windows/svc/mgr                             from tailscale.com/cmd/tailscaled+
         golang.org/x/term                                            from tailscale.com/logpolicy
         golang.org/x/text/secure/bidirule                            from golang.org/x/net/idna
         golang.org/x/text/transform                                  from golang.org/x/text/secure/bidirule+

cmd/tailscaled/tailscaled_windows.go

@@ -23,6 +23,7 @@ package main // import "tailscale.com/cmd/tailscaled"
 import (
 	"context"
 	"encoding/json"
+	"errors"
 	"fmt"
 	"log"
 	"net/netip"
@@ -270,6 +271,12 @@ func startIPNServer(ctx context.Context, logid string) error {
 	getEngineRaw := func() (wgengine.Engine, *netstack.Impl, error) {
 		dev, devName, err := tstun.New(logf, "Tailscale")
 		if err != nil {
+			if errors.Is(err, windows.ERROR_DEVICE_NOT_AVAILABLE) {
+				// Wintun is not installing correctly. Dump the state of NetSetupSvc
+				// (which is a user-mode service that must be active for network devices
+				// to install) and its dependencies to the log.
+				winutil.LogSvcState(logf, "NetSetupSvc")
+			}
 			return nil, nil, fmt.Errorf("TUN: %w", err)
 		}
 		r, err := router.New(logf, dev, nil)

util/winutil/mksyscall.go

@@ -0,0 +1,9 @@
+// Copyright (c) 2022 Tailscale Inc & AUTHORS All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package winutil
+
+//go:generate go run golang.org/x/sys/windows/mkwinsyscall -output zsyscall_windows.go mksyscall.go
+
+//sys queryServiceConfig2(hService windows.Handle, infoLevel uint32, buf *byte, bufLen uint32, bytesNeeded *uint32) (err error) [failretval==0] = advapi32.QueryServiceConfig2W

util/winutil/svcdiag_windows.go

@@ -0,0 +1,303 @@
+// Copyright (c) 2022 Tailscale Inc & AUTHORS All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package winutil
+
+import (
+	"encoding/hex"
+	"encoding/json"
+	"fmt"
+	"strings"
+	"unsafe"
+
+	"golang.org/x/sys/windows"
+	"golang.org/x/sys/windows/svc"
+	"golang.org/x/sys/windows/svc/mgr"
+	"tailscale.com/types/logger"
+)
+
+// LogSvcState obtains the state of the Windows service named rootSvcName and
+// all of its dependencies, and then emits that state to logf.
+func LogSvcState(logf logger.Logf, rootSvcName string) {
+	logEntries := []svcStateLogEntry{}
+
+	walkFn := func(svc *mgr.Service, config mgr.Config) {
+		status, err := svc.Query()
+		if err != nil {
+			logf("Failed retrieving Status for service %q: %v", svc.Name, err)
+		}
+
+		logEntries = append(logEntries, makeLogEntry(svc, status, config))
+	}
+
+	err := walkServices(rootSvcName, walkFn)
+	if err != nil {
+		logf("LogSvcState error: %v", err)
+		return
+	}
+
+	json, err := json.MarshalIndent(logEntries, "", "  ")
+	if err != nil {
+		logf("Error marshaling service log entries: %v", err)
+		return
+	}
+
+	var builder strings.Builder
+	builder.WriteString("State of service ")
+	fmt.Fprintf(&builder, "%q", rootSvcName)
+	builder.WriteString(" and its dependencies:")
+	builder.WriteString("\n")
+	builder.Write(json)
+	builder.WriteString("\n")
+
+	logf(builder.String())
+}
+
+// walkSvcFunc is type of the callback function invoked by WalkServices.
+type walkSvcFunc func(*mgr.Service, mgr.Config)
+
+// walkServices opens the service named rootSvcName and walks its dependency
+// graph, invoking callback for each service (including the root itself).
+func walkServices(rootSvcName string, callback walkSvcFunc) error {
+	scm, err := connectToLocalSCMForRead()
+	if err != nil {
+		return fmt.Errorf("connecting to Service Control Manager: %w", err)
+	}
+	defer scm.Disconnect()
+
+	rootSvc, err := openServiceForRead(scm, rootSvcName)
+	if err != nil {
+		return fmt.Errorf("opening service %q: %w", rootSvcName, err)
+	}
+
+	deps := []*mgr.Service{rootSvc}
+	defer func() {
+		// Any service still in deps when we return is open and must be closed.
+		for _, dep := range deps {
+			dep.Close()
+		}
+	}()
+
+	seen := make(map[string]struct{})
+
+	for err == nil && len(deps) > 0 {
+		err = func() error {
+			curSvc := deps[len(deps)-1]
+			defer curSvc.Close()
+
+			deps = deps[:len(deps)-1]
+
+			seen[curSvc.Name] = struct{}{}
+
+			curCfg, err := curSvc.Config()
+			if err != nil {
+				return fmt.Errorf("retrieving Config for service %q: %w", curSvc.Name, err)
+			}
+
+			callback(curSvc, curCfg)
+
+			for _, depName := range curCfg.Dependencies {
+				if _, ok := seen[depName]; ok {
+					continue
+				}
+
+				depSvc, err := openServiceForRead(scm, depName)
+				if err != nil {
+					return fmt.Errorf("opening service %q: %w", depName, err)
+				}
+
+				deps = append(deps, depSvc)
+			}
+
+			return nil
+		}()
+	}
+
+	return err
+}
+
+type svcStateLogEntry struct {
+	ServiceName   string                 `json:"serviceName"`
+	ServiceType   string                 `json:"serviceType"`
+	State         string                 `json:"state"`
+	StartupType   string                 `json:"startupType"`
+	Triggers      *_SERVICE_TRIGGER_INFO `json:"triggers,omitempty"`
+	TriggersError error                  `json:"triggersError,omitempty"`
+}
+
+type _SERVICE_TRIGGER_SPECIFIC_DATA_ITEM struct {
+	dataType uint32
+	cbData   uint32
+	data     *byte
+}
+
+type serviceTriggerSpecificDataItemJSONMarshal struct {
+	DataType uint32 `json:"dataType"`
+	Data     string `json:"data,omitempty"`
+}
+
+func (tsdi *_SERVICE_TRIGGER_SPECIFIC_DATA_ITEM) MarshalJSON() ([]byte, error) {
+	m := serviceTriggerSpecificDataItemJSONMarshal{DataType: tsdi.dataType}
+
+	const maxDataLen = 128
+	data := unsafe.Slice(tsdi.data, tsdi.cbData)
+	if len(data) > maxDataLen {
+		// Only output the first maxDataLen bytes.
+		m.Data = fmt.Sprintf("%s... (truncated %d bytes)", hex.EncodeToString(data[:maxDataLen]), len(data)-maxDataLen)
+	} else {
+		m.Data = hex.EncodeToString(data)
+	}
+
+	return json.Marshal(m)
+}
+
+type _SERVICE_TRIGGER struct {
+	triggerType    uint32
+	action         uint32
+	triggerSubtype *windows.GUID
+	cDataItems     uint32
+	pDataItems     *_SERVICE_TRIGGER_SPECIFIC_DATA_ITEM
+}
+
+type serviceTriggerJSONMarshal struct {
+	TriggerType    uint32                                `json:"triggerType"`
+	Action         uint32                                `json:"action"`
+	TriggerSubtype string                                `json:"triggerSubtype,omitempty"`
+	DataItems      []_SERVICE_TRIGGER_SPECIFIC_DATA_ITEM `json:"dataItems"`
+}
+
+func (ti *_SERVICE_TRIGGER) MarshalJSON() ([]byte, error) {
+	m := serviceTriggerJSONMarshal{
+		TriggerType: ti.triggerType,
+		Action:      ti.action,
+		DataItems:   unsafe.Slice(ti.pDataItems, ti.cDataItems),
+	}
+	if ti.triggerSubtype != nil {
+		m.TriggerSubtype = ti.triggerSubtype.String()
+	}
+	return json.Marshal(m)
+}
+
+type _SERVICE_TRIGGER_INFO struct {
+	cTriggers uint32
+	pTriggers *_SERVICE_TRIGGER
+	_         *byte // pReserved
+}
+
+func (sti *_SERVICE_TRIGGER_INFO) MarshalJSON() ([]byte, error) {
+	triggers := unsafe.Slice(sti.pTriggers, sti.cTriggers)
+	return json.Marshal(triggers)
+}
+
+// getSvcTriggerInfo obtains information about any system events that may be
+// used to start svc. Only relevant for demand-start (aka manual) services.
+func getSvcTriggerInfo(svc *mgr.Service) (*_SERVICE_TRIGGER_INFO, error) {
+	var desiredLen uint32
+	err := queryServiceConfig2(svc.Handle, windows.SERVICE_CONFIG_TRIGGER_INFO,
+		nil, 0, &desiredLen)
+	if err != windows.ERROR_INSUFFICIENT_BUFFER {
+		return nil, err
+	}
+
+	buf := make([]byte, desiredLen)
+	err = queryServiceConfig2(svc.Handle, windows.SERVICE_CONFIG_TRIGGER_INFO,
+		&buf[0], desiredLen, &desiredLen)
+	if err != nil {
+		return nil, err
+	}
+
+	return (*_SERVICE_TRIGGER_INFO)(unsafe.Pointer(&buf[0])), nil
+}
+
+// makeLogEntry consolidates relevant service information into a svcStateLogEntry.
+// We record the values of various service configuration constants as strings
+// so the the log entries are easy to interpret at a glance by humans.
+func makeLogEntry(svc *mgr.Service, status svc.Status, cfg mgr.Config) (entry svcStateLogEntry) {
+	entry.ServiceName = svc.Name
+
+	switch status.State {
+	case windows.SERVICE_STOPPED:
+		entry.State = "STOPPED"
+	case windows.SERVICE_START_PENDING:
+		entry.State = "START_PENDING"
+	case windows.SERVICE_STOP_PENDING:
+		entry.State = "STOP_PENDING"
+	case windows.SERVICE_RUNNING:
+		entry.State = "RUNNING"
+	case windows.SERVICE_CONTINUE_PENDING:
+		entry.State = "CONTINUE_PENDING"
+	case windows.SERVICE_PAUSE_PENDING:
+		entry.State = "PAUSE_PENDING"
+	case windows.SERVICE_PAUSED:
+		entry.State = "PAUSED"
+	case windows.SERVICE_NO_CHANGE:
+		entry.State = "NO_CHANGE"
+	default:
+		entry.State = fmt.Sprintf("Unknown constant %d", status.State)
+	}
+
+	switch cfg.ServiceType {
+	case windows.SERVICE_FILE_SYSTEM_DRIVER:
+		entry.ServiceType = "FILE_SYSTEM_DRIVER"
+	case windows.SERVICE_KERNEL_DRIVER:
+		entry.ServiceType = "KERNEL_DRIVER"
+	case windows.SERVICE_WIN32_OWN_PROCESS, windows.SERVICE_WIN32_SHARE_PROCESS:
+		entry.ServiceType = "WIN32"
+	default:
+		entry.ServiceType = fmt.Sprintf("Unknown constant %d", cfg.ServiceType)
+	}
+
+	switch cfg.StartType {
+	case windows.SERVICE_BOOT_START:
+		entry.StartupType = "BOOT_START"
+	case windows.SERVICE_SYSTEM_START:
+		entry.StartupType = "SYSTEM_START"
+	case windows.SERVICE_AUTO_START:
+		if cfg.DelayedAutoStart {
+			entry.StartupType = "DELAYED_AUTO_START"
+		} else {
+			entry.StartupType = "AUTO_START"
+		}
+	case windows.SERVICE_DEMAND_START:
+		entry.StartupType = "DEMAND_START"
+		triggerInfo, err := getSvcTriggerInfo(svc)
+		if err == nil {
+			entry.Triggers = triggerInfo
+		} else {
+			entry.TriggersError = err
+		}
+	case windows.SERVICE_DISABLED:
+		entry.StartupType = "DISABLED"
+	default:
+		entry.StartupType = fmt.Sprintf("Unknown constant %d", cfg.StartType)
+	}
+
+	return entry
+}
+
+// connectToLocalSCMForRead connects to the Windows Service Control Manager with
+// read-only access. x/sys/windows/svc/mgr/Connect requests read+write access,
+// which requires higher privileges than we want.
+func connectToLocalSCMForRead() (*mgr.Mgr, error) {
+	h, err := windows.OpenSCManager(nil, nil, windows.GENERIC_READ)
+	if err != nil {
+		return nil, err
+	}
+	return &mgr.Mgr{Handle: h}, nil
+}
+
+// openServiceForRead opens a service with read-only access.
+// x/sys/windows/svc/mgr/(*Mgr).OpenService requests read+write access,
+// which requires higher privileges than we want.
+func openServiceForRead(scm *mgr.Mgr, svcName string) (*mgr.Service, error) {
+	svcNamePtr, err := windows.UTF16PtrFromString(svcName)
+	if err != nil {
+		return nil, err
+	}
+	h, err := windows.OpenService(scm.Handle, svcNamePtr, windows.GENERIC_READ)
+	if err != nil {
+		return nil, err
+	}
+	return &mgr.Service{Name: svcName, Handle: h}, nil
+}

util/winutil/zsyscall_windows.go

@@ -0,0 +1,52 @@
+// Code generated by 'go generate'; DO NOT EDIT.
+
+package winutil
+
+import (
+	"syscall"
+	"unsafe"
+
+	"golang.org/x/sys/windows"
+)
+
+var _ unsafe.Pointer
+
+// Do the interface allocations only once for common
+// Errno values.
+const (
+	errnoERROR_IO_PENDING = 997
+)
+
+var (
+	errERROR_IO_PENDING error = syscall.Errno(errnoERROR_IO_PENDING)
+	errERROR_EINVAL     error = syscall.EINVAL
+)
+
+// errnoErr returns common boxed Errno values, to prevent
+// allocations at runtime.
+func errnoErr(e syscall.Errno) error {
+	switch e {
+	case 0:
+		return errERROR_EINVAL
+	case errnoERROR_IO_PENDING:
+		return errERROR_IO_PENDING
+	}
+	// TODO: add more here, after collecting data on the common
+	// error values see on Windows. (perhaps when running
+	// all.bat?)
+	return e
+}
+
+var (
+	modadvapi32 = windows.NewLazySystemDLL("advapi32.dll")
+
+	procQueryServiceConfig2W = modadvapi32.NewProc("QueryServiceConfig2W")
+)
+
+func queryServiceConfig2(hService windows.Handle, infoLevel uint32, buf *byte, bufLen uint32, bytesNeeded *uint32) (err error) {
+	r1, _, e1 := syscall.Syscall6(procQueryServiceConfig2W.Addr(), 5, uintptr(hService), uintptr(infoLevel), uintptr(unsafe.Pointer(buf)), uintptr(bufLen), uintptr(unsafe.Pointer(bytesNeeded)), 0)
+	if r1 == 0 {
+		err = errnoErr(e1)
+	}
+	return
+}