diff --git a/chromium/browser_type.go b/chromium/browser_type.go index 54b9d6d25..00d0d22a3 100644 --- a/chromium/browser_type.go +++ b/chromium/browser_type.go @@ -25,11 +25,11 @@ import ( "errors" "fmt" "os" - "regexp" "github.com/dop251/goja" "github.com/grafana/xk6-browser/api" "github.com/grafana/xk6-browser/common" + "github.com/sirupsen/logrus" k6common "go.k6.io/k6/js/common" k6lib "go.k6.io/k6/lib" ) @@ -161,21 +161,22 @@ func (b *BrowserType) Name() string { // makes an extension wide logger func makeLogger(ctx context.Context, launchOpts *common.LaunchOptions) (*common.Logger, error) { var ( - k6Logger = k6lib.GetState(ctx).Logger - reCategoryFilter, _ = regexp.Compile(launchOpts.LogCategoryFilter) - logger = common.NewLogger(ctx, k6Logger, launchOpts.Debug, reCategoryFilter) + k6Logger = k6lib.GetState(ctx).Logger + logger = common.NewLogger(k6Logger) ) // set the log level from the launch options (usually from a script's options). if launchOpts.Debug { - _ = logger.SetLevel("debug") + logger.SetLevel(logrus.DebugLevel) } if el, ok := os.LookupEnv("XK6_BROWSER_LOG"); ok { - if err := logger.SetLevel(el); err != nil { + lvl, err := logrus.ParseLevel(el) + if err != nil { return nil, err } + logger.SetLevel(lvl) } - if _, ok := os.LookupEnv("XK6_BROWSER_CALLER"); ok { - logger.ReportCaller() + if c := os.Getenv("XK6_BROWSER_CALLER"); c == "1" || c == "true" { + logger.EnableReportCaller() } return logger, nil } diff --git a/common/barrier_test.go b/common/barrier_test.go index c82c992fc..70bc6e623 100644 --- a/common/barrier_test.go +++ b/common/barrier_test.go @@ -32,7 +32,7 @@ func TestBarrier(t *testing.T) { t.Run("should work", func(t *testing.T) { ctx := context.Background() timeoutSetings := NewTimeoutSettings(nil) - frameManager := NewFrameManager(ctx, nil, nil, timeoutSetings, NewLogger(ctx, NullLogger(), false, nil)) + frameManager := NewFrameManager(ctx, nil, nil, timeoutSetings, NewLogger(NullLogger())) frame := NewFrame(ctx, frameManager, nil, cdp.FrameID("frame_id_0123456789")) barrier := NewBarrier() diff --git a/common/browser.go b/common/browser.go index 818f0d43e..37cb6a469 100644 --- a/common/browser.go +++ b/common/browser.go @@ -108,7 +108,7 @@ func NewBrowser(ctx context.Context, cancelFn context.CancelFunc, browserProc *B } func (b *Browser) connect() error { - b.logger.Debugf("Browser:connect", "wsURL:%v", b.browserProc.WsURL()) + b.logger.Debugf("Browser:connect wsURL:%v", b.browserProc.WsURL()) var err error b.conn, err = NewConnection(b.ctx, b.browserProc.WsURL(), b.logger) if err != nil { @@ -123,7 +123,7 @@ func (b *Browser) connect() error { } func (b *Browser) disposeContext(id cdp.BrowserContextID) error { - b.logger.Debugf("Browser:disposeContext", "bctxid:%v", id) + b.logger.Debugf("Browser:disposeContext bctxid:%v", id) action := target.DisposeBrowserContext(id) if err := action.Do(cdp.WithExecutor(b.ctx, b.conn)); err != nil { return fmt.Errorf("unable to dispose browser context %T: %w", action, err) @@ -162,13 +162,13 @@ func (b *Browser) initEvents() error { return case event := <-chHandler: if ev, ok := event.data.(*target.EventAttachedToTarget); ok { - b.logger.Debugf("Browser:initEvents:onAttachedToTarget", "sid:%v tid:%v", ev.SessionID, ev.TargetInfo.TargetID) + b.logger.Debugf("Browser:initEvents:onAttachedToTarget sid:%v tid:%v", ev.SessionID, ev.TargetInfo.TargetID) go b.onAttachedToTarget(ev) } else if ev, ok := event.data.(*target.EventDetachedFromTarget); ok { - b.logger.Debugf("Browser:initEvents:onDetachedFromTarget", "sid:%v", ev.SessionID) + b.logger.Debugf("Browser:initEvents:onDetachedFromTarget sid:%v", ev.SessionID) go b.onDetachedFromTarget(ev) } else if event.typ == EventConnectionClose { - b.logger.Debugf("Browser:initEvents:EventConnectionClose", "") + b.logger.Debugf("Browser:initEvents:EventConnectionClose") b.connMu.Lock() b.connected = false @@ -203,13 +203,13 @@ func (b *Browser) onAttachedToTarget(ev *target.EventAttachedToTarget) { if ok { browserCtx = bctx } - b.logger.Debugf("Browser:onAttachedToTarget", "sid:%v tid:%v bcid:%v bctx nil=%t", ev.SessionID, ev.TargetInfo.TargetID, ev.TargetInfo.BrowserContextID, bctx == nil) + b.logger.Debugf("Browser:onAttachedToTarget sid:%v tid:%v bcid:%v bctx nil=%t", ev.SessionID, ev.TargetInfo.TargetID, ev.TargetInfo.BrowserContextID, bctx == nil) b.contextsMu.RUnlock() // We're not interested in the top-level browser target, other targets or DevTools targets right now. isDevTools := strings.HasPrefix(ev.TargetInfo.URL, "devtools://devtools") if ev.TargetInfo.Type == "browser" || ev.TargetInfo.Type == "other" || isDevTools { - b.logger.Debugf("Browser:onAttachedToTarget", "sid:%v tid:%v, returns: devtools", ev.SessionID, ev.TargetInfo.TargetID) + b.logger.Debugf("Browser:onAttachedToTarget sid:%v tid:%v, returns: devtools", ev.SessionID, ev.TargetInfo.TargetID) return } @@ -219,18 +219,18 @@ func (b *Browser) onAttachedToTarget(ev *target.EventAttachedToTarget) { isRunning := atomic.LoadInt64(&b.state) == BrowserStateOpen && b.IsConnected() //b.conn.isConnected() if _, ok := err.(*websocket.CloseError); !ok && !isRunning { // If we're no longer connected to browser, then ignore WebSocket errors - b.logger.Debugf("Browser:onAttachedToTarget:background_page", "sid:%v tid:%v, returns: websocket err: %v", + b.logger.Debugf("Browser:onAttachedToTarget:background_page sid:%v tid:%v, returns: websocket err: %v", ev.SessionID, ev.TargetInfo.TargetID, err) return } k6Throw(b.ctx, "cannot create NewPage for background_page event: %w", err) } b.pagesMu.Lock() - b.logger.Debugf("Browser:onAttachedToTarget:background_page", "sid:%v tid:%v, adding tid", ev.SessionID, ev.TargetInfo.TargetID) + b.logger.Debugf("Browser:onAttachedToTarget:background_page sid:%v tid:%v, adding tid", ev.SessionID, ev.TargetInfo.TargetID) b.pages[ev.TargetInfo.TargetID] = p b.pagesMu.Unlock() b.sessionIDtoTargetIDMu.Lock() - b.logger.Debugf("Browser:onAttachedToTarget:background_page", "sid:%v tid:%v, adding sid", ev.SessionID, ev.TargetInfo.TargetID) + b.logger.Debugf("Browser:onAttachedToTarget:background_page sid:%v tid:%v, adding sid", ev.SessionID, ev.TargetInfo.TargetID) b.sessionIDtoTargetID[ev.SessionID] = ev.TargetInfo.TargetID b.sessionIDtoTargetIDMu.Unlock() } else if ev.TargetInfo.Type == "page" { @@ -239,24 +239,24 @@ func (b *Browser) onAttachedToTarget(ev *target.EventAttachedToTarget) { if t, ok := b.pages[ev.TargetInfo.OpenerID]; ok { opener = t } - b.logger.Debugf("Browser:onAttachedToTarget:page", "sid:%v tid:%v opener nil:%t", ev.SessionID, ev.TargetInfo.TargetID, opener == nil) + b.logger.Debugf("Browser:onAttachedToTarget:page sid:%v tid:%v opener nil:%t", ev.SessionID, ev.TargetInfo.TargetID, opener == nil) b.pagesMu.RUnlock() p, err := NewPage(b.ctx, b.conn.getSession(ev.SessionID), browserCtx, ev.TargetInfo.TargetID, opener, true, b.logger) if err != nil { isRunning := atomic.LoadInt64(&b.state) == BrowserStateOpen && b.IsConnected() //b.conn.isConnected() if _, ok := err.(*websocket.CloseError); !ok && !isRunning { // If we're no longer connected to browser, then ignore WebSocket errors - b.logger.Debugf("Browser:onAttachedToTarget:page", "sid:%v tid:%v, returns: websocket error", ev.SessionID, ev.TargetInfo.TargetID) + b.logger.Debugf("Browser:onAttachedToTarget:page sid:%v tid:%v, returns: websocket error", ev.SessionID, ev.TargetInfo.TargetID) return } k6Throw(b.ctx, "cannot create NewPage for page event: %w", err) } b.pagesMu.Lock() - b.logger.Debugf("Browser:onAttachedToTarget:page", "sid:%v tid:%v, adding page as a target", ev.SessionID, ev.TargetInfo.TargetID) + b.logger.Debugf("Browser:onAttachedToTarget:page sid:%v tid:%v, adding page as a target", ev.SessionID, ev.TargetInfo.TargetID) b.pages[ev.TargetInfo.TargetID] = p b.pagesMu.Unlock() b.sessionIDtoTargetIDMu.Lock() - b.logger.Debugf("Browser:onAttachedToTarget:page", "sid:%v tid:%v, changing sid to tid", ev.SessionID, ev.TargetInfo.TargetID) + b.logger.Debugf("Browser:onAttachedToTarget:page sid:%v tid:%v, changing sid to tid", ev.SessionID, ev.TargetInfo.TargetID) b.sessionIDtoTargetID[ev.SessionID] = ev.TargetInfo.TargetID b.sessionIDtoTargetIDMu.Unlock() browserCtx.emit(EventBrowserContextPage, p) @@ -266,10 +266,10 @@ func (b *Browser) onAttachedToTarget(ev *target.EventAttachedToTarget) { func (b *Browser) onDetachedFromTarget(ev *target.EventDetachedFromTarget) { b.sessionIDtoTargetIDMu.RLock() targetID, ok := b.sessionIDtoTargetID[ev.SessionID] - b.logger.Debugf("Browser:onDetachedFromTarget", "sid:%v tid:%v", ev.SessionID, targetID) + b.logger.Debugf("Browser:onDetachedFromTarget sid:%v tid:%v", ev.SessionID, targetID) b.sessionIDtoTargetIDMu.RUnlock() if !ok { - b.logger.Debugf("Browser:onDetachedFromTarget", "sid:%v tid:%v, returns", ev.SessionID, targetID) + b.logger.Debugf("Browser:onDetachedFromTarget sid:%v tid:%v, returns", ev.SessionID, targetID) // We don't track targets of type "browser", "other" and "devtools", so ignore if we don't recognize target. return } @@ -277,7 +277,7 @@ func (b *Browser) onDetachedFromTarget(ev *target.EventDetachedFromTarget) { b.pagesMu.Lock() defer b.pagesMu.Unlock() if t, ok := b.pages[targetID]; ok { - b.logger.Debugf("Browser:onDetachedFromTarget", "tid:%v, delete page", targetID) + b.logger.Debugf("Browser:onDetachedFromTarget tid:%v, delete page", targetID) delete(b.pages, targetID) t.didClose() } @@ -303,7 +303,7 @@ func (b *Browser) newPageInContext(id cdp.BrowserContextID) (*Page, error) { func(data interface{}) bool { mu.RLock() defer mu.RUnlock() - b.logger.Debugf("Browser:newPageInContext", "tid:%v bcid:%v, createWaitForEventHandler", targetID, id) + b.logger.Debugf("Browser:newPageInContext tid:%v bcid:%v, createWaitForEventHandler", targetID, id) return data.(*Page).targetID == targetID }, ) @@ -314,20 +314,20 @@ func (b *Browser) newPageInContext(id cdp.BrowserContextID) (*Page, error) { mu.Lock() defer mu.Unlock() localTargetID = targetID - b.logger.Debugf("Browser:newPageInContext", "tid:%v bcid:%v, CreateTarget(blank)", localTargetID, id) + b.logger.Debugf("Browser:newPageInContext tid:%v bcid:%v, CreateTarget(blank)", localTargetID, id) if targetID, err = action.Do(cdp.WithExecutor(b.ctx, b.conn)); err != nil { errCh <- fmt.Errorf("unable to execute %T: %w", action, err) } }() select { case <-b.ctx.Done(): - b.logger.Debugf("Browser:newPageInContext:<-b.ctx.Done", "tid:%v bcid:%v", localTargetID, id) + b.logger.Debugf("Browser:newPageInContext:<-b.ctx.Done tid:%v bcid:%v", localTargetID, id) case <-time.After(b.launchOpts.Timeout): - b.logger.Debugf("Browser:newPageInContext:timeout", "tid:%v bcid:%v timeout:%s", localTargetID, id, b.launchOpts.Timeout) + b.logger.Debugf("Browser:newPageInContext:timeout tid:%v bcid:%v timeout:%s", localTargetID, id, b.launchOpts.Timeout) case c := <-ch: - b.logger.Debugf("Browser:newPageInContext:<-ch", "tid:%v bcid:%v, c:%v", localTargetID, id, c) + b.logger.Debugf("Browser:newPageInContext:<-ch tid:%v bcid:%v, c:%v", localTargetID, id, c) case err := <-errCh: - b.logger.Debugf("Browser:newPageInContext:<-errCh", "tid:%v bcid:%v, err:%v", localTargetID, id, err) + b.logger.Debugf("Browser:newPageInContext:<-errCh tid:%v bcid:%v, err:%v", localTargetID, id, err) return nil, err } b.pagesMu.RLock() @@ -337,10 +337,10 @@ func (b *Browser) newPageInContext(id cdp.BrowserContextID) (*Page, error) { // Close shuts down the browser func (b *Browser) Close() { - b.logger.Debugf("Browser:Close", "") + b.logger.Debugf("Browser:Close") if !atomic.CompareAndSwapInt64(&b.state, b.state, BrowserStateClosing) { // If we're already in a closing state then no need to continue. - b.logger.Debugf("Browser:Close", "already in a closing state") + b.logger.Debugf("Browser:Close already in a closing state") return } b.browserProc.GracefulClose() @@ -376,7 +376,7 @@ func (b *Browser) IsConnected() bool { func (b *Browser) NewContext(opts goja.Value) api.BrowserContext { action := target.CreateBrowserContext().WithDisposeOnDetach(true) browserContextID, err := action.Do(cdp.WithExecutor(b.ctx, b.conn)) - b.logger.Debugf("Browser:NewContext", "browserContextID: %v", browserContextID) + b.logger.Debugf("Browser:NewContext browserContextID: %v", browserContextID) if err != nil { k6Throw(b.ctx, "unable to execute %T: %w", action, err) } @@ -388,7 +388,7 @@ func (b *Browser) NewContext(opts goja.Value) api.BrowserContext { b.contextsMu.Lock() defer b.contextsMu.Unlock() - b.logger.Debugf("Browser:NewContext", "NewBrowserContext: %v", browserContextID) + b.logger.Debugf("Browser:NewContext NewBrowserContext: %v", browserContextID) browserCtx := NewBrowserContext(b.ctx, b.conn, b, browserContextID, browserCtxOpts, b.logger) b.contexts[browserContextID] = browserCtx diff --git a/common/browser_context.go b/common/browser_context.go index 1216c2fa6..90bca5d85 100644 --- a/common/browser_context.go +++ b/common/browser_context.go @@ -79,7 +79,7 @@ func (b *BrowserContext) AddCookies(cookies goja.Value) { // AddInitScript adds a script that will be initialized on all new pages. func (b *BrowserContext) AddInitScript(script goja.Value, arg goja.Value) { - b.logger.Debugf("BrowserContext:AddInitScript", "") + b.logger.Debugf("BrowserContext:AddInitScript") rt := k6common.GetRuntime(b.ctx) @@ -165,7 +165,7 @@ func (b *BrowserContext) ExposeFunction(name string, callback goja.Callable) { // GrantPermissions enables the specified permissions, all others will be disabled. func (b *BrowserContext) GrantPermissions(permissions []string, opts goja.Value) { - b.logger.Debugf("BrowserContext:GrantPermissions", "") + b.logger.Debugf("BrowserContext:GrantPermissions") rt := k6common.GetRuntime(b.ctx) permsToProtocol := map[string]cdpbrowser.PermissionType{ "geolocation": cdpbrowser.PermissionTypeGeolocation, @@ -216,7 +216,7 @@ func (b *BrowserContext) NewCDPSession() api.CDPSession { // NewPage creates a new page inside this browser context. func (b *BrowserContext) NewPage() api.Page { - b.logger.Debugf("BrowserContext:NewPage", "b.id:%v", b.id) + b.logger.Debugf("BrowserContext:NewPage b.id:%v", b.id) p, err := b.browser.newPageInContext(b.id) if err != nil { rt := k6common.GetRuntime(b.ctx) @@ -303,7 +303,7 @@ func (b *BrowserContext) Unroute(url goja.Value, handler goja.Callable) { } func (b *BrowserContext) WaitForEvent(event string, optsOrPredicate goja.Value) interface{} { - b.logger.Debugf("BrowserContext:WaitForEvent", "event:%q", event) + b.logger.Debugf("BrowserContext:WaitForEvent event:%q", event) // TODO: This public API needs Promise support (as return value) to be useful in JS! rt := k6common.GetRuntime(b.ctx) @@ -340,16 +340,16 @@ func (b *BrowserContext) WaitForEvent(event string, optsOrPredicate goja.Value) ch := make(chan interface{}) go func() { - b.logger.Debugf("BrowserContext:WaitForEvent:go()", "starts") - defer b.logger.Debugf("BrowserContext:WaitForEvent:go()", "returns") + b.logger.Debugf("BrowserContext:WaitForEvent:go() starts") + defer b.logger.Debugf("BrowserContext:WaitForEvent:go() returns") for { select { case <-evCancelCtx.Done(): - b.logger.Debugf("BrowserContext:WaitForEvent:go()", "evCancelCtx done") + b.logger.Debugf("BrowserContext:WaitForEvent:go() evCancelCtx done") return case ev := <-chEvHandler: if ev.typ == EventBrowserContextClose { - b.logger.Debugf("BrowserContext:WaitForEvent:go()", "EventBrowserContextClose returns") + b.logger.Debugf("BrowserContext:WaitForEvent:go() EventBrowserContextClose returns") ch <- nil close(ch) @@ -359,11 +359,11 @@ func (b *BrowserContext) WaitForEvent(event string, optsOrPredicate goja.Value) return } if ev.typ == EventBrowserContextPage { - b.logger.Debugf("BrowserContext:WaitForEvent:go()", "EventBrowserContextPage") + b.logger.Debugf("BrowserContext:WaitForEvent:go() EventBrowserContextPage") p := ev.data.(*Page) exported := k6common.Bind(rt, p, &b.ctx) if retVal, err := predicateFn(rt.ToValue(exported)); err == nil && retVal.ToBoolean() { - b.logger.Debugf("BrowserContext:WaitForEvent:go()", "EventBrowserContextPage returns") + b.logger.Debugf("BrowserContext:WaitForEvent:go() EventBrowserContextPage returns") ch <- p close(ch) @@ -382,13 +382,13 @@ func (b *BrowserContext) WaitForEvent(event string, optsOrPredicate goja.Value) select { case <-b.ctx.Done(): - b.logger.Debugf("BrowserContext:WaitForEvent", "b.ctx Done") + b.logger.Debugf("BrowserContext:WaitForEvent b.ctx Done") case <-time.After(timeout): - b.logger.Debugf("BrowserContext:WaitForEvent", "timeout") + b.logger.Debugf("BrowserContext:WaitForEvent timeout") case evData := <-ch: - b.logger.Debugf("BrowserContext:WaitForEvent", "evData") + b.logger.Debugf("BrowserContext:WaitForEvent evData") return evData } - b.logger.Debugf("BrowserContext:WaitForEvent", "nil return") + b.logger.Debugf("BrowserContext:WaitForEvent nil return") return nil } diff --git a/common/browser_process.go b/common/browser_process.go index 49a22ed0b..0ca3d6cd0 100644 --- a/common/browser_process.go +++ b/common/browser_process.go @@ -79,13 +79,13 @@ func (p *BrowserProcess) didLoseConnection() { // GracefulClose triggers a graceful closing of the browser process func (p *BrowserProcess) GracefulClose() { - p.logger.Debugf("Browser:GracefulClose", "") + p.logger.Debugf("Browser:GracefulClose") close(p.processIsGracefullyClosing) } // Terminate triggers the termination of the browser process func (p *BrowserProcess) Terminate() { - p.logger.Debugf("Browser:Close", "browserProc terminate") + p.logger.Debugf("Browser:Close browserProc terminate") p.cancel() } diff --git a/common/connection.go b/common/connection.go index f50d7c110..ac17a2583 100644 --- a/common/connection.go +++ b/common/connection.go @@ -182,7 +182,7 @@ func (c *Connection) closeConnection(code int) error { } func (c *Connection) closeSession(sid target.SessionID, tid target.ID) { - c.logger.Debugf("Connection:closeSession", "sid:%v tid:%v wsURL:%v", sid, tid, c.wsURL) + c.logger.Debugf("Connection:closeSession sid:%v tid:%v wsURL:%v", sid, tid, c.wsURL) c.sessionsMu.Lock() if session, ok := c.sessions[sid]; ok { session.close() @@ -192,24 +192,24 @@ func (c *Connection) closeSession(sid target.SessionID, tid target.ID) { } func (c *Connection) createSession(info *target.Info) (*Session, error) { - c.logger.Debugf("Connection:createSession", "tid:%v bctxid:%v type:%s", info.TargetID, info.BrowserContextID, info.Type) + c.logger.Debugf("Connection:createSession tid:%v bctxid:%v type:%s", info.TargetID, info.BrowserContextID, info.Type) var sessionID target.SessionID var err error action := target.AttachToTarget(info.TargetID).WithFlatten(true) if sessionID, err = action.Do(cdp.WithExecutor(c.ctx, c)); err != nil { - c.logger.Debugf("Connection:createSession", "tid:%v bctxid:%v type:%s err:%v", info.TargetID, info.BrowserContextID, info.Type, err) + c.logger.Debugf("Connection:createSession tid:%v bctxid:%v type:%s err:%v", info.TargetID, info.BrowserContextID, info.Type, err) return nil, err } sess := c.getSession(sessionID) if sess == nil { - c.logger.Warnf("Connection:createSession", "tid:%v bctxid:%v type:%s sid:%v, session is nil", info.TargetID, info.BrowserContextID, info.Type, sessionID) + c.logger.Warnf("Connection:createSession tid:%v bctxid:%v type:%s sid:%v, session is nil", info.TargetID, info.BrowserContextID, info.Type, sessionID) } return sess, nil } func (c *Connection) handleIOError(err error) { - c.logger.Errorf("Connection:handleIOError", "err:%v", err) + c.logger.Errorf("Connection:handleIOError err:%v", err) if websocket.IsUnexpectedCloseError(err, websocket.CloseNormalClosure, websocket.CloseGoingAway) { // Report an unexpected closure @@ -225,9 +225,9 @@ func (c *Connection) handleIOError(err error) { } select { case c.closeCh <- code: - c.logger.Debugf("Connection:handleIOError:c.closeCh <-", "code:%d", code) + c.logger.Debugf("Connection:handleIOError:c.closeCh <- code:%d", code) case <-c.done: - c.logger.Debugf("Connection:handleIOError:<-c.done", "") + c.logger.Debugf("Connection:handleIOError:<-c.done") } } @@ -251,16 +251,16 @@ func (c *Connection) findTargetIDForLog(id target.SessionID) target.ID { } func (c *Connection) recvLoop() { - c.logger.Debugf("Connection:recvLoop", "wsURL:%q", c.wsURL) + c.logger.Debugf("Connection:recvLoop wsURL:%q", c.wsURL) for { _, buf, err := c.conn.ReadMessage() if err != nil { c.handleIOError(err) - c.logger.Debugf("Connection:recvLoop", "wsURL:%q ioErr:%v", c.wsURL, err) + c.logger.Debugf("Connection:recvLoop wsURL:%q ioErr:%v", c.wsURL, err) return } - c.logger.Tracef("cdp:recv", "<- %s", buf) + c.logger.Tracef("cdp:recv <- %s", buf) var msg cdproto.Message c.decoder = jlexer.Lexer{Data: buf} @@ -268,9 +268,9 @@ func (c *Connection) recvLoop() { if err := c.decoder.Error(); err != nil { select { case c.errorCh <- err: - c.logger.Debugf("Connection:recvLoop:<-err", "wsURL:%q err:%v", c.wsURL, err) + c.logger.Debugf("Connection:recvLoop:<-err wsURL:%q err:%v", c.wsURL, err) case <-c.done: - c.logger.Debugf("Connection:recvLoop:<-c.done", "wsURL:%q", c.wsURL) + c.logger.Debugf("Connection:recvLoop:<-c.done wsURL:%q", c.wsURL) return } } @@ -280,26 +280,26 @@ func (c *Connection) recvLoop() { if msg.Method == cdproto.EventTargetAttachedToTarget { ev, err := cdproto.UnmarshalMessage(&msg) if err != nil { - c.logger.Errorf("cdp", "%s", err) + c.logger.Errorf("cdp %s", err) continue } eva := ev.(*target.EventAttachedToTarget) sid, tid := eva.SessionID, eva.TargetInfo.TargetID c.sessionsMu.Lock() session := NewSession(c.ctx, c, sid, tid, c.logger) - c.logger.Debugf("Connection:recvLoop:EventAttachedToTarget", "sid:%v tid:%v wsURL:%q, NewSession", sid, tid, c.wsURL) + c.logger.Debugf("Connection:recvLoop:EventAttachedToTarget sid:%v tid:%v wsURL:%q, NewSession", sid, tid, c.wsURL) c.sessions[sid] = session c.sessionsMu.Unlock() } else if msg.Method == cdproto.EventTargetDetachedFromTarget { ev, err := cdproto.UnmarshalMessage(&msg) if err != nil { - c.logger.Errorf("cdp", "%s", err) + c.logger.Errorf("cdp %s", err) continue } evt := ev.(*target.EventDetachedFromTarget) sid := evt.SessionID tid := c.findTargetIDForLog(sid) - c.logger.Debugf("Connection:recvLoop:EventDetachedFromTarget", "sid:%v tid:%v wsURL:%q, closeSession", sid, tid, c.wsURL) + c.logger.Debugf("Connection:recvLoop:EventDetachedFromTarget sid:%v tid:%v wsURL:%q, closeSession", sid, tid, c.wsURL) c.closeSession(sid, tid) } @@ -311,7 +311,7 @@ func (c *Connection) recvLoop() { continue } if msg.Error != nil && msg.Error.Message == "No session with given id" { - c.logger.Debugf("Connection:recvLoop", "sid:%v tid:%v wsURL:%q, closeSession #2", session.id, session.targetID, c.wsURL) + c.logger.Debugf("Connection:recvLoop sid:%v tid:%v wsURL:%q, closeSession #2", session.id, session.targetID, c.wsURL) c.closeSession(session.id, session.targetID) continue } @@ -319,28 +319,28 @@ func (c *Connection) recvLoop() { select { case session.readCh <- &msg: case code := <-c.closeCh: - c.logger.Debugf("Connection:recvLoop:<-c.closeCh", "sid:%v tid:%v wsURL:%v crashed:%t", session.id, session.targetID, c.wsURL, session.crashed) + c.logger.Debugf("Connection:recvLoop:<-c.closeCh sid:%v tid:%v wsURL:%v crashed:%t", session.id, session.targetID, c.wsURL, session.crashed) _ = c.closeConnection(code) case <-c.done: - c.logger.Debugf("Connection:recvLoop:<-c.done", "sid:%v tid:%v wsURL:%v crashed:%t", session.id, session.targetID, c.wsURL, session.crashed) + c.logger.Debugf("Connection:recvLoop:<-c.done sid:%v tid:%v wsURL:%v crashed:%t", session.id, session.targetID, c.wsURL, session.crashed) return } case msg.Method != "": - c.logger.Debugf("Connection:recvLoop:msg.Method:emit", "method:%q", msg.Method) + c.logger.Debugf("Connection:recvLoop:msg.Method:emit method:%q", msg.Method) ev, err := cdproto.UnmarshalMessage(&msg) if err != nil { - c.logger.Errorf("cdp", "%s", err) + c.logger.Errorf("cdp %s", err) continue } c.emit(string(msg.Method), ev) case msg.ID != 0: - c.logger.Debugf("Connection:recvLoop:msg.ID:emit", "method:%q", msg.ID) + c.logger.Debugf("Connection:recvLoop:msg.ID:emit method:%q", msg.ID) c.emit("", &msg) default: - c.logger.Errorf("cdp", "ignoring malformed incoming message (missing id or method): %#v (message: %s)", msg, msg.Error.Message) + c.logger.Errorf("cdp ignoring malformed incoming message (missing id or method): %#v (message: %s)", msg, msg.Error.Message) } } } @@ -349,14 +349,14 @@ func (c *Connection) send(msg *cdproto.Message, recvCh chan *cdproto.Message, re select { case c.sendCh <- msg: case err := <-c.errorCh: - c.logger.Debugf("Connection:send:<-c.errorCh", "wsURL:%q sid:%v, err:%v", c.wsURL, msg.SessionID, err) + c.logger.Debugf("Connection:send:<-c.errorCh wsURL:%q sid:%v, err:%v", c.wsURL, msg.SessionID, err) return err case code := <-c.closeCh: - c.logger.Debugf("Connection:send:<-c.closeCh", "wsURL:%q sid:%v, websocket code:%v", c.wsURL, msg.SessionID, code) + c.logger.Debugf("Connection:send:<-c.closeCh wsURL:%q sid:%v, websocket code:%v", c.wsURL, msg.SessionID, code) _ = c.closeConnection(code) return &websocket.CloseError{Code: code} case <-c.done: - c.logger.Debugf("Connection:send:<-c.done", "wsURL:%q sid:%v", c.wsURL, msg.SessionID) + c.logger.Debugf("Connection:send:<-c.done wsURL:%q sid:%v", c.wsURL, msg.SessionID) return nil } @@ -375,25 +375,25 @@ func (c *Connection) send(msg *cdproto.Message, recvCh chan *cdproto.Message, re } switch { case msg == nil: - c.logger.Debugf("Connection:send", "wsURL:%q, err:ErrChannelClosed", c.wsURL) + c.logger.Debugf("Connection:send wsURL:%q, err:ErrChannelClosed", c.wsURL) return ErrChannelClosed case msg.Error != nil: - c.logger.Debugf("Connection:send", "sid:%v tid:%v wsURL:%q, msg err:%v", sid, tid, c.wsURL, msg.Error) + c.logger.Debugf("Connection:send sid:%v tid:%v wsURL:%q, msg err:%v", sid, tid, c.wsURL, msg.Error) return msg.Error case res != nil: return easyjson.Unmarshal(msg.Result, res) } case err := <-c.errorCh: - c.logger.Debugf("Connection:send:<-c.errorCh #2", "sid:%v tid:%v wsURL:%q, err:%v", msg.SessionID, tid, c.wsURL, err) + c.logger.Debugf("Connection:send:<-c.errorCh #2 sid:%v tid:%v wsURL:%q, err:%v", msg.SessionID, tid, c.wsURL, err) return err case code := <-c.closeCh: - c.logger.Debugf("Connection:send:<-c.closeCh #2", "sid:%v tid:%v wsURL:%q, websocket code:%v", msg.SessionID, tid, c.wsURL, code) + c.logger.Debugf("Connection:send:<-c.closeCh #2 sid:%v tid:%v wsURL:%q, websocket code:%v", msg.SessionID, tid, c.wsURL, code) _ = c.closeConnection(code) return &websocket.CloseError{Code: code} case <-c.done: - c.logger.Debugf("Connection:send:<-c.done #2", "sid:%v tid:%v wsURL:%q", msg.SessionID, tid, c.wsURL) + c.logger.Debugf("Connection:send:<-c.done #2 sid:%v tid:%v wsURL:%q", msg.SessionID, tid, c.wsURL) case <-c.ctx.Done(): - c.logger.Debugf("Connection:send:<-c.ctx.Done()", "sid:%v tid:%v wsURL:%q err:%v", msg.SessionID, tid, c.wsURL, c.ctx.Err()) + c.logger.Debugf("Connection:send:<-c.ctx.Done() sid:%v tid:%v wsURL:%q err:%v", msg.SessionID, tid, c.wsURL, c.ctx.Err()) // TODO: this brings many bugs to the surface return c.ctx.Err() // TODO: add a timeout? @@ -404,7 +404,7 @@ func (c *Connection) send(msg *cdproto.Message, recvCh chan *cdproto.Message, re } func (c *Connection) sendLoop() { - c.logger.Debugf("Connection:sendLoop", "wsURL:%q, starts", c.wsURL) + c.logger.Debugf("Connection:sendLoop wsURL:%q, starts", c.wsURL) for { select { case msg := <-c.sendCh: @@ -415,15 +415,15 @@ func (c *Connection) sendLoop() { tid := c.findTargetIDForLog(sid) select { case c.errorCh <- err: - c.logger.Debugf("Connection:sendLoop:c.errorCh <- err", "sid:%v tid:%v wsURL:%q err:%v", sid, tid, c.wsURL, err) + c.logger.Debugf("Connection:sendLoop:c.errorCh <- err sid:%v tid:%v wsURL:%q err:%v", sid, tid, c.wsURL, err) case <-c.done: - c.logger.Debugf("Connection:sendLoop:<-c.done", "sid:%v tid:%v wsURL:%q", sid, tid, c.wsURL) + c.logger.Debugf("Connection:sendLoop:<-c.done sid:%v tid:%v wsURL:%q", sid, tid, c.wsURL) return } } buf, _ := c.encoder.BuildBytes() - c.logger.Tracef("cdp:send", "-> %s", buf) + c.logger.Tracef("cdp:send -> %s", buf) writer, err := c.conn.NextWriter(websocket.TextMessage) if err != nil { c.handleIOError(err) @@ -438,15 +438,15 @@ func (c *Connection) sendLoop() { return } case code := <-c.closeCh: - c.logger.Debugf("Connection:sendLoop:<-c.closeCh", "wsURL:%q code:%d", c.wsURL, code) + c.logger.Debugf("Connection:sendLoop:<-c.closeCh wsURL:%q code:%d", c.wsURL, code) _ = c.closeConnection(code) case <-c.done: - c.logger.Debugf("Connection:sendLoop:<-c.done#2", "wsURL:%q", c.wsURL) + c.logger.Debugf("Connection:sendLoop:<-c.done#2 wsURL:%q", c.wsURL) case <-c.ctx.Done(): - c.logger.Debugf("connection:sendLoop", "returning, ctx.Err: %q", c.ctx.Err()) + c.logger.Debugf("connection:sendLoop returning, ctx.Err: %q", c.ctx.Err()) return // case <-time.After(time.Second * 10): - // c.logger.Errorf("connection:sendLoop", "returning, timeout") + // c.logger.Errorf("connection:sendLoop returning, timeout") // c.Close() // return } @@ -458,13 +458,13 @@ func (c *Connection) Close(args ...goja.Value) { if len(args) > 0 { code = int(args[0].ToInteger()) } - c.logger.Debugf("connection:Close", "wsURL:%q code:%d", c.wsURL, code) + c.logger.Debugf("connection:Close wsURL:%q code:%d", c.wsURL, code) _ = c.closeConnection(code) } // Execute implements cdproto.Executor and performs a synchronous send and receive func (c *Connection) Execute(ctx context.Context, method string, params easyjson.Marshaler, res easyjson.Unmarshaler) error { - c.logger.Debugf("connection:Execute", "wsURL:%q method:%q", c.wsURL, method) + c.logger.Debugf("connection:Execute wsURL:%q method:%q", c.wsURL, method) id := atomic.AddInt64(&c.msgID, 1) // Setup event handler used to block for response to message being sent. @@ -475,14 +475,14 @@ func (c *Connection) Execute(ctx context.Context, method string, params easyjson for { select { case <-evCancelCtx.Done(): - c.logger.Debugf("connection:Execute:<-evCancelCtx.Done()", "wsURL:%q err:%v", c.wsURL, evCancelCtx.Err()) + c.logger.Debugf("connection:Execute:<-evCancelCtx.Done() wsURL:%q err:%v", c.wsURL, evCancelCtx.Err()) return case ev := <-chEvHandler: msg, ok := ev.data.(*cdproto.Message) if ok && msg.ID == id { select { case <-evCancelCtx.Done(): - c.logger.Debugf("connection:Execute:<-evCancelCtx.Done()#2", "wsURL:%q err:%v", c.wsURL, evCancelCtx.Err()) + c.logger.Debugf("connection:Execute:<-evCancelCtx.Done()#2 wsURL:%q err:%v", c.wsURL, evCancelCtx.Err()) case ch <- msg: // We expect only one response with the matching message ID, // then remove event handler by cancelling context and stopping goroutine. diff --git a/common/connection_test.go b/common/connection_test.go index a6282ca4c..b5fa5458b 100644 --- a/common/connection_test.go +++ b/common/connection_test.go @@ -44,7 +44,7 @@ func TestConnection(t *testing.T) { ctx := context.Background() url, _ := url.Parse(server.ServerHTTP.URL) wsURL := fmt.Sprintf("ws://%s/echo", url.Host) - conn, err := NewConnection(ctx, wsURL, NewLogger(ctx, NullLogger(), false, nil)) + conn, err := NewConnection(ctx, wsURL, NewLogger(NullLogger())) conn.Close() require.NoError(t, err) @@ -59,7 +59,7 @@ func TestConnectionClosureAbnormal(t *testing.T) { ctx := context.Background() url, _ := url.Parse(server.ServerHTTP.URL) wsURL := fmt.Sprintf("ws://%s/closure-abnormal", url.Host) - conn, err := NewConnection(ctx, wsURL, NewLogger(ctx, NullLogger(), false, nil)) + conn, err := NewConnection(ctx, wsURL, NewLogger(NullLogger())) if assert.NoError(t, err) { action := target.SetDiscoverTargets(true) @@ -77,7 +77,7 @@ func TestConnectionSendRecv(t *testing.T) { ctx := context.Background() url, _ := url.Parse(server.ServerHTTP.URL) wsURL := fmt.Sprintf("ws://%s/cdp", url.Host) - conn, err := NewConnection(ctx, wsURL, NewLogger(ctx, NullLogger(), false, nil)) + conn, err := NewConnection(ctx, wsURL, NewLogger(NullLogger())) if assert.NoError(t, err) { action := target.SetDiscoverTargets(true) @@ -141,7 +141,7 @@ func TestConnectionCreateSession(t *testing.T) { ctx := context.Background() url, _ := url.Parse(server.ServerHTTP.URL) wsURL := fmt.Sprintf("ws://%s/cdp", url.Host) - conn, err := NewConnection(ctx, wsURL, NewLogger(ctx, NullLogger(), false, nil)) + conn, err := NewConnection(ctx, wsURL, NewLogger(NullLogger())) if assert.NoError(t, err) { session, err := conn.createSession(&target.Info{ diff --git a/common/frame_manager.go b/common/frame_manager.go index 161af3a2e..4e21e7583 100644 --- a/common/frame_manager.go +++ b/common/frame_manager.go @@ -309,7 +309,7 @@ func (m *FrameManager) requestFailed(req *Request, canceled bool) { frame := req.getFrame() if frame == nil { - m.logger.Debugf("FrameManager:requestFailed", "frame is nil") + m.logger.Debugf("FrameManager:requestFailed frame is nil") return } frame.deleteRequest(req.getID()) @@ -320,7 +320,7 @@ func (m *FrameManager) requestFailed(req *Request, canceled bool) { case rc <= 10: for reqID := range frame.inflightRequests { req := frame.requestByID(reqID) - m.logger.Debugf("FrameManager:requestFailed", "reqID:%s inflightURL:%s frameID:%s", reqID, req.url, frame.id) + m.logger.Debugf("FrameManager:requestFailed reqID:%s inflightURL:%s frameID:%s", reqID, req.url, frame.id) } } diff --git a/common/frame_session.go b/common/frame_session.go index 591a8590b..57d9b9193 100644 --- a/common/frame_session.go +++ b/common/frame_session.go @@ -80,7 +80,7 @@ type FrameSession struct { } func NewFrameSession(ctx context.Context, session *Session, page *Page, parent *FrameSession, targetID target.ID, logger *Logger) (*FrameSession, error) { - logger.Debugf("NewFrameSession", "sid:%v tid:%v", session.id, targetID) + logger.Debugf("NewFrameSession sid:%v tid:%v", session.id, targetID) fs := FrameSession{ ctx: ctx, // TODO: create cancelable context that can be used to cancel and close all child sessions session: session, @@ -99,43 +99,43 @@ func NewFrameSession(ctx context.Context, session *Session, page *Page, parent * } var err error if fs.parent != nil { - fs.networkManager, err = NewNetworkManager(ctx, session, fs.manager, fs.parent.networkManager) + fs.networkManager, err = NewNetworkManager(ctx, session, fs.manager, fs.parent.networkManager, logger) if err != nil { - logger.Debugf("NewFrameSession:NewNetworkManager", "sid:%v tid:%v err:%v", session.id, targetID, err) + logger.Debugf("NewFrameSession:NewNetworkManager sid:%v tid:%v err:%v", session.id, targetID, err) return nil, err } } else { - fs.networkManager, err = NewNetworkManager(ctx, session, fs.manager, nil) + fs.networkManager, err = NewNetworkManager(ctx, session, fs.manager, nil, logger) if err != nil { - logger.Debugf("NewFrameSession:NewNetworkManager#2", "sid:%v tid:%v err:%v", session.id, targetID, err) + logger.Debugf("NewFrameSession:NewNetworkManager#2 sid:%v tid:%v err:%v", session.id, targetID, err) return nil, err } } action := browser.GetWindowForTarget().WithTargetID(fs.targetID) if fs.windowID, _, err = action.Do(cdp.WithExecutor(fs.ctx, fs.session)); err != nil { - logger.Debugf("NewFrameSession:GetWindowForTarget", "sid:%v tid:%v err:%v", session.id, targetID, err) + logger.Debugf("NewFrameSession:GetWindowForTarget sid:%v tid:%v err:%v", session.id, targetID, err) return nil, fmt.Errorf(`unable to get window ID: %w`, err) } fs.initEvents() if err = fs.initFrameTree(); err != nil { - logger.Debugf("NewFrameSession:initFrameTree", "sid:%v tid:%v err:%v", session.id, targetID, err) + logger.Debugf("NewFrameSession:initFrameTree sid:%v tid:%v err:%v", session.id, targetID, err) return nil, err } if err = fs.initIsolatedWorld(utilityWorldName); err != nil { - logger.Debugf("NewFrameSession:initIsolatedWorld", "sid:%v tid:%v err:%v", session.id, targetID, err) + logger.Debugf("NewFrameSession:initIsolatedWorld sid:%v tid:%v err:%v", session.id, targetID, err) return nil, err } if err = fs.initDomains(); err != nil { - logger.Debugf("NewFrameSession:initDomains", "sid:%v tid:%v err:%v", session.id, targetID, err) + logger.Debugf("NewFrameSession:initDomains sid:%v tid:%v err:%v", session.id, targetID, err) return nil, err } if err = fs.initOptions(); err != nil { - logger.Debugf("NewFrameSession:initOptions", "sid:%v tid:%v err:%v", session.id, targetID, err) + logger.Debugf("NewFrameSession:initOptions sid:%v tid:%v err:%v", session.id, targetID, err) return nil, err } - logger.Debugf("NewFrameSession", "sid:%v tid:%v wid:%v err:%v", session.id, targetID, fs.windowID, err) + logger.Debugf("NewFrameSession sid:%v tid:%v wid:%v err:%v", session.id, targetID, fs.windowID, err) return &fs, nil } @@ -181,8 +181,7 @@ func (fs *FrameSession) initDomains() error { } func (fs *FrameSession) initEvents() { - fs.logger.Debugf("NewFrameSession:initEvents", - "sid:%v tid:%v", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:initEvents sid:%v tid:%v", fs.session.id, fs.targetID) events := []string{ cdproto.EventInspectorTargetCrashed, @@ -193,18 +192,13 @@ func (fs *FrameSession) initEvents() { } go func() { - fs.logger.Debugf("NewFrameSession:initEvents:go", - "sid:%v tid:%v", fs.session.id, fs.targetID) - defer fs.logger.Debugf("NewFrameSession:initEvents:go", - "sid:%v tid:%v, returns", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:initEvents:go sid:%v tid:%v", fs.session.id, fs.targetID) + defer fs.logger.Debugf("NewFrameSession:initEvents:go sid:%v tid:%v, returns", fs.session.id, fs.targetID) for { select { case <-fs.ctx.Done(): - fs.logger.Debugf( - "NewFrameSession:initEvents:go:ctx.Done", - "sid:%v tid:%v", - fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:initEvents:go:ctx.Done sid:%v tid:%v", fs.session.id, fs.targetID) return case event := <-fs.eventCh: if ev, ok := event.data.(*inspector.EventTargetCrashed); ok { @@ -248,8 +242,7 @@ func (fs *FrameSession) initEvents() { } func (fs *FrameSession) initFrameTree() error { - fs.logger.Debugf("NewFrameSession:initFrameTree", - "sid:%v tid:%v", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:initFrameTree sid:%v tid:%v", fs.session.id, fs.targetID) action := cdppage.Enable() if err := action.Do(cdp.WithExecutor(fs.ctx, fs.session)); err != nil { @@ -277,8 +270,7 @@ func (fs *FrameSession) initFrameTree() error { } func (fs *FrameSession) initIsolatedWorld(name string) error { - fs.logger.Debugf("NewFrameSession:initIsolatedWorld", - "sid:%v tid:%v", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:initIsolatedWorld sid:%v tid:%v", fs.session.id, fs.targetID) action := cdppage.SetLifecycleEventsEnabled(true) if err := action.Do(cdp.WithExecutor(fs.ctx, fs.session)); err != nil { @@ -286,8 +278,7 @@ func (fs *FrameSession) initIsolatedWorld(name string) error { } if _, ok := fs.isolatedWorlds[name]; ok { - fs.logger.Debugf("NewFrameSession:initIsolatedWorld", - "sid:%v tid:%v, not found: %q", fs.session.id, fs.targetID, name) + fs.logger.Debugf("NewFrameSession:initIsolatedWorld sid:%v tid:%v, not found: %q", fs.session.id, fs.targetID, name) return nil } fs.isolatedWorlds[name] = true @@ -307,9 +298,7 @@ func (fs *FrameSession) initIsolatedWorld(name string) error { }, nil) } - fs.logger.Debugf( - "NewFrameSession:initIsolatedWorld:AddScriptToEvaluateOnNewDocument", - "sid:%v tid:%v", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:initIsolatedWorld:AddScriptToEvaluateOnNewDocument sid:%v tid:%v", fs.session.id, fs.targetID) action2 := cdppage.AddScriptToEvaluateOnNewDocument(`//# sourceURL=` + evaluationScriptURL). WithWorldName(name) @@ -320,8 +309,7 @@ func (fs *FrameSession) initIsolatedWorld(name string) error { } func (fs *FrameSession) initOptions() error { - fs.logger.Debugf("NewFrameSession:initOptions", - "sid:%v tid:%v", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:initOptions sid:%v tid:%v", fs.session.id, fs.targetID) opts := fs.manager.page.browserCtx.opts optActions := []Action{} @@ -329,10 +317,7 @@ func (fs *FrameSession) initOptions() error { if fs.isMainFrame() { optActions = append(optActions, emulation.SetFocusEmulationEnabled(true)) if err := fs.updateViewport(); err != nil { - fs.logger.Debugf( - "NewFrameSession:initOptions:updateViewport", - "sid:%v tid:%v, err:%v", - fs.session.id, fs.targetID, err) + fs.logger.Debugf("NewFrameSession:initOptions:updateViewport sid:%v tid:%v, err:%v", fs.session.id, fs.targetID, err) return err } } @@ -394,8 +379,7 @@ func (fs *FrameSession) initOptions() error { } func (fs *FrameSession) initRendererEvents() { - fs.logger.Debugf("NewFrameSession:initEvents:initRendererEvents", - "sid:%v tid:%v", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:initEvents:initRendererEvents sid:%v tid:%v", fs.session.id, fs.targetID) events := []string{ cdproto.EventLogEntryAdded, @@ -425,8 +409,7 @@ func (fs *FrameSession) isMainFrame() bool { } func (fs *FrameSession) handleFrameTree(frameTree *cdppage.FrameTree) { - fs.logger.Debugf("NewFrameSession:handleFrameTree", - "sid:%v tid:%v", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:handleFrameTree sid:%v tid:%v", fs.session.id, fs.targetID) if frameTree.Frame.ParentID != "" { fs.onFrameAttached(frameTree.Frame.ID, frameTree.Frame.ParentID) @@ -441,9 +424,7 @@ func (fs *FrameSession) handleFrameTree(frameTree *cdppage.FrameTree) { } func (fs *FrameSession) navigateFrame(frame *Frame, url, referrer string) (string, error) { - fs.logger.Debugf("NewFrameSession:navigateFrame", - "sid:%v tid:%v url:%q referrer:%q", - fs.session.id, fs.targetID, url, referrer) + fs.logger.Debugf("NewFrameSession:navigateFrame sid:%v tid:%v url:%q referrer:%q", fs.session.id, fs.targetID, url, referrer) action := cdppage.Navigate(url).WithReferrer(referrer).WithFrameID(cdp.FrameID(frame.ID())) _, documentID, errorText, err := action.Do(cdp.WithExecutor(fs.ctx, fs.session)) @@ -454,13 +435,11 @@ func (fs *FrameSession) navigateFrame(frame *Frame, url, referrer string) (strin } func (fs *FrameSession) onConsoleAPICalled(event *runtime.EventConsoleAPICalled) { - // TODO: switch to using browser logger instead of directly outputting to k6 logging system - state := k6lib.GetState(fs.ctx) - l := state.Logger. + le := fs.logger. WithTime(event.Timestamp.Time()). WithField("source", "browser-console-api") - if state.Group.Path != "" { - l = l.WithField("group", state.Group.Path) + if s := k6lib.GetState(fs.ctx); s.Group.Path != "" { + le = le.WithField("group", s.Group.Path) } var convertedArgs []interface{} for _, arg := range event.Args { @@ -473,15 +452,15 @@ func (fs *FrameSession) onConsoleAPICalled(event *runtime.EventConsoleAPICalled) } switch event.Type { case "log": - l.Info(convertedArgs...) + le.Info(convertedArgs...) case "info": - l.Info(convertedArgs...) + le.Info(convertedArgs...) case "warning": - l.Warn(convertedArgs...) + le.Warn(convertedArgs...) case "error": - l.Error(convertedArgs...) + le.Error(convertedArgs...) default: - l.Debug(convertedArgs...) + le.Debug(convertedArgs...) } } @@ -490,8 +469,7 @@ func (fs *FrameSession) onExceptionThrown(event *runtime.EventExceptionThrown) { } func (fs *FrameSession) onExecutionContextCreated(event *runtime.EventExecutionContextCreated) { - fs.logger.Debugf("NewFrameSession:onExecutionContextCreated", - "sid:%v tid:%v ectxid:%v", fs.session.id, fs.targetID, event.Context.ID) + fs.logger.Debugf("NewFrameSession:onExecutionContextCreated sid:%v tid:%v ectxid:%v", fs.session.id, fs.targetID, event.Context.ID) auxData := event.Context.AuxData var i struct { @@ -527,8 +505,7 @@ func (fs *FrameSession) onExecutionContextCreated(event *runtime.EventExecutionC } func (fs *FrameSession) onExecutionContextDestroyed(execCtxID runtime.ExecutionContextID) { - fs.logger.Debugf("NewFrameSession:onExecutionContextDestroyed", - "sid:%v tid:%v ectxid:%v", fs.session.id, fs.targetID, execCtxID) + fs.logger.Debugf("NewFrameSession:onExecutionContextDestroyed sid:%v tid:%v ectxid:%v", fs.session.id, fs.targetID, execCtxID) fs.contextIDToContextMu.Lock() defer fs.contextIDToContextMu.Unlock() @@ -543,8 +520,7 @@ func (fs *FrameSession) onExecutionContextDestroyed(execCtxID runtime.ExecutionC } func (fs *FrameSession) onExecutionContextsCleared() { - fs.logger.Debugf("NewFrameSession:onExecutionContextsCleared", - "sid:%v tid:%v", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:onExecutionContextsCleared sid:%v tid:%v", fs.session.id, fs.targetID) fs.contextIDToContextMu.Lock() defer fs.contextIDToContextMu.Unlock() @@ -559,24 +535,20 @@ func (fs *FrameSession) onExecutionContextsCleared() { } func (fs *FrameSession) onFrameAttached(frameID cdp.FrameID, parentFrameID cdp.FrameID) { - fs.logger.Debugf("NewFrameSession:onFrameAttached", - "sid:%v tid:%v fid:%v pfid:%v", - fs.session.id, fs.targetID, frameID, parentFrameID) + fs.logger.Debugf("NewFrameSession:onFrameAttached sid:%v tid:%v fid:%v pfid:%v", fs.session.id, fs.targetID, frameID, parentFrameID) // TODO: add handling for cross-process frame transitioning fs.manager.frameAttached(frameID, parentFrameID) } func (fs *FrameSession) onFrameDetached(frameID cdp.FrameID) { - fs.logger.Debugf("NewFrameSession:onFrameDetached", - "sid:%v tid:%v fid:%v", fs.session.id, fs.targetID, frameID) + fs.logger.Debugf("NewFrameSession:onFrameDetached sid:%v tid:%v fid:%v", fs.session.id, fs.targetID, frameID) fs.manager.frameDetached(frameID) } func (fs *FrameSession) onFrameNavigated(frame *cdp.Frame, initial bool) { - fs.logger.Debugf("NewFrameSession:onFrameNavigated", - "sid:%v tid:%v fid:%v", fs.session.id, fs.targetID, frame.ID) + fs.logger.Debugf("NewFrameSession:onFrameNavigated sid:%v tid:%v fid:%v", fs.session.id, fs.targetID, frame.ID) err := fs.manager.frameNavigated(frame.ID, frame.ParentID, frame.LoaderID.String(), frame.Name, frame.URL+frame.URLFragment, initial) if err != nil { @@ -585,8 +557,7 @@ func (fs *FrameSession) onFrameNavigated(frame *cdp.Frame, initial bool) { } func (fs *FrameSession) onFrameRequestedNavigation(event *cdppage.EventFrameRequestedNavigation) { - fs.logger.Debugf("NewFrameSession:onFrameRequestedNavigation", - "sid:%v tid:%v fid:%v url:%q", + fs.logger.Debugf("NewFrameSession:onFrameRequestedNavigation sid:%v tid:%v fid:%v url:%q", fs.session.id, fs.targetID, event.FrameID, event.URL) if event.Disposition == "currentTab" { @@ -598,30 +569,27 @@ func (fs *FrameSession) onFrameRequestedNavigation(event *cdppage.EventFrameRequ } func (fs *FrameSession) onFrameStartedLoading(frameID cdp.FrameID) { - fs.logger.Debugf("NewFrameSession:onFrameStartedLoading", - "sid:%v tid:%v fid:%v", fs.session.id, fs.targetID, frameID) + fs.logger.Debugf("NewFrameSession:onFrameStartedLoading sid:%v tid:%v fid:%v", fs.session.id, fs.targetID, frameID) fs.manager.frameLoadingStarted(frameID) } func (fs *FrameSession) onFrameStoppedLoading(frameID cdp.FrameID) { - fs.logger.Debugf("NewFrameSession:onFrameStoppedLoading", - "sid:%v tid:%v fid:%v", fs.session.id, fs.targetID, frameID) + fs.logger.Debugf("NewFrameSession:onFrameStoppedLoading sid:%v tid:%v fid:%v", fs.session.id, fs.targetID, frameID) fs.manager.frameLoadingStopped(frameID) } func (fs *FrameSession) onLogEntryAdded(event *log.EventEntryAdded) { - // TODO: switch to using Browser logger instead of directly outputting to k6 logging system - state := k6lib.GetState(fs.ctx) - l := state.Logger. + l := fs.logger. WithTime(event.Entry.Timestamp.Time()). WithField("source", "browser"). WithField("url", event.Entry.URL). WithField("browser_source", event.Entry.Source.String()). WithField("line_number", event.Entry.LineNumber) - if state.Group.Path != "" { - l = l.WithField("group", state.Group.Path) + + if s := k6lib.GetState(fs.ctx); s.Group.Path != "" { + l = l.WithField("group", s.Group.Path) } switch event.Entry.Level { case "info": @@ -636,9 +604,7 @@ func (fs *FrameSession) onLogEntryAdded(event *log.EventEntryAdded) { } func (fs *FrameSession) onPageLifecycle(event *cdppage.EventLifecycleEvent) { - fs.logger.Debugf("NewFrameSession:onPageLifecycle", - "sid:%v tid:%v fid:%v event:%q", - fs.session.id, fs.targetID, event.FrameID, event.Name) + fs.logger.Debugf("NewFrameSession:onPageLifecycle sid:%v tid:%v fid:%v event:%q", fs.session.id, fs.targetID, event.FrameID, event.Name) state := k6lib.GetState(fs.ctx) if event.Name == "init" || event.Name == "commit" { @@ -717,15 +683,13 @@ func (fs *FrameSession) onPageLifecycle(event *cdppage.EventLifecycleEvent) { } func (fs *FrameSession) onPageNavigatedWithinDocument(event *cdppage.EventNavigatedWithinDocument) { - fs.logger.Debugf("NewFrameSession:onPageNavigatedWithinDocument", - "sid:%v tid:%v fid:%v", fs.session.id, fs.targetID, event.FrameID) + fs.logger.Debugf("NewFrameSession:onPageNavigatedWithinDocument sid:%v tid:%v fid:%v", fs.session.id, fs.targetID, event.FrameID) fs.manager.frameNavigatedWithinDocument(event.FrameID, event.URL) } func (fs *FrameSession) onAttachedToTarget(event *target.EventAttachedToTarget) { - fs.logger.Debugf("NewFrameSession:onAttachedToTarget", - "sid:%v tid:%v esid:%v etid:%v ebctxid:%v type:%q", + fs.logger.Debugf("NewFrameSession:onAttachedToTarget sid:%v tid:%v esid:%v etid:%v ebctxid:%v type:%q", fs.session.id, fs.targetID, event.SessionID, event.TargetInfo.TargetID, event.TargetInfo.BrowserContextID, event.TargetInfo.Type) @@ -771,19 +735,19 @@ func (fs *FrameSession) onAttachedToTarget(event *target.EventAttachedToTarget) } func (fs *FrameSession) onDetachedFromTarget(event *target.EventDetachedFromTarget) { - fs.logger.Debugf("NewFrameSession:onDetachedFromTarget", "sid:%v tid:%v esid:%v", fs.session.id, fs.targetID, event.SessionID) + fs.logger.Debugf("NewFrameSession:onDetachedFromTarget sid:%v tid:%v esid:%v", fs.session.id, fs.targetID, event.SessionID) fs.page.closeWorker(event.SessionID) } func (fs *FrameSession) onTargetCrashed(event *inspector.EventTargetCrashed) { - fs.logger.Debugf("NewFrameSession:onTargetCrashed", "sid:%v tid:%v", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:onTargetCrashed sid:%v tid:%v", fs.session.id, fs.targetID) fs.session.markAsCrashed() fs.page.didCrash() } func (fs *FrameSession) updateEmulateMedia(initial bool) error { - fs.logger.Debugf("NewFrameSession:updateEmulateMedia", "sid:%v tid:%v", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:updateEmulateMedia sid:%v tid:%v", fs.session.id, fs.targetID) features := make([]*emulation.MediaFeature, 0) switch fs.page.colorScheme { @@ -812,7 +776,7 @@ func (fs *FrameSession) updateEmulateMedia(initial bool) error { } func (fs *FrameSession) updateExtraHTTPHeaders(initial bool) { - fs.logger.Debugf("NewFrameSession:updateExtraHTTPHeaders", "sid:%v tid:%v", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:updateExtraHTTPHeaders sid:%v tid:%v", fs.session.id, fs.targetID) // Merge extra headers from browser context and page, where page specific headers ake precedence. mergedHeaders := make(network.Headers) @@ -828,7 +792,7 @@ func (fs *FrameSession) updateExtraHTTPHeaders(initial bool) { } func (fs *FrameSession) updateGeolocation(initial bool) error { - fs.logger.Debugf("NewFrameSession:updateGeolocation", "sid:%v tid:%v", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:updateGeolocation sid:%v tid:%v", fs.session.id, fs.targetID) geolocation := fs.page.browserCtx.opts.Geolocation if !initial || geolocation != nil { @@ -844,7 +808,7 @@ func (fs *FrameSession) updateGeolocation(initial bool) error { } func (fs *FrameSession) updateHttpCredentials(initial bool) { - fs.logger.Debugf("NewFrameSession:updateHttpCredentials", "sid:%v tid:%v", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:updateHttpCredentials sid:%v tid:%v", fs.session.id, fs.targetID) credentials := fs.page.browserCtx.opts.HttpCredentials if !initial || credentials != nil { @@ -853,7 +817,7 @@ func (fs *FrameSession) updateHttpCredentials(initial bool) { } func (fs *FrameSession) updateOffline(initial bool) { - fs.logger.Debugf("NewFrameSession:updateOffline", "sid:%v tid:%v", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:updateOffline sid:%v tid:%v", fs.session.id, fs.targetID) offline := fs.page.browserCtx.opts.Offline if !initial || offline { @@ -862,13 +826,13 @@ func (fs *FrameSession) updateOffline(initial bool) { } func (fs *FrameSession) updateRequestInterception(initial bool) error { - fs.logger.Debugf("NewFrameSession:updateRequestInterception", "sid:%v tid:%v", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:updateRequestInterception sid:%v tid:%v", fs.session.id, fs.targetID) return fs.networkManager.setRequestInterception(fs.page.hasRoutes()) } func (fs *FrameSession) updateViewport() error { - fs.logger.Debugf("NewFrameSession:updateViewport", "sid:%v tid:%v", fs.session.id, fs.targetID) + fs.logger.Debugf("NewFrameSession:updateViewport sid:%v tid:%v", fs.session.id, fs.targetID) opts := fs.page.browserCtx.opts emulatedSize := fs.page.emulatedSize diff --git a/common/helper_test.go b/common/helper_test.go index 0db28f9f2..734195d51 100644 --- a/common/helper_test.go +++ b/common/helper_test.go @@ -153,7 +153,7 @@ func TestHelpersConvertArgument(t *testing.T) { execCtx := NewExecutionContext(ctx, nil, nil, runtime.ExecutionContextID(123456789)) rt := goja.New() timeoutSetings := NewTimeoutSettings(nil) - frameManager := NewFrameManager(ctx, nil, nil, timeoutSetings, NewLogger(ctx, NullLogger(), false, nil)) + frameManager := NewFrameManager(ctx, nil, nil, timeoutSetings, NewLogger(NullLogger())) frame := NewFrame(ctx, frameManager, nil, cdp.FrameID("frame_id_0123456789")) remoteObjValue := "hellow world" result, _ := json.Marshal(remoteObjValue) @@ -176,7 +176,7 @@ func TestHelpersConvertArgument(t *testing.T) { execCtx := NewExecutionContext(ctx, nil, nil, runtime.ExecutionContextID(123456789)) rt := goja.New() timeoutSetings := NewTimeoutSettings(nil) - frameManager := NewFrameManager(ctx, nil, nil, timeoutSetings, NewLogger(ctx, NullLogger(), false, nil)) + frameManager := NewFrameManager(ctx, nil, nil, timeoutSetings, NewLogger(NullLogger())) frame := NewFrame(ctx, frameManager, nil, cdp.FrameID("frame_id_0123456789")) remoteObjectID := runtime.RemoteObjectID("object_id_0123456789") remoteObject := &runtime.RemoteObject{ @@ -198,7 +198,7 @@ func TestHelpersConvertArgument(t *testing.T) { execCtx := NewExecutionContext(ctx, nil, nil, runtime.ExecutionContextID(123456789)) rt := goja.New() timeoutSetings := NewTimeoutSettings(nil) - frameManager := NewFrameManager(ctx, nil, nil, timeoutSetings, NewLogger(ctx, NullLogger(), false, nil)) + frameManager := NewFrameManager(ctx, nil, nil, timeoutSetings, NewLogger(NullLogger())) frame := NewFrame(ctx, frameManager, nil, cdp.FrameID("frame_id_0123456789")) remoteObjectID := runtime.RemoteObjectID("object_id_0123456789") remoteObject := &runtime.RemoteObject{ @@ -220,7 +220,7 @@ func TestHelpersConvertArgument(t *testing.T) { execCtx := NewExecutionContext(ctx, nil, nil, runtime.ExecutionContextID(123456789)) rt := goja.New() timeoutSetings := NewTimeoutSettings(nil) - frameManager := NewFrameManager(ctx, nil, nil, timeoutSetings, NewLogger(ctx, NullLogger(), false, nil)) + frameManager := NewFrameManager(ctx, nil, nil, timeoutSetings, NewLogger(NullLogger())) frame := NewFrame(ctx, frameManager, nil, cdp.FrameID("frame_id_0123456789")) remoteObjectID := runtime.RemoteObjectID("object_id_0123456789") remoteObject := &runtime.RemoteObject{ diff --git a/common/logger.go b/common/logger.go index 1b0aa2a71..638a88aec 100644 --- a/common/logger.go +++ b/common/logger.go @@ -21,27 +21,16 @@ package common import ( - "context" "fmt" "io/ioutil" - "regexp" "runtime" - "strconv" "strings" - "sync" - "time" - "github.com/fatih/color" "github.com/sirupsen/logrus" ) type Logger struct { - ctx context.Context - log *logrus.Logger - mu sync.Mutex - lastLogCall int64 - debugOverride bool - categoryFilter *regexp.Regexp + *logrus.Logger } func NullLogger() *logrus.Logger { @@ -50,111 +39,41 @@ func NullLogger() *logrus.Logger { return log } -func NewLogger(ctx context.Context, logger *logrus.Logger, debugOverride bool, categoryFilter *regexp.Regexp) *Logger { - return &Logger{ - ctx: ctx, - log: logger, - debugOverride: debugOverride, - categoryFilter: categoryFilter, - } -} - -func (l *Logger) Tracef(category string, msg string, args ...interface{}) { - l.Logf(logrus.TraceLevel, category, msg, args...) -} - -func (l *Logger) Debugf(category string, msg string, args ...interface{}) { - l.Logf(logrus.DebugLevel, category, msg, args...) -} - -func (l *Logger) Errorf(category string, msg string, args ...interface{}) { - l.Logf(logrus.ErrorLevel, category, msg, args...) -} - -func (l *Logger) Infof(category string, msg string, args ...interface{}) { - l.Logf(logrus.InfoLevel, category, msg, args...) -} - -func (l *Logger) Warnf(category string, msg string, args ...interface{}) { - l.Logf(logrus.WarnLevel, category, msg, args...) -} - -func (l *Logger) Logf(level logrus.Level, category string, msg string, args ...interface{}) { - // don't log if the current log level isn't in the required level. - if l.log.GetLevel() < level { - return - } - l.mu.Lock() - defer l.mu.Unlock() - - now := time.Now().UnixNano() / 1000000 - elapsed := now - l.lastLogCall - if now == elapsed { - elapsed = 0 - } - defer func() { - l.lastLogCall = now - }() - - if l.categoryFilter != nil && !l.categoryFilter.Match([]byte(category)) { - return - } - if l.log == nil { - magenta := color.New(color.FgMagenta).SprintFunc() - fmt.Printf("%s [%d]: %s - %s ms\n", magenta(category), goRoutineID(), string(msg), magenta(elapsed)) - return - } - entry := l.log.WithFields(logrus.Fields{ - "category": category, - "elapsed": fmt.Sprintf("%d ms", elapsed), - "goroutine": goRoutineID(), - }) - if l.log.GetLevel() < level && l.debugOverride { - entry.Printf(msg, args...) - return - } - entry.Logf(level, msg, args...) -} - -// SetLevel sets the logger level from a level string. -// Accepted values: -func (l *Logger) SetLevel(level string) error { - pl, err := logrus.ParseLevel(level) - if err != nil { - return err - } - l.log.SetLevel(pl) - return nil +func NewLogger(logger *logrus.Logger) *Logger { + return &Logger{logger} } // DebugMode returns true if the logger level is set to Debug or higher. func (l *Logger) DebugMode() bool { - return l.log.GetLevel() >= logrus.DebugLevel + return l.Logger.GetLevel() >= logrus.DebugLevel } // ReportCaller adds source file and function names to the log entries. -func (l *Logger) ReportCaller() { +func (l *Logger) EnableReportCaller() { + const mod = "github.com/grafana/xk6-browser" + + // strip the module informaiton + strip := func(s string) string { + if !strings.Contains(s, mod) { + return s + } + s = strings.TrimPrefix(s, mod) + s = s[strings.Index(s, "/")+1:] + return s + } caller := func() func(*runtime.Frame) (string, string) { - return func(f *runtime.Frame) (function string, file string) { - return f.Func.Name(), fmt.Sprintf("%s:%d", f.File, f.Line) + return func(f *runtime.Frame) (fn string, loc string) { + // find the caller of the log func + fn = f.Func.Name() + _, file, no, ok := runtime.Caller(8) + if ok { + fn = fmt.Sprintf("%s:%d", strip(file), no) + } + return fn, "" } } - l.log.SetFormatter(&logrus.TextFormatter{ + l.SetFormatter(&logrus.TextFormatter{ CallerPrettyfier: caller(), - FieldMap: logrus.FieldMap{ - logrus.FieldKeyFile: "caller", - }, }) - l.log.SetReportCaller(true) -} - -func goRoutineID() int { - var buf [64]byte - n := runtime.Stack(buf[:], false) - idField := strings.Fields(strings.TrimPrefix(string(buf[:n]), "goroutine "))[0] - id, err := strconv.Atoi(idField) - if err != nil { - panic(fmt.Sprintf("cannot get goroutine id: %v", err)) - } - return id + l.SetReportCaller(true) } diff --git a/common/network_manager.go b/common/network_manager.go index aacac2200..54e578989 100644 --- a/common/network_manager.go +++ b/common/network_manager.go @@ -69,14 +69,12 @@ type NetworkManager struct { // NewNetworkManager creates a new network manager func NewNetworkManager( ctx context.Context, session *Session, manager *FrameManager, parent *NetworkManager, + logger *Logger, ) (*NetworkManager, error) { - state := k6lib.GetState(ctx) m := NetworkManager{ - BaseEventEmitter: NewBaseEventEmitter(ctx), - 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: NewLogger(ctx, state.Logger, false, nil), + BaseEventEmitter: NewBaseEventEmitter(ctx), + ctx: ctx, + logger: logger, session: session, parent: parent, frameManager: manager, @@ -219,7 +217,7 @@ func (m *NetworkManager) emitResponseMetrics(resp *Response) { } func (m *NetworkManager) handleRequestRedirect(req *Request, redirectResponse *network.Response, timestamp *cdp.MonotonicTime) { - resp := NewHTTPResponse(m.ctx, req, redirectResponse, timestamp) + resp := NewHTTPResponse(m.ctx, req, redirectResponse, timestamp, m.logger) req.response = resp req.redirectChain = append(req.redirectChain, req) @@ -343,16 +341,16 @@ func (m *NetworkManager) onRequest(event *network.EventRequestWillBeSent, interc frame = m.frameManager.getFrameByID(event.FrameID) } if frame == nil { - m.logger.Debugf("NetworkManager", "frame is nil") + m.logger.Debugf("NetworkManager frame is nil") } req, err := NewRequest(m.ctx, event, frame, redirectChain, interceptionID, m.userReqInterceptionEnabled) if err != nil { - m.logger.Errorf("NetworkManager", "cannot create Request: %s", err) + m.logger.Errorf("NetworkManager cannot create Request: %s", err) return } if req.url.Scheme == "data" { - m.logger.Debugf("NetworkManager", "skipped request handling of data URL") + m.logger.Debugf("NetworkManager skipped request handling of data URL") return } m.reqsMu.Lock() @@ -400,7 +398,7 @@ func (m *NetworkManager) onResponseReceived(event *network.EventResponseReceived if req == nil { return } - resp := NewHTTPResponse(m.ctx, req, event.Response, event.Timestamp) + resp := NewHTTPResponse(m.ctx, req, event.Response, event.Timestamp, m.logger) req.response = resp if req.url.Scheme != "data" { m.emitResponseMetrics(resp) diff --git a/common/page.go b/common/page.go index 5534ca1d5..7b2eee9b1 100644 --- a/common/page.go +++ b/common/page.go @@ -138,7 +138,7 @@ func (p *Page) initEvents() error { } func (p *Page) closeWorker(sessionID target.SessionID) { - p.logger.Debugf("Page:closeWorker", "sid:%v", sessionID) + p.logger.Debugf("Page:closeWorker sid:%v", sessionID) if worker, ok := p.workers[sessionID]; ok { worker.didClose() delete(p.workers, sessionID) @@ -150,13 +150,13 @@ func (p *Page) defaultTimeout() time.Duration { } func (p *Page) didClose() { - p.logger.Debugf("Page:didClose", "sid:%v", p.session.id) + p.logger.Debugf("Page:didClose sid:%v", p.session.id) p.closed = true p.emit(EventPageClose, p) } func (p *Page) didCrash() { - p.logger.Debugf("Page:didCrash", "sid:%v", p.session.id) + p.logger.Debugf("Page:didCrash sid:%v", p.session.id) p.frameManager.dispose() p.emit(EventPageCrash, p) } @@ -166,7 +166,7 @@ func (p *Page) evaluateOnNewDocument(source string) { } func (p *Page) getFrameElement(f *Frame) (*ElementHandle, error) { - p.logger.Debugf("Page:getFrameElement", "sid:%v", p.session.id) + p.logger.Debugf("Page:getFrameElement sid:%v", p.session.id) parent := f.parentFrame if parent == nil { return nil, errors.New("frame has been detached 1") @@ -191,7 +191,7 @@ func (p *Page) getFrameElement(f *Frame) (*ElementHandle, error) { } func (p *Page) getOwnerFrame(apiCtx context.Context, h *ElementHandle) cdp.FrameID { - p.logger.Debugf("Page:getOwnerFrame", "sid:%v", p.session.id) + p.logger.Debugf("Page:getOwnerFrame sid:%v", p.session.id) // document.documentElement has frameId of the owner frame rt := k6common.GetRuntime(p.ctx) pageFn := rt.ToValue(` @@ -228,7 +228,7 @@ func (p *Page) getOwnerFrame(apiCtx context.Context, h *ElementHandle) cdp.Frame } func (p *Page) getFrameSession(frameID cdp.FrameID) *FrameSession { - p.logger.Debugf("Page:getFrameSession", "sid:%v fid=%v", p.session.id, frameID) + p.logger.Debugf("Page:getFrameSession sid:%v fid=%v", p.session.id, frameID) return p.frameSessions[frameID] } @@ -310,7 +310,7 @@ func (p *Page) AddStyleTag(opts goja.Value) { // BringToFront activates the browser tab for this page func (p *Page) BringToFront() { - p.logger.Debugf("Page:BringToFront", "sid:%v", p.session.id) + p.logger.Debugf("Page:BringToFront sid:%v", p.session.id) rt := k6common.GetRuntime(p.ctx) action := cdppage.BringToFront() if err := action.Do(cdp.WithExecutor(p.ctx, p.session)); err != nil { @@ -349,7 +349,7 @@ func (p *Page) Dblclick(selector string, opts goja.Value) { } func (p *Page) DispatchEvent(selector string, typ string, eventInit goja.Value, opts goja.Value) { - p.logger.Debugf("Page:DispatchEvent", "sid:%v selector:%q", p.session.id, selector) + p.logger.Debugf("Page:DispatchEvent sid:%v selector:%q", p.session.id, selector) p.MainFrame().DispatchEvent(selector, typ, eventInit, opts) } @@ -458,7 +458,7 @@ func (p *Page) GoForward(opts goja.Value) api.Response { // Goto will navigate the page to the specified URL and return a HTTP response object func (p *Page) Goto(url string, opts goja.Value) api.Response { - p.logger.Debugf("Page:Goto", "sid:%v url:%q", p.session.id, url) + p.logger.Debugf("Page:Goto sid:%v url:%q", p.session.id, url) return p.MainFrame().Goto(url, opts) } @@ -532,18 +532,18 @@ func (p *Page) Press(selector string, key string, opts goja.Value) { } func (p *Page) Query(selector string) api.ElementHandle { - p.logger.Debugf("Page:Query", "sid:%v selector:%q", p.session.id, selector) + p.logger.Debugf("Page:Query sid:%v selector:%q", p.session.id, selector) return p.frameManager.MainFrame().Query(selector) } func (p *Page) QueryAll(selector string) []api.ElementHandle { - p.logger.Debugf("Page:QueryAll", "sid:%v selector:%q", p.session.id, selector) + p.logger.Debugf("Page:QueryAll sid:%v selector:%q", p.session.id, selector) return p.frameManager.MainFrame().QueryAll(selector) } // Reload will reload the current page func (p *Page) Reload(opts goja.Value) api.Response { - p.logger.Debugf("Page:Reload", "sid:%v", p.session.id) + p.logger.Debugf("Page:Reload sid:%v", p.session.id) rt := k6common.GetRuntime(p.ctx) parsedOpts := NewPageReloadOptions(LifecycleEventLoad, p.defaultTimeout()) if err := parsedOpts.Parse(p.ctx, opts); err != nil { @@ -616,13 +616,13 @@ func (p *Page) SetContent(html string, opts goja.Value) { // SetDefaultNavigationTimeout sets the default navigation timeout in milliseconds func (p *Page) SetDefaultNavigationTimeout(timeout int64) { - p.logger.Debugf("Page:SetDefaultNavigationTimeout", "sid:%v timeout=%d", p.session.id, timeout) + p.logger.Debugf("Page:SetDefaultNavigationTimeout sid:%v timeout=%d", p.session.id, timeout) p.timeoutSettings.setDefaultNavigationTimeout(timeout) } // SetDefaultTimeout sets the default maximum timeout in milliseconds func (p *Page) SetDefaultTimeout(timeout int64) { - p.logger.Debugf("Page:SetDefaultTimeout", "sid:%v timeout=%d", p.session.id, timeout) + p.logger.Debugf("Page:SetDefaultTimeout sid:%v timeout=%d", p.session.id, timeout) p.timeoutSettings.setDefaultTimeout(timeout) } @@ -640,7 +640,7 @@ func (p *Page) SetInputFiles(selector string, files goja.Value, opts goja.Value) // SetViewportSize will update the viewport width and height func (p *Page) SetViewportSize(viewportSize goja.Value) { - p.logger.Debugf("Page:SetViewportSize", "sid:%v", p.session.id) + p.logger.Debugf("Page:SetViewportSize sid:%v", p.session.id) rt := k6common.GetRuntime(p.ctx) s := &Size{} if err := s.Parse(p.ctx, viewportSize); err != nil { @@ -710,19 +710,19 @@ func (p *Page) WaitForEvent(event string, optsOrPredicate goja.Value) interface{ // WaitForFunction waits for the given predicate to return a truthy value func (p *Page) WaitForFunction(pageFunc goja.Value, arg goja.Value, opts goja.Value) api.JSHandle { - p.logger.Debugf("Page:WaitForFunction", "sid:%v", p.session.id) + p.logger.Debugf("Page:WaitForFunction sid:%v", p.session.id) return p.frameManager.MainFrame().WaitForFunction(pageFunc, opts, arg) } // WaitForLoadState waits for the specified page life cycle event func (p *Page) WaitForLoadState(state string, opts goja.Value) { - p.logger.Debugf("Page:WaitForLoadState", "sid:%v state=%q", p.session.id, state) + p.logger.Debugf("Page:WaitForLoadState sid:%v state=%q", p.session.id, state) p.frameManager.MainFrame().WaitForLoadState(state, opts) } // WaitForNavigation waits for the given navigation lifecycle event to happen func (p *Page) WaitForNavigation(opts goja.Value) api.Response { - p.logger.Debugf("Page:WaitForNavigation", "sid:%v", p.session.id) + p.logger.Debugf("Page:WaitForNavigation sid:%v", p.session.id) return p.frameManager.MainFrame().WaitForNavigation(opts) } @@ -740,13 +740,13 @@ func (p *Page) WaitForResponse(urlOrPredicate, opts goja.Value) api.Response { // WaitForSelector waits for the given selector to match the waiting criteria func (p *Page) WaitForSelector(selector string, opts goja.Value) api.ElementHandle { - p.logger.Debugf("Page:WaitForSelector", "sid:%v stid:%v ptid:%v selector:%q", p.session.id, p.session.targetID, p.targetID, selector) + p.logger.Debugf("Page:WaitForSelector sid:%v stid:%v ptid:%v selector:%q", p.session.id, p.session.targetID, p.targetID, selector) return p.frameManager.MainFrame().WaitForSelector(selector, opts) } // WaitForTimeout waits the specified number of milliseconds func (p *Page) WaitForTimeout(timeout int64) { - p.logger.Debugf("Page:WaitForTimeout", "sid:%v timeout=%d", p.session.id, timeout) + p.logger.Debugf("Page:WaitForTimeout sid:%v timeout=%d", p.session.id, timeout) p.frameManager.MainFrame().WaitForTimeout(timeout) } diff --git a/common/response.go b/common/response.go index 525e9dd16..f7ed4365e 100644 --- a/common/response.go +++ b/common/response.go @@ -34,7 +34,6 @@ import ( "github.com/dop251/goja" "github.com/grafana/xk6-browser/api" k6common "go.k6.io/k6/js/common" - k6lib "go.k6.io/k6/lib" ) // Ensure Response implements the api.Response interface @@ -81,13 +80,15 @@ type Response struct { } // NewHTTPResponse creates a new HTTP response -func NewHTTPResponse(ctx context.Context, req *Request, resp *network.Response, timestamp *cdp.MonotonicTime) *Response { - state := k6lib.GetState(ctx) +func NewHTTPResponse( + ctx context.Context, + req *Request, resp *network.Response, + timestamp *cdp.MonotonicTime, + logger *Logger, +) *Response { r := 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: NewLogger(ctx, state.Logger, false, nil), + ctx: ctx, + logger: logger, request: req, remoteAddress: &RemoteAddress{IPAddress: resp.RemoteIPAddress, Port: resp.RemotePort}, securityDetails: nil, @@ -201,11 +202,11 @@ func (r *Response) bodySize() int64 { if err == nil { return cl } - r.logger.Warnf("cdp", "error parsing content-length header: %s", err) + r.logger.Warnf("cdp error parsing content-length header: %s", err) } if err := r.fetchBody(); err != nil { - r.logger.Warnf("cdp", "error fetching response body for '%s': %s", r.url, err) + r.logger.Warnf("cdp error fetching response body for '%s': %s", r.url, err) } r.bodyMu.RLock() diff --git a/common/session.go b/common/session.go index cbc54bce9..e2f545401 100644 --- a/common/session.go +++ b/common/session.go @@ -66,15 +66,15 @@ func NewSession(ctx context.Context, conn *Connection, id target.SessionID, tid logger: logger, } - s.logger.Debugf("Session:NewSession", "sid:%v tid:%v", id, tid) + s.logger.Debugf("Session:NewSession sid:%v tid:%v", id, tid) go s.readLoop() return &s } func (s *Session) close() { - s.logger.Debugf("Session:close", "sid:%v tid:%v", s.id, s.targetID) + s.logger.Debugf("Session:close sid:%v tid:%v", s.id, s.targetID) if s.closed { - s.logger.Debugf("Session:close", "already closed, sid:%v tid:%v", s.id, s.targetID) + s.logger.Debugf("Session:close already closed, sid:%v tid:%v", s.id, s.targetID) return } @@ -86,7 +86,7 @@ func (s *Session) close() { } func (s *Session) markAsCrashed() { - s.logger.Debugf("Session:markAsCrashed", "sid:%v tid:%v", s.id, s.targetID) + s.logger.Debugf("Session:markAsCrashed sid:%v tid:%v", s.id, s.targetID) s.crashed = true } @@ -99,7 +99,7 @@ func (s *Session) readLoop() { case msg := <-s.readCh: ev, err := cdproto.UnmarshalMessage(msg) if err != nil { - s.logger.Debugf("Session:readLoop:<-s.readCh", "sid:%v tid:%v cannot unmarshal: %v", s.id, s.targetID, err) + s.logger.Debugf("Session:readLoop:<-s.readCh sid:%v tid:%v cannot unmarshal: %v", s.id, s.targetID, err) if _, ok := err.(cdp.ErrUnknownCommandOrEvent); ok { // This is most likely an event received from an older // Chrome which a newer cdproto doesn't have, as it is @@ -112,7 +112,7 @@ func (s *Session) readLoop() { } s.emit(string(msg.Method), ev) case <-s.done: - s.logger.Debugf("Session:readLoop:<-s.done", "sid:%v tid:%v", s.id, s.targetID) + s.logger.Debugf("Session:readLoop:<-s.done sid:%v tid:%v", s.id, s.targetID) return } } @@ -120,13 +120,13 @@ func (s *Session) readLoop() { // Execute implements the cdp.Executor interface func (s *Session) Execute(ctx context.Context, method string, params easyjson.Marshaler, res easyjson.Unmarshaler) error { - s.logger.Debugf("Session:Execute", "sid:%v tid:%v method:%q", s.id, s.targetID, method) + s.logger.Debugf("Session:Execute sid:%v tid:%v method:%q", s.id, s.targetID, method) // Certain methods aren't available to the user directly. if method == target.CommandCloseTarget { return errors.New("to close the target, cancel its context") } if s.crashed { - s.logger.Debugf("Session:Execute", "sid:%v tid:%v method:%q, returns: crashed", s.id, s.targetID, method) + s.logger.Debugf("Session:Execute sid:%v tid:%v method:%q, returns: crashed", s.id, s.targetID, method) return ErrTargetCrashed } @@ -140,13 +140,13 @@ func (s *Session) Execute(ctx context.Context, method string, params easyjson.Ma for { select { case <-evCancelCtx.Done(): - s.logger.Debugf("Session:Execute:<-evCancelCtx.Done()", "sid:%v tid:%v method:%q, returns", s.id, s.targetID, method) + s.logger.Debugf("Session:Execute:<-evCancelCtx.Done() sid:%v tid:%v method:%q, returns", s.id, s.targetID, method) return case ev := <-chEvHandler: if msg, ok := ev.data.(*cdproto.Message); ok && msg.ID == id { select { case <-evCancelCtx.Done(): - s.logger.Debugf("Session:Execute:<-evCancelCtx.Done():2", "sid:%v tid:%v method:%q, returns", s.id, s.targetID, method) + s.logger.Debugf("Session:Execute:<-evCancelCtx.Done():2 sid:%v tid:%v method:%q, returns", s.id, s.targetID, method) case ch <- msg: // We expect only one response with the matching message ID, // then remove event handler by cancelling context and stopping goroutine. @@ -175,18 +175,18 @@ func (s *Session) Execute(ctx context.Context, method string, params easyjson.Ma Method: cdproto.MethodType(method), Params: buf, } - s.logger.Debugf("Session:Execute:s.conn.send", "sid:%v tid:%v method:%q", s.id, s.targetID, method) + s.logger.Debugf("Session:Execute:s.conn.send sid:%v tid:%v method:%q", s.id, s.targetID, method) return s.conn.send(msg, ch, res) } func (s *Session) ExecuteWithoutExpectationOnReply(ctx context.Context, method string, params easyjson.Marshaler, res easyjson.Unmarshaler) error { - s.logger.Debugf("Session:ExecuteWithoutExpectationOnReply", "sid:%v tid:%v method:%q", s.id, s.targetID, method) + s.logger.Debugf("Session:ExecuteWithoutExpectationOnReply sid:%v tid:%v method:%q", s.id, s.targetID, method) // Certain methods aren't available to the user directly. if method == target.CommandCloseTarget { return errors.New("to close the target, cancel its context") } if s.crashed { - s.logger.Debugf("Session:ExecuteWithoutExpectationOnReply", "sid:%v tid:%v method:%q, ErrTargetCrashed", s.id, s.targetID, method) + s.logger.Debugf("Session:ExecuteWithoutExpectationOnReply sid:%v tid:%v method:%q, ErrTargetCrashed", s.id, s.targetID, method) return ErrTargetCrashed } @@ -198,7 +198,7 @@ func (s *Session) ExecuteWithoutExpectationOnReply(ctx context.Context, method s var err error buf, err = easyjson.Marshal(params) if err != nil { - s.logger.Debugf("Session:ExecuteWithoutExpectationOnReply:Marshal", "sid:%v tid:%v method:%q err=%v", s.id, s.targetID, method, err) + s.logger.Debugf("Session:ExecuteWithoutExpectationOnReply:Marshal sid:%v tid:%v method:%q err=%v", s.id, s.targetID, method, err) return err } } diff --git a/common/session_test.go b/common/session_test.go index cbf90115f..1992d14fe 100644 --- a/common/session_test.go +++ b/common/session_test.go @@ -78,7 +78,7 @@ func TestSessionCreateSession(t *testing.T) { ctx := context.Background() url, _ := url.Parse(server.ServerHTTP.URL) wsURL := fmt.Sprintf("ws://%s/cdp", url.Host) - conn, err := NewConnection(ctx, wsURL, NewLogger(ctx, NullLogger(), false, nil)) + conn, err := NewConnection(ctx, wsURL, NewLogger(NullLogger())) if assert.NoError(t, err) { session, err := conn.createSession(&target.Info{ diff --git a/tests/network_manager_test.go b/tests/network_manager_test.go index c8350ba8c..9a0bda960 100644 --- a/tests/network_manager_test.go +++ b/tests/network_manager_test.go @@ -21,6 +21,7 @@ package tests import ( + "strings" "testing" "github.com/grafana/xk6-browser/testutils/browsertest" @@ -42,7 +43,7 @@ func TestDataURLSkipRequest(t *testing.T) { var gotMsg bool for _, evt := range logHook.Drain() { - if evt.Message == "skipped request handling of data URL" { + if strings.Contains(evt.Message, "skipped request handling of data URL") { gotMsg = true } }