cmd/tailscaled: change Windows service shutdown and add optional event logging

Once a stop request is received and the service updates its status to `svc.StopPending`,
it should continue running *until the shutdown sequence is complete*, and then
return out of `(*ipnService).Execute`, which automatically sends a `svc.Stopped`
notification to Windows.

To make this happen, I changed the loop so that it runs until `doneCh` is
closed, and then returns. I also removed a spurious `svc.StopPending` notification
that the Windows Service Control Manager might be interpreting as a request for
more time to shut down.

Finally, I added some optional logging that sends a record of service notifications
to the Windows event log, allowing us to more easily correlate with any Service
Control Manager errors that are sent to the same log.

Change-Id: I5b596122e5e89c4c655fe747a612a52cb4e8f1e0
Signed-off-by: Aaron Klotz <aaron@tailscale.com>

cmd/tailscaled/depaware.txt

@@ -323,6 +323,7 @@ tailscale.com/cmd/tailscaled dependencies: (generated by github.com/tailscale/de
    W    golang.org/x/sys/windows                                     from github.com/go-ole/go-ole+
    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/eventlog                        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

cmd/tailscaled/tailscaled_windows.go

@@ -30,6 +30,7 @@ import (
 
 	"golang.org/x/sys/windows"
 	"golang.org/x/sys/windows/svc"
+	"golang.org/x/sys/windows/svc/eventlog"
 	"golang.zx2c4.com/wireguard/windows/tunnel/winipcfg"
 	"inet.af/netaddr"
 	"tailscale.com/envknob"
@@ -60,12 +61,31 @@ func isWindowsService() bool {
 	return v
 }
 
+// syslogf is a logger function that writes to the Windows event log (ie, the
+// one that you see in the Windows Event Viewer). tailscaled may optionally
+// generate diagnostic messages in the same event timeline as the Windows
+// Service Control Manager to assist with diagnosing issues with tailscaled's
+// lifetime (such as slow shutdowns).
+var syslogf logger.Logf = logger.Discard
+
 // runWindowsService starts running Tailscale under the Windows
 // Service environment.
 //
 // At this point we're still the parent process that
 // Windows started.
 func runWindowsService(pol *logpolicy.Policy) error {
+	if winutil.GetPolicyInteger("LogSCMInteractions", 0) != 0 {
+		syslog, err := eventlog.Open(serviceName)
+		if err == nil {
+			syslogf = func(format string, args ...any) {
+				syslog.Info(0, fmt.Sprintf(format, args...))
+			}
+			defer syslog.Close()
+		}
+	}
+
+	syslogf("Service entering svc.Run")
+	defer syslogf("Service exiting svc.Run")
 	return svc.Run(serviceName, &ipnService{Policy: pol})
 }
 
@@ -75,7 +95,10 @@ type ipnService struct {
 
 // Called by Windows to execute the windows service.
 func (service *ipnService) Execute(args []string, r <-chan svc.ChangeRequest, changes chan<- svc.Status) (bool, uint32) {
+	defer syslogf("SvcStopped notification imminent")
+
 	changes <- svc.Status{State: svc.StartPending}
+	syslogf("Service start pending")
 
 	svcAccepts := svc.AcceptStop
 	if winutil.GetPolicyInteger("FlushDNSOnSessionUnlock", 0) != 0 {
@@ -98,26 +121,29 @@ func (service *ipnService) Execute(args []string, r <-chan svc.ChangeRequest, ch
 	}()
 
 	changes <- svc.Status{State: svc.Running, Accepts: svcAccepts}
+	syslogf("Service running")
 
-	for ctx.Err() == nil {
+	for {
 		select {
 		case <-doneCh:
+			return false, windows.NO_ERROR
 		case cmd := <-r:
 			log.Printf("Got Windows Service event: %v", cmdName(cmd.Cmd))
 			switch cmd.Cmd {
 			case svc.Stop:
-				cancel()
+				changes <- svc.Status{State: svc.StopPending}
+				syslogf("Service stop pending")
+				cancel() // so BabysitProc will kill the child process
 			case svc.Interrogate:
+				syslogf("Service interrogation")
 				changes <- cmd.CurrentStatus
 			case svc.SessionChange:
+				syslogf("Service session change notification")
 				handleSessionChange(cmd)
 				changes <- cmd.CurrentStatus
 			}
 		}
 	}
-
-	changes <- svc.Status{State: svc.StopPending}
-	return false, windows.NO_ERROR
 }
 
 func cmdName(c svc.Cmd) string {

tstest/integration/tailscaled_deps_test_windows.go

@@ -13,6 +13,7 @@ import (
 	// process and can cache a prior success when a dependency changes.
 	_ "golang.org/x/sys/windows"
 	_ "golang.org/x/sys/windows/svc"
+	_ "golang.org/x/sys/windows/svc/eventlog"
 	_ "golang.org/x/sys/windows/svc/mgr"
 	_ "golang.zx2c4.com/wireguard/windows/tunnel/winipcfg"
 	_ "inet.af/netaddr"