Backed out changeset d5d1f7579011 (bug 1743885) for causing xpc failures in...

=========

This section describes existing telemetry probes measuring interaction with

search engines from the browser UI.

Other search-related telemetry is recorded by Toolkit such as search service

telemetry and telemetry related to fetching search suggestions. Toolkit search

telemetry is relevant to Firefox as well as other consumers of Toolkit. See

:doc:`/toolkit/search/Telemetry` in the Toolkit documentation for details.

search engines.

.. toctree::

   :caption: Table of Contents

const SEARCH_TELEMETRY_KEY_PREFIX = "sggt";

const SEARCH_TELEMETRY_PRIVATE_BROWSING_KEY_SUFFIX = "pb";

const SEARCH_TELEMETRY_LATENCY = "SEARCH_SUGGESTIONS_LATENCY_MS";

/**

 * Generates an UUID.

 *

    });

  },

  /**

   * Records per-engine telemetry after a search has finished.

   *

   * @param {string} engineId

   * @param {boolean} privateMode

   *   Whether the search was in a private context.

   * @param {boolean} [aborted]

   *   Whether the search was aborted.

   */

  _reportTelemetryForEngine(engineId, privateMode, aborted = false) {

    this._reportBandwidthForEngine(engineId, privateMode);

    // Stop the latency stopwatch.

    if (this._requestStopwatchToken) {

      if (aborted) {

        TelemetryStopwatch.cancelKeyed(

          SEARCH_TELEMETRY_LATENCY,

          engineId,

          this._requestStopwatchToken

        );

      } else {

        TelemetryStopwatch.finishKeyed(

          SEARCH_TELEMETRY_LATENCY,

          engineId,

          this._requestStopwatchToken

        );

      }

      this._requestStopwatchToken = null;

    }

  },

  /**

   * Report bandwidth used by search activities. It only reports when it matches

   * search provider information.

      this._onRemoteLoaded.bind(this, deferredResponse, engineId, privateMode)

    );

    this._request.addEventListener("error", evt => {

      this._reportTelemetryForEngine(engineId, privateMode);

      this._reportBandwidthForEngine(engineId, privateMode);

      deferredResponse.resolve("HTTP error");

    });

    // Reject for an abort assuming it's always from .stop() in which case we shouldn't return local

    // or remote results for existing searches.

    this._request.addEventListener("abort", evt => {

      this._reportTelemetryForEngine(engineId, privateMode, true);

      this._reportBandwidthForEngine(engineId, privateMode);

      deferredResponse.reject("HTTP request aborted");

    });

      this._request.send();

    }

    // Start the latency stopwatch, but first cancel the current one if any.

    // `_requestStopwatchToken` is used to associate a stopwatch with each new

    // remote fetch. It also keeps track of the engine ID that was used for the

    // fetch, which is useful since the histogram is keyed on it.

    if (this._requestStopwatchToken) {

      TelemetryStopwatch.cancelKeyed(

        SEARCH_TELEMETRY_LATENCY,

        this._requestStopwatchToken.engineId,

        this._requestStopwatchToken

      );

    }

    this._requestStopwatchToken = { engineId };

    TelemetryStopwatch.startKeyed(

      SEARCH_TELEMETRY_LATENCY,

      engineId,

      this._requestStopwatchToken

    );

    return deferredResponse;

  },

   * @private

   */

  _onRemoteLoaded(deferredResponse, engineId, privateMode) {

    this._reportTelemetryForEngine(engineId, privateMode);

    if (!this._request) {

      deferredResponse.resolve(

        "Got HTTP response after the request was cancelled"

      return;

    }

    this._reportBandwidthForEngine(engineId, privateMode);

    let status, serverResults;

    try {

      status = this._request.status;

 */

SearchSuggestionController.SEARCH_HISTORY_MAX_VALUE_LENGTH = 255;

SearchSuggestionController.REMOTE_TIMEOUT_DEFAULT = REMOTE_TIMEOUT_DEFAULT;

/**

 * The maximum time (ms) to wait before giving up on a remote suggestions.

 */

Telemetry

=========

This document describes search telemetry recorded by Toolkit such as search

service telemetry and telemetry related to fetching search suggestions.

Other important search-related telemetry is recorded by Firefox and is

documented in :doc:`/browser/search/telemetry` in the Firefox documentation.

Scalars

-------

  1. Associated WebExtension is not installed.

  2. Associated WebExtension is disabled.

  3. The submission URL of the associated WebExtension is different to that of the saved settings.

Histograms

----------

SEARCH_SUGGESTIONS_LATENCY_MS

  This histogram records the latency in milliseconds of fetches to the

  suggestions endpoints of search engines, or in other words, the time from

  Firefox's request to a suggestions endpoint to the time Firefox receives a

  response. It is a keyed exponential histogram with 50 buckets and values

  between 0 and 30000 (0s and 30s). Keys in this histogram are search engine IDs

  for built-in search engines and 'other' for non-built-in search engines.

    response.setStatusLine(request.httpVersion, q.replace("HTTP ", ""), q);

    writeSuggestions(q, [q]);

  } else if (q && q.startsWith("delay")) {

    // Delay the response by delayMs milliseconds. 200ms is the default, less

    // than the timeout but hopefully enough to abort before completion.

    let match = /^delay([0-9]+)/.exec(q);

    let delayMs = match ? parseInt(match[1]) : 200;

    // Delay the response by 200 milliseconds (less than the timeout but hopefully enough to abort

    // before completion).

    response.processAsync();

    writeSuggestions(q, [q]);

    setTimeout(() => response.finish(), delayMs);

    setTimeout(() => response.finish(), 200);

  } else if (q && q.startsWith("slow ")) {

    // Delay the response by 10 seconds so the client timeout is reached.

    response.processAsync();

const { PromiseUtils } = ChromeUtils.import(

  "resource://gre/modules/PromiseUtils.jsm"

);

const { TelemetryTestUtils } = ChromeUtils.import(

  "resource://testing-common/TelemetryTestUtils.jsm"

);

const ENGINE_NAME = "other";

const SEARCH_TELEMETRY_LATENCY = "SEARCH_SUGGESTIONS_LATENCY_MS";

// We must make sure the FormHistoryStartup component is

// initialized in order for it to respond to FormHistory

// Begin tests

add_task(async function simple_no_result_callback() {

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  await new Promise(resolve => {

    let controller = new SearchSuggestionController(result => {

      Assert.equal(result.term, "no remote");

    controller.fetch("no remote", false, getEngine);

  });

  assertLatencyHistogram(histogram, true);

});

add_task(async function simple_no_result_callback_and_promise() {

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  // Make sure both the callback and promise get results

  let deferred = PromiseUtils.defer();

  let controller = new SearchSuggestionController(result => {

  Assert.equal(result.remote.length, 0);

  await deferred.promise;

  assertLatencyHistogram(histogram, true);

});

add_task(async function simple_no_result_promise() {

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  let controller = new SearchSuggestionController();

  let result = await controller.fetch("no remote", false, getEngine);

  Assert.equal(result.term, "no remote");

  Assert.equal(result.local.length, 0);

  Assert.equal(result.remote.length, 0);

  assertLatencyHistogram(histogram, true);

});

add_task(async function simple_remote_no_local_result() {

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  let controller = new SearchSuggestionController();

  let result = await controller.fetch("mo", false, getEngine);

  Assert.equal(result.term, "mo");

  Assert.equal(result.remote[0].value, "Mozilla");

  Assert.equal(result.remote[1].value, "modern");

  Assert.equal(result.remote[2].value, "mom");

  assertLatencyHistogram(histogram, true);

});

add_task(async function simple_remote_no_local_result_telemetry() {

  Services.telemetry.clearScalars();

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  let controller = new SearchSuggestionController();

  await controller.fetch("mo", false, getEngine);

  }, "should have the expected keyed scalars");

  const scalar = scalars[key];

  Assert.ok(`sggt-${ENGINE_NAME}` in scalar, "correct telemetry category");

  Assert.notEqual(scalar[`sggt-${ENGINE_NAME}`], 0, "bandwidth logged");

  assertLatencyHistogram(histogram, true);

  Assert.ok("sggt-other" in scalar, "correct telemetry category");

  Assert.notEqual(scalar["sggt-other"], 0, "bandwidth logged");

});

add_task(async function simple_remote_no_local_result_alternative_type() {

});

add_task(async function fetch_twice_in_a_row() {

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  // Two entries since the first will match the first fetch but not the second.

  await updateSearchHistory("bump", "delay local");

  await updateSearchHistory("bump", "delayed local");

  Assert.equal(result.local[0].value, "delayed local");

  Assert.equal(result.remote.length, 1);

  Assert.equal(result.remote[0].value, "delayed ");

  // Only the second fetch's latency should be recorded since the first fetch

  // was aborted and latencies for aborted fetches are not recorded.

  assertLatencyHistogram(histogram, true);

});

add_task(async function fetch_twice_subset_reuse_formHistoryResult() {

});

add_task(async function noremote_maxLocal() {

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  let controller = new SearchSuggestionController();

  controller.maxLocalResults = 2; // (should be ignored because no remote results)

  controller.maxRemoteResults = 0;

    );

  }

  Assert.equal(result.remote.length, 0);

  assertLatencyHistogram(histogram, false);

});

add_task(async function someremote_maxLocal() {

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  let controller = new SearchSuggestionController();

  controller.maxLocalResults = 2;

  controller.maxRemoteResults = 4;

      "letter " + String.fromCharCode("C".charCodeAt() + i)

    );

  }

  assertLatencyHistogram(histogram, true);

});

add_task(async function one_of_each() {

});

add_task(async function local_result_returned_remote_result_disabled() {

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  Services.prefs.setBoolPref("browser.search.suggest.enabled", false);

  let controller = new SearchSuggestionController();

  controller.maxLocalResults = 1;

    );

  }

  Assert.equal(result.remote.length, 0);

  assertLatencyHistogram(histogram, false);

  Services.prefs.setBoolPref("browser.search.suggest.enabled", true);

});

