x/sys/windows/svc: does not handle shutdown gracefully

[JohanKnutzen]

What version of Go are you using (go version)?

$ go version
go version go1.14.3 windows/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
set GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\knutz\AppData\Local\go-build
set GOENV=C:\Users\knutz\AppData\Roaming\go\env
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\Users\knutz\go
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=c:\go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=c:\go\pkg\tool\windows_amd64
set GCCGO=gccgo
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=C:\tmp\test2\svcshutdownbug\go.mod
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=C:\Users\knutz\AppData\Local\Temp\go-build509631438=/tmp/go-build -gno-record-gcc-switches

What did you do?

go.mod

module svcshutdownbug

go 1.14

require golang.org/x/sys v0.0.0-20200625212154-ddb9806d33ae

main.go

package main

import (
	"fmt"
	"log"
	"os"
	"strings"
	"time"
	"strconv"
	"path/filepath"
	"golang.org/x/sys/windows/svc"
	"golang.org/x/sys/windows/svc/eventlog"
	"golang.org/x/sys/windows/svc/mgr"
)

// Log interface allows different log implementations to be used.
type Log interface {
	Close() error
	Info(eid uint32, msg string) error
	Warning(eid uint32, msg string) error
	Error(eid uint32, msg string) error
}

// ConsoleLog provides access to the console.
type ConsoleLog struct {
	Name string
}

// New creates new ConsoleLog.
func New(source string) *ConsoleLog {
	return &ConsoleLog{Name: source}
}

// Close closes console log l.
func (l *ConsoleLog) Close() error {
	return nil
}

func (l *ConsoleLog) report(kind string, eid uint32, msg string) error {
	s := l.Name + "." + kind + "(" + strconv.Itoa(int(eid)) + "): " + msg + "\n"
	_, err := os.Stdout.Write([]byte(s))
	return err
}

// Info writes an information event msg with event id eid to the console l.
func (l *ConsoleLog) Info(eid uint32, msg string) error {
	return l.report("info", eid, msg)
}

// Warning writes an warning event msg with event id eid to the console l.
func (l *ConsoleLog) Warning(eid uint32, msg string) error {
	return l.report("warn", eid, msg)
}

// Error writes an error event msg with event id eid to the console l.
func (l *ConsoleLog) Error(eid uint32, msg string) error {
	return l.report("error", eid, msg)
}

func exePath() (string, error) {
	prog := os.Args[0]
	p, err := filepath.Abs(prog)
	if err != nil {
		return "", err
	}
	fi, err := os.Stat(p)
	if err == nil {
		if !fi.Mode().IsDir() {
			return p, nil
		}
		err = fmt.Errorf("%s is directory", p)
	}
	if filepath.Ext(p) == "" {
		p += ".exe"
		fi, err := os.Stat(p)
		if err == nil {
			if !fi.Mode().IsDir() {
				return p, nil
			}
			err = fmt.Errorf("%s is directory", p)
		}
	}
	return "", err
}

func installService(name, desc string) error {
	exepath, err := exePath()
	if err != nil {
		return err
	}
	m, err := mgr.Connect()
	if err != nil {
		return err
	}
	defer m.Disconnect()
	s, err := m.OpenService(name)
	if err == nil {
		s.Close()
		return fmt.Errorf("service %s already exists", name)
	}
	s, err = m.CreateService(name, exepath, mgr.Config{DisplayName: desc}, "is", "auto-started")
	if err != nil {
		return err
	}
	defer s.Close()
	err = eventlog.InstallAsEventCreate(name, eventlog.Error|eventlog.Warning|eventlog.Info)
	if err != nil {
		s.Delete()
		return fmt.Errorf("SetupEventLogSource() failed: %s", err)
	}
	return nil
}

func removeService(name string) error {
	m, err := mgr.Connect()
	if err != nil {
		return err
	}
	defer m.Disconnect()
	s, err := m.OpenService(name)
	if err != nil {
		return fmt.Errorf("service %s is not installed", name)
	}
	defer s.Close()
	err = s.Delete()
	if err != nil {
		return err
	}
	err = eventlog.Remove(name)
	if err != nil {
		return fmt.Errorf("RemoveEventLogSource() failed: %s", err)
	}
	return nil
}



var elog Log

type myservice struct{}

func (m *myservice) Execute(args []string, r <-chan svc.ChangeRequest, changes chan<- svc.Status) (ssec bool, errno uint32) {
	const cmdsAccepted = svc.AcceptStop | svc.AcceptShutdown | svc.AcceptPauseAndContinue
	changes <- svc.Status{State: svc.StartPending}
	changes <- svc.Status{State: svc.Running, Accepts: cmdsAccepted}
loop:
	for {
		select {
		case c := <-r:
			switch c.Cmd {
			case svc.Interrogate:
				changes <- c.CurrentStatus
				// Testing deadlock from https://code.google.com/p/winsvc/issues/detail?id=4
				time.Sleep(100 * time.Millisecond)
				changes <- c.CurrentStatus
			case svc.Stop:
				elog.Info(1337, "stop")
				break loop
			case svc.Shutdown:
				elog.Info(1337, "shutdown")
				break loop
			case svc.Pause:
				changes <- svc.Status{State: svc.Paused, Accepts: cmdsAccepted}
			case svc.Continue:
				changes <- svc.Status{State: svc.Running, Accepts: cmdsAccepted}
			default:
				elog.Error(1, fmt.Sprintf("unexpected control request #%d", c))
			}
		}
	}
	changes <- svc.Status{State: svc.StopPending}
	return
}

