corysanin/tubestation
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Bug 1799265 - Add a name, configurable timeout, and more logging to MerinoClient. r=daisuke

Browse Source 
This adds a new `name` property to MerinoClient that's included in log
messages. That makes it easier to understand logs when there's more than one
client, as there will be since the new weather feature will use its own. This
also adds more logging.

It also adds a timeout param to `fetch()`. The param overrides the timeout pref.
The weather MerinoClient will use a custom timeout.

Differential Revision: https://phabricator.services.mozilla.com/D161369
This commit is contained in:
Drew Willcoxon
2022-11-08 02:13:00 +00:00
parent a477ca4587
commit 21a047b345
2 changed files with 94 additions and 18 deletions
Download Patch File Download Diff File Expand all files Collapse all files

61
browser/components/urlbar/MerinoClient.sys.mjs
View File

@@ -27,7 +27,9 @@ const HISTOGRAM_LATENCY = "FX_URLBAR_MERINO_LATENCY_MS";
const HISTOGRAM_RESPONSE = "FX_URLBAR_MERINO_RESPONSE";
/**
* Client class for querying the Merino server.
* Client class for querying the Merino server. Each instance maintains its own
* session state including a session ID and sequence number that is included in
* its requests to Merino.
*/
export class MerinoClient {
/**
@@ -38,12 +40,25 @@ export class MerinoClient {
return { ...SEARCH_PARAMS };
}
constructor() {
/**
* @param {string} name
* An optional name for the client. It will be included in log messages.
*/
constructor(name = "anonymous") {
this.#name = name;
XPCOMUtils.defineLazyGetter(this, "logger", () =>
lazy.UrlbarUtils.getLogger({ prefix: "MerinoClient" })
lazy.UrlbarUtils.getLogger({ prefix: `MerinoClient [${name}]` })
);
}
/**
* @returns {string}
* The name of the client.
*/
get name() {
return this.#name;
}
/**
* @returns {number}
* If `resetSession()` is not called within this timeout period after a
@@ -95,11 +110,21 @@ export class MerinoClient {
* Array of provider names to request from Merino. If this is given it will
* override the `merinoProviders` Nimbus variable and its fallback pref
* `browser.urlbar.merino.providers`.
* @param {number} options.timeoutMs
* Timeout in milliseconds. This method will return once the timeout
* elapses, a response is received, or an error occurs, whichever happens
* first.
* @returns {Array}
* The Merino suggestions or null if there's an error or unexpected
* response.
*/
async fetch({ query, providers = null }) {
async fetch({
query,
providers = null,
timeoutMs = lazy.UrlbarPrefs.get("merinoTimeoutMs"),
}) {
this.logger.info(`Fetch starting with query: "${query}"`);
// Set up the Merino session ID and related state. The session ID is a UUID
// without leading and trailing braces.
if (!this.#sessionID) {
@@ -128,7 +153,7 @@ export class MerinoClient {
try {
url = new URL(endpointString);
} catch (error) {
this.logger.error("Could not make Merino endpoint URL: " + error);
this.logger.error("Error creating endpoint URL: " + error);
return null;
}
url.searchParams.set(SEARCH_PARAMS.QUERY, query);
@@ -162,21 +187,24 @@ export class MerinoClient {
url.searchParams.set(SEARCH_PARAMS.PROVIDERS, providersString);
}
let details = { query, providers, timeoutMs, url };
this.logger.debug("Fetch details: " + JSON.stringify(details));
let recordResponse = category => {
this.logger.info("Fetch done with status: " + category);
Services.telemetry.getHistogramById(HISTOGRAM_RESPONSE).add(category);
this.#lastFetchStatus = category;
recordResponse = null;
};
// Set up the timeout timer.
let timeout = lazy.UrlbarPrefs.get("merinoTimeoutMs");
let timer = (this.#timeoutTimer = new lazy.SkippableTimer({
name: "Merino timeout",
time: timeout,
time: timeoutMs,
logger: this.logger,
callback: () => {
// The fetch timed out.
this.logger.info(`Merino fetch timed out (timeout = ${timeout}ms)`);
this.logger.info(`Fetch timed out (timeout = ${timeoutMs}ms)`);
recordResponse?.("timeout");
},
}));
@@ -187,7 +215,7 @@ export class MerinoClient {
try {
this.#fetchController?.abort();
} catch (error) {
this.logger.error("Could not abort Merino fetch: " + error);
this.logger.error("Error aborting previous fetch: " + error);
}
// Do the fetch.
@@ -209,11 +237,15 @@ export class MerinoClient {
// returned by `Promise.race`.
response = await fetch(url, { signal: controller.signal });
TelemetryStopwatch.finish(HISTOGRAM_LATENCY, stopwatchInstance);
this.logger.debug(
"Got response: " +
JSON.stringify({ "response.status": response.status, ...details })
);
recordResponse?.(response.ok ? "success" : "http_error");
} catch (error) {
TelemetryStopwatch.cancel(HISTOGRAM_LATENCY, stopwatchInstance);
if (error.name != "AbortError") {
this.logger.error("Could not fetch Merino endpoint: " + error);
this.logger.error("Fetch error: " + error);
recordResponse?.("network_error");
}
} finally {
@@ -238,7 +270,11 @@ export class MerinoClient {
try {
body = await response?.json();
} catch (error) {
this.logger.error("Could not get Merino response as JSON: " + error);
this.logger.error("Error getting response as JSON: " + error);
}
if (body) {
this.logger.debug("Response body: " + JSON.stringify(body));
}
if (!body?.suggestions?.length) {
@@ -247,7 +283,7 @@ export class MerinoClient {
let { suggestions, request_id } = body;
if (!Array.isArray(suggestions)) {
this.logger.error("Unexpected Merino response: " + JSON.stringify(body));
this.logger.error("Unexpected response: " + JSON.stringify(body));
return [];
}
@@ -327,6 +363,7 @@ export class MerinoClient {
#sessionTimer = null;
#sessionTimeoutMs = SESSION_TIMEOUT_MS;
#name;
#timeoutTimer = null;
#fetchController = null;
#latencyStopwatchInstance = null;

51
browser/components/urlbar/tests/quicksuggest/unit/test_merinoClient.js
View File

@@ -35,6 +35,18 @@ add_task(async function init() {
}
});
// Checks client names.
add_task(async function name() {
Assert.equal(
gClient.name,
"anonymous",
"gClient name is 'anonymous' since it wasn't given a name"
);
let client = new MerinoClient("New client");
Assert.equal(client.name, "New client", "newClient name is correct");
});
// Basic test that checks fetched suggestions.
add_task(async function basic() {
let histograms = MerinoTestUtils.getAndClearHistograms();
@@ -175,26 +187,53 @@ add_task(async function httpError() {
// Tests a client timeout.
add_task(async function clientTimeout() {
await doClientTimeoutTest(200);
await doClientTimeoutTest();
});
// Tests a client timeout followed by an HTTP error. Only the timeout should be
// recorded.
add_task(async function clientTimeoutFollowedByHTTPError() {
MerinoTestUtils.server.response = { status: 500 };
await doClientTimeoutTest(500);
await doClientTimeoutTest({ expectedResponseStatus: 500 });
});
async function doClientTimeoutTest(expectedResponseStatus) {
// Tests a client timeout when a timeout value is passed to `fetch()`, which
// should override the value in the `merino.timeoutMs` pref.
add_task(async function timeoutPassedToFetch() {
// Set up a timeline like this:
//
// 1ms: The timeout passed to `fetch()` elapses
// 400ms: Merino returns a response
// 30000ms: The timeout in the pref elapses
//
// The expected behavior is that the 1ms timeout is hit, the request fails
// with a timeout, and Merino later returns a response. If the 1ms timeout is
// not hit, then Merino will return a response before the 30000ms timeout
// elapses and the request will complete successfully.
UrlbarPrefs.set("merino.timeoutMs", 30000);
await doClientTimeoutTest({
responseDelay: 400,
fetchArgs: { query: "search", timeoutMs: 1 },
});
UrlbarPrefs.clear("merino.timeoutMs");
});
async function doClientTimeoutTest({
responseDelay = 2 * UrlbarPrefs.get("merino.timeoutMs"),
fetchArgs = { query: "search" },
expectedResponseStatus = 200,
} = {}) {
let histograms = MerinoTestUtils.getAndClearHistograms();
// Make the server return a delayed response so the client times out waiting
// for it.
MerinoTestUtils.server.response.delay =
2 * UrlbarPrefs.get("merino.timeoutMs");
MerinoTestUtils.server.response.delay = responseDelay;
let responsePromise = gClient.waitForNextResponse();
await fetchAndCheckSuggestions({ expected: [] });
await fetchAndCheckSuggestions({ args: fetchArgs, expected: [] });
Assert.equal(gClient.lastFetchStatus, "timeout", "The request timed out");