Merge pull request #833 from cheesedosa/redirect-console

Redirect console to a file.

cmd/archive.go

@@ -75,7 +75,10 @@ An archive is a fully self-contained test run, and can be executed identically e
 			return err
 		}
 
-		r.SetOptions(conf.Options)
+		err = r.SetOptions(conf.Options)
+		if err != nil {
+			return err
+		}
 
 		// Archive.
 		arc := r.MakeArchive()

cmd/cloud.go

@@ -93,7 +93,10 @@ This will execute the test on the Load Impact cloud service. Use "k6 login cloud
 			return err
 		}
 
-		r.SetOptions(conf.Options)
+		err = r.SetOptions(conf.Options)
+		if err != nil {
+			return err
+		}
 
 		// Cloud config
 		cloudConfig := cloud.NewConfig().Apply(conf.Collectors.Cloud)

cmd/options.go

@@ -67,6 +67,7 @@ func optionFlagSet() *pflag.FlagSet {
 	flags.String("summary-time-unit", "", "define the time unit used to display the trend stats. Possible units are: 's', 'ms' and 'us'")
 	flags.StringSlice("system-tags", lib.DefaultSystemTagList, "only include these system tags in metrics")
 	flags.StringSlice("tag", nil, "add a `tag` to be applied to all samples, as `[name]=[value]`")
+	flags.String("console-output", "", "redirects the console logging to the provided output file")
 	flags.Bool("discard-response-bodies", false, "Read but don't process or save HTTP response bodies")
 	return flags
 }
@@ -174,6 +175,15 @@ func getOptions(flags *pflag.FlagSet) (lib.Options, error) {
 		opts.RunTags = stats.IntoSampleTags(&parsedRunTags)
 	}
 
+	redirectConFile, err := flags.GetString("console-output")
+	if err != nil {
+		return opts, err
+	}
+
+	if redirectConFile != "" {
+		opts.ConsoleOutput = null.StringFrom(redirectConFile)
+	}
+
 	return opts, nil
 }
 

cmd/run.go