add_task(

  async function local_result_returned_remote_result_disabled_after_creation_of_controller() {

    let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

      SEARCH_TELEMETRY_LATENCY

    );

    let controller = new SearchSuggestionController();

    controller.maxLocalResults = 1;

    controller.maxRemoteResults = 1;

      );

    }

    Assert.equal(result.remote.length, 0);

    assertLatencyHistogram(histogram, false);

    Services.prefs.setBoolPref("browser.search.suggest.enabled", true);

  }

);

add_task(

  async function one_of_each_disabled_before_creation_enabled_after_creation_of_controller() {

    let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

      SEARCH_TELEMETRY_LATENCY

    );

    Services.prefs.setBoolPref("browser.search.suggest.enabled", false);

    let controller = new SearchSuggestionController();

    controller.maxLocalResults = 1;

    Assert.equal(result.remote.length, 1);

    Assert.equal(result.remote[0].value, "letter B");

    assertLatencyHistogram(histogram, true);

    Services.prefs.setBoolPref("browser.search.suggest.enabled", true);

  }

);

add_task(async function one_local_zero_remote() {

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  let controller = new SearchSuggestionController();

  controller.maxLocalResults = 1;

  controller.maxRemoteResults = 0;

    );

  }

  Assert.equal(result.remote.length, 0);

  assertLatencyHistogram(histogram, false);

});

