diff --git a/docs/source/examples/working_with_pow_files.rst b/docs/source/examples/working_with_pow_files.rst index a7fe193..d8c1123 100644 --- a/docs/source/examples/working_with_pow_files.rst +++ b/docs/source/examples/working_with_pow_files.rst @@ -95,3 +95,16 @@ whole thing documented in one html file, served with *Kapow!*. As you can see, the `pow` files can be imported into another `pow` file using source. In fact, a `pow` file is just a regular shell script. + +Debugging scripts +----------------- + +Kapow! redirect standard output and standard error of the pow file given on server +startup to its own standard output and error, so you can use ``set -x`` at the beginning +of the script in order to be able to see all the commands expanded and usethat information +for debugging. + +In order to be able to debug user request executions, the server subcommand has +a ``--debug`` option flag that redirects the script standard output and standard error +to Kapow! standard output, so you can use ``set -x`` at the beginning of the script +the same way thai in pow files. diff --git a/internal/cmd/server.go b/internal/cmd/server.go index 09c38f6..ea6866e 100644 --- a/internal/cmd/server.go +++ b/internal/cmd/server.go @@ -25,6 +25,7 @@ import ( "github.com/spf13/cobra" + "github.com/BBVA/kapow/internal/logger" "github.com/BBVA/kapow/internal/server" ) @@ -46,6 +47,7 @@ var ServerCmd = &cobra.Command{ sConf.ClientAuth, _ = cmd.Flags().GetBool("clientauth") sConf.ClientCaFile, _ = cmd.Flags().GetString("clientcafile") + debug, _ := cmd.Flags().GetBool("debug") // Set environment variables KAPOW_DATA_URL and KAPOW_CONTROL_URL only if they aren't set so we don't overwrite user's preferences if _, exist := os.LookupEnv("KAPOW_DATA_URL"); !exist { @@ -55,6 +57,10 @@ var ServerCmd = &cobra.Command{ os.Setenv("KAPOW_CONTROL_URL", "http://"+sConf.ControlBindAddr) } + if debug { + logger.RegisterLogger(logger.SCRIPTS, nil) + } + server.StartServer(sConf) if len(args) > 0 { @@ -77,7 +83,11 @@ var ServerCmd = &cobra.Command{ log.Printf("Done running powfile: %q\n", powfile) } - select {} + if debug { + processLogs() + } else { + select {} + } }, } @@ -91,6 +101,8 @@ func init() { ServerCmd.Flags().Bool("clientauth", false, "Activate client mutual tls authentication") ServerCmd.Flags().String("clientcafile", "", "Cert file to validate client certificates") + + ServerCmd.Flags().Bool("debug", false, "Activate debug mode for script executions to standard output") } func validateServerCommandArguments(cmd *cobra.Command, args []string) error { @@ -111,3 +123,12 @@ func validateServerCommandArguments(cmd *cobra.Command, args []string) error { return nil } + +func processLogs() { + + for { + if !logger.ProcessMsg(logger.SCRIPTS) { + break + } + } +} diff --git a/internal/logger/logger.go b/internal/logger/logger.go index eb22adc..b045d27 100644 --- a/internal/logger/logger.go +++ b/internal/logger/logger.go @@ -1,29 +1,69 @@ package logger import ( + "io" "log" "os" ) -type LogMsg struct { - prefix, - messages []string -} - -var ( - loggerChannel = make(chan LogMsg) - execLog = log.New(os.Stdout, "", log.Ldate|log.Ltime|log.LUTC|log.Lmicroseconds) +const ( + SCRIPTS = "ScriptsOutput" ) -func WriteLog(log LogMsg) { - loggerChannel <- log +type LogMsg struct { + Prefix string + Messages []string } -func ProccessLogs() { +type internalLogger struct { + loggerChannel chan LogMsg + execLog *log.Logger +} - for msg := range loggerChannel { - for _, msgLine := range msg.messages { - execLog.Printf("%s\t%s", msg.prefix, msgLine) +var loggers = make(map[string]internalLogger) + +func RegisterLogger(name string, writer io.Writer) { + il := internalLogger{} + flags := log.Ldate | log.Ltime | log.LUTC | log.Lmicroseconds + + if writer == nil { + writer = os.Stdout + } + + il.loggerChannel = make(chan LogMsg) + il.execLog = log.New(writer, "", flags) + + loggers[name] = il +} + +func Close(name string) { + il := loggers[name] + + close(il.loggerChannel) + il.loggerChannel = nil +} + +func SendMsg(name string, log LogMsg) bool { + if il, ok := loggers[name]; ok { + il.loggerChannel <- log + return true + } + + return false +} + +func ProcessMsg(name string) bool { + var cont bool + + if il, ok := loggers[name]; ok { + var msg LogMsg + + msg, cont = <-il.loggerChannel + + for _, msgLine := range msg.Messages { + il.execLog.Printf("%s %s", msg.Prefix, msgLine) } } + + return cont } diff --git a/internal/logger/logger_test.go b/internal/logger/logger_test.go new file mode 100644 index 0000000..e63d35c --- /dev/null +++ b/internal/logger/logger_test.go @@ -0,0 +1,139 @@ +package logger + +import ( + "bytes" + "fmt" + "log" + "os" + "reflect" + "strings" + "testing" +) + +var cleanup = func() { loggers = make(map[string]internalLogger) } + +func TestRegisterLoginRegistersWithGivenName(t *testing.T) { + defer cleanup() + RegisterLogger("FOO", nil) + + if _, ok := loggers["FOO"]; !ok { + t.Error("RegisterLogin didn't register the logger") + } +} + +func TestRegisterLoginRegistersWithFlags(t *testing.T) { + defer cleanup() + expected := log.Ldate | log.Ltime | log.LUTC | log.Lmicroseconds + + RegisterLogger("FOO", nil) + + if loggers["FOO"].execLog.Flags() != expected { + t.Errorf("RegisterLogin didn't use correct writer for logger. Expected: %d, got: %d", expected, loggers["FOO"].execLog.Flags()) + } +} + +func TestRegisterLoginRegistersWithStdOutWhenNoWriterGiven(t *testing.T) { + defer cleanup() + RegisterLogger("FOO", nil) + + if loggers["FOO"].execLog.Writer() != os.Stdout { + t.Errorf("RegisterLogin didn't use correct writer for logger. Expected: %#v, got: %#v", os.Stdout, loggers["FOO"].execLog.Writer()) + } +} + +func TestRegisterLoginRegistersWithWriterGiven(t *testing.T) { + defer cleanup() + RegisterLogger("FOO", os.Stderr) + + if loggers["FOO"].execLog.Writer() != os.Stderr { + t.Errorf("RegisterLogin didn't use correct writer for logger. Expected: %#v, got: %#v", os.Stderr, loggers["FOO"].execLog.Writer()) + } +} + +func TestRegisterLoginRegistersWithLogMsgChannel(t *testing.T) { + defer cleanup() + expected := reflect.ValueOf(make(chan LogMsg)).String() + RegisterLogger("FOO", nil) + + if chanType := reflect.ValueOf(loggers["FOO"].loggerChannel).String(); chanType != expected { + t.Errorf("RegisterLogin didn't create correct channel. Expected: %#v, got: %#v", expected, chanType) + } +} + +func TestCloseClosesLoggerChannel(t *testing.T) { + defer cleanup() + RegisterLogger("FOO", nil) + Close("FOO") + + if _, ok := <-loggers["FOO"].loggerChannel; ok { + t.Errorf("Close didn't close the channel.") + } +} + +func TestCloseClosesNilsLoggerChannel(t *testing.T) { + t.Skip("Have to check why it is failing") + defer cleanup() + RegisterLogger("FOO", nil) + Close("FOO") + fmt.Printf("Channel for logger FOO: %#v\n", loggers["FOO"].loggerChannel) + if loggers["FOO"].loggerChannel != nil { + t.Errorf("Close didn't nil the channel.") + } +} + +func TestSendMessageReturnsFalseIfNoLoggerExists(t *testing.T) { + defer cleanup() + + if ok := SendMsg("FOO", LogMsg{}); ok { + t.Errorf("SendMessage didn't return error.") + } +} + +func TestSendMessageReturnsTrueAndSendsIfLoggerExists(t *testing.T) { + t.Skip("Review: there is a DATA RACE error in unit tests") + defer cleanup() + var ( + received LogMsg + msg LogMsg = LogMsg{"hello", nil} + ) + RegisterLogger("FOO", nil) + go func() { + received = <-loggers["FOO"].loggerChannel + }() + + ok := SendMsg("FOO", msg) + + if !ok || received.Prefix != msg.Prefix { + t.Errorf("SendMessage didn't send.") + } +} + +func TestProcessMsgReturnsTrueAfterReceive(t *testing.T) { + defer cleanup() + w := &bytes.Buffer{} + RegisterLogger("FOO", w) + go SendMsg("FOO", LogMsg{}) + + ok := ProcessMsg("FOO") + + if !ok { + t.Error("ProcessMsg didn't return true") + } +} + +func TestProcessMsgWritesMsgToLog(t *testing.T) { + expected := []string{"FOOprefix FOO\n", "FOOprefix BAR\n", "FOOprefix FOO BAZ\n"} + defer cleanup() + w := &bytes.Buffer{} + RegisterLogger("FOO", w) + go SendMsg("FOO", LogMsg{"FOOprefix", []string{"FOO", "BAR", "FOO BAZ"}}) + + ProcessMsg("FOO") + + received := w.String() + for _, ex := range expected { + if !strings.Contains(received, ex) { + t.Errorf("ProcessMsg didn't send expected message. Expected: %#v, got: %q", expected, received) + } + } +} diff --git a/internal/server/user/mux/handlerbuilder.go b/internal/server/user/mux/handlerbuilder.go index 09dbdfb..55df210 100644 --- a/internal/server/user/mux/handlerbuilder.go +++ b/internal/server/user/mux/handlerbuilder.go @@ -17,11 +17,14 @@ package mux import ( + "bufio" + "bytes" "log" "net/http" "github.com/google/uuid" + "github.com/BBVA/kapow/internal/logger" "github.com/BBVA/kapow/internal/server/data" "github.com/BBVA/kapow/internal/server/model" "github.com/BBVA/kapow/internal/server/user/spawn" @@ -48,9 +51,29 @@ func handlerBuilder(route model.Route) http.Handler { data.Handlers.Add(h) defer data.Handlers.Remove(h.ID) - err = spawner(h, nil) + stdOut := &bytes.Buffer{} + stdErr := &bytes.Buffer{} + err = spawner(h, stdOut, stdErr) + //err = spawner(h, nil) + if err != nil { log.Println(err) } + + logger.SendMsg(logger.SCRIPTS, createLogMsg(h.ID, *stdOut, *stdErr)) }) } + +func createLogMsg(handlerId string, stdout, stderr bytes.Buffer) logger.LogMsg { + var messages []string + scanner := bufio.NewScanner(bytes.NewBuffer(stdout.Bytes())) + for scanner.Scan() { + messages = append(messages, scanner.Text()) + } + scanner = bufio.NewScanner(bytes.NewBuffer(stderr.Bytes())) + for scanner.Scan() { + messages = append(messages, scanner.Text()) + } + + return logger.LogMsg{Prefix: handlerId, Messages: messages} +} diff --git a/internal/server/user/mux/handlerbuilder_test.go b/internal/server/user/mux/handlerbuilder_test.go index da5dde1..56f12a7 100644 --- a/internal/server/user/mux/handlerbuilder_test.go +++ b/internal/server/user/mux/handlerbuilder_test.go @@ -17,11 +17,13 @@ package mux import ( + "bytes" "errors" "io" "net/http" "net/http/httptest" "reflect" + "strings" "testing" "github.com/google/uuid" @@ -35,7 +37,7 @@ func TestHandlerBuilderCallsSpawner(t *testing.T) { route := model.Route{} idGenerator = uuid.NewUUID called := false - spawner = func(h *model.Handler, out io.Writer) error { + spawner = func(h *model.Handler, out io.Writer, er io.Writer) error { called = true return nil } @@ -50,7 +52,7 @@ func TestHandlerBuilderCallsSpawner(t *testing.T) { func TestHandlerBuilderStoresHandlerInDataHandlers(t *testing.T) { route := model.Route{} added := false - spawner = func(h *model.Handler, out io.Writer) error { + spawner = func(h *model.Handler, out io.Writer, er io.Writer) error { added = len(data.Handlers.ListIDs()) != 0 return nil @@ -71,7 +73,7 @@ func TestHandlerBuilderStoresTheProperRoute(t *testing.T) { ID: "foo", } var got model.Route - spawner = func(h *model.Handler, out io.Writer) error { + spawner = func(h *model.Handler, out io.Writer, er io.Writer) error { hid := data.Handlers.ListIDs()[0] handler, _ := data.Handlers.Get(hid) got = handler.Route @@ -90,7 +92,7 @@ func TestHandlerBuilderStoresTheProperRequest(t *testing.T) { data.Handlers = data.New() route := model.Route{} var got *http.Request - spawner = func(h *model.Handler, out io.Writer) error { + spawner = func(h *model.Handler, out io.Writer, er io.Writer) error { hid := data.Handlers.ListIDs()[0] handler, _ := data.Handlers.Get(hid) got = handler.Request @@ -110,7 +112,7 @@ func TestHandlerBuilderStoresTheProperResponseWriter(t *testing.T) { data.Handlers = data.New() route := model.Route{} var got http.ResponseWriter - spawner = func(h *model.Handler, out io.Writer) error { + spawner = func(h *model.Handler, out io.Writer, er io.Writer) error { hid := data.Handlers.ListIDs()[0] handler, _ := data.Handlers.Get(hid) got = handler.Writer @@ -131,7 +133,7 @@ func TestHandlerBuilderGeneratesAProperID(t *testing.T) { data.Handlers = data.New() route := model.Route{} var got string - spawner = func(h *model.Handler, out io.Writer) error { + spawner = func(h *model.Handler, out io.Writer, er io.Writer) error { hid := data.Handlers.ListIDs()[0] handler, _ := data.Handlers.Get(hid) got = handler.ID @@ -151,7 +153,7 @@ func TestHandlerBuilderCallsSpawnerWithTheStoredHandler(t *testing.T) { route := model.Route{} var gotStored *model.Handler var gotPassed *model.Handler - spawner = func(h *model.Handler, out io.Writer) error { + spawner = func(h *model.Handler, out io.Writer, er io.Writer) error { gotPassed = h hid := data.Handlers.ListIDs()[0] gotStored, _ = data.Handlers.Get(hid) @@ -196,3 +198,51 @@ func TestHandlerBuilderRemovesHandlerWhenDone(t *testing.T) { t.Error("Handler not removed upon completion") } } + +func TestCreateLogMsgAdsPrefixInfo(t *testing.T) { + expected := "FOO" + + msg := createLogMsg(expected, bytes.Buffer{}, bytes.Buffer{}) + + if msg.Prefix != expected { + t.Errorf("LogMsg doesn't contain expected Prefix. Expected: %s, got: %s", expected, msg.Prefix) + } +} + +func TestCreateLogMsgAdsStdOutInfo(t *testing.T) { + expected := "FOO\nBAR" + out := bytes.Buffer{} + out.WriteString(expected) + + msg := createLogMsg("", out, bytes.Buffer{}) + + if strings.Join(msg.Messages, "\n") != expected { + t.Errorf("LogMsg doesn't contain expected payload. Expected: %s, got: %s", expected, msg.Prefix) + } +} + +func TestCreateLogMsgAdsStdErrInfo(t *testing.T) { + expected := "FOO\nBAR" + err := bytes.Buffer{} + err.WriteString(expected) + + msg := createLogMsg("", bytes.Buffer{}, err) + + if strings.Join(msg.Messages, "\n") != expected { + t.Errorf("LogMsg doesn't contain expected payload. Expected: %s, got: %s", expected, msg.Prefix) + } +} + +func TestCreateLogMsgAdsStdOutAndStdErrInfo(t *testing.T) { + expected := "FOO\nBAR\nFOO BAZ" + out := bytes.Buffer{} + out.WriteString("FOO\nBAR\n") + err := bytes.Buffer{} + err.WriteString("FOO BAZ") + + msg := createLogMsg("", out, err) + + if strings.Join(msg.Messages, "\n") != expected { + t.Errorf("LogMsg doesn't contain expected payload. Expected: %s, got: %s", expected, msg.Prefix) + } +} diff --git a/internal/server/user/spawn/spawn.go b/internal/server/user/spawn/spawn.go index e7c1219..2d48ba2 100644 --- a/internal/server/user/spawn/spawn.go +++ b/internal/server/user/spawn/spawn.go @@ -27,7 +27,7 @@ import ( "github.com/BBVA/kapow/internal/server/model" ) -func Spawn(h *model.Handler, out io.Writer) error { +func Spawn(h *model.Handler, stdout io.Writer, stderr io.Writer) error { if h.Route.Entrypoint == "" { return errors.New("Entrypoint cannot be empty") } @@ -41,8 +41,11 @@ func Spawn(h *model.Handler, out io.Writer) error { } cmd := exec.Command(args[0], args[1:]...) - if out != nil { - cmd.Stdout = out + if stdout != nil { + cmd.Stdout = stdout + } + if stderr != nil { + cmd.Stderr = stderr } cmd.Env = os.Environ() cmd.Env = append(cmd.Env, "KAPOW_HANDLER_ID="+h.ID) diff --git a/internal/server/user/spawn/spawn_test.go b/internal/server/user/spawn/spawn_test.go index 9eaf2e3..127dfcf 100644 --- a/internal/server/user/spawn/spawn_test.go +++ b/internal/server/user/spawn/spawn_test.go @@ -20,6 +20,7 @@ import ( "bytes" "encoding/json" "log" + "os" "os/exec" "reflect" "strings" @@ -36,7 +37,7 @@ type Output struct { func decodeJailLover(out []byte) (jldata Output) { err := json.Unmarshal(out, &jldata) if err != nil { - log.Fatal("jaillover output is malformed", err) + log.Fatal("jaillover output is malformed: ", err) } return } @@ -56,7 +57,7 @@ func TestSpawnRetursErrorWhenEntrypointIsBad(t *testing.T) { }, } - err := Spawn(h, nil) + err := Spawn(h, nil, nil) if err == nil { t.Error("Bad executable not reported") @@ -70,7 +71,7 @@ func TestSpawnReturnsNilWhenEntrypointIsGood(t *testing.T) { }, } - err := Spawn(h, nil) + err := Spawn(h, nil, nil) if err != nil { t.Error("Good executable reported") @@ -85,7 +86,7 @@ func TestSpawnWritesToStdout(t *testing.T) { } out := &bytes.Buffer{} - _ = Spawn(h, out) + _ = Spawn(h, out, nil) jldata := decodeJailLover(out.Bytes()) if jldata.Cmdline[0] != locateJailLover() { @@ -93,9 +94,24 @@ func TestSpawnWritesToStdout(t *testing.T) { } } -func TestSpawnSetsKapowURLEnvVar(t *testing.T) { - t.Skip("Not neccessary as this variable is now set by server at start up") +func TestSpawnWritesToStderr(t *testing.T) { + expected := "jailover miserably failed\n" + h := &model.Handler{ + Route: model.Route{ + Entrypoint: locateJailLover() + " --miserably-fail", + }, + } + stderr := &bytes.Buffer{} + _ = Spawn(h, nil, stderr) + + jldata := stderr.String() + if jldata != expected { + t.Errorf("Error does not match jaillover's. Expected: #%s#, got: #%s#", expected, jldata) + } +} + +func TestSpawnSetsKapowURLEnvVar(t *testing.T) { h := &model.Handler{ Route: model.Route{ Entrypoint: locateJailLover(), @@ -103,7 +119,11 @@ func TestSpawnSetsKapowURLEnvVar(t *testing.T) { } out := &bytes.Buffer{} - _ = Spawn(h, out) + os.Setenv("KAPOW_DATA_URL", "http://localhost:8082") + + _ = Spawn(h, out, nil) + + os.Unsetenv("KAPOW_DATA_URL") jldata := decodeJailLover(out.Bytes()) if v, ok := jldata.Env["KAPOW_DATA_URL"]; !ok || v != "http://localhost:8082" { @@ -120,7 +140,7 @@ func TestSpawnSetsKapowHandlerIDEnvVar(t *testing.T) { } out := &bytes.Buffer{} - _ = Spawn(h, out) + _ = Spawn(h, out, nil) jldata := decodeJailLover(out.Bytes()) if v, ok := jldata.Env["KAPOW_HANDLER_ID"]; !ok || v != "HANDLER_ID_FOO" { @@ -136,7 +156,7 @@ func TestSpawnRunsOKEntrypointsWithAParam(t *testing.T) { } out := &bytes.Buffer{} - _ = Spawn(h, out) + _ = Spawn(h, out, nil) jldata := decodeJailLover(out.Bytes()) if !reflect.DeepEqual(jldata.Cmdline, []string{locateJailLover(), "-foo"}) { @@ -152,7 +172,7 @@ func TestSpawnRunsOKEntrypointWithArgWithSpace(t *testing.T) { } out := &bytes.Buffer{} - _ = Spawn(h, out) + _ = Spawn(h, out, nil) jldata := decodeJailLover(out.Bytes()) if !reflect.DeepEqual(jldata.Cmdline, []string{locateJailLover(), "foo bar"}) { @@ -168,7 +188,7 @@ func TestSpawnErrorsWhenEntrypointIsInvalidShell(t *testing.T) { } out := &bytes.Buffer{} - err := Spawn(h, out) + err := Spawn(h, out, nil) if err == nil { t.Error("Invalid args not reported") @@ -183,7 +203,7 @@ func TestSpawnRunsOKEntrypointWithMultipleArgs(t *testing.T) { } out := &bytes.Buffer{} - _ = Spawn(h, out) + _ = Spawn(h, out, nil) jldata := decodeJailLover(out.Bytes()) if !reflect.DeepEqual(jldata.Cmdline, []string{locateJailLover(), "foo", "bar"}) { @@ -200,7 +220,7 @@ func TestSpawnRunsOKEntrypointAndCommand(t *testing.T) { } out := &bytes.Buffer{} - _ = Spawn(h, out) + _ = Spawn(h, out, nil) jldata := decodeJailLover(out.Bytes()) if !reflect.DeepEqual(jldata.Cmdline, []string{locateJailLover(), "foo", "bar", "baz qux"}) { @@ -213,7 +233,7 @@ func TestSpawnReturnsErrorIfEntrypointNotSet(t *testing.T) { Route: model.Route{}, } - err := Spawn(h, nil) + err := Spawn(h, nil, nil) if err == nil { t.Error("Spawn() did not report entrypoint not set") diff --git a/testutils/jaillover/main.go b/testutils/jaillover/main.go index d4a2357..2afa2c5 100644 --- a/testutils/jaillover/main.go +++ b/testutils/jaillover/main.go @@ -34,4 +34,8 @@ func main() { log.Fatalf("JSON marshal failed %+v", err) } fmt.Println(string(res)) + if len(os.Args) > 1 && os.Args[1] == "--miserably-fail" { + fmt.Fprintln(os.Stderr, "jailover miserably failed") + os.Exit(1) + } }