Add logging to file, improve windows console handling

Gopkg.lock

@@ -83,14 +83,6 @@
   revision = "f0e32980c006571efd537032e5f9cd8c1a92819e"
   version = "v0.1.0"
 
-[[projects]]
-  digest = "1:cbec35fe4d5a4fba369a656a8cd65e244ea2c743007d8f6c1ccb132acf9d1296"
-  name = "github.com/gorilla/mux"
-  packages = ["."]
-  pruneopts = "UT"
-  revision = "00bdffe0f3c77e27d2cf6f5c70232a2d3e4d9c15"
-  version = "v1.7.3"
-
 [[projects]]
   digest = "1:870d441fe217b8e689d7949fef6e43efbc787e50f200cb1e70dbca9204a1d6be"
   name = "github.com/inconshreveable/mousetrap"
@@ -219,12 +211,15 @@
 
 [[projects]]
   branch = "master"
-  digest = "1:7e3e63385ebe2dd5210be1534c516d8ae33c7ffac74126e5243d43ba7222e0d4"
+  digest = "1:a931c816b1c08002eddb0ec1b920ed1987a0e873dad1f9f443e4905d70b59c66"
   name = "golang.org/x/sys"
   packages = [
     "cpu",
     "unix",
     "windows",
+    "windows/registry",
+    "windows/svc",
+    "windows/svc/eventlog",
   ]
   pruneopts = "UT"
   revision = "04f50cda93cbb67f2afa353c52f342100e80e625"
@@ -242,7 +237,6 @@
     "github.com/google/gopacket/layers",
     "github.com/google/gopacket/tcpassembly",
     "github.com/google/renameio",
-    "github.com/gorilla/mux",
     "github.com/miekg/dns",
     "github.com/oschwald/maxminddb-golang",
     "github.com/satori/go.uuid",
@@ -256,6 +250,8 @@
     "golang.org/x/net/icmp",
     "golang.org/x/net/ipv4",
     "golang.org/x/sys/windows",
+    "golang.org/x/sys/windows/svc",
+    "golang.org/x/sys/windows/svc/eventlog",
   ]
   solver-name = "gps-cdcl"
   solver-version = 1

Gopkg.toml

@@ -54,10 +54,6 @@ ignored = ["github.com/safing/portbase/*"]
   name = "github.com/google/renameio"
   version = "0.1.0"
 
-[[constraint]]
-  name = "github.com/gorilla/mux"
-  version = "1.7.3"
-
 [[constraint]]
   name = "github.com/miekg/dns"
   version = "1.1.15"

pmctl/console_default.go

@@ -1,3 +1,5 @@
+// +build !windows
+
 package main
 
 import "os/exec"

pmctl/main.go

