Merge pull request #620 from grafana/add/log-default-opts-override

Log when a launch option is set to null

Author: inancgumus

chromium/browser_type.go

@@ -8,7 +8,6 @@ import (
 	"os"
 	"os/exec"
 	"path/filepath"
-	"regexp"
 	"runtime"
 	"sort"
 	"strings"
@@ -42,6 +41,7 @@ type BrowserType struct {
 	execPath  string       // path to the Chromium executable
 	storage   *storage.Dir // stores temporary data for the extension and user
 	randSrc   *rand.Rand
+	logger    *log.Logger
 }
 
 // NewBrowserType registers our custom k6 metrics, creates method mappings on
@@ -126,8 +126,14 @@ func (b *BrowserType) initContext() context.Context {
 // which can be used for controlling the Chrome browser.
 func (b *BrowserType) Launch(opts goja.Value) api.Browser {
 	ctx := b.initContext()
+
+	var err error
+	if b.logger, err = makeLogger(ctx); err != nil {
+		k6ext.Panic(ctx, "setting up logger: %w", err)
+	}
+
 	launchOpts := common.NewLaunchOptions()
-	if err := launchOpts.Parse(ctx, opts); err != nil {
+	if err := launchOpts.Parse(ctx, opts, b.logger); err != nil {
 		k6ext.Panic(ctx, "parsing launch options: %w", err)
 	}
 	ctx = common.WithLaunchOptions(ctx, launchOpts)
@@ -145,16 +151,17 @@ func (b *BrowserType) Launch(opts goja.Value) api.Browser {
 }
 
 func (b *BrowserType) launch(ctx context.Context, opts *common.LaunchOptions) (*common.Browser, error) {
+	if err := b.logger.SetCategoryFilter(opts.LogCategoryFilter); err != nil {
+		return nil, fmt.Errorf("%w", err)
+	}
+	if opts.Debug {
+		_ = b.logger.SetLevel("debug")
+	}
+
 	envs := make([]string, 0, len(opts.Env))
 	for k, v := range opts.Env {
 		envs = append(envs, fmt.Sprintf("%s=%s", k, v))
 	}
-
-	logger, err := makeLogger(ctx, opts)
-	if err != nil {
-		return nil, fmt.Errorf("setting up logger: %w", err)
-	}
-
 	var (
 		flags   = prepareFlags(opts, &(b.vu.State()).Options)
 		dataDir = b.storage
@@ -167,7 +174,7 @@ func (b *BrowserType) launch(ctx context.Context, opts *common.LaunchOptions) (*
 	go func(c context.Context) {
 		defer func() {
 			if err := dataDir.Cleanup(); err != nil {
-				logger.Errorf("BrowserType:Launch", "cleaning up the user data directory: %v", err)
+				b.logger.Errorf("BrowserType:Launch", "cleaning up the user data directory: %v", err)
 			}
 		}()
 		// There's a small chance that this might be called
@@ -178,12 +185,12 @@ func (b *BrowserType) launch(ctx context.Context, opts *common.LaunchOptions) (*
 		<-c.Done()
 	}(ctx)
 
-	browserProc, err := b.allocate(ctx, opts, flags, envs, dataDir, logger)
+	browserProc, err := b.allocate(ctx, opts, flags, envs, dataDir, b.logger)
 	if browserProc == nil {
 		return nil, fmt.Errorf("launching browser: %w", err)
 	}
 
-	browserProc.AttachLogger(logger)
+	browserProc.AttachLogger(b.logger)
 
 	// If this context is cancelled we'll initiate an extension wide
 	// cancellation and shutdown.
@@ -194,7 +201,7 @@ func (b *BrowserType) launch(ctx context.Context, opts *common.LaunchOptions) (*
 	browserCtx = k6ext.WithProcessID(browserCtx, browserProc.Pid())
 	b.Ctx = browserCtx
 	browser, err := common.NewBrowser(browserCtx, browserCtxCancel,
-		browserProc, opts, logger)
+		browserProc, opts, b.logger)
 	if err != nil {
 		return nil, fmt.Errorf("launching browser: %w", err)
 	}
@@ -371,17 +378,11 @@ func setFlagsFromK6Options(flags map[string]any, k6opts *k6lib.Options) {
 }
 
 // makeLogger makes and returns an extension wide logger.
-func makeLogger(ctx context.Context, launchOpts *common.LaunchOptions) (*log.Logger, error) {
+func makeLogger(ctx context.Context) (*log.Logger, error) {
 	var (
-		k6Logger            = k6ext.GetVU(ctx).State().Logger
-		reCategoryFilter, _ = regexp.Compile(launchOpts.LogCategoryFilter)
-		logger              = log.New(k6Logger, common.GetIterationID(ctx), launchOpts.Debug, reCategoryFilter)
+		k6Logger = k6ext.GetVU(ctx).State().Logger
+		logger   = log.New(k6Logger, common.GetIterationID(ctx))
 	)
-
-	// set the log level from the launch options (usually from a script's options).
-	if launchOpts.Debug {
-		_ = logger.SetLevel("debug")
-	}
 	if el, ok := os.LookupEnv("XK6_BROWSER_LOG"); ok {
 		if logger.SetLevel(el) != nil {
 			return nil, fmt.Errorf(

common/browser_options.go

@@ -8,6 +8,7 @@ import (
 	"github.com/dop251/goja"
 
 	"github.com/grafana/xk6-browser/k6ext"
+	"github.com/grafana/xk6-browser/log"
 )
 
 // ProxyOptions allows configuring a proxy server.
@@ -41,28 +42,36 @@ type LaunchPersistentContextOptions struct {
 
 // NewLaunchOptions returns a new LaunchOptions.
 func NewLaunchOptions() *LaunchOptions {
-	launchOpts := LaunchOptions{
+	return &LaunchOptions{
 		Env:               make(map[string]string),
 		Headless:          true,
 		LogCategoryFilter: ".*",
 		Timeout:           DefaultTimeout,
 	}
-	return &launchOpts
 }
 
 // Parse parses launch options from a JS object.
-func (l *LaunchOptions) Parse(ctx context.Context, opts goja.Value) error { //nolint:cyclop
+func (l *LaunchOptions) Parse(ctx context.Context, opts goja.Value, logger *log.Logger) error { //nolint:cyclop
 	if !gojaValueExists(opts) {
 		return errors.New("LaunchOptions does not exist in the runtime")
 	}
 	var (
-		rt = k6ext.Runtime(ctx)
-		o  = opts.ToObject(rt)
+		rt       = k6ext.Runtime(ctx)
+		o        = opts.ToObject(rt)
+		defaults = map[string]any{
+			"env":               l.Env,
+			"headless":          l.Headless,
+			"logCategoryFilter": l.LogCategoryFilter,
+			"timeout":           l.Timeout,
+		}
 	)
 	for _, k := range o.Keys() {
 		v := o.Get(k)
 		if v.Export() == nil {
-			continue // don't override the defaults on `null``
+			if dv, ok := defaults[k]; ok {
+				logger.Warnf("LaunchOptions", "%s was null and set to its default: %v", k, dv)
+			}
+			continue
 		}
 		var err error
 		switch k {

common/browser_options_test.go

@@ -8,6 +8,7 @@ import (
 	"github.com/stretchr/testify/require"
 
 	"github.com/grafana/xk6-browser/k6ext/k6test"
+	"github.com/grafana/xk6-browser/log"
 )
 
 func TestBrowserLaunchOptionsParse(t *testing.T) {
@@ -213,7 +214,7 @@ func TestBrowserLaunchOptionsParse(t *testing.T) {
 				vu = k6test.NewVU(t)
 				lo = NewLaunchOptions()
 			)
-			err := lo.Parse(vu.Context(), vu.ToGojaValue(tt.opts))
+			err := lo.Parse(vu.Context(), vu.ToGojaValue(tt.opts), log.NewNullLogger())
 			if tt.err != "" {
 				require.ErrorContains(t, err, tt.err)
 			} else {

common/browser_test.go

@@ -23,7 +23,8 @@ func TestBrowserNewPageInContext(t *testing.T) {
 	}
 	newTestCase := func(id cdp.BrowserContextID) *testCase {
 		ctx, cancel := context.WithCancel(context.Background())
-		b := newBrowser(ctx, cancel, nil, NewLaunchOptions(), log.NewNullLogger())
+		logger := log.NewNullLogger()
+		b := newBrowser(ctx, cancel, nil, NewLaunchOptions(), logger)
 		// set a new browser context in the browser with `id`, so that newPageInContext can find it.
 		b.contexts[id] = NewBrowserContext(ctx, b, id, nil, nil)
 		return &testCase{

common/helpers_test.go

@@ -10,15 +10,14 @@ import (
 	"github.com/chromedp/cdproto/cdp"
 	"github.com/chromedp/cdproto/runtime"
 	"github.com/dop251/goja"
-	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/require"
 
 	"github.com/grafana/xk6-browser/log"
 )
 
 func newExecCtx() (*ExecutionContext, context.Context, *goja.Runtime) {
 	ctx := context.Background()
-	logger := log.New(logrus.New(), "", false, nil)
+	logger := log.NewNullLogger()
 	execCtx := NewExecutionContext(ctx, nil, nil, runtime.ExecutionContextID(123456789), logger)
 
 	return execCtx, ctx, goja.New()

common/network_manager.go

@@ -74,7 +74,7 @@ func NewNetworkManager(
 		ctx:              ctx,
 		// TODO: Pass an internal logger instead of basing it on k6's logger?
 		// See https://github.com/grafana/xk6-browser/issues/54
-		logger:           log.New(state.Logger, GetIterationID(ctx), false, nil),
+		logger:           log.New(state.Logger, GetIterationID(ctx)),
 		session:          s,
 		parent:           parent,
 		frameManager:     fm,

common/network_manager_test.go

@@ -63,7 +63,7 @@ func newTestNetworkManager(t *testing.T, k6opts k6lib.Options) (*NetworkManager,
 	vu.MoveToVUContext()
 	st := vu.State()
 	st.Options = k6opts
-	logger := log.New(st.Logger, "", false, nil)
+	logger := log.New(st.Logger, "")
 	nm := &NetworkManager{
 		ctx:      vu.Context(),
 		logger:   logger,

common/response.go

@@ -71,7 +71,7 @@ func NewHTTPResponse(ctx context.Context, req *Request, resp *network.Response,
 		ctx: ctx,
 		// TODO: Pass an internal logger instead of basing it on k6's logger?
 		// See https://github.com/grafana/xk6-browser/issues/54
-		logger:            log.New(state.Logger, GetIterationID(ctx), false, nil),
+		logger:            log.New(state.Logger, GetIterationID(ctx)),
 		request:           req,
 		remoteAddress:     &RemoteAddress{IPAddress: resp.RemoteIPAddress, Port: resp.RemotePort},
 		securityDetails:   nil,

log/logger.go

@@ -20,7 +20,6 @@ type Logger struct {
 	mu             sync.Mutex
 	lastLogCall    int64
 	iterID         string
-	debugOverride  bool
 	categoryFilter *regexp.Regexp
 }
 
@@ -29,17 +28,14 @@ type Logger struct {
 func NewNullLogger() *Logger {
 	log := logrus.New()
 	log.SetOutput(ioutil.Discard)
-
-	return New(log, "", false, nil)
+	return New(log, "")
 }
 
 // New creates a new logger.
-func New(logger *logrus.Logger, iterID string, debugOverride bool, categoryFilter *regexp.Regexp) *Logger {
+func New(logger *logrus.Logger, iterID string) *Logger {
 	return &Logger{
-		Logger:         logger,
-		iterID:         iterID,
-		debugOverride:  debugOverride,
-		categoryFilter: categoryFilter,
+		Logger: logger,
+		iterID: iterID,
 	}
 }
 
@@ -89,7 +85,7 @@ func (l *Logger) Logf(level logrus.Level, category string, msg string, args ...a
 		l.lastLogCall = now
 	}()
 
-	if l.categoryFilter != nil && !l.categoryFilter.Match([]byte(category)) {
+	if l.categoryFilter != nil && !l.categoryFilter.MatchString(category) {
 		return
 	}
 	if l.Logger == nil {
@@ -106,7 +102,7 @@ func (l *Logger) Logf(level logrus.Level, category string, msg string, args ...a
 		fields["iteration_id"] = l.iterID
 	}
 	entry := l.WithFields(fields)
-	if l.GetLevel() < level && l.debugOverride {
+	if l.GetLevel() < level {
 		entry.Printf(msg, args...)
 		return
 	}
@@ -165,6 +161,17 @@ func (l *Logger) ConsoleLogFormatterSerializer() *Logger {
 	}
 }
 
+// SetCategoryFilter enables filtering logs by the filter regex.
+func (l *Logger) SetCategoryFilter(filter string) (err error) {
+	if filter == "" {
+		return nil
+	}
+	if l.categoryFilter, err = regexp.Compile(filter); err != nil {
+		return fmt.Errorf("invalid category filter %q: %w", filter, err)
+	}
+	return nil
+}
+
 func goRoutineID() int {
 	var buf [64]byte
 	n := runtime.Stack(buf[:], false)