diff --git a/pmctl/console_windows.go b/pmctl/console_windows.go index ba9a3ac0..5a1c09b3 100644 --- a/pmctl/console_windows.go +++ b/pmctl/console_windows.go @@ -11,7 +11,7 @@ package main // MS AttachConsole: https://docs.microsoft.com/en-us/windows/console/attachconsole import ( - "fmt" + "log" "os" "os/exec" "syscall" @@ -116,11 +116,11 @@ func attachToParentConsole() (attached bool, err error) { var st uint32 err := windows.GetConsoleMode(h, &st) if err != nil { - fmt.Printf("%s failed to get console mode: %s\n", logPrefix, err) + log.Printf("failed to get console mode: %s\n", err) } else { err = windows.SetConsoleMode(h, st&^windows.DISABLE_NEWLINE_AUTO_RETURN) if err != nil { - fmt.Printf("%s failed to set console mode: %s\n", logPrefix, err) + log.Printf("failed to set console mode: %s\n", err) } } } @@ -128,18 +128,18 @@ func attachToParentConsole() (attached bool, err error) { // fix std handles to correct values (ie. redirects) if stdin != invalid { os.Stdin = os.NewFile(uintptr(stdin), "stdin") - fmt.Printf("%s fixed os.Stdin after attaching to parent console\n", logPrefix) + log.Printf("fixed os.Stdin after attaching to parent console\n") } if stdout != invalid { os.Stdout = os.NewFile(uintptr(stdout), "stdout") - fmt.Printf("%s fixed os.Stdout after attaching to parent console\n", logPrefix) + log.Printf("fixed os.Stdout after attaching to parent console\n") } if stderr != invalid { os.Stderr = os.NewFile(uintptr(stderr), "stderr") - fmt.Printf("%s fixed os.Stderr after attaching to parent console\n", logPrefix) + log.Printf("fixed os.Stderr after attaching to parent console\n") } - fmt.Printf("%s attached to parent console\n", logPrefix) + log.Println("attached to parent console") return true, nil } diff --git a/pmctl/get.go b/pmctl/get.go index 248e8f4f..81cc3842 100644 --- a/pmctl/get.go +++ b/pmctl/get.go @@ -2,7 +2,7 @@ package main import ( "errors" - "fmt" + "log" "time" "github.com/safing/portmaster/updates" @@ -22,7 +22,7 @@ func getFile(opts *Options) (*updates.File, error) { // download if opts.AllowDownload { - fmt.Printf("%s downloading %s...\n", logPrefix, opts.Identifier) + log.Printf("downloading %s...\n", opts.Identifier) // download indexes err = updates.UpdateIndexes() @@ -39,7 +39,7 @@ func getFile(opts *Options) (*updates.File, error) { } // wait for 30 seconds - fmt.Printf("%s waiting for download of %s (by Portmaster Core) to complete...\n", logPrefix, opts.Identifier) + log.Printf("waiting for download of %s (by Portmaster Core) to complete...\n", opts.Identifier) // try every 0.5 secs for tries := 0; tries < 60; tries++ { diff --git a/pmctl/install_windows.go b/pmctl/install_windows.go index b5bca3bd..c7850fbb 100644 --- a/pmctl/install_windows.go +++ b/pmctl/install_windows.go @@ -7,8 +7,10 @@ package main import ( "fmt" + "log" "os" "path/filepath" + "strings" "time" "github.com/spf13/cobra" @@ -43,7 +45,11 @@ var installService = &cobra.Command{ var uninstallService = &cobra.Command{ Use: "core-service", Short: "Uninstall Portmaster Core Windows Service", - RunE: uninstallWindowsService, + PersistentPreRunE: func(cmd *cobra.Command, args []string) error { + // non-nil dummy to override db flag requirement + return nil + }, + RunE: uninstallWindowsService, } func getExePath() (string, error) { @@ -75,12 +81,15 @@ func getExePath() (string, error) { return "", err } -func getServiceExecCommand(exePath string) string { - return fmt.Sprintf( - "%s run core-service --db %s --input-signals", +func getServiceExecCommand(exePath string) []string { + return []string{ windows.EscapeArg(exePath), + "run", + "core-service", + "--db", windows.EscapeArg(*databaseRootDir), - ) + "--input-signals", + } } func getServiceConfig(exePath string) mgr.Config { @@ -88,7 +97,7 @@ func getServiceConfig(exePath string) mgr.Config { ServiceType: windows.SERVICE_WIN32_OWN_PROCESS, StartType: mgr.StartAutomatic, ErrorControl: mgr.ErrorNormal, - BinaryPathName: getServiceExecCommand(exePath), + BinaryPathName: strings.Join(getServiceExecCommand(exePath), " "), DisplayName: "Portmaster Core", Description: "Portmaster Application Firewall - Core Service", } @@ -130,7 +139,8 @@ func installWindowsService(cmd *cobra.Command, args []string) error { s, err := m.OpenService(serviceName) if err != nil { // create service - s, err = m.CreateService(serviceName, getServiceExecCommand(exePath), getServiceConfig(exePath)) + cmd := getServiceExecCommand(exePath) + s, err = m.CreateService(serviceName, cmd[0], getServiceConfig(exePath), cmd[1:]...) if err != nil { return fmt.Errorf("failed to create service: %s", err) } @@ -152,9 +162,9 @@ func installWindowsService(cmd *cobra.Command, args []string) error { } if created { - fmt.Printf("%s created service %s\n", logPrefix, serviceName) + log.Printf("created service %s\n", serviceName) } else { - fmt.Printf("%s updated service %s\n", logPrefix, serviceName) + log.Printf("updated service %s\n", serviceName) } return nil @@ -181,6 +191,6 @@ func uninstallWindowsService(cmd *cobra.Command, args []string) error { return fmt.Errorf("failed to delete service: %s", err) } - fmt.Printf("%s uninstalled service %s\n", logPrefix, serviceName) + log.Printf("uninstalled service %s\n", serviceName) return nil } diff --git a/pmctl/lock.go b/pmctl/lock.go new file mode 100644 index 00000000..a5e34aa3 --- /dev/null +++ b/pmctl/lock.go @@ -0,0 +1,70 @@ +package main + +import ( + "fmt" + "io/ioutil" + "log" + "os" + "path/filepath" + "strconv" + "strings" + + processInfo "github.com/shirou/gopsutil/process" +) + +func checkAndCreateInstanceLock(name string) (pid int32, err error) { + lockFilePath := filepath.Join(*databaseRootDir, fmt.Sprintf("%s-lock.pid", name)) + + // read current pid file + data, err := ioutil.ReadFile(lockFilePath) + if err != nil { + if os.IsNotExist(err) { + // create new lock + return 0, createInstanceLock(lockFilePath) + } + return 0, err + } + + // file exists! + parsedPid, err := strconv.ParseInt(strings.TrimSpace(string(data)), 10, 64) + if err != nil { + log.Printf("failed to parse existing lock pid file (ignoring): %s\n", err) + return 0, createInstanceLock(lockFilePath) + } + + log.Printf("===== checking if PID %d exists\n", int32(parsedPid)) + + // check if process exists + p, err := processInfo.NewProcess(int32(parsedPid)) + if err == nil { + _, err = p.Name() + if err == nil { + // process exists + return p.Pid, nil + } + } + + // else create new lock + return 0, createInstanceLock(lockFilePath) +} + +func createInstanceLock(lockFilePath string) error { + // create database dir + err := os.MkdirAll(*databaseRootDir, 0777) + if err != nil { + log.Printf("failed to create base folder: %s\n", err) + } + + // create lock file + err = ioutil.WriteFile(lockFilePath, []byte(fmt.Sprintf("%d", os.Getpid())), 0666) + if err != nil { + return err + } + + return nil +} + +func deleteInstanceLock(name string) error { + lockFilePath := filepath.Join(*databaseRootDir, fmt.Sprintf("%s-lock.pid", name)) + return os.Remove(lockFilePath) +} diff --git a/pmctl/logs.go b/pmctl/logs.go new file mode 100644 index 00000000..acb24043 --- /dev/null +++ b/pmctl/logs.go @@ -0,0 +1,143 @@ +package main + +import ( + "fmt" + "log" + "os" + "path/filepath" + "runtime" + "runtime/pprof" + "time" + + "github.com/safing/portbase/container" + "github.com/safing/portbase/database/record" + "github.com/safing/portbase/formats/dsd" + "github.com/safing/portbase/info" + "github.com/safing/portmaster/updates" + "github.com/spf13/cobra" +) + +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 { + log.Printf("failed to create log file %s: %s\n", 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 { + log.Printf("failed to serialize header for log file %s: %s\n", 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 { + log.Printf("failed to write header for log file %s: %s\n", logFilePath, err) + finalizeLogFile(logFile, logFilePath) + return nil + } + + return logFile +} + +func finalizeLogFile(logFile *os.File, logFilePath string) { + err := logFile.Close() + if err != nil { + log.Printf("failed to close log file %s: %s\n", logFilePath, err) + } + + // check file size + stat, err := os.Stat(logFilePath) + if err == nil { + // delete if file is smaller than + if stat.Size() < 200 { // header + info is about 150 bytes + err := os.Remove(logFilePath) + if err != nil { + log.Printf("failed to delete empty log file %s: %s\n", logFilePath, err) + } + } + } +} + +func initControlLogFile() *os.File { + // create logging dir + logFileBasePath := filepath.Join(*databaseRootDir, "logs", "fstree", "control") + err := os.MkdirAll(logFileBasePath, 0777) + if err != nil { + log.Printf("failed to create log file folder %s: %s\n", logFileBasePath, err) + return nil + } + + // open log file + logFilePath := filepath.Join(logFileBasePath, fmt.Sprintf("%s.log", time.Now().UTC().Format("2006-02-01-15-04-05"))) + return initializeLogFile(logFilePath, "control/portmaster-control", updates.NewFile("", info.Version(), false)) +} + +func logControlError(cErr error) { + // check if error present + if cErr == nil { + return + } + + // create dir + logFileBasePath := filepath.Join(*databaseRootDir, "logs", "fstree", "control") + err := os.MkdirAll(logFileBasePath, 0777) + if err != nil { + log.Printf("failed to create log file folder %s: %s\n", logFileBasePath, err) + } + + // open log file + logFilePath := filepath.Join(logFileBasePath, fmt.Sprintf("%s.error.log", time.Now().UTC().Format("2006-02-01-15-04-05"))) + errorFile := initializeLogFile(logFilePath, "control/portmaster-control", updates.NewFile("", info.Version(), false)) + if errorFile == nil { + return + } + + // write error and close + fmt.Fprintln(errorFile, cErr.Error()) + errorFile.Close() +} + +func logControlStack() { + // create dir + logFileBasePath := filepath.Join(*databaseRootDir, "logs", "fstree", "control") + err := os.MkdirAll(logFileBasePath, 0777) + if err != nil { + log.Printf("failed to create log file folder %s: %s\n", logFileBasePath, err) + } + + // open log file + logFilePath := filepath.Join(logFileBasePath, fmt.Sprintf("%s.stack.log", time.Now().UTC().Format("2006-02-01-15-04-05"))) + errorFile := initializeLogFile(logFilePath, "control/portmaster-control", updates.NewFile("", info.Version(), false)) + if errorFile == nil { + return + } + + // write error and close + pprof.Lookup("goroutine").WriteTo(errorFile, 1) + errorFile.Close() +} + +func runAndLogControlError(wrappedFunc func(cmd *cobra.Command, args []string) error) func(cmd *cobra.Command, args []string) error { + return func(cmd *cobra.Command, args []string) error { + err := wrappedFunc(cmd, args) + if err != nil { + logControlError(err) + } + return err + } +} diff --git a/pmctl/main.go b/pmctl/main.go index df8283cb..dfcebaa1 100644 --- a/pmctl/main.go +++ b/pmctl/main.go @@ -2,31 +2,26 @@ package main import ( "errors" - "fmt" + "log" "os" "os/signal" - "path/filepath" "runtime" + "strings" "syscall" "github.com/safing/portbase/info" - "github.com/safing/portbase/log" + portlog "github.com/safing/portbase/log" "github.com/safing/portmaster/updates" "github.com/spf13/cobra" ) -const ( - logPrefix = "[control]" -) - var ( - updateStoragePath string - databaseRootDir *string + databaseRootDir *string rootCmd = &cobra.Command{ Use: "portmaster-control", Short: "contoller for all portmaster components", - PersistentPreRunE: initPmCtl, + PersistentPreRunE: cmdSetup, RunE: func(cmd *cobra.Command, args []string) error { return cmd.Help() }, @@ -47,20 +42,27 @@ func init() { func main() { var err error - // check if we are running in a console (try to attach to parent console if available) - runningInConsole, err = attachToParentConsole() - if err != nil { - fmt.Printf("failed to attach to parent console: %s\n", err) - os.Exit(1) - } + runtime.GOMAXPROCS(runtime.NumCPU()) // set meta info info.Set("Portmaster Control", "0.2.5", "AGPLv3", true) + // check if we are running in a console (try to attach to parent console if available) + runningInConsole, err = attachToParentConsole() + if err != nil { + log.Printf("failed to attach to parent console: %s\n", err) + os.Exit(1) + } + + // set up logging + log.SetFlags(log.Ldate | log.Ltime | log.LUTC) + log.SetPrefix("[control] ") + log.SetOutput(os.Stdout) + // check if meta info is ok err = info.CheckVersion() if err != nil { - fmt.Printf("%s compile error: please compile using the provided build script\n", logPrefix) + log.Println("compile error: please compile using the provided build script") os.Exit(1) } @@ -71,12 +73,12 @@ func main() { // warn about CTRL-C on windows if runningInConsole && runtime.GOOS == "windows" { - 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) + log.Println("WARNING: portmaster-control is marked as a GUI application in order to get rid of the console window.") + log.Println("WARNING: CTRL-C will immediately kill without clean shutdown.") } // not using portbase logger - log.SetLogLevel(log.CriticalLevel) + portlog.SetLogLevel(portlog.CriticalLevel) // for debugging // log.Start() @@ -107,22 +109,32 @@ func main() { os.Exit(0) }() + // for debugging windows service (no stdout/err) + // go func() { + // time.Sleep(10 * time.Second) + // // initiateShutdown(nil) + // // logControlStack() + // }() + // 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) + log.Printf("got %s signal (ignoring), waiting for child to exit...\n", sig) } else { - fmt.Printf("%s got %s signal, exiting... (not executing anything)\n", logPrefix, sig) + log.Printf("got %s signal, exiting... (not executing anything)\n", sig) os.Exit(0) } } } -func initPmCtl(cmd *cobra.Command, args []string) (err error) { +func cmdSetup(cmd *cobra.Command, args []string) (err error) { + // check for database root path // transform from db base path to updates path if *databaseRootDir != "" { + // remove redundant escape characters and quotes + *databaseRootDir = strings.Trim(*databaseRootDir, `\"`) + // set updates path updates.SetDatabaseRoot(*databaseRootDir) - updateStoragePath = filepath.Join(*databaseRootDir, "updates") } else { return errors.New("please supply the database directory using the --db flag") } diff --git a/pmctl/run.go b/pmctl/run.go index dbafd019..eca89d52 100644 --- a/pmctl/run.go +++ b/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) - // } - //} -} diff --git a/pmctl/service.go b/pmctl/service.go new file mode 100644 index 00000000..4a9130ca --- /dev/null +++ b/pmctl/service.go @@ -0,0 +1,31 @@ +package main + +import ( + "sync" +) + +var ( + startupComplete = make(chan struct{}) // signal that the start procedure completed (is never closed, just signaled once) + shuttingDown = make(chan struct{}) // signal that we are shutting down (will be closed, may not be closed directly, use initiateShutdown) + shutdownInitiated = false // not to be used directly + shutdownError error // may not be read or written to directly + shutdownLock sync.Mutex +) + +func initiateShutdown(err error) { + shutdownLock.Lock() + defer shutdownLock.Unlock() + + if !shutdownInitiated { + shutdownInitiated = true + shutdownError = err + close(shuttingDown) + } +} + +func getShutdownError() error { + shutdownLock.Lock() + defer shutdownLock.Unlock() + + return shutdownError +} diff --git a/pmctl/service_windows.go b/pmctl/service_windows.go index 36b6c7d8..4fb68bc6 100644 --- a/pmctl/service_windows.go +++ b/pmctl/service_windows.go @@ -7,6 +7,8 @@ package main import ( "fmt" + "log" + "sync" "time" "github.com/spf13/cobra" @@ -19,25 +21,23 @@ var ( runCoreService = &cobra.Command{ Use: "core-service", Short: "Run the Portmaster Core as a Windows Service", - RunE: func(cmd *cobra.Command, args []string) error { + RunE: runAndLogControlError(func(cmd *cobra.Command, args []string) error { return runService(cmd, &Options{ Identifier: "core/portmaster-core", AllowDownload: true, - AllowHidingWindow: true, + AllowHidingWindow: false, + NoOutput: true, }) - }, + }), FParseErrWhitelist: cobra.FParseErrWhitelist{ // UnknownFlags will ignore unknown flags errors and continue parsing rest of the flags UnknownFlags: true, }, } - // helpers for execution - runError chan error - runWrapper func() error - - // eventlog - eventlogger *eventlog.Log + // wait groups + runWg sync.WaitGroup + finishWg sync.WaitGroup ) func init() { @@ -52,102 +52,87 @@ func (ws *windowsService) Execute(args []string, changeRequests <-chan svc.Chang const cmdsAccepted = svc.AcceptStop | svc.AcceptShutdown changes <- svc.Status{State: svc.StartPending} - // start logic - var runError chan error - go func() { - runError <- runWrapper() - }() - - // poll for start completion - started := make(chan struct{}) - go func() { - for { - time.Sleep(10 * time.Millisecond) - if childIsRunning.IsSet() { - close(started) - return - } - } - }() - - // wait for start - select { - case err := <-runError: - // TODO: log error to windows - fmt.Printf("%s start error: %s", logPrefix, err) - eventlogger.Error(4, fmt.Sprintf("failed to start Portmaster Core: %s", err)) - changes <- svc.Status{State: svc.Stopped} - return false, 1 - case <-started: - // give some more time for enabling packet interception - time.Sleep(500 * time.Millisecond) - changes <- svc.Status{State: svc.Running, Accepts: cmdsAccepted} - fmt.Printf("%s startup complete, entered service running state\n", logPrefix) - } - - // wait for change requests -serviceLoop: +service: for { select { + case <-startupComplete: + changes <- svc.Status{State: svc.Running, Accepts: cmdsAccepted} case <-shuttingDown: - break serviceLoop + changes <- svc.Status{State: svc.StopPending} + break service case c := <-changeRequests: switch c.Cmd { case svc.Interrogate: changes <- c.CurrentStatus case svc.Stop, svc.Shutdown: - initiateShutdown() - break serviceLoop + initiateShutdown(nil) default: - fmt.Printf("%s unexpected control request: #%d\n", logPrefix, c) + log.Printf("unexpected control request: #%d\n", c) } } } - // signal that we are shutting down - changes <- svc.Status{State: svc.StopPending} - // wait for program to exit - <-programEnded - // signal shutdown complete + // define return values + if getShutdownError() != nil { + ssec = true // this error is specific to this service (ie. custom) + errno = 1 // generic error, check logs / windows events + } + + // wait until everything else is finished + finishWg.Wait() + // send stopped status changes <- svc.Status{State: svc.Stopped} + // wait a little for the status to reach Windows + time.Sleep(100 * time.Millisecond) return } func runService(cmd *cobra.Command, opts *Options) error { - // set run wrapper - runWrapper = func() error { - return run(cmd, opts) - } - // check if we are running interactively isDebug, err := svc.IsAnInteractiveSession() if err != nil { return fmt.Errorf("could not determine if running interactively: %s", err) } + // select service run type + svcRun := svc.Run + if isDebug { + log.Printf("WARNING: running interactively, switching to debug execution (no real service).\n") + svcRun = debug.Run + } // open eventlog - // TODO: do something useful with eventlog elog, err := eventlog.Open(serviceName) if err != nil { return fmt.Errorf("failed to open eventlog: %s", err) } defer elog.Close() - eventlogger = elog - elog.Info(1, fmt.Sprintf("starting %s service", serviceName)) - // select run method bas - run := svc.Run - if isDebug { - fmt.Printf("%s WARNING: running interactively, switching to debug execution (no real service).\n", logPrefix) - run = debug.Run - } - // run - err = run(serviceName, &windowsService{}) + runWg.Add(2) + finishWg.Add(1) + + // run service client + go func() { + sErr := svcRun(serviceName, &windowsService{}) + initiateShutdown(sErr) + runWg.Done() + }() + + // run service + go func() { + // run slightly delayed + time.Sleep(250 * time.Millisecond) + handleRun(cmd, opts) + finishWg.Done() + runWg.Done() + }() + + runWg.Wait() + + err = getShutdownError() if err != nil { - elog.Error(3, fmt.Sprintf("%s service failed: %v", serviceName, err)) - return fmt.Errorf("failed to start service: %s", err) + log.Printf("%s service experienced an error: %s\n", serviceName, err) + elog.Error(1, fmt.Sprintf("%s experienced an error: %s", serviceName, err)) } - elog.Info(2, fmt.Sprintf("%s service stopped", serviceName)) - return nil + return err } diff --git a/pmctl/show.go b/pmctl/show.go index 7e4b3396..277b27b9 100644 --- a/pmctl/show.go +++ b/pmctl/show.go @@ -2,6 +2,7 @@ package main import ( "fmt" + "log" "os" "strings" @@ -63,8 +64,6 @@ var showNotifier = &cobra.Command{ } func show(cmd *cobra.Command, opts *Options) error { - defer close(programEnded) - // get original arguments var args []string if len(os.Args) < 4 { @@ -82,8 +81,8 @@ func show(cmd *cobra.Command, opts *Options) error { return fmt.Errorf("could not get component: %s", err) } - fmt.Printf("%s command:\n", logPrefix) - fmt.Printf("%s %s\n", file.Path(), strings.Join(args, " ")) + log.Println("command:") + log.Printf("%s %s\n", file.Path(), strings.Join(args, " ")) return nil }