add_task(async function zero_local_one_remote() {

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  let controller = new SearchSuggestionController();

  controller.maxLocalResults = 0;

  controller.maxRemoteResults = 1;

  Assert.equal(result.local.length, 0);

  Assert.equal(result.remote.length, 1);

  Assert.equal(result.remote[0].value, "letter A");

  assertLatencyHistogram(histogram, true);

});

add_task(async function stop_search() {

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  let controller = new SearchSuggestionController(result => {

    do_throw("The callback shouldn't be called after stop()");

  });

  await resultPromise.then(result => {

    Assert.equal(null, result);

  });

  assertLatencyHistogram(histogram, false);

});

add_task(async function empty_searchTerm() {

  // Empty searches don't go to the server but still get form history.

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  let controller = new SearchSuggestionController();

  let result = await controller.fetch("", false, getEngine);

  Assert.equal(result.term, "");

  Assert.ok(!!result.local.length);

  Assert.equal(result.remote.length, 0);

  assertLatencyHistogram(histogram, false);

});

add_task(async function slow_timeout() {

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  // Make the server return suggestions on a delay longer than the timeout of

  // the suggestion controller.

  let delayMs = 3 * SearchSuggestionController.REMOTE_TIMEOUT_DEFAULT;

  let searchString = `delay${delayMs} `;

  // Add a local result.

  let localValue = searchString + " local result";

  await updateSearchHistory("bump", localValue);

  // Do a search. The remote fetch should time out but the local result should

  // be returned.

  let controller = new SearchSuggestionController();

  let result = await controller.fetch(searchString, false, getEngine);

  Assert.equal(result.term, searchString);

  let d = PromiseUtils.defer();

  function check_result(result) {

    Assert.equal(result.term, "slow ");

    Assert.equal(result.local.length, 1);

  Assert.equal(result.local[0].value, localValue);

  Assert.equal(result.remote.length, 0);

  // The remote fetch isn't done yet, so the latency histogram should not be

  // updated.

  assertLatencyHistogram(histogram, false);

  // Wait for the remote fetch to finish.

  await new Promise(r => setTimeout(r, delayMs));

  // Now the latency histogram should be updated.

  assertLatencyHistogram(histogram, true);

});

add_task(async function slow_timeout_2() {

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  // Make the server return suggestions on a delay longer the timeout of the

  // suggestion controller.

  let delayMs = 3 * SearchSuggestionController.REMOTE_TIMEOUT_DEFAULT;

  let searchString = `delay${delayMs} `;

  // Add a local result.

  let localValue = searchString + " local result";

  await updateSearchHistory("bump", localValue);

  // Do two searches using the same controller. Both times, the remote fetches

  // should time out and only the local result should be returned. The second

  // search should abort the remote fetch of the first search, and the remote

  // fetch of the second search should be ongoing when the second search

  // finishes.

  let controller = new SearchSuggestionController();

  for (let i = 0; i < 2; i++) {

    let result = await controller.fetch(searchString, false, getEngine);

    Assert.equal(result.term, searchString);

    Assert.equal(result.local.length, 1);

    Assert.equal(result.local[0].value, localValue);

    Assert.equal(result.local[0].value, "slow local result");

    Assert.equal(result.remote.length, 0);

  }

  await updateSearchHistory("bump", "slow local result");

  // The remote fetch of the second search isn't done yet, so the latency

  // histogram should not be updated.

  assertLatencyHistogram(histogram, false);

  // Wait for the second remote fetch to finish.

  await new Promise(r => setTimeout(r, delayMs));

  // Now the latency histogram should be updated, and only the remote fetch of

  // the second search should be recorded.

  assertLatencyHistogram(histogram, true);

  let controller = new SearchSuggestionController();

  setTimeout(function check_timeout() {

    // The HTTP response takes 10 seconds so check that we already have results after 2 seconds.

    check_result(result);

    d.resolve();

  }, 2000);

  let result = await controller.fetch("slow ", false, getEngine);

  check_result(result);

  await d.promise;

});

add_task(async function slow_stop() {

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  // Make the server return suggestions on a delay longer the timeout of the

  // suggestion controller.

  let delayMs = 3 * SearchSuggestionController.REMOTE_TIMEOUT_DEFAULT;

  let searchString = `delay${delayMs} `;

  // Do a search but stop it before it finishes. Wait a tick before stopping it

  // to better simulate the real world.

  let d = PromiseUtils.defer();

  let controller = new SearchSuggestionController();

  let resultPromise = controller.fetch(searchString, false, getEngine);

  await TestUtils.waitForTick();

  let resultPromise = controller.fetch("slow ", false, getEngine);

  setTimeout(function check_timeout() {

    // The HTTP response takes 10 seconds but we timeout in less than a second so just use 0.

    controller.stop();

  let result = await resultPromise;

  Assert.equal(result, null, "No result should be returned");

  // The remote fetch should have been aborted by stopping the controller, but

  // wait for the timeout period just to make sure it's done.

  await new Promise(r => setTimeout(r, delayMs));

    d.resolve();

  }, 0);

  await resultPromise.then(result => {

    Assert.equal(null, result);

  });

  // Since the latencies of aborted fetches are not recorded, the latency

  // histogram should not be updated.

  assertLatencyHistogram(histogram, false);

  await d.promise;

});

// Error handling

add_task(async function remote_term_mismatch() {

  await updateSearchHistory("bump", "Query Mismatch Entry");

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  let controller = new SearchSuggestionController();

  let result = await controller.fetch("Query Mismatch", false, getEngine);

  Assert.equal(result.term, "Query Mismatch");

  Assert.equal(result.local.length, 1);

  Assert.equal(result.local[0].value, "Query Mismatch Entry");

  Assert.equal(result.remote.length, 0);

  assertLatencyHistogram(histogram, true);

});

add_task(async function http_404() {

  await updateSearchHistory("bump", "HTTP 404 Entry");

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  let controller = new SearchSuggestionController();

  let result = await controller.fetch("HTTP 404", false, getEngine);

  Assert.equal(result.term, "HTTP 404");

  Assert.equal(result.local.length, 1);

  Assert.equal(result.local[0].value, "HTTP 404 Entry");

  Assert.equal(result.remote.length, 0);

  assertLatencyHistogram(histogram, true);

});

add_task(async function http_500() {

  await updateSearchHistory("bump", "HTTP 500 Entry");

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  let controller = new SearchSuggestionController();

  let result = await controller.fetch("HTTP 500", false, getEngine);

  Assert.equal(result.term, "HTTP 500");

  Assert.equal(result.local.length, 1);

  Assert.equal(result.local[0].value, "HTTP 500 Entry");

  Assert.equal(result.remote.length, 0);

  assertLatencyHistogram(histogram, true);

});

add_task(async function unresolvable_server() {

  await updateSearchHistory("bump", "Unresolvable Server Entry");

  let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(

    SEARCH_TELEMETRY_LATENCY

  );

  let controller = new SearchSuggestionController();

  let result = await controller.fetch(

    "Unresolvable Server",

  Assert.equal(result.local.length, 1);

  Assert.equal(result.local[0].value, "Unresolvable Server Entry");

  Assert.equal(result.remote.length, 0);

  assertLatencyHistogram(histogram, true);

});

// Exception handling

    );

  });

}

function assertLatencyHistogram(histogram, shouldRecord) {

  let snapshot = histogram.snapshot();

  info("Checking latency snapshot: " + JSON.stringify(snapshot));

  // Build a map from engine ID => number of non-zero values recorded for it.

  let valueCountByEngineId = Object.entries(snapshot).reduce(

    (memo, [key, data]) => {

      memo[key] = Object.values(data.values).filter(v => v != 0);

      return memo;

    },

    {}

  );

  let expected = shouldRecord ? { [ENGINE_NAME]: [1] } : {};

  Assert.deepEqual(

    valueCountByEngineId,

    expected,

    shouldRecord ? "Latency histogram updated" : "Latency histogram not updated"

  );

}