Merge pull request #109 from BBVA/feature-script-debugging

Feature script debugging
This commit is contained in:
César Gallego Rodríguez
2020-04-21 11:11:14 +02:00
committed by GitHub
10 changed files with 361 additions and 40 deletions
+8
View File
@@ -24,3 +24,11 @@ Calling with :program:`curl`:
$ curl -v http://localhost:8080/parallel/10.0.0.1/10.10.10.1
Script debugging
----------------
Bash provides the ``set -x`` builtin command that "After expanding each simple command,
for command, case command, select command, or arithmetic for command, display the
expanded value of PS4, followed by the command and its expanded arguments or associated
word list". This feature can be used to help debugging the `.pow` scripts and, together
the ``--debug`` option in the server sub-command, the scripts executed in user requests.
@@ -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 as in pow files.
+22 -1
View File
@@ -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
}
}
}
+54 -14
View File
@@ -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
}
+139
View File
@@ -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)
}
}
}
+24 -1
View File
@@ -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}
}
@@ -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)
}
}
+6 -3
View File
@@ -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)
+34 -14
View File
@@ -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")
+4
View File
@@ -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)
}
}