Bug 1639843 - Added reason field to command-received telemetry events r=markh,rfkelly

Differential Revision: https://phabricator.services.mozilla.com/D82096
2020-07-13 21:46:49 +00:00 · 2020-07-13 21:46:49 +00:00 · 5cdf58ff2a
--- a/services/fxaccounts/FxAccountsCommands.js
+++ b/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,7 +165,24 @@ 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) {
@ -173,8 +190,9 @@ class FxAccountsCommands {
    }
    // 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 {
--- a/services/fxaccounts/tests/xpcshell/test_commands.js
+++ b/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,7 +228,8 @@ 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",
@ -235,11 +237,44 @@ add_task(async function test_sendtab_receive_old_client() {
      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();
--- a/toolkit/components/telemetry/docs/data/sync-ping.rst
+++ b/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