Bug 1639843 - Added reason field to command-received telemetry events…

… r=markh,rfkelly

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

services/fxaccounts/FxAccountsCommands.js

@@ -101,15 +101,15 @@ class FxAccountsCommands {
    * This method can be called either in response to a Push message,
    * or by itself as a "commands recovery" mechanism.
    *
-   * @param {Number} receivedIndex "Command received" push messages include
+   * @param {Number} notifiedIndex "Command received" push messages include
    * the index of the command that triggered the message. We use it as a
    * hint when we have no "last command index" stored.
    */
-  async pollDeviceCommands(receivedIndex = 0) {
+  async pollDeviceCommands(notifiedIndex = 0) {
     // Whether the call to `pollDeviceCommands` was initiated by a Push message from the FxA
     // servers in response to a message being received or simply scheduled in order
     // to fetch missed messages.
-    const scheduledFetch = receivedIndex == 0;
+    const scheduledFetch = notifiedIndex == 0;
     if (
       !Services.prefs.getBoolPref("identity.fxaccounts.commands.enabled", true)
     ) {
@@ -123,9 +123,9 @@ class FxAccountsCommands {
       }
       // We increment lastCommandIndex by 1 because the server response includes the current index.
       // If we don't have a `lastCommandIndex` stored, we fall back on the index from the push message we just got.
-      const lastCommandIndex = device.lastCommandIndex + 1 || receivedIndex;
+      const lastCommandIndex = device.lastCommandIndex + 1 || notifiedIndex;
       // We have already received this message before.
-      if (receivedIndex > 0 && receivedIndex < lastCommandIndex) {
+      if (notifiedIndex > 0 && notifiedIndex < lastCommandIndex) {
         return;
       }
       const { index, messages } = await this._fetchDeviceCommands(
@@ -142,7 +142,7 @@ class FxAccountsCommands {
             messages.length
           );
         }
-        await this._handleCommands(messages);
+        await this._handleCommands(messages, notifiedIndex);
       }
     });
     return true;
@@ -165,16 +165,34 @@ class FxAccountsCommands {
     return client.getCommands(sessionToken, opts);
   }
 
-  async _handleCommands(messages) {
+  _getReason(notifiedIndex, messageIndex) {
+    // The returned reason value represents an explanation for why the command associated with the
+    // message of the given `messageIndex` is being handled. If `notifiedIndex` is zero the command
+    // is a part of a fallback polling process initiated by "Sync Now" ["poll"]. If `notifiedIndex` is
+    // greater than `messageIndex` this is a push command that was previously missed ["push-missed"],
+    // otherwise we assume this is a push command with no missed messages ["push"].
+    if (notifiedIndex == 0) {
+      return "poll";
+    } else if (notifiedIndex > messageIndex) {
+      return "push-missed";
+    }
+    // Note: The returned reason might be "push" in the case where a user sends multiple tabs
+    // in quick succession. We are not attempting to distinguish this from other push cases at
+    // present.
+    return "push";
+  }
+
+  async _handleCommands(messages, notifiedIndex) {
     try {
       await this._fxai.device.refreshDeviceList();
     } catch (e) {
       log.warn("Error refreshing device list", e);
     }
     // We debounce multiple incoming tabs so we show a single notification.
     const tabsReceived = [];
-    for (const { data } of messages) {
+    for (const { index, data } of messages) {
       const { command, payload, sender: senderId } = data;
+      const reason = this._getReason(notifiedIndex, index);
       const sender =
         senderId && this._fxai.device.recentDeviceList
           ? this._fxai.device.recentDeviceList.find(d => d.id == senderId)
@@ -187,7 +205,11 @@ class FxAccountsCommands {
       switch (command) {
         case COMMAND_SENDTAB:
           try {
-            const { title, uri } = await this.sendTab.handle(senderId, payload);
+            const { title, uri } = await this.sendTab.handle(
+              senderId,
+              payload,
+              reason
+            );
             log.info(
               `Tab received with FxA commands: ${title} from ${
                 sender ? sender.name : "Unknown device"
@@ -276,7 +298,7 @@ class SendTab {
   }
 
   // Handle incoming send tab payload, called by FxAccountsCommands.
-  async handle(senderID, { encrypted }) {
+  async handle(senderID, { encrypted }, reason) {
     const bytes = await this._decrypt(encrypted);
     const decoder = new TextDecoder("utf8");
     const data = JSON.parse(decoder.decode(bytes));
@@ -292,7 +314,7 @@ class SendTab {
       "command-received",
       COMMAND_SENDTAB_TAIL,
       this._fxai.telemetry.sanitizeDeviceId(senderID),
-      { flowID, streamID }
+      { flowID, streamID, reason }
     );
 
     return {

services/fxaccounts/tests/xpcshell/test_commands.js

@@ -180,6 +180,7 @@ add_task(async function test_sendtab_receive() {
   };
   const tab = { title: "tab title", url: "http://example.com" };
   const to = [{ id: "devid", name: "The Device" }];
+  const reason = "push";
 
   await sendTab.send(to, tab);
   Assert.equal(commands._invokes.length, 1);
@@ -191,7 +192,7 @@ add_task(async function test_sendtab_receive() {
     Assert.ok(!payload.hasOwnProperty("flowID"));
     // change it - ensure we still get what we expect in telemetry later.
     payload.flowID = "ignore-me";
-    Assert.deepEqual(await sendTab.handle(device.id, payload), {
+    Assert.deepEqual(await sendTab.handle(device.id, payload, reason), {
       title: "tab title",
       uri: "http://example.com",
     });
@@ -208,7 +209,7 @@ add_task(async function test_sendtab_receive() {
       object: "command-received",
       method: COMMAND_SENDTAB_TAIL,
       value: "devid-san",
-      extra: { flowID: "1", streamID: "2" },
+      extra: { flowID: "1", streamID: "2", reason },
     },
   ]);
 });
@@ -227,19 +228,53 @@ add_task(async function test_sendtab_receive_old_client() {
     flowID: "flow-id",
     encrypted: new TextEncoder("utf8").encode(JSON.stringify(data)),
   };
-  await sendTab.handle("sender-id", payload);
+  const reason = "push";
+  await sendTab.handle("sender-id", payload, reason);
   Assert.deepEqual(fxai.telemetry._events, [
     {
       object: "command-received",
       method: COMMAND_SENDTAB_TAIL,
       value: "sender-id-san",
       // deepEqual doesn't ignore undefined, but our telemetry code and
       // JSON.stringify() do...
-      extra: { flowID: undefined, streamID: undefined },
+      extra: { flowID: undefined, streamID: undefined, reason },
     },
   ]);
 });
 
+add_task(function test_commands_getReason() {
+  const fxAccounts = {
+    async withCurrentAccountState(cb) {
+      await cb({});
+    },
+  };
+  const commands = new FxAccountsCommands(fxAccounts);
+  const testCases = [
+    {
+      receivedIndex: 0,
+      currentIndex: 0,
+      expectedReason: "poll",
+      message: "should return reason 'poll'",
+    },
+    {
+      receivedIndex: 7,
+      currentIndex: 3,
+      expectedReason: "push-missed",
+      message: "should return reason 'push-missed'",
+    },
+    {
+      receivedIndex: 2,
+      currentIndex: 8,
+      expectedReason: "push",
+      message: "should return reason 'push'",
+    },
+  ];
+  for (const tc of testCases) {
+    const reason = commands._getReason(tc.receivedIndex, tc.currentIndex);
+    Assert.equal(reason, tc.expectedReason, tc.message);
+  }
+});
+
 add_task(async function test_commands_pollDeviceCommands_push() {
   // Server state.
   const remoteMessages = [
@@ -288,7 +323,7 @@ add_task(async function test_commands_pollDeviceCommands_push() {
   mockCommands
     .expects("_handleCommands")
     .once()
-    .withArgs(remoteMessages);
+    .withArgs(remoteMessages, pushIndexReceived);
   await commands.pollDeviceCommands(pushIndexReceived);
 
   mockCommands.verify();
@@ -329,6 +364,55 @@ add_task(
   }
 );
 
+add_task(async function test_commands_handleCommands() {
+  // This test ensures that `_getReason` is being called by
+  // `_handleCommands` with the expected parameters.
+  const pushIndexReceived = 12;
+  const senderID = "6d09f6c4-89b2-41b3-a0ac-e4c2502b5485";
+  const remoteMessageIndex = 8;
+  const remoteMessages = [
+    {
+      index: remoteMessageIndex,
+      data: {
+        command: COMMAND_SENDTAB,
+        payload: {
+          encrypted: {},
+        },
+        sender: senderID,
+      },
+    },
+  ];
+
+  const fxAccounts = {
+    async withCurrentAccountState(cb) {
+      await cb({});
+    },
+  };
+  const commands = new FxAccountsCommands(fxAccounts);
+  commands.sendTab.handle = (sender, data, reason) => {
+    return {
+      title: "testTitle",
+      uri: "testURI",
+    };
+  };
+  commands._fxai.device = {
+    refreshDeviceList: () => {},
+    recentDeviceList: [
+      {
+        id: senderID,
+      },
+    ],
+  };
+  const mockCommands = sinon.mock(commands);
+  mockCommands
+    .expects("_getReason")
+    .once()
+    .withExactArgs(pushIndexReceived, remoteMessageIndex);
+
+  await commands._handleCommands(remoteMessages, pushIndexReceived);
+  mockCommands.verify();
+});
+
 add_task(
   async function test_commands_pollDeviceCommands_push_local_state_empty() {
     // Server state.
@@ -376,7 +460,7 @@ add_task(
     mockCommands
       .expects("_handleCommands")
       .once()
-      .withArgs(remoteMessages);
+      .withArgs(remoteMessages, pushIndexReceived);
     await commands.pollDeviceCommands(pushIndexReceived);
 
     mockCommands.verify();
@@ -397,7 +481,7 @@ add_task(async function test_commands_pollDeviceCommands_scheduled_local() {
     },
   ];
   const remoteIndex = 12;
-
+  const pushIndexReceived = 0;
   // Local state.
   const accountState = {
     data: {
@@ -431,7 +515,7 @@ add_task(async function test_commands_pollDeviceCommands_scheduled_local() {
   mockCommands
     .expects("_handleCommands")
     .once()
-    .withArgs(remoteMessages);
+    .withArgs(remoteMessages, pushIndexReceived);
   await commands.pollDeviceCommands();
 
   mockCommands.verify();
@@ -452,7 +536,7 @@ add_task(
       },
     ];
     const remoteIndex = 12;
-
+    const pushIndexReceived = 0;
     // Local state.
     const accountState = {
       data: {
@@ -484,7 +568,7 @@ add_task(
     mockCommands
       .expects("_handleCommands")
       .once()
-      .withArgs(remoteMessages);
+      .withArgs(remoteMessages, pushIndexReceived);
     await commands.pollDeviceCommands();
 
     mockCommands.verify();

toolkit/components/telemetry/docs/data/sync-ping.rst

@@ -295,6 +295,8 @@ client. This is logically the "other end" of ``sendcommand``.
   - streamID: A GUID which uniquely identifies this command invocation's
               specific target. The value for this GUID will be the same as the
               streamID sent to the client via ``sendcommand`` (new in Firefox 79).
+  - reason: A string value of either ``"poll"``, ``"push"``, or ``"push-missed"``
+            representing an explanation for why the command is being processed.
   - serverTime: (optional) Most recent server timestamp, as described above.
 
 The ``migrations`` Array