@@ -4,7 +4,10 @@ import (
 	"errors"
 	"fmt"
 	"os"
+	"os/signal"
 	"path/filepath"
+	"runtime"
+	"syscall"
 
 	"github.com/safing/portbase/info"
 	"github.com/safing/portbase/log"
@@ -51,18 +54,6 @@ func main() {
 		os.Exit(1)
 	}
 
-	// not using portbase logger
-	log.SetLogLevel(log.CriticalLevel)
-
-	// for debugging
-	// log.Start()
-	// log.SetLogLevel(log.TraceLevel)
-	// go func() {
-	// 	time.Sleep(3 * time.Second)
-	// 	pprof.Lookup("goroutine").WriteTo(os.Stdout, 2)
-	// 	os.Exit(1)
-	// }()
-
 	// set meta info
 	info.Set("Portmaster Control", "0.2.5", "AGPLv3", true)
 
@@ -78,11 +69,53 @@ func main() {
 		os.Exit(0)
 	}
 
-	// start root command
+	// warn about CTRL-C on windows
-	if err = rootCmd.Execute(); err != nil {
+	if runningInConsole && runtime.GOOS == "windows" {
-		os.Exit(1)
+		fmt.Printf("%s WARNING: portmaster-control is marked as a GUI application in order to get rid of the console window.\n", logPrefix)
+		fmt.Printf("%s WARNING: CTRL-C will immediately kill without clean shutdown.\n", logPrefix)
+	}
+
+	// not using portbase logger
+	log.SetLogLevel(log.CriticalLevel)
+
+	// for debugging
+	// log.Start()
+	// log.SetLogLevel(log.TraceLevel)
+	// go func() {
+	// 	time.Sleep(3 * time.Second)
+	// 	pprof.Lookup("goroutine").WriteTo(os.Stdout, 2)
+	// 	os.Exit(1)
+	// }()
+
+	// catch interrupt for clean shutdown
+	signalCh := make(chan os.Signal)
+	signal.Notify(
+		signalCh,
+		os.Interrupt,
+		os.Kill,
+		syscall.SIGHUP,
+		syscall.SIGINT,
+		syscall.SIGTERM,
+		syscall.SIGQUIT,
+	)
+
+	// start root command
+	go func() {
+		if err = rootCmd.Execute(); err != nil {
+			os.Exit(1)
+		}
+		os.Exit(0)
+	}()
+
+	// wait for signals
+	for sig := range signalCh {
+		if childIsRunning.IsSet() {
+			fmt.Printf("%s got %s signal (ignoring), waiting for child to exit...\n", logPrefix, sig)
+		} else {
+			fmt.Printf("%s got %s signal, exiting... (not executing anything)\n", logPrefix, sig)
+			os.Exit(0)
+		}
 	}
-	os.Exit(0)
 }
 
 func initPmCtl(cmd *cobra.Command, args []string) (err error) {

pmctl/run.go

@@ -5,17 +5,28 @@ import (
 	"io"
 	"os"
 	"os/exec"
-	"os/signal"
+	"path/filepath"
 	"runtime"
 	"strings"
-	"syscall"
+	"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"
 )
 
 var (
 	runningInConsole bool
 	onWindows        = runtime.GOOS == "windows"
+
+	childIsRunning    = abool.NewBool(false)
+	shuttingDown      = make(chan struct{})
+	shutdownInitiated = abool.NewBool(false)
+	programEnded      = make(chan struct{})
 )
 
 // Options for starting component
@@ -86,6 +97,7 @@ var runNotifier = &cobra.Command{
 }
 
 func run(cmd *cobra.Command, opts *Options) error {
+	defer close(programEnded)
 
 	// get original arguments
 	var args []string
@@ -100,110 +112,244 @@ func run(cmd *cobra.Command, opts *Options) error {
 	}
 
 	// run
+	tries := 0
 	for {
-		file, err := getFile(opts)
+		// normal execution
+		tryAgain, err := execute(opts, args)
+		if tryAgain && err == nil {
+			continue
+		}
+
 		if err != nil {
-			return fmt.Errorf("could not get component: %s", err)
+			tries++
+			fmt.Printf("%s execution of %s failed: %s\n", logPrefix, opts.Identifier, err)
 		}
-
+		if !tryAgain {
-		// check permission
+			break
-		if !onWindows {
-			info, err := os.Stat(file.Path())
-			if err != nil {
-				return fmt.Errorf("failed to get file info on %s: %s", file.Path(), err)
-			}
-			if info.Mode() != 0755 {
-				err := os.Chmod(file.Path(), 0755)
-				if err != nil {
-					return fmt.Errorf("failed to set exec permissions on %s: %s", file.Path(), err)
-				}
-			}
 		}
-
+		if tries >= 5 {
-		fmt.Printf("%s starting %s %s\n", logPrefix, file.Path(), strings.Join(args, " "))
+			fmt.Printf("%s error seems to be permanent, giving up...\n", logPrefix)
-
+			return err
-		// create command
-		exc := exec.Command(file.Path(), args...)
-
-		if !runningInConsole && opts.AllowHidingWindow {
-			// Windows only:
-			// only hide (all) windows of program if we are not running in console and windows may be hidden
-			hideWindow(exc)
 		}
-
+		fmt.Printf("%s trying again...\n", logPrefix)
-		// consume stdout/stderr
-		stdout, err := exc.StdoutPipe()
-		if err != nil {
-			return fmt.Errorf("failed to connect stdout: %s", err)
-		}
-		stderr, err := exc.StderrPipe()
-		if err != nil {
-			return fmt.Errorf("failed to connect stderr: %s", err)
-		}
-
-		// start
-		err = exc.Start()
-		if err != nil {
-			return fmt.Errorf("failed to start %s: %s", opts.Identifier, err)
-		}
-
-		// start output writers
-		go func() {
-			io.Copy(os.Stdout, stdout)
-		}()
-		go func() {
-			io.Copy(os.Stderr, stderr)
-		}()
-
-		// catch interrupt for clean shutdown
-		signalCh := make(chan os.Signal)
-		signal.Notify(
-			signalCh,
-			os.Interrupt,
-			os.Kill,
-			syscall.SIGHUP,
-			syscall.SIGINT,
-			syscall.SIGTERM,
-			syscall.SIGQUIT,
-		)
-		go func() {
-			for {
-				sig := <-signalCh
-				fmt.Printf("%s got %s signal (ignoring), waiting for %s to exit...\n", logPrefix, sig, opts.Identifier)
-			}
-		}()
-
-		// wait for completion
-		err = exc.Wait()
-		if err != nil {
-			exErr, ok := err.(*exec.ExitError)
-			if ok {
-				switch exErr.ProcessState.ExitCode() {
-				case 0:
-					// clean exit
-					fmt.Printf("%s clean exit of %s, but with error: %s\n", logPrefix, opts.Identifier, err)
-					os.Exit(1)
-				case 1:
-					// error exit
-					fmt.Printf("%s error during execution of %s: %s\n", logPrefix, opts.Identifier, err)
-					os.Exit(1)
-				case 2357427: // Leet Speak for "restart"
-					// restart request
-					fmt.Printf("%s restarting %s\n", logPrefix, opts.Identifier)
-					continue
-				default:
-					fmt.Printf("%s unexpected error during execution of %s: %s\n", logPrefix, opts.Identifier, err)
-					os.Exit(exErr.ProcessState.ExitCode())
-				}
-			} else {
-				fmt.Printf("%s unexpected error type during execution of %s: %s\n", logPrefix, opts.Identifier, err)
-				os.Exit(1)
-			}
-		}
-		// clean exit
-		break
 	}
 
 	fmt.Printf("%s %s completed successfully\n", logPrefix, opts.Identifier)
 	return nil
 }
+
+func execute(opts *Options, args []string) (cont bool, err error) {
+	file, err := getFile(opts)
+	if err != nil {
+		return true, fmt.Errorf("could not get component: %s", err)
+	}
+
+	// check permission
+	if !onWindows {
+		info, err := os.Stat(file.Path())
+		if err != nil {
+			return true, fmt.Errorf("failed to get file info on %s: %s", file.Path(), err)
+		}
+		if info.Mode() != 0755 {
+			err := os.Chmod(file.Path(), 0755)
+			if err != nil {
+				return true, fmt.Errorf("failed to set exec permissions on %s: %s", file.Path(), err)
+			}
+		}
+	}
+
+	fmt.Printf("%s starting %s %s\n", logPrefix, file.Path(), strings.Join(args, " "))
+
+	// log files
+	var logFile, errorFile *os.File
+	logFileBasePath := filepath.Join(*databaseRootDir, "logs", "fstree", strings.SplitN(opts.Identifier, "/", 2)[0])
+	err = os.MkdirAll(logFileBasePath, 0777)
+	if err != nil {
+		fmt.Printf("%s failed to create log file folder %s: %s\n", logPrefix, logFileBasePath, err)
+	} else {
+		// open log file
+		logFilePath := filepath.Join(logFileBasePath, fmt.Sprintf("%s.log", time.Now().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")))
+		errorFile = initializeLogFile(errorFilePath, opts.Identifier, file)
+		if errorFile != nil {
+			defer finalizeLogFile(errorFile, errorFilePath)
+		}
+	}
+
+	// create command
+	exc := exec.Command(file.Path(), args...)
+
+	if !runningInConsole && opts.AllowHidingWindow {
+		// Windows only:
+		// only hide (all) windows of program if we are not running in console and windows may be hidden
+		hideWindow(exc)
+	}
+
+	// consume stdout/stderr
+	stdout, err := exc.StdoutPipe()
+	if err != nil {
+		return true, fmt.Errorf("failed to connect stdout: %s", err)
+	}
+	stderr, err := exc.StderrPipe()
+	if err != nil {
+		return true, fmt.Errorf("failed to connect stderr: %s", err)
+	}
+
+	// start
+	err = exc.Start()
+	if err != nil {
+		return true, fmt.Errorf("failed to start %s: %s", opts.Identifier, err)
+	}
+	childIsRunning.Set()
+
+	// start output writers
+	go func() {
+		var logFileError error
+		if logFile == nil {
+			_, logFileError = io.Copy(os.Stdout, stdout)
+		} else {
+			_, logFileError = io.Copy(io.MultiWriter(os.Stdout, logFile), stdout)
+		}
+		if logFileError != nil {
+			fmt.Printf("%s failed write logs: %s\n", logPrefix, logFileError)
+		}
+	}()
+	go func() {
+		var errorFileError error
+		if logFile == nil {
+			_, errorFileError = io.Copy(os.Stderr, 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)
+		}
+	}()
+	// give some time to finish log file writing
+	defer func() {
+		time.Sleep(100 * time.Millisecond)
+		childIsRunning.UnSet()
+	}()
+
+	// wait for completion
+	finished := make(chan error)
+	go func() {
+		finished <- exc.Wait()
+		close(finished)
+	}()
+
+	// state change listeners
+	for {
+		select {
+		case <-shuttingDown:
+			err := exc.Process.Signal(os.Interrupt)
+			if err != nil {
+				fmt.Printf("%s failed to signal %s to shutdown: %s\n", logPrefix, opts.Identifier, err)
+				fmt.Printf("%s forcing shutdown...\n", logPrefix)
+				// wait until shut down
+				<-finished
+				return false, nil
+			}
+		case err := <-finished:
+			if err != nil {
+				exErr, ok := err.(*exec.ExitError)
+				if ok {
+					switch exErr.ProcessState.ExitCode() {
+					case 0:
+						// clean exit
+						return false, fmt.Errorf("clean exit, but with error: %s", err)
+					case 1:
+						// error exit
+						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)
+						return true, nil
+					default:
+						return true, fmt.Errorf("unexpected error during execution: %s", err)
+					}
+				} else {
+					return true, fmt.Errorf("unexpected error type during execution: %s", err)
+				}
+			}
+			// clean exit
+			return false, nil
+		}
+	}
+}
+
+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)
+	//	}
+	//}
+}