From 636c748328b191b09266c2ce9b72b6ebc90e1a4c Mon Sep 17 00:00:00 2001 From: Daniel Date: Thu, 18 Jul 2019 16:15:16 +0200 Subject: [PATCH] Add logging to file, improve windows console handling --- Gopkg.lock | 16 +- Gopkg.toml | 4 - .../{console_linux.go => console_default.go} | 2 + pmctl/main.go | 65 +++- pmctl/run.go | 344 +++++++++++++----- 5 files changed, 302 insertions(+), 129 deletions(-) rename pmctl/{console_linux.go => console_default.go} (87%) diff --git a/Gopkg.lock b/Gopkg.lock index 68febc82..74c0b71c 100644 --- a/Gopkg.lock +++ b/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 diff --git a/Gopkg.toml b/Gopkg.toml index d398ae51..6ada84bf 100644 --- a/Gopkg.toml +++ b/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" diff --git a/pmctl/console_linux.go b/pmctl/console_default.go similarity index 87% rename from pmctl/console_linux.go rename to pmctl/console_default.go index 471e100a..7f2fc446 100644 --- a/pmctl/console_linux.go +++ b/pmctl/console_default.go @@ -1,3 +1,5 @@ +// +build !windows + package main import "os/exec" diff --git a/pmctl/main.go b/pmctl/main.go index f7950f3a..df8283cb 100644 --- a/pmctl/main.go +++ b/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 - if err = rootCmd.Execute(); err != nil { - os.Exit(1) + // 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) + } + + // 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) { diff --git a/pmctl/run.go b/pmctl/run.go index 6f817067..6b5a8844 100644 --- a/pmctl/run.go +++ b/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) } - - // check permission - 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 !tryAgain { + break } - - fmt.Printf("%s starting %s %s\n", logPrefix, file.Path(), strings.Join(args, " ")) - - // 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) + if tries >= 5 { + fmt.Printf("%s error seems to be permanent, giving up...\n", logPrefix) + return err } - - // 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 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) { + 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) + // } + //} +}