Bug 1835614 - [devtools] Log function call arguments. r=devtools-reviewers,fluent-reviewers,devtools-backward-compat-reviewers,nchevobbe

Introduce a new global option in the tracer to log values.

For now, it only triggers javascript function call arguments to be logged,
but this will also impact the incoming feature logging native function calls,
and also the other incoming feature to log the returned values.

Differential Revision: https://phabricator.services.mozilla.com/D196019

Author: ochameau

devtools/client/debugger/src/actions/ui.js

@@ -234,6 +234,12 @@ export function setJavascriptTracingLogMethod(value) {
   };
 }
 
+export function toggleJavascriptTracingValues() {
+  return {
+    type: "TOGGLE_JAVASCRIPT_TRACING_VALUES",
+  };
+}
+
 export function setHideOrShowIgnoredSources(shouldHide) {
   return ({ dispatch, getState }) => {
     dispatch({ type: "HIDE_IGNORED_SOURCES", shouldHide });

devtools/client/debugger/src/components/SecondaryPanes/CommandBar.js

@@ -16,6 +16,7 @@ import {
   getIsCurrentThreadPaused,
   getIsThreadCurrentlyTracing,
   getJavascriptTracingLogMethod,
+  getJavascriptTracingValues,
 } from "../../selectors";
 import { formatKeyShortcut } from "../../utils/text";
 import actions from "../../actions";
@@ -117,6 +118,7 @@ class CommandBar extends Component {
       topFrameSelected: PropTypes.bool.isRequired,
       toggleTracing: PropTypes.func.isRequired,
       logMethod: PropTypes.string.isRequired,
+      logValues: PropTypes.bool.isRequired,
       setJavascriptTracingLogMethod: PropTypes.func.isRequired,
       setHideOrShowIgnoredSources: PropTypes.func.isRequired,
       toggleSourceMapIgnoreList: PropTypes.func.isRequired,
@@ -242,6 +244,16 @@ class CommandBar extends Component {
               this.props.setJavascriptTracingLogMethod(LOG_METHODS.STDOUT);
             },
           },
+          { type: "separator" },
+          {
+            id: "debugger-trace-menu-item-log-values",
+            label: L10N.getStr("traceValues"),
+            type: "checkbox",
+            checked: this.props.logValues,
+            click: () => {
+              this.props.toggleJavascriptTracingValues();
+            },
+          },
         ];
         showMenu(event, items);
       },
