Bug 1631799 - Fix order of command and its result message when server and client don't have the same clock time. r=jdescottes.

When remote-debugging a device, it might happen that the device clock
is not exactly at the same time as the client clock. In such case, we
may end up in cases where the result of a command as an older timestamp,
which means we could have in the console output a result that was displayed
before the command message that triggered it.
In order to fix this, we add a `startTime` property on the evaluateJSAsync
response, that we can then check on the client. If the server time is
older than the client time, then we remove the existing command message
and add a new one, with the server timestamp.

We could have waited the result of the command before displaying the
command message (so we don't have to add a message, and then remove it
when the timestamps don't match), but the UI wouldn't feel snappy, and
even worse in case of long execution times (e.g. a top-level await fetch command).

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

devtools/client/webconsole/actions/input.js

@@ -66,7 +66,7 @@ function evaluateExpression(expression, from = "input") {
     }
 
     // We use the messages action as it's doing additional transformation on the message.
-    dispatch(
+    const { messages } = dispatch(
       messagesActions.messagesAdd([
         new ConsoleCommand({
           messageText: expression,
@@ -74,6 +74,8 @@ function evaluateExpression(expression, from = "input") {
         }),
       ])
     );
+    const [consoleCommandMessage] = messages;
+
     dispatch({
       type: EVALUATE_EXPRESSION,
       expression,
@@ -98,6 +100,29 @@ function evaluateExpression(expression, from = "input") {
       })
       .then(onSettled, onSettled);
 
+    // Before Firefox 77, the response did not have a `startTime` property, so we're using
+    // the `resultID`, which does contain the server time at which the evaluation started
+    // (its shape is `${timestamp}-${someId}`).
+    const serverConsoleCommandTimestamp =
+      response.startTime || Number(response.resultID.replace(/\-\d*$/, ""));
+
+    // In case of remote debugging, it might happen that the debuggee page does not have
+    // the exact same clock time as the client. This could cause some ordering issues
+    // where the result message is displayed *before* the expression that lead to it.
+    if (consoleCommandMessage.timeStamp > serverConsoleCommandTimestamp) {
+      // If we're in such case, we remove the original command message, and add it again,
+      // with the timestamp coming from the server.
+      dispatch(messagesActions.messageRemove(consoleCommandMessage.id));
+      dispatch(
+        messagesActions.messagesAdd([
+          new ConsoleCommand({
+            messageText: expression,
+            timeStamp: serverConsoleCommandTimestamp,
+          }),
+        ])
+      );
+    }
+
     return dispatch(onExpressionEvaluated(response));
   };
 }

devtools/client/webconsole/actions/messages.js

@@ -24,6 +24,7 @@ const {
   MESSAGE_OPEN,
   MESSAGE_CLOSE,
   MESSAGE_TYPE,
+  MESSAGE_REMOVE,
   MESSAGE_UPDATE_PAYLOAD,
   PRIVATE_MESSAGES_CLEAR,
 } = require("devtools/client/webconsole/constants");
@@ -129,6 +130,13 @@ function messageUpdatePayload(id, data) {
   };
 }
 
+function messageRemove(id) {
+  return {
+    type: MESSAGE_REMOVE,
+    id,
+  };
+}
+
 function networkMessageUpdate(packet, idGenerator = null, response) {
   if (idGenerator == null) {
     idGenerator = defaultIdGenerator;
@@ -157,6 +165,7 @@ module.exports = {
   messagesClearLogpoint,
   messageOpen,
   messageClose,
+  messageRemove,
   messageGetMatchingElements,
   messageUpdatePayload,
   networkMessageUpdate,

devtools/client/webconsole/constants.js

@@ -27,6 +27,7 @@ const actionTypes = {
   MESSAGE_CLOSE: "MESSAGE_CLOSE",
   MESSAGE_OPEN: "MESSAGE_OPEN",
   MESSAGE_UPDATE_PAYLOAD: "MESSAGE_UPDATE_PAYLOAD",
+  MESSAGE_REMOVE: "MESSAGE_REMOVE",
   MESSAGES_ADD: "MESSAGES_ADD",
   MESSAGES_CLEAR: "MESSAGES_CLEAR",
   MESSAGES_CLEAR_LOGPOINT: "MESSAGES_CLEAR_LOGPOINT",

devtools/client/webconsole/reducers/messages.js

@@ -649,6 +649,14 @@ function messages(
         forceTimestampSort: !prefsState.groupWarnings,
       });
 
+    case constants.MESSAGE_REMOVE:
+      return removeMessagesFromState(
+        {
+          ...state,
+        },
+        [action.id]
+      );
+
     case constants.FILTER_TOGGLE:
     case constants.FILTER_TEXT_SET:
     case constants.FILTERS_CLEAR:

devtools/client/webconsole/test/browser/stub-generator-helpers.js

@@ -277,6 +277,10 @@ function cleanTimeStamp(packet) {
     packet.timeStamp = uniqueTimeStamp;
   }
 
+  if (packet.startTime) {
+    packet.startTime = uniqueTimeStamp;
+  }
+
   if (packet?.message?.timeStamp) {
     packet.message.timeStamp = uniqueTimeStamp;
   }

devtools/client/webconsole/test/node/fixtures/stubs/evaluationResult.js

@@ -36,6 +36,7 @@ rawPackets.set(`new Date(0)`, {
     },
     "actorID": "server0.conn0.child1/obj23"
   },
+  "startTime": 1572867483805,
   "timestamp": 1572867483805
 });
 
@@ -83,6 +84,7 @@ rawPackets.set(`asdf()`, {
   "result": {
     "type": "undefined"
   },
+  "startTime": 1572867483805,
   "timestamp": 1572867483805
 });
 
@@ -121,6 +123,7 @@ rawPackets.set(`1 + @`, {
   "result": {
     "type": "undefined"
   },
+  "startTime": 1572867483805,
   "timestamp": 1572867483805
 });
 
@@ -162,6 +165,7 @@ rawPackets.set(`inspect({a: 1})`, {
   "result": {
     "type": "undefined"
   },
+  "startTime": 1572867483805,
   "timestamp": 1572867483805
 });
 
@@ -175,6 +179,7 @@ rawPackets.set(`cd(document)`, {
   "result": {
     "type": "undefined"
   },
+  "startTime": 1572867483805,
   "timestamp": 1572867483805
 });
 
@@ -184,6 +189,7 @@ rawPackets.set(`undefined`, {
   "result": {
     "type": "undefined"
   },
+  "startTime": 1572867483805,
   "timestamp": 1572867483805
 });
 
@@ -246,6 +252,7 @@ rawPackets.set(`longString message Error`, {
   "result": {
     "type": "undefined"
   },
+  "startTime": 1572867483805,
   "timestamp": 1572867483805
 });
 
@@ -272,6 +279,7 @@ rawPackets.set(`eval throw ""`, {
   "result": {
     "type": "undefined"
   },
+  "startTime": 1572867483805,
   "timestamp": 1572867483805
 });
 
@@ -298,6 +306,7 @@ rawPackets.set(`eval throw "tomato"`, {
   "result": {
     "type": "undefined"
   },
+  "startTime": 1572867483805,
   "timestamp": 1572867483805
 });
 

devtools/client/webconsole/test/node/store/messages.test.js

@@ -1116,4 +1116,30 @@ describe("Message reducer:", () => {
       expect(repeat[getLastMessage(getState()).id]).toBe(undefined);
     });
   });
