Improve logs in some entities

Author: inancgumus

common/barrier_test.go

@@ -31,9 +31,12 @@ import (
 func TestBarrier(t *testing.T) {
 	t.Run("should work", func(t *testing.T) {
 		ctx := context.Background()
+
+		log := NewLogger(ctx, NullLogger(), false, nil)
+
 		timeoutSetings := NewTimeoutSettings(nil)
-		frameManager := NewFrameManager(ctx, nil, nil, timeoutSetings, NewLogger(ctx, NullLogger(), false, nil))
-		frame := NewFrame(ctx, frameManager, nil, cdp.FrameID("frame_id_0123456789"))
+		frameManager := NewFrameManager(ctx, nil, nil, timeoutSetings, log)
+		frame := NewFrame(ctx, frameManager, nil, cdp.FrameID("frame_id_0123456789"), log)
 
 		barrier := NewBarrier()
 		barrier.AddFrameNavigation(frame)

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:%q", 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", "bid::%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)
@@ -209,7 +209,7 @@ func (b *Browser) onAttachedToTarget(ev *target.EventAttachedToTarget) {
 	// 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:returns", "sid:%v tid:%v (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:returns", "sid:%v tid:%v 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:addTid", "sid:%v tid:%v", 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:addSid", "sid:%v tid:%v", ev.SessionID, ev.TargetInfo.TargetID)
 		b.sessionIDtoTargetID[ev.SessionID] = ev.TargetInfo.TargetID
 		b.sessionIDtoTargetIDMu.Unlock()
 	} else if ev.TargetInfo.Type == "page" {
@@ -246,17 +246,17 @@ 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:page", "sid:%v tid:%v, returns: websocket error", ev.SessionID, ev.TargetInfo.TargetID)
+				b.logger.Debugf("Browser:onAttachedToTarget:page:return", "sid:%v tid:%v websocket err:", 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:addTarget", "sid:%v tid:%v", 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:sidToTid", "sid:%v tid:%v", ev.SessionID, ev.TargetInfo.TargetID)
 		b.sessionIDtoTargetID[ev.SessionID] = ev.TargetInfo.TargetID
 		b.sessionIDtoTargetIDMu.Unlock()
 		browserCtx.emit(EventBrowserContextPage, p)
@@ -266,18 +266,21 @@ 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)
+	defer b.logger.Debugf("Browser:onDetachedFromTarget:return", "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)
 		// We don't track targets of type "browser", "other" and "devtools", so ignore if we don't recognize target.
 		return
 	}
 
 	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:deletePage", "sid:%v tid:%v", ev.SessionID, targetID)
+
 		delete(b.pages, targetID)
 		t.didClose()
 	}
@@ -303,7 +306,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:createWaitForEventHandler", "tid:%v bcid:%v", targetID, id)
 			return data.(*Page).targetID == targetID
 		},
 	)
@@ -314,7 +317,7 @@ 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:CreateTargetBlank", "tid:%v bcid:%v", 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)
 		}
@@ -378,7 +381,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", "bcid:%v", browserContextID)
 	if err != nil {
 		k6Throw(b.ctx, "cannot create browser context (%s): %w", browserContextID, err)
 	}
@@ -390,7 +393,6 @@ func (b *Browser) NewContext(opts goja.Value) api.BrowserContext {
 
 	b.contextsMu.Lock()
 	defer b.contextsMu.Unlock()
-	b.logger.Debugf("Browser:NewContext", "NewBrowserContext: %v", browserContextID)
 	browserCtx := NewBrowserContext(b.ctx, b.conn, b, browserContextID, browserCtxOpts, b.logger)
 	b.contexts[browserContextID] = browserCtx
 

common/browser_context.go

@@ -207,12 +207,12 @@ 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", "bid:%v", b.id)
+	b.logger.Debugf("BrowserContext:NewPage", "bcid:%v", b.id)
 	p, err := b.browser.newPageInContext(b.id)
 	if err != nil {
 		k6Throw(b.ctx, "cannot create a new page: %w", err)
 	}
-	b.logger.Debugf("BrowserContext:NewPage:returns", "bid:%v ptid:%s", b.id, p.targetID)
+	b.logger.Debugf("BrowserContext:NewPage:returns", "bcid:%v ptid:%s", b.id, p.targetID)
 	return p
 }
 

common/connection.go

@@ -192,18 +192,18 @@ 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 bid::%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 bid::%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 bid::%v type:%s sid:%v, session is nil", info.TargetID, info.BrowserContextID, info.Type, sessionID)
 	}
 	return sess, nil
 }