@@ -410,11 +422,13 @@ const mapStateToProps = state => ({
   isPaused: getIsCurrentThreadPaused(state),
   isTracingEnabled: getIsThreadCurrentlyTracing(state, getCurrentThread(state)),
   logMethod: getJavascriptTracingLogMethod(state),
+  logValues: getJavascriptTracingValues(state),
 });
 
 export default connect(mapStateToProps, {
   toggleTracing: actions.toggleTracing,
   setJavascriptTracingLogMethod: actions.setJavascriptTracingLogMethod,
+  toggleJavascriptTracingValues: actions.toggleJavascriptTracingValues,
   resume: actions.resume,
   stepIn: actions.stepIn,
   stepOut: actions.stepOut,

devtools/client/debugger/src/reducers/ui.js

@@ -36,6 +36,7 @@ export const initialUIState = ({ supportsDebuggerStatementIgnore } = {}) => ({
   editorWrappingEnabled: prefs.editorWrapping,
   javascriptEnabled: true,
   javascriptTracingLogMethod: prefs.javascriptTracingLogMethod,
+  javascriptTracingValues: prefs.javascriptTracingValues,
   mutableSearchOptions: prefs.searchOptions || {
     [searchKeys.FILE_SEARCH]: {
       regexMatch: false,
@@ -164,6 +165,14 @@ function update(state = initialUIState(), action) {
       return { ...state, javascriptTracingLogMethod: action.value };
     }
 
+    case "TOGGLE_JAVASCRIPT_TRACING_VALUES": {
+      prefs.javascriptTracingValues = !prefs.javascriptTracingValues;
+      return {
+        ...state,
+        javascriptTracingValues: prefs.javascriptTracingValues,
+      };
+    }
+
     case "SET_SEARCH_OPTIONS": {
       state.mutableSearchOptions[action.searchKey] = {
         ...state.mutableSearchOptions[action.searchKey],

devtools/client/debugger/src/selectors/ui.js

@@ -72,6 +72,10 @@ export function getJavascriptTracingLogMethod(state) {
   return state.ui.javascriptTracingLogMethod;
 }
 
+export function getJavascriptTracingValues(state) {
+  return state.ui.javascriptTracingValues;
+}
+
 export function getSearchOptions(state, searchKey) {
   return state.ui.mutableSearchOptions[searchKey];
 }

devtools/client/debugger/src/utils/prefs.js

@@ -45,6 +45,7 @@ if (isNode()) {
   pref("devtools.debugger.log-actions", true);
   pref("devtools.debugger.log-event-breakpoints", false);
   pref("devtools.debugger.javascript-tracing-log-method", "console");
+  pref("devtools.debugger.javascript-tracing-values", false);
   pref("devtools.debugger.hide-ignored-sources", false);
   pref("devtools.debugger.source-map-ignore-list-enabled", true);
   pref("devtools.debugger.features.wasm", true);
@@ -104,6 +105,7 @@ export const prefs = new PrefsHelper("devtools", {
     "String",
     "debugger.javascript-tracing-log-method",
   ],
+  javascriptTracingValues: ["Bool", "debugger.javascript-tracing-values"],
   hideIgnoredSources: ["Bool", "debugger.hide-ignored-sources"],
   sourceMapIgnoreListEnabled: [
     "Bool",

devtools/client/debugger/test/mochitest/browser_dbg-javascript-tracer.js

@@ -15,11 +15,11 @@ add_task(async function () {
   info("Enable the tracing");
   await clickElement(dbg, "trace");
 
-  const topLevelThread =
+  const topLevelThreadActorID =
     dbg.toolbox.commands.targetCommand.targetFront.threadFront.actorID;
   info("Wait for tracing to be enabled");
   await waitForState(dbg, state => {
-    return dbg.selectors.getIsThreadCurrentlyTracing(topLevelThread);
+    return dbg.selectors.getIsThreadCurrentlyTracing(topLevelThreadActorID);
   });
 
   ok(
@@ -89,7 +89,7 @@ add_task(async function () {
   await clickElement(dbg, "trace");
   info("Wait for tracing to be disabled");
   await waitForState(dbg, state => {
-    return !dbg.selectors.getIsThreadCurrentlyTracing(topLevelThread);
+    return !dbg.selectors.getIsThreadCurrentlyTracing(topLevelThreadActorID);
   });
 
   invokeInTab("inline_script2");
@@ -179,10 +179,10 @@ add_task(async function testPageKeyShortcut() {
 
   const dbg = await initDebuggerWithAbsoluteURL("data:text/html,key-shortcut");
 
-  const topLevelThread =
+  const topLevelThreadActorID =
     dbg.toolbox.commands.targetCommand.targetFront.threadFront.actorID;
   ok(
-    !dbg.selectors.getIsThreadCurrentlyTracing(topLevelThread),
+    !dbg.selectors.getIsThreadCurrentlyTracing(topLevelThreadActorID),
     "Tracing is disabled on debugger opening"
   );
 
@@ -212,7 +212,7 @@ add_task(async function testPageKeyShortcut() {
 
   info("Wait for tracing to be enabled");
   await waitForState(dbg, state => {
-    return dbg.selectors.getIsThreadCurrentlyTracing(topLevelThread);
+    return dbg.selectors.getIsThreadCurrentlyTracing(topLevelThreadActorID);
   });
 
   is(
@@ -232,7 +232,7 @@ add_task(async function testPageKeyShortcut() {
 
   info("Wait for tracing to be disabled");
   await waitForState(dbg, state => {
-    return !dbg.selectors.getIsThreadCurrentlyTracing(topLevelThread);
+    return !dbg.selectors.getIsThreadCurrentlyTracing(topLevelThreadActorID);
   });
 });
 
@@ -316,3 +316,44 @@ add_task(async function testPageKeyShortcutWithoutDebugger() {
   info("Wait for tracing to be disabled");
   await onTracingStateDisabled;
 });
+
+add_task(async function testTracingValues() {
+  await pushPref("devtools.debugger.features.javascript-tracing", true);
+  // Cover tracing function argument values
+  const jsCode = `function foo() { bar(1, ["array"], { attribute: 3 }, BigInt(4), Infinity, Symbol("6"), "7"); }; function bar(a, b, c) {}`;
+  const dbg = await initDebuggerWithAbsoluteURL(
+    "data:text/html," + encodeURIComponent(`<script>${jsCode}</script>`)
+  );
+
+  await openContextMenuInDebugger(dbg, "trace", 4);
+  const toggled = waitForDispatch(
+    dbg.store,
+    "TOGGLE_JAVASCRIPT_TRACING_VALUES"
+  );
+  selectContextMenuItem(dbg, `#debugger-trace-menu-item-log-values`);
+  await toggled;
+  ok(true, "Toggled the log values setting");
+
+  await clickElement(dbg, "trace");
+
+  const topLevelThreadActorID =
+    dbg.toolbox.commands.targetCommand.targetFront.threadFront.actorID;
+  info("Wait for tracing to be enabled");
+  await waitForState(dbg, state => {
+    return dbg.selectors.getIsThreadCurrentlyTracing(topLevelThreadActorID);
+  });
+
+  invokeInTab("foo");
+
+  await hasConsoleMessage(dbg, "λ foo()");
+  await hasConsoleMessage(dbg, "λ bar");
+  const { value } = await findConsoleMessage(dbg, "λ bar");
+  is(
+    value,
+    `interpreter⟶λ bar(1, \nArray [ "array" ]\n, \nObject { attribute: 3 }\n, 4n, Infinity, Symbol("6"), "7")`,
+    "The argument were printed for bar()"
+  );
+
+  // Reset the log values setting
+  Services.prefs.clearUserPref("devtools.debugger.javascript-tracing-values");
+});

devtools/client/locales/en-US/debugger.properties

@@ -142,6 +142,12 @@ traceInWebConsole=Trace in the web console
 # This is used to force logging JavaScript traces in the stdout.
 traceInStdout=Trace in the stdout
 
+# LOCALIZATION NOTE (traceValues): The label that is displayed in the context menu
+# of the trace button, which is in the top of the debugger right sidebar.
+# This is used to enable logging arguments passed to function calls
+# as well as returned values (only for JS function calls, but not native function calls)
+traceValues=Log function arguments and returned values
+
 # LOCALIZATION NOTE (resumeButtonTooltip): The label that is displayed on the pause
 # button when the debugger is in a paused state.
 resumeButtonTooltip=Resume %S

devtools/client/preferences/debugger.js

@@ -51,6 +51,7 @@ pref("devtools.debugger.map-scopes-enabled", false);
 pref("devtools.debugger.log-actions", false);
 pref("devtools.debugger.log-event-breakpoints", false);
 pref("devtools.debugger.javascript-tracing-log-method", "console");
+pref("devtools.debugger.javascript-tracing-values", false);
 
 pref("devtools.debugger.features.wasm", true);
 pref("devtools.debugger.features.code-folding", false);

devtools/client/webconsole/test/browser/browser_jsterm_trace_command.js

@@ -43,18 +43,19 @@ add_task(async function () {
   // Instead the frontend log a message as a console API message.
   msg = await evaluateExpressionInConsole(
     hud,
-    ":trace --logMethod console --prefix foo",
+    ":trace --logMethod console --prefix foo --values",
     "console-api"
   );
   is(msg.textContent.trim(), "Started tracing to Web Console");
 
   info("Trigger some code to log some traces");
   await SpecialPowers.spawn(gBrowser.selectedBrowser, [], () => {
-    content.wrappedJSObject.main();
+    content.wrappedJSObject.main("arg", 2);
   });
 
+  // Assert that we also see the custom prefix, as well as function arguments
   await waitFor(
-    () => !!findTracerMessages(hud, `foo: interpreter⟶λ main`).length
+    () => !!findTracerMessages(hud, `foo: interpreter⟶λ main("arg", 2)`).length
   );
 
   info("Test toggling the tracer OFF");

devtools/server/actors/tracer.js

@@ -19,6 +19,11 @@ const { tracerSpec } = require("resource://devtools/shared/specs/tracer.js");
 
 const { throttle } = require("resource://devtools/shared/throttle.js");
 
+const {
+  makeDebuggeeValue,
+  createValueGripForTarget,
+} = require("devtools/server/actors/object/utils");
+
 const {
   TYPES,
   getResourceWatcher,
@@ -85,8 +90,18 @@ class TracerActor extends Actor {
     return false;
   }
 
-  startTracing(logMethod = LOG_METHODS.STDOUT) {
-    this.#startTracing({ logMethod });
+  /**
+   * Start tracing.
+   *
+   * @param {String} logMethod
+   *        The output method used by the tracer.
+   *        See `LOG_METHODS` for potential values.
+   * @param {Object} options
+   *        Options used to configure JavaScriptTracer.
+   *        See `JavaScriptTracer.startTracing`.
+   */
+  startTracing(logMethod = LOG_METHODS.STDOUT, options = {}) {
+    this.#startTracing({ ...options, logMethod });
   }
 
   #startTracing(options) {
@@ -109,11 +124,14 @@ class TracerActor extends Actor {
       onTracingInfiniteLoop: this.onTracingInfiniteLoop.bind(this),
     };
     addTracingListener(this.tracingListener);
+    this.traceValues = !!options.traceValues;
     startTracing({
       global: this.targetActor.window || this.targetActor.workerGlobal,
       prefix: options.prefix || "",
       // Enable receiving the `currentDOMEvent` being passed to `onTracingFrame`
       traceDOMEvents: true,
+      // Enable tracing function arguments as well as returned values
+      traceValues: !!options.traceValues,
     });
   }
 
@@ -238,6 +256,22 @@ class TracerActor extends Actor {
         });
       }
 
+      let args = undefined;
+      // Log arguments, but only when this feature is enabled as it introduce
+      // some significant overhead in perf as well as memory as it may hold the objects in memory.
+      if (this.traceValues) {
+        args = [];
+        for (let arg of frame.arguments) {
+          // Debugger.Frame.arguments contains either a Debugger.Object or primitive object
+          if (arg?.unsafeDereference) {
+            arg = arg.unsafeDereference();
+          }
+          // Instantiate a object actor so that the tools can easily inspect these objects
+          const dbgObj = makeDebuggeeValue(this.targetActor, arg);
+          args.push(createValueGripForTarget(this.targetActor, dbgObj));
+        }
+      }
+
       // Create a message object that fits Console Message Watcher expectations
       this.throttledTraces.push({
         resourceType: JSTRACER_TRACE,
@@ -251,6 +285,7 @@ class TracerActor extends Actor {
         lineNumber,
         columnNumber: columnNumber - columnBase,
         sourceId: script.source.id,
+        args,
       });
       this.throttleEmitTraces();
     } else if (this.logMethod == LOG_METHODS.PROFILER) {

devtools/server/actors/webconsole/commands/manager.js

@@ -16,7 +16,7 @@ loader.lazyGetter(this, "l10n", () => {
 });
 const USAGE_STRING_MAPPING = {
   block: "webconsole-commands-usage-block",
-  trace: "webconsole-commands-usage-trace",
+  trace: "webconsole-commands-usage-trace2",
   unblock: "webconsole-commands-usage-unblock",
 };
 
@@ -871,6 +871,7 @@ WebConsoleCommandsManager.register({
     const enabled = tracerActor.toggleTracing({
       logMethod,
       prefix: args.prefix || null,
+      traceValues: !!args.values,
     });
 
     owner.helperResult = {
@@ -879,5 +880,5 @@ WebConsoleCommandsManager.register({
       logMethod,
     };
   },
-  validArguments: ["logMethod", "prefix"],
+  validArguments: ["logMethod", "prefix", "values"],
 });

devtools/server/tracer/tests/xpcshell/test_tracer.js

@@ -137,3 +137,35 @@ add_task(async function testTracingJSMGlobal() {
 
   removeTracingListener(listenerSandbox.listener);
 });
+
+add_task(async function testTracingValues() {
+  // Test the `traceValues` flag
+  const sandbox = Cu.Sandbox("https://example.com");
+  Cu.evalInSandbox(
+    `function foo() { bar(-0, 1, ["array"], { attribute: 3 }, "4", BigInt(5), Symbol("6"), Infinity, undefined, null, false, NaN, function foo() {}, function () {}, class MyClass {}); }; function bar(a, b, c) {}`,
+    sandbox
+  );
+
+  // Pass an override method to catch all strings tentatively logged to stdout
+  const logs = [];
+  function loggingMethod(str) {
+    logs.push(str);
+  }
+
+  info("Start tracing");
+  startTracing({ global: sandbox, traceValues: true, loggingMethod });
+
+  info("Call some code");
+  sandbox.foo();
+
+  Assert.equal(logs.length, 3);
+  Assert.equal(logs[0], "Start tracing JavaScript\n");
+  Assert.stringContains(logs[1], "λ foo()");
+  Assert.stringContains(
+    logs[2],
+    `λ bar(-0, 1, Array(1), [object Object], "4", BigInt(5), Symbol(6), Infinity, undefined, null, false, NaN, function foo(), function anonymous(), class MyClass)`
+  );
+
+  info("Stop tracing");
+  stopTracing();
+});