Add logs to ExecutionContext

Also add a minor log for BrowserContext as it is somewhat
related.

Author: inancgumus

common/execution_context.go

@@ -28,6 +28,7 @@ import (
 	"github.com/chromedp/cdproto/cdp"
 	"github.com/chromedp/cdproto/dom"
 	"github.com/chromedp/cdproto/runtime"
+	"github.com/chromedp/cdproto/target"
 	"github.com/dop251/goja"
 	"github.com/grafana/xk6-browser/api"
 	k6common "go.k6.io/k6/js/common"
@@ -52,6 +53,21 @@ func NewExecutionContext(
 	ctx context.Context, session *Session, frame *Frame,
 	id runtime.ExecutionContextID, logger *Logger,
 ) *ExecutionContext {
+	var (
+		sid  target.SessionID
+		fid  cdp.FrameID
+		furl string
+	)
+	if session != nil {
+		sid = session.id
+	}
+	if frame != nil {
+		fid = frame.id
+		furl = frame.url
+	}
+	logger.Debugf("NewExecutionContext", "sid:%s fid:%s ecid:%d furl:%q",
+		sid, fid, id, furl)
+
 	return &ExecutionContext{
 		ctx:            ctx,
 		session:        session,
@@ -64,21 +80,31 @@ func NewExecutionContext(
 
 // Adopts specified backend node into this execution context from another execution context
 func (e *ExecutionContext) adoptBackendNodeId(backendNodeID cdp.BackendNodeID) (*ElementHandle, error) {
-	var remoteObj *runtime.RemoteObject
-	var err error
+	e.logger.Debugf("ExecutionContext:adoptBackendNodeId", "sid:%s tid:%s fid:%s ecid:%d furl:%q bnid:%d",
+		e.session.id, e.session.targetID, e.frame.id, e.id, e.frame.url, backendNodeID)
+
+	var (
+		remoteObj *runtime.RemoteObject
+		err       error
+	)
 
 	action := dom.ResolveNode().
 		WithBackendNodeID(backendNodeID).
 		WithExecutionContextID(e.id)
+
 	if remoteObj, err = action.Do(cdp.WithExecutor(e.ctx, e.session)); err != nil {
-		return nil, fmt.Errorf("unable to get DOM node: %w", err)
+		return nil, fmt.Errorf("cannot resolve dom node: %w", err)
 	}
 
 	return NewJSHandle(e.ctx, e.session, e, e.frame, remoteObj, e.logger).AsElement().(*ElementHandle), nil
 }
 
 // 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.session.id, e.session.targetID, e.frame.id, e.id, e.frame.url,
+		elementHandle.frame.id, elementHandle.session.id)
+
 	if elementHandle.execCtx == e {
 		panic("Cannot adopt handle that already belongs to this execution context")
 	}
@@ -91,95 +117,108 @@ func (e *ExecutionContext) adoptElementHandle(elementHandle *ElementHandle) (*El
 
 	action := dom.DescribeNode().WithObjectID(elementHandle.remoteObject.ObjectID)
 	if node, err = action.Do(cdp.WithExecutor(e.ctx, e.session)); err != nil {
-		return nil, fmt.Errorf("unable to get DOM node: %w", err)
+		return nil, fmt.Errorf("cannot describe dom node: %w", err)
 	}
 
 	return e.adoptBackendNodeId(node.BackendNodeID)
 }
 
 // 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.session.id, e.session.targetID, e.frame.id, e.id, e.frame.url)
+
 	suffix := `//# sourceURL=` + evaluationScriptURL
 
-	isCallable := forceCallable
+	var (
+		isCallable = forceCallable
+		expression = pageFunc.ToString().String()
+	)
 	if !forceCallable {
-		_, isCallable = goja.AssertFunction(pageFunc.(goja.Value))
+		_, isCallable = goja.AssertFunction(pageFunc)
 	}
-
 	if !isCallable {
-		expression := pageFunc.ToString().String()
 		expressionWithSourceURL := expression
 		if !sourceURLRegex.Match([]byte(expression)) {
 			expressionWithSourceURL = expression + "\n" + suffix
 		}
 
-		var remoteObject *runtime.RemoteObject
-		var exceptionDetails *runtime.ExceptionDetails
+		var (
+			remoteObject     *runtime.RemoteObject
+			exceptionDetails *runtime.ExceptionDetails
+		)
 		action := runtime.Evaluate(expressionWithSourceURL).
 			WithContextID(e.id).
 			WithReturnByValue(returnByValue).
 			WithAwaitPromise(true).
 			WithUserGesture(true)
 		if remoteObject, exceptionDetails, err = action.Do(cdp.WithExecutor(apiCtx, e.session)); err != nil {
-			return nil, fmt.Errorf("unable to evaluate expression: %w", err)
+			return nil, fmt.Errorf("cannot evaluate expression (%s): %w", expressionWithSourceURL, exceptionDetails)
 		}
 		if exceptionDetails != nil {
-			return nil, fmt.Errorf("unable to evaluate expression: %w", exceptionDetails)
+			return nil, fmt.Errorf("cannot evaluate expression (%s): %w", expressionWithSourceURL, exceptionDetails)
 		}
-		if remoteObject != nil {
-			if returnByValue {
-				res, err = valueFromRemoteObject(apiCtx, remoteObject)
-				if err != nil {
-					return nil, fmt.Errorf("unable to extract value from remote object: %w", err)
-				}
-			} else if remoteObject.ObjectID != "" {
-				// Note: we don't use the passed in apiCtx here as it could be tied to a timeout
-				res = NewJSHandle(e.ctx, e.session, e, e.frame, remoteObject, e.logger)
+		if remoteObject == nil {
+			return
+		}
+		if returnByValue {
+			res, err = valueFromRemoteObject(apiCtx, remoteObject)
+			if err != nil {
+				return nil, fmt.Errorf("cannot extract value from remote object (%s): %w", remoteObject.ObjectID, err)
 			}
+		} else if remoteObject.ObjectID != "" {
+			// Note: we don't use the passed in apiCtx here as it could be tied to a timeout
+			res = NewJSHandle(e.ctx, e.session, e, e.frame, remoteObject, e.logger)
 		}
 	} else {
-		functionText := pageFunc.ToString().String()
 		var arguments []*runtime.CallArgument
 		for _, arg := range args {
 			result, err := convertArgument(apiCtx, e, arg)
 			if err != nil {
-				return nil, fmt.Errorf("unable to convert argument: %w", err)
+				return nil, fmt.Errorf("cannot convert argument (%q): %w", arg, err)
 			}
 			arguments = append(arguments, result)
 		}
 
-		var remoteObject *runtime.RemoteObject
-		var exceptionDetails *runtime.ExceptionDetails
-		action := runtime.CallFunctionOn(functionText + "\n" + suffix + "\n").
+		var (
+			remoteObject     *runtime.RemoteObject
+			exceptionDetails *runtime.ExceptionDetails
+			functionOn       = expression + "\n" + suffix + "\n"
+		)
+		action := runtime.CallFunctionOn(functionOn).
 			WithArguments(arguments).
 			WithExecutionContextID(e.id).
 			WithReturnByValue(returnByValue).
 			WithAwaitPromise(true).
 			WithUserGesture(true)
 		if remoteObject, exceptionDetails, err = action.Do(cdp.WithExecutor(apiCtx, e.session)); err != nil {
-			return nil, fmt.Errorf("unable to evaluate expression: %w", err)
+			return nil, fmt.Errorf("cannot call function on expression (%q) in execution context (%d): %w", functionOn, e.id, err)
 		}
 		if exceptionDetails != nil {
-			return nil, fmt.Errorf("unable to evaluate expression: %w", exceptionDetails)
+			return nil, fmt.Errorf("cannot call function on expression (%q) in execution context (%d): %w", functionOn, e.id, err)
 		}
-		if remoteObject != nil {
-			if returnByValue {
-				res, err = valueFromRemoteObject(apiCtx, remoteObject)
-				if err != nil {
-					return nil, fmt.Errorf("unable to extract value from remote object: %w", err)
-				}
-			} else if remoteObject.ObjectID != "" {
-				// Note: we don't use the passed in apiCtx here as it could be tied to a timeout
-				res = NewJSHandle(e.ctx, e.session, e, e.frame, remoteObject, e.logger)
+		if remoteObject == nil {
+			return
+		}
+		if returnByValue {
+			res, err = valueFromRemoteObject(apiCtx, remoteObject)
+			if err != nil {
+				return nil, fmt.Errorf("cannot extract value from remote object (%s): %w", remoteObject.ObjectID, err)
 			}
+		} else if remoteObject.ObjectID != "" {
+			// Note: we don't use the passed in apiCtx here as it could be tied to a timeout
+			res = NewJSHandle(e.ctx, e.session, e, e.frame, remoteObject, e.logger)
 		}
 	}
 
-	return res, err
+	return res, nil
 }
 
 // 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.session.id, e.session.targetID, e.frame.id, e.id, e.frame.url)
+
 	if e.injectedScript == nil {
 		rt := k6common.GetRuntime(e.ctx)
 		suffix := `//# sourceURL=` + evaluationScriptURL
@@ -192,7 +231,7 @@ func (e *ExecutionContext) getInjectedScript(apiCtx context.Context) (api.JSHand
 
 		handle, err := e.evaluate(apiCtx, false, false, rt.ToValue(expressionWithSourceURL))
 		if handle == nil || err != nil {
-			return nil, err
+			return nil, fmt.Errorf("cannot get injected script (%q): %w", suffix, err)
 		}
 		e.injectedScript = handle.(api.JSHandle)
 	}