@@ -285,9 +285,10 @@ func (c *Connection) recvLoop() {
 			}
 			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", sid, tid, c.wsURL)
 			c.sessions[sid] = session
 			c.sessionsMu.Unlock()
 		} else if msg.Method == cdproto.EventTargetDetachedFromTarget {
@@ -299,7 +300,6 @@ func (c *Connection) recvLoop() {
 			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.closeSession(sid, tid)
 		}
 
@@ -327,7 +327,7 @@ func (c *Connection) recvLoop() {
 			}
 
 		case msg.Method != "":
-			c.logger.Debugf("Connection:recvLoop:msg.Method:emit", "method:%q", msg.Method)
+			c.logger.Debugf("Connection:recvLoop:msg.Method:emit", "sid:%v method:%q", msg.SessionID, msg.Method)
 			ev, err := cdproto.UnmarshalMessage(&msg)
 			if err != nil {
 				c.logger.Errorf("cdp", "%s", err)
@@ -336,7 +336,7 @@ func (c *Connection) recvLoop() {
 			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", "sid:%v method:%q", msg.SessionID, msg.Method)
 			c.emit("", &msg)
 
 		default:

common/execution_context.go

@@ -65,7 +65,7 @@ func NewExecutionContext(
 		fid = frame.id
 		furl = frame.url
 	}
-	logger.Debugf("NewExecutionContext", "sid:%s fid:%s ecid:%d furl:%q",
+	logger.Debugf("NewExecutionContext", "sid:%s tid:%s ecid:%d furl:%q",
 		sid, fid, id, furl)
 
 	return &ExecutionContext{
@@ -80,7 +80,7 @@ func NewExecutionContext(
 
 // Adopts specified backend node into this execution context from another execution context
 func (e *ExecutionContext) adoptBackendNodeId(backendNodeID cdp.BackendNodeID) (*ElementHandle, error) {
-	e.logger.Debugf("ExecutionContext:adoptBackendNodeId", "sid:%s tid:%s fid:%s ecid:%d furl:%q bnid:%d",
+	e.logger.Debugf("ExecutionContext:adoptBackendNodeId", "sid:%s tid:%s tid:%s ecid:%d furl:%q bnid:%d",
 		e.session.id, e.session.targetID, e.frame.id, e.id, e.frame.url, backendNodeID)
 
 	var (
@@ -101,7 +101,7 @@ func (e *ExecutionContext) adoptBackendNodeId(backendNodeID cdp.BackendNodeID) (
 
 // Adopts the specified element handle into this execution context from another execution context
 func (e *ExecutionContext) adoptElementHandle(elementHandle *ElementHandle) (*ElementHandle, error) {
-	e.logger.Debugf("ExecutionContext:adoptElementHandle", "sid:%s tid:%s fid:%s ecid:%d furl:%q ehfid:%s ehsid:%s",
+	e.logger.Debugf("ExecutionContext:adoptElementHandle", "sid:%s tid:%s tid:%s ecid:%d furl:%q ehtid:%s ehsid:%s",
 		e.session.id, e.session.targetID, e.frame.id, e.id, e.frame.url,
 		elementHandle.frame.id, elementHandle.session.id)
 
@@ -125,7 +125,7 @@ func (e *ExecutionContext) adoptElementHandle(elementHandle *ElementHandle) (*El
 
 // evaluate will evaluate provided callable within this execution context and return by value or handle
 func (e *ExecutionContext) evaluate(apiCtx context.Context, forceCallable bool, returnByValue bool, pageFunc goja.Value, args ...goja.Value) (res interface{}, err error) {
-	e.logger.Debugf("ExecutionContext:evaluate", "sid:%s tid:%s fid:%s ecid:%d furl:%q",
+	e.logger.Debugf("ExecutionContext:evaluate", "sid:%s tid:%s tid:%s ecid:%d furl:%q",
 		e.session.id, e.session.targetID, e.frame.id, e.id, e.frame.url)
 
 	suffix := `//# sourceURL=` + evaluationScriptURL
@@ -216,7 +216,7 @@ func (e *ExecutionContext) evaluate(apiCtx context.Context, forceCallable bool,
 
 // getInjectedScript returns a JS handle to the injected script of helper functions
 func (e *ExecutionContext) getInjectedScript(apiCtx context.Context) (api.JSHandle, error) {
-	e.logger.Debugf("ExecutionContext:getInjectedScript", "sid:%s tid:%s fid:%s ecid:%d furl:%q",
+	e.logger.Debugf("ExecutionContext:getInjectedScript", "sid:%s tid:%s tid:%s ecid:%d furl:%q",
 		e.session.id, e.session.targetID, e.frame.id, e.id, e.frame.url)
 
 	if e.injectedScript == nil {