func runService(name string) {
	var err error
	elog, err = eventlog.Open(name)
	if err != nil {
		return
	}
	defer elog.Close()

	elog.Info(1337, fmt.Sprintf("starting %s service", name))
	run := svc.Run
	err = run(name, &myservice{})
	if err != nil {
		elog.Error(1337, fmt.Sprintf("%s service failed: %v", name, err))
		return
	}
	elog.Info(1337, fmt.Sprintf("%s service stopped", name))
}


func startService(name string) error {
	m, err := mgr.Connect()
	if err != nil {
		return err
	}
	defer m.Disconnect()
	s, err := m.OpenService(name)
	if err != nil {
		return fmt.Errorf("could not access service: %v", err)
	}
	defer s.Close()
	err = s.Start("is", "manual-started")
	if err != nil {
		return fmt.Errorf("could not start service: %v", err)
	}
	return nil
}

func controlService(name string, c svc.Cmd, to svc.State) error {
	m, err := mgr.Connect()
	if err != nil {
		return err
	}
	defer m.Disconnect()
	s, err := m.OpenService(name)
	if err != nil {
		return fmt.Errorf("could not access service: %v", err)
	}
	defer s.Close()
	status, err := s.Control(c)
	if err != nil {
		return fmt.Errorf("could not send control=%d: %v", c, err)
	}
	timeout := time.Now().Add(10 * time.Second)
	for status.State != to {
		if timeout.Before(time.Now()) {
			return fmt.Errorf("timeout waiting for service to go to state=%d", to)
		}
		time.Sleep(300 * time.Millisecond)
		status, err = s.Query()
		if err != nil {
			return fmt.Errorf("could not retrieve service status: %v", err)
		}
	}
	return nil
}

func usage(errmsg string) {
	fmt.Fprintf(os.Stderr,
		"%s\n\n"+
			"usage: %s <command>\n"+
			"       where <command> is one of\n"+
			"       install, remove, debug, start, stop, pause or continue.\n",
		errmsg, os.Args[0])
	os.Exit(2)
}

func main() {
	const svcName = "myservice"

	isIntSess, err := svc.IsAnInteractiveSession()
	if err != nil {
		log.Fatalf("failed to determine if we are running in an interactive session: %v", err)
	}
	if !isIntSess {
		runService(svcName)
		return
	}

	cmd := strings.ToLower(os.Args[1])
	switch cmd {
	default:
		runService(svcName)
		return
	case "install":
		err = installService(svcName, "my service")
	case "remove":
		err = removeService(svcName)
	case "start":
		err = startService(svcName)
	case "stop":
		err = controlService(svcName, svc.Stop, svc.Stopped)
	case "pause":
		err = controlService(svcName, svc.Pause, svc.Paused)
	case "continue":
		err = controlService(svcName, svc.Continue, svc.Running)
	}
	if err != nil {
		log.Fatalf("failed to %s %s: %v", cmd, svcName, err)
	}
	return
}

I've copied and modified the source code slightly from sys/windows/svc/example and put them all in one file to minimize the repro.

Windows services has a number of events that are processed in a loop. These need to be handled gracefully, otherwise Windows will mark the service as not behaving appropriately and will prevent/throttle restarts.

The following are a few examples: stop, shutdown. When you receive a stop event or a shutdown event, you are expected to perform cleanup and stop the service. If this is not performed, Windows will kill the service.

In sys/windows/svc, these events are called svc.Stop and svc.Shutdown. In main.go, the event loop is called loop where these events are handled. All events seem to be handled correctly except for svc.Shutdown.

Repro steps:

1. go build
2. open up admin cmd and run:
   a) svcshutdownbug.exe install
   b) svcshutdownbug.exe start

You should now have a service called myservice running. If you right click on it in the Task Manager and do "Restart", you should be able to find a few logged events in the Event Viewer under Windows Logs->Application. These are expected to be:

starting myservice service
stop
myservice service stopped
starting myservice service

The above entries are correct and can be found under the Event ID "1337" and Source "myservice".

3. To test svc.Shutdown, a shutdown of the computer is required. Perform the following in cmd: shutdown /s

Cleanup
Execute svcshutdownbug.exe remove to uninstall the service

What did you expect to see?

shutdown
myservice service stopped

What did you see instead?

Nothing is logged.

The process was terminated unexpectedly or killed by Windows due to not processing the svc.Shutdown event properly. This event is called SERVICE_CONTROL_SHUTDOWN in w32 lingo.

[JohanKnutzen]

@alexbrainman Do you have any ideas?

[JohanKnutzen]

This issue seems to be related to the go runtime rather than the sys/windows/svc package. I've created a new issue here: 40167