@@ -171,7 +171,9 @@ a commandline interface for interacting with it.`,
 		}
 
 		// Write options back to the runner too.
-		r.SetOptions(conf.Options)
+		if err = r.SetOptions(conf.Options); err != nil {
+			return err
+		}
 
 		// Create a local executor wrapping the runner.
 		fprintf(stdout, "%s executor\r", initBar.String())

js/console.go

@@ -22,21 +22,37 @@ package js
 
 import (
 	"context"
+	"os"
 	"strconv"
 
 	"github.com/dop251/goja"
 	log "github.com/sirupsen/logrus"
 )
 
-type Console struct {
+// console represents a JS console implemented as a logrus.Logger.
+type console struct {
 	Logger *log.Logger
 }
 
-func NewConsole() *Console {
-	return &Console{log.StandardLogger()}
+// Creates a console with the standard logrus logger.
+func newConsole() *console {
+	return &console{log.StandardLogger()}
 }
 
-func (c Console) log(ctx *context.Context, level log.Level, msgobj goja.Value, args ...goja.Value) {
+// Creates a console logger with its output set to the file at the provided `filepath`.
+func newFileConsole(filepath string) (*console, error) {
+	f, err := os.OpenFile(filepath, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0644)
+	if err != nil {
+		return nil, err
+	}
+
+	l := log.New()
+	l.SetOutput(f)
+
+	return &console{l}, nil
+}
+
+func (c console) log(ctx *context.Context, level log.Level, msgobj goja.Value, args ...goja.Value) {
 	if ctx != nil && *ctx != nil {
 		select {
 		case <-(*ctx).Done():
@@ -63,22 +79,22 @@ func (c Console) log(ctx *context.Context, level log.Level, msgobj goja.Value, a
 	}
 }
 
-func (c Console) Log(ctx *context.Context, msg goja.Value, args ...goja.Value) {
+func (c console) Log(ctx *context.Context, msg goja.Value, args ...goja.Value) {
 	c.Info(ctx, msg, args...)
 }
 
-func (c Console) Debug(ctx *context.Context, msg goja.Value, args ...goja.Value) {
+func (c console) Debug(ctx *context.Context, msg goja.Value, args ...goja.Value) {
 	c.log(ctx, log.DebugLevel, msg, args...)
 }
 
-func (c Console) Info(ctx *context.Context, msg goja.Value, args ...goja.Value) {
+func (c console) Info(ctx *context.Context, msg goja.Value, args ...goja.Value) {
 	c.log(ctx, log.InfoLevel, msg, args...)
 }
 
-func (c Console) Warn(ctx *context.Context, msg goja.Value, args ...goja.Value) {
+func (c console) Warn(ctx *context.Context, msg goja.Value, args ...goja.Value) {
 	c.log(ctx, log.WarnLevel, msg, args...)
 }
 
-func (c Console) Error(ctx *context.Context, msg goja.Value, args ...goja.Value) {
+func (c console) Error(ctx *context.Context, msg goja.Value, args ...goja.Value) {
 	c.log(ctx, log.ErrorLevel, msg, args...)
 }

js/console_test.go

@@ -23,8 +23,12 @@ package js
 import (
 	"context"
 	"fmt"
+	"io/ioutil"
+	"os"
 	"testing"
 
+	"gopkg.in/guregu/null.v3"
+
 	"github.com/dop251/goja"
 	"github.com/loadimpact/k6/js/common"
 	"github.com/loadimpact/k6/lib"
@@ -41,7 +45,7 @@ func TestConsoleContext(t *testing.T) {
 
 	ctxPtr := new(context.Context)
 	logger, hook := logtest.NewNullLogger()
-	rt.Set("console", common.Bind(rt, &Console{logger}, ctxPtr))
+	rt.Set("console", common.Bind(rt, &console{logger}, ctxPtr))
 
 	_, err := common.RunString(rt, `console.log("a")`)
 	assert.NoError(t, err)
@@ -122,3 +126,85 @@ func TestConsole(t *testing.T) {
 		})
 	}
 }
+
+func TestFileConsole(t *testing.T) {
+	logFile := "/tmp/loadtest.log"
+	levels := map[string]log.Level{
+		"log":   log.InfoLevel,
+		"debug": log.DebugLevel,
+		"info":  log.InfoLevel,
+		"warn":  log.WarnLevel,
+		"error": log.ErrorLevel,
+	}
+	argsets := map[string]struct {
+		Message string
+		Data    log.Fields
+	}{
+		`"string"`:         {Message: "string"},
+		`"string","a","b"`: {Message: "string", Data: log.Fields{"0": "a", "1": "b"}},
+		`"string",1,2`:     {Message: "string", Data: log.Fields{"0": "1", "1": "2"}},
+		`{}`:               {Message: "[object Object]"},
+	}
+	for name, level := range levels {
+		t.Run(name, func(t *testing.T) {
+			for args, result := range argsets {
+				t.Run(args, func(t *testing.T) {
+					r, err := New(&lib.SourceData{
+						Filename: "/script",
+						Data: []byte(fmt.Sprintf(
+							`export default function() { console.%s(%s); }`,
+							name, args,
+						)),
+					}, afero.NewMemMapFs(), lib.RuntimeOptions{})
+					assert.NoError(t, err)
+
+					err = r.SetOptions(lib.Options{
+						ConsoleOutput: null.StringFrom(logFile),
+					})
+					assert.NoError(t, err)
+
+					samples := make(chan stats.SampleContainer, 100)
+					vu, err := r.newVU(samples)
+					assert.NoError(t, err)
+
+					vu.Console.Logger.Level = log.DebugLevel
+					hook := logtest.NewLocal(vu.Console.Logger)
+
+					err = vu.RunOnce(context.Background())
+					assert.NoError(t, err)
+
+					// Test if the file was created.
+					_, err = os.Stat(logFile)
+					assert.NoError(t, err)
+
+					entry := hook.LastEntry()
+					if assert.NotNil(t, entry, "nothing logged") {
+						assert.Equal(t, level, entry.Level)
+						assert.Equal(t, result.Message, entry.Message)
+
+						data := result.Data
+						if data == nil {
+							data = make(log.Fields)
+						}
+						assert.Equal(t, data, entry.Data)
+
+						// Test if what we logged to the hook is the same as what we logged
+						// to the file.
+						entryStr, err := entry.String()
+						assert.NoError(t, err)
+
+						f, err := os.Open(logFile)
+						assert.NoError(t, err)
+
+						fileContent, err := ioutil.ReadAll(f)
+						assert.NoError(t, err)
+
+						assert.Equal(t, entryStr, string(fileContent))
+					}
+
+					os.Remove(logFile)
+				})
+			}
+		})
+	}
+}

js/runner.go

@@ -58,6 +58,7 @@ type Runner struct {
 	Resolver   *dnscache.Resolver
 	RPSLimit   *rate.Limiter
 
+	console   *console
 	setupData []byte
 }
 
@@ -92,10 +93,12 @@ func NewFromBundle(b *Bundle) (*Runner, error) {
 			KeepAlive: 30 * time.Second,
 			DualStack: true,
 		},
+		console:  newConsole(),
 		Resolver: dnscache.New(0),
 	}
-	r.SetOptions(r.Bundle.Options)
-	return r, nil
+
+	err = r.SetOptions(r.Bundle.Options)
+	return r, err
 }
 
 func (r *Runner) MakeArchive() *lib.Archive {
@@ -179,7 +182,7 @@ func (r *Runner) newVU(samplesOut chan<- stats.SampleContainer) (*VU, error) {
 		Dialer:         dialer,
 		CookieJar:      cookieJar,
 		TLSConfig:      tlsConfig,
-		Console:        NewConsole(),
+		Console:        r.console,
 		BPool:          bpool.NewBufferPool(100),
 		Samples:        samplesOut,
 	}
@@ -260,13 +263,24 @@ func (r *Runner) GetOptions() lib.Options {
 	return r.Bundle.Options
 }
 
-func (r *Runner) SetOptions(opts lib.Options) {
+func (r *Runner) SetOptions(opts lib.Options) error {
 	r.Bundle.Options = opts
 
 	r.RPSLimit = nil
 	if rps := opts.RPS; rps.Valid {
 		r.RPSLimit = rate.NewLimiter(rate.Limit(rps.Int64), 1)
 	}
+
+	if consoleOutputFile := opts.ConsoleOutput; consoleOutputFile.Valid {
+		c, err := newFileConsole(consoleOutputFile.String)
+		if err != nil {
+			return err
+		}
+
+		r.console = c
+	}
+
+	return nil
 }
 
 // Runs an exported function in its own temporary VU, optionally with an argument. Execution is
@@ -322,7 +336,7 @@ type VU struct {
 	ID        int64
 	Iteration int64
 
-	Console *Console
+	Console *console
 	BPool   *bpool.BufferPool
 
 	Samples chan<- stats.SampleContainer

lib/options.go

@@ -272,6 +272,9 @@ type Options struct {
 
 	// Discard Http Responses Body
 	DiscardResponseBodies null.Bool `json:"discardResponseBodies" envconfig:"discard_response_bodies"`
+
+	// Redirect console logging to a file
+	ConsoleOutput null.String `json:"-" envconfig:"console_output"`
 }
 
 // Returns the result of overwriting any fields with any that are set on the argument.
@@ -385,6 +388,10 @@ func (o Options) Apply(opts Options) Options {
 	if opts.DiscardResponseBodies.Valid {
 		o.DiscardResponseBodies = opts.DiscardResponseBodies
 	}
+	if opts.ConsoleOutput.Valid {
+		o.ConsoleOutput = opts.ConsoleOutput
+	}
+
 	return o
 }
 

lib/runner.go

@@ -65,7 +65,7 @@ type Runner interface {
 	// `export let options = {}`); cmd/run.go will mix this in with CLI-, config- and env-provided
 	// values and write it back to the runner.
 	GetOptions() Options
-	SetOptions(opts Options)
+	SetOptions(opts Options) error
 }
 
 // A VU is a Virtual User, that can be scheduled by an Executor.
@@ -138,8 +138,9 @@ func (r MiniRunner) GetOptions() Options {
 	return r.Options
 }
 
-func (r *MiniRunner) SetOptions(opts Options) {
+func (r *MiniRunner) SetOptions(opts Options) error {
 	r.Options = opts
+	return nil
 }
 
 // A VU spawned by a MiniRunner.