+
+  describe("messageRemove", () => {
+    it("removes the message from the store", () => {
+      const { dispatch, getState } = setupStore([
+        "console.trace()",
+        "console.log(undefined)",
+        "console.trace()",
+        "console.log(undefined)",
+      ]);
+
+      let expanded = getAllMessagesUiById(getState());
+      expect(expanded.length).toBe(2);
+
+      const secondTraceMessage = getMessageAt(getState(), 2);
+      dispatch(actions.messageRemove(secondTraceMessage.id));
+
+      const messages = getAllMessagesById(getState());
+      // The messages was removed
+      expect(messages.size).toBe(3);
+
+      // Its id was removed from the messagesUI property as well
+      expanded = getAllMessagesUiById(getState());
+      expect(expanded.length).toBe(1);
+      expect(expanded.includes(secondTraceMessage.id)).toBeFalsy();
+    });
+  });
 });

devtools/server/actors/webconsole.js

@@ -1011,11 +1011,12 @@ const WebConsoleActor = ActorClassWithSpec(webconsoleSpec, {
    *         `resultID` field.
    */
   evaluateJSAsync: async function(request) {
+    const startTime = Date.now();
     // Use Date instead of UUID as this code is used by workers, which
     // don't have access to the UUID XPCOM component.
     // Also use a counter in order to prevent mixing up response when calling
     // evaluateJSAsync during the same millisecond.
-    const resultID = Date.now() + "-" + this._evalCounter++;
+    const resultID = startTime + "-" + this._evalCounter++;
 
     // Execute the evaluation in the next event loop in order to immediately
     // reply with the resultID.
@@ -1032,6 +1033,7 @@ const WebConsoleActor = ActorClassWithSpec(webconsoleSpec, {
         this.emit("evaluationResult", {
           type: "evaluationResult",
           resultID,
+          startTime,
           ...response,
         });
         return;

devtools/shared/specs/webconsole.js

@@ -57,6 +57,7 @@ const webconsoleSpecPrototype = {
       input: Option(0, "nullable:string"),
       notes: Option(0, "nullable:string"),
       result: Option(0, "nullable:json"),
+      startTime: Option(0, "number"),
       timestamp: Option(0, "string"),
       topLevelAwaitRejected: Option(0, "nullable:boolean"),
     },