From 44f13d32d7396acbab942eb34d9044f2495aecb7 Mon Sep 17 00:00:00 2001 From: Aaron Klotz Date: Mon, 19 Sep 2022 15:49:58 -0600 Subject: [PATCH] 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 --- cmd/derper/depaware.txt | 2 + cmd/tailscale/depaware.txt | 2 + cmd/tailscaled/depaware.txt | 2 +- cmd/tailscaled/tailscaled_windows.go | 7 + util/winutil/mksyscall.go | 9 + util/winutil/svcdiag_windows.go | 303 +++++++++++++++++++++++++++ util/winutil/zsyscall_windows.go | 52 +++++ 7 files changed, 376 insertions(+), 1 deletion(-) create mode 100644 util/winutil/mksyscall.go create mode 100644 util/winutil/svcdiag_windows.go create mode 100644 util/winutil/zsyscall_windows.go diff --git a/cmd/derper/depaware.txt b/cmd/derper/depaware.txt index a390ddb82..20cc285c9 100644 --- a/cmd/derper/depaware.txt +++ b/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+ diff --git a/cmd/tailscale/depaware.txt b/cmd/tailscale/depaware.txt index 8e9229ec0..4dfd77fac 100644 --- a/cmd/tailscale/depaware.txt +++ b/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+ diff --git a/cmd/tailscaled/depaware.txt b/cmd/tailscaled/depaware.txt index c85a08962..0e97fc118 100644 --- a/cmd/tailscaled/depaware.txt +++ b/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+ diff --git a/cmd/tailscaled/tailscaled_windows.go b/cmd/tailscaled/tailscaled_windows.go index 7ed82ce0b..1e672eecb 100644 --- a/cmd/tailscaled/tailscaled_windows.go +++ b/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) diff --git a/util/winutil/mksyscall.go b/util/winutil/mksyscall.go new file mode 100644 index 000000000..28063dfd0 --- /dev/null +++ b/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 diff --git a/util/winutil/svcdiag_windows.go b/util/winutil/svcdiag_windows.go new file mode 100644 index 000000000..48ce180d2 --- /dev/null +++ b/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 +} diff --git a/util/winutil/zsyscall_windows.go b/util/winutil/zsyscall_windows.go new file mode 100644 index 000000000..8c899232f --- /dev/null +++ b/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 +}