Finish windows support

- Fix service creation
- Singleton lock
- Control error/logging
- Revamp run/service interaction
- Add option to turn off stdout/stderr output (for Windows Service)
- Use log instead of fmt.Print*

pmctl/run.go

@@ -3,19 +3,16 @@ package main
 import (
 	"fmt"
 	"io"
+	"log"
 	"os"
 	"os/exec"
+	"path"
 	"path/filepath"
 	"runtime"
 	"strings"
 	"sync"
 	"time"
 
-	"github.com/safing/portbase/container"
-	"github.com/safing/portbase/database/record"
-	"github.com/safing/portbase/formats/dsd"
-	"github.com/safing/portmaster/updates"
-
 	"github.com/spf13/cobra"
 	"github.com/tevino/abool"
 )
@@ -24,17 +21,16 @@ var (
 	runningInConsole bool
 	onWindows        = runtime.GOOS == "windows"
 
-	childIsRunning    = abool.NewBool(false)
-	shuttingDown      = make(chan struct{})
-	shutdownInitiated = abool.NewBool(false)
-	programEnded      = make(chan struct{})
+	childIsRunning = abool.NewBool(false)
 )
 
 // Options for starting component
 type Options struct {
-	Identifier        string
-	AllowDownload     bool
-	AllowHidingWindow bool
+	Identifier        string // component identifier
+	ShortIdentifier   string // populated automatically
+	AllowDownload     bool   // allow download of component if it is not yet available
+	AllowHidingWindow bool   // allow hiding the window of the subprocess
+	NoOutput          bool   // do not use stdout/err if logging to file is available (did not fail to open log file)
 }
 
 func init() {
@@ -53,7 +49,7 @@ var runCore = &cobra.Command{
 	Use:   "core",
 	Short: "Run the Portmaster Core",
 	RunE: func(cmd *cobra.Command, args []string) error {
-		return run(cmd, &Options{
+		return handleRun(cmd, &Options{
 			Identifier:        "core/portmaster-core",
 			AllowDownload:     true,
 			AllowHidingWindow: true,
@@ -69,7 +65,7 @@ var runApp = &cobra.Command{
 	Use:   "app",
 	Short: "Run the Portmaster App",
 	RunE: func(cmd *cobra.Command, args []string) error {
-		return run(cmd, &Options{
+		return handleRun(cmd, &Options{
 			Identifier:        "app/portmaster-app",
 			AllowDownload:     false,
 			AllowHidingWindow: false,
@@ -85,7 +81,7 @@ var runNotifier = &cobra.Command{
 	Use:   "notifier",
 	Short: "Run the Portmaster Notifier",
 	RunE: func(cmd *cobra.Command, args []string) error {
-		return run(cmd, &Options{
+		return handleRun(cmd, &Options{
 			Identifier:        "notifier/portmaster-notifier",
 			AllowDownload:     false,
 			AllowHidingWindow: true,
@@ -97,8 +93,40 @@ var runNotifier = &cobra.Command{
 	},
 }
 
-func run(cmd *cobra.Command, opts *Options) error {
-	defer close(programEnded)
+func handleRun(cmd *cobra.Command, opts *Options) (err error) {
+	err = run(cmd, opts)
+	initiateShutdown(err)
+	return
+}
+
+func run(cmd *cobra.Command, opts *Options) (err error) {
+
+	// parse identifier
+	opts.ShortIdentifier = path.Dir(opts.Identifier)
+
+	// check for concurrent error (eg. service)
+	shutdownLock.Lock()
+	alreadyDead := shutdownInitiated
+	shutdownLock.Unlock()
+	if alreadyDead {
+		return
+	}
+
+	// check for duplicate instances
+	if opts.ShortIdentifier == "core" {
+		pid, _ := checkAndCreateInstanceLock(opts.ShortIdentifier)
+		if pid != 0 {
+			return fmt.Errorf("another instance of Portmaster Core is already running: PID %d", pid)
+		}
+		defer deleteInstanceLock(opts.ShortIdentifier)
+	}
+
+	// notify service after some time
+	go func() {
+		// assume that after 5 seconds service has finished starting
+		time.Sleep(3 * time.Second)
+		startupComplete <- struct{}{}
+	}()
 
 	// get original arguments
 	var args []string
@@ -112,31 +140,47 @@ func run(cmd *cobra.Command, opts *Options) error {
 		opts.Identifier += ".exe"
 	}
 
+	// setup logging
+	// init log file
+	logFile := initControlLogFile()
+	if logFile != nil {
+		// don't close logFile, will be closed by system
+		if opts.NoOutput {
+			log.Println("disabling log output to stdout... bye!")
+			log.SetOutput(logFile)
+		} else {
+			log.SetOutput(io.MultiWriter(os.Stdout, logFile))
+		}
+	}
+
 	// run
 	tries := 0
 	for {
 		// normal execution
-		tryAgain, err := execute(opts, args)
-		if tryAgain && err == nil {
-			continue
-		}
-
-		if err != nil {
+		tryAgain := false
+		tryAgain, err = execute(opts, args)
+		switch {
+		case tryAgain && err != nil:
+			// temporary? execution error
+			log.Printf("execution of %s failed: %s\n", opts.Identifier, err)
 			tries++
-			fmt.Printf("%s execution of %s failed: %s\n", logPrefix, opts.Identifier, err)
-		}
-		if !tryAgain {
-			break
-		}
-		if tries >= 5 {
-			fmt.Printf("%s error seems to be permanent, giving up...\n", logPrefix)
+			if tries >= 5 {
+				log.Println("error seems to be permanent, giving up...")
+				return err
+			}
+			log.Println("trying again...")
+		case tryAgain && err == nil:
+			// upgrade
+			log.Println("restarting by request...")
+		case !tryAgain && err != nil:
+			// fatal error
 			return err
+		case !tryAgain && err == nil:
+			// clean exit
+			log.Printf("%s completed successfully\n", opts.Identifier)
+			return nil
 		}
-		fmt.Printf("%s trying again...\n", logPrefix)
 	}
-
-	fmt.Printf("%s %s completed successfully\n", logPrefix, opts.Identifier)
-	return nil
 }
 
 func execute(opts *Options, args []string) (cont bool, err error) {
@@ -159,23 +203,23 @@ func execute(opts *Options, args []string) (cont bool, err error) {
 		}
 	}
 
-	fmt.Printf("%s starting %s %s\n", logPrefix, file.Path(), strings.Join(args, " "))
+	log.Printf("starting %s %s\n", file.Path(), strings.Join(args, " "))
 
 	// log files
 	var logFile, errorFile *os.File
-	logFileBasePath := filepath.Join(*databaseRootDir, "logs", "fstree", strings.SplitN(opts.Identifier, "/", 2)[0])
+	logFileBasePath := filepath.Join(*databaseRootDir, "logs", "fstree", opts.ShortIdentifier)
 	err = os.MkdirAll(logFileBasePath, 0777)
 	if err != nil {
-		fmt.Printf("%s failed to create log file folder %s: %s\n", logPrefix, logFileBasePath, err)
+		log.Printf("failed to create log file folder %s: %s\n", logFileBasePath, err)
 	} else {
 		// open log file
-		logFilePath := filepath.Join(logFileBasePath, fmt.Sprintf("%s.log", time.Now().Format("2006-02-01-15-04-05")))
+		logFilePath := filepath.Join(logFileBasePath, fmt.Sprintf("%s.log", time.Now().UTC().Format("2006-02-01-15-04-05")))
 		logFile = initializeLogFile(logFilePath, opts.Identifier, file)
 		if logFile != nil {
 			defer finalizeLogFile(logFile, logFilePath)
 		}
 		// open error log file
-		errorFilePath := filepath.Join(logFileBasePath, fmt.Sprintf("%s.error.log", time.Now().Format("2006-02-01-15-04-05")))
+		errorFilePath := filepath.Join(logFileBasePath, fmt.Sprintf("%s.error.log", time.Now().UTC().Format("2006-02-01-15-04-05")))
 		errorFile = initializeLogFile(errorFilePath, opts.Identifier, file)
 		if errorFile != nil {
 			defer finalizeLogFile(errorFile, errorFilePath)
@@ -232,10 +276,14 @@ func execute(opts *Options, args []string) (cont bool, err error) {
 		if logFile == nil {
 			_, logFileError = io.Copy(os.Stdout, stdout)
 		} else {
-			_, logFileError = io.Copy(io.MultiWriter(os.Stdout, logFile), stdout)
+			if opts.NoOutput {
+				_, logFileError = io.Copy(logFile, stdout)
+			} else {
+				_, logFileError = io.Copy(io.MultiWriter(os.Stdout, logFile), stdout)
+			}
 		}
 		if logFileError != nil {
-			fmt.Printf("%s failed write logs: %s\n", logPrefix, logFileError)
+			log.Printf("failed write logs: %s\n", logFileError)
 		}
 		wg.Done()
 	}()
@@ -244,23 +292,28 @@ func execute(opts *Options, args []string) (cont bool, err error) {
 		if logFile == nil {
 			_, errorFileError = io.Copy(os.Stderr, stderr)
 		} else {
-			_, errorFileError = io.Copy(io.MultiWriter(os.Stderr, errorFile), stderr)
+			if opts.NoOutput {
+				_, errorFileError = io.Copy(errorFile, stderr)
+			} else {
+				_, errorFileError = io.Copy(io.MultiWriter(os.Stderr, errorFile), stderr)
+			}
 		}
 		if errorFileError != nil {
-			fmt.Printf("%s failed write error logs: %s\n", logPrefix, errorFileError)
+			log.Printf("failed write error logs: %s\n", errorFileError)
 		}
 		wg.Done()
 	}()
-	// give some time to finish log file writing
-	defer func() {
-		wg.Wait()
-		childIsRunning.UnSet()
-	}()
 
 	// wait for completion
 	finished := make(chan error)
 	go func() {
+		// wait for output writers to complete
+		wg.Wait()
+		// wait for process to return
 		finished <- exc.Wait()
+		// update status
+		childIsRunning.UnSet()
+		// notify manager
 		close(finished)
 	}()
 
@@ -276,16 +329,24 @@ func execute(opts *Options, args []string) (cont bool, err error) {
 				err = exc.Process.Signal(os.Interrupt)
 			}
 			if err != nil {
-				fmt.Printf("%s failed to signal %s to shutdown: %s\n", logPrefix, opts.Identifier, err)
+				log.Printf("failed to signal %s to shutdown: %s\n", opts.Identifier, err)
 				err = exc.Process.Kill()
 				if err != nil {
-					fmt.Printf("%s failed to kill %s: %s\n", logPrefix, opts.Identifier, err)
-				} else {
-					fmt.Printf("%s killed %s\n", logPrefix, opts.Identifier)
+					return false, fmt.Errorf("failed to kill %s: %s", opts.Identifier, err)
 				}
+				return false, fmt.Errorf("killed %s", opts.Identifier)
 			}
 			// wait until shut down
-			<-finished
+			select {
+			case <-finished:
+			case <-time.After(11 * time.Second): // portmaster core prints stack if not able to shutdown in 10 seconds
+				// kill
+				err = exc.Process.Kill()
+				if err != nil {
+					return false, fmt.Errorf("failed to kill %s: %s", opts.Identifier, err)
+				}
+				return false, fmt.Errorf("killed %s", opts.Identifier)
+			}
 			return false, nil
 		case err := <-finished:
 			if err != nil {
@@ -300,7 +361,7 @@ func execute(opts *Options, args []string) (cont bool, err error) {
 						return true, fmt.Errorf("error during execution: %s", err)
 					case 2357427: // Leet Speak for "restart"
 						// restart request
-						fmt.Printf("%s restarting %s\n", logPrefix, opts.Identifier)
+						log.Printf("restarting %s\n", opts.Identifier)
 						return true, nil
 					default:
 						return true, fmt.Errorf("unexpected error during execution: %s", err)
@@ -314,74 +375,3 @@ func execute(opts *Options, args []string) (cont bool, err error) {
 		}
 	}
 }
-
-func initiateShutdown() {
-	if shutdownInitiated.SetToIf(false, true) {
-		close(shuttingDown)
-	}
-}
-
-func initializeLogFile(logFilePath string, identifier string, updateFile *updates.File) *os.File {
-	logFile, err := os.OpenFile(logFilePath, os.O_RDWR|os.O_CREATE, 0644)
-	if err != nil {
-		fmt.Printf("%s failed to create log file %s: %s\n", logPrefix, logFilePath, err)
-		return nil
-	}
-
-	// create header, so that the portmaster can view log files as a database
-	meta := record.Meta{}
-	meta.Update()
-	meta.SetAbsoluteExpiry(time.Now().Add(720 * time.Hour).Unix()) // one month
-
-	// manually marshal
-	// version
-	c := container.New([]byte{1})
-	// meta
-	metaSection, err := dsd.Dump(meta, dsd.JSON)
-	if err != nil {
-		fmt.Printf("%s failed to serialize header for log file %s: %s\n", logPrefix, logFilePath, err)
-		finalizeLogFile(logFile, logFilePath)
-		return nil
-	}
-	c.AppendAsBlock(metaSection)
-	// log file data type (string) and newline for better manual viewing
-	c.Append([]byte("S\n"))
-	c.Append([]byte(fmt.Sprintf("executing %s version %s on %s %s\n", identifier, updateFile.Version(), runtime.GOOS, runtime.GOARCH)))
-
-	_, err = logFile.Write(c.CompileData())
-	if err != nil {
-		fmt.Printf("%s failed to write header for log file %s: %s\n", logPrefix, logFilePath, err)
-		finalizeLogFile(logFile, logFilePath)
-		return nil
-	}
-
-	return logFile
-}
-
-func finalizeLogFile(logFile *os.File, logFilePath string) {
-	err := logFile.Close()
-	if err != nil {
-		fmt.Printf("%s failed to close log file %s: %s\n", logPrefix, logFilePath, err)
-	}
-
-	//keep := true
-	// check file size
-	stat, err := os.Stat(logFilePath)
-	if err == nil {
-		// delete again if file is smaller than
-		if stat.Size() < 200 { // header + info is about 150 bytes
-			// keep = false
-			err := os.Remove(logFilePath)
-			if err != nil {
-				fmt.Printf("%s failed to delete empty log file %s: %s\n", logPrefix, logFilePath, err)
-			}
-		}
-	}
-
-	//if !keep {
-	//	err := os.Remove(logFilePath)
-	//	if err != nil {
-	//		fmt.Printf("%s failed to delete empty log file %s: %s\n", logPrefix, logFilePath, err)
-	//	}
-	//}
-}