Improve shutdown logs (#87)

CHANGELOG.md

@@ -9,6 +9,8 @@ This project adheres to [Semantic Versioning](http://semver.org/).
 
 ### Changed
 
+- service: Improve shutdown logs #87
+
 ### Deprecated
 
 ### Removed

service/service.go

@@ -38,7 +38,7 @@ import (
 
 // HandleSignals manages OS signals that ask the service/daemon to stop.
 // The stopFunction should break the loop in the Beat so that
-// the service shut downs gracefully.
+// the service shuts down gracefully.
 func HandleSignals(stopFunction func(), cancel context.CancelFunc) {
 	var callback sync.Once
 	logger := logp.NewLogger("service")
@@ -49,20 +49,14 @@ func HandleSignals(stopFunction func(), cancel context.CancelFunc) {
 	go func() {
 		sig := <-sigc
 
-		switch sig {
-		case syscall.SIGINT, syscall.SIGTERM:
-			logger.Debug("Received sigterm/sigint, stopping")
-		case syscall.SIGHUP:
-			logger.Debug("Received sighup, stopping")
-		}
-
+		logger.Infof("Received signal %q, stopping", sig)
 		cancel()
 		callback.Do(stopFunction)
 	}()
 
 	// Handle the Windows service events
 	go ProcessWindowsControlEvents(func() {
-		logger.Debug("Received svc stop/shutdown request")
+		logger.Info("Received Windows SVC stop/shutdown request")
 		callback.Do(stopFunction)
 	})
 }

service/service_windows.go

@@ -47,6 +47,7 @@ func (m *beatService) Execute(args []string, r <-chan svc.ChangeRequest, changes
 	changes <- svc.Status{State: svc.StartPending}
 	changes <- svc.Status{State: svc.Running, Accepts: cmdsAccepted}
 
+	log := logp.NewLogger("service_windows")
 loop:
 	for c := range r {
 		switch c.Cmd {
@@ -55,18 +56,29 @@ loop:
 			// Testing deadlock from https://code.google.com/p/winsvc/issues/detail?id=4
 			time.Sleep(100 * time.Millisecond)
 			changes <- c.CurrentStatus
-		case svc.Stop, svc.Shutdown:
+
+		// The svc.Cmd tye does not implement the Stringer interface and its
+		// underlying type is an integer, therefore it's needed to manually log them.
+		case svc.Stop:
+			log.Info("received state change 'svc.Stop' from windows service manager")
+			break loop
+		case svc.Shutdown:
+			log.Info("received state change 'svc.Shutdown' from windows service manager")
 			break loop
+
 		default:
-			logp.Err("Unexpected control request: $%d. Ignored.", c)
+			log.Errorf("Unexpected control request: $%d. Ignored.", c)
 		}
 	}
 	changes <- svc.Status{State: svc.StopPending}
+	log.Info("changed windows service state to svc.StopPending, invoking stopCallback")
 	m.stopCallback()
+
 	// Block until notifyWindowsServiceStopped below is called. This is required
 	// as the windows/svc package will transition the service to STOPPED state
 	// once this function returns.
 	<-m.done
+	log.Debug("windows service state changed to svc.Stopped")
 	return ssec, errno
 }
 
@@ -89,7 +101,7 @@ const couldNotConnect syscall.Errno = 1063
 func ProcessWindowsControlEvents(stopCallback func()) {
 	defer close(serviceInstance.executeFinished)
 
-	// nolint: staticcheck // keep using the deprecated method in order to maintain the existing behavior
+	//nolint:staticcheck // keep using the deprecated method in order to maintain the existing behavior
 	isInteractive, err := svc.IsAnInteractiveSession()
 	if err != nil {
 		logp.Err("IsAnInteractiveSession: %v", err)
@@ -104,12 +116,11 @@ func ProcessWindowsControlEvents(stopCallback func()) {
 
 	serviceInstance.stopCallback = stopCallback
 	err = run(os.Args[0], serviceInstance)
-
 	if err == nil {
 		return
 	}
 
-	// nolint: errorlint // this system error is a special case
+	//nolint:errorlint // this system error is a special case
 	if errnoErr, ok := err.(syscall.Errno); ok && errnoErr == couldNotConnect {
 		/*
 			 If, as in the case of Jenkins, the process is started as an interactive process, but the invoking process