Added stderr output management to jaillover.

Added Spawn support for stderr redirection.
Added --debug option to server cmd.
Added debug information to documentation.
Finnished script logger.

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
+		}
+	}
+}

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
 }

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)
+		}
+	}
+}

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}
+}

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)
+	}
+}

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)

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")