From f74554002b17cc8f2afcaa183ab5d2c65e35b8ca Mon Sep 17 00:00:00 2001 From: Nicolas Chevobbe Date: Wed, 29 Apr 2020 17:12:32 +0000 Subject: [PATCH] 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 | 27 ++++++++++++++++++- .../client/webconsole/actions/messages.js | 9 +++++++ devtools/client/webconsole/constants.js | 1 + .../client/webconsole/reducers/messages.js | 8 ++++++ .../test/browser/stub-generator-helpers.js | 4 +++ .../node/fixtures/stubs/evaluationResult.js | 9 +++++++ .../test/node/store/messages.test.js | 26 ++++++++++++++++++ devtools/server/actors/webconsole.js | 4 ++- devtools/shared/specs/webconsole.js | 1 + 9 files changed, 87 insertions(+), 2 deletions(-) diff --git a/devtools/client/webconsole/actions/input.js b/devtools/client/webconsole/actions/input.js index 3f2ab7f753b7..fe01af300b4b 100644 --- a/devtools/client/webconsole/actions/input.js +++ b/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)); }; } diff --git a/devtools/client/webconsole/actions/messages.js b/devtools/client/webconsole/actions/messages.js index 7545ba0dd05b..ce0946fd369d 100644 --- a/devtools/client/webconsole/actions/messages.js +++ b/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, diff --git a/devtools/client/webconsole/constants.js b/devtools/client/webconsole/constants.js index d9e5bff06813..68d66541a48e 100644 --- a/devtools/client/webconsole/constants.js +++ b/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", diff --git a/devtools/client/webconsole/reducers/messages.js b/devtools/client/webconsole/reducers/messages.js index 67ccda6545bd..a93cbda5b79a 100644 --- a/devtools/client/webconsole/reducers/messages.js +++ b/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: diff --git a/devtools/client/webconsole/test/browser/stub-generator-helpers.js b/devtools/client/webconsole/test/browser/stub-generator-helpers.js index 4cdeda123692..69c4aedcc6b8 100644 --- a/devtools/client/webconsole/test/browser/stub-generator-helpers.js +++ b/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; } diff --git a/devtools/client/webconsole/test/node/fixtures/stubs/evaluationResult.js b/devtools/client/webconsole/test/node/fixtures/stubs/evaluationResult.js index 3c4006d92b8f..13ad96b24575 100644 --- a/devtools/client/webconsole/test/node/fixtures/stubs/evaluationResult.js +++ b/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 }); diff --git a/devtools/client/webconsole/test/node/store/messages.test.js b/devtools/client/webconsole/test/node/store/messages.test.js index 8a1fc1bee0e5..12ed61fe0ae0 100644 --- a/devtools/client/webconsole/test/node/store/messages.test.js +++ b/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(); + }); + }); }); diff --git a/devtools/server/actors/webconsole.js b/devtools/server/actors/webconsole.js index 28a2b2a6b2aa..ec4d44948d13 100644 --- a/devtools/server/actors/webconsole.js +++ b/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; diff --git a/devtools/shared/specs/webconsole.js b/devtools/shared/specs/webconsole.js index b655acacc2df..efc130133957 100644 --- a/devtools/shared/specs/webconsole.js +++ b/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"), },