firefox/services/sync/modules/doctor.sys.mjs

/* This Source Code Form is subject to the terms of the Mozilla Public
 * License, v. 2.0. If a copy of the MPL was not distributed with this
 * file, You can obtain one at http://mozilla.org/MPL/2.0/. */

// A doctor for our collections. She can be asked to make a consultation, and
// may just diagnose an issue without attempting to cure it, may diagnose and
// attempt to cure, or may decide she is overworked and underpaid.
// Or something - naming is hard :)

import { Log } from "resource://gre/modules/Log.sys.mjs";

import { Async } from "resource://services-common/async.sys.mjs";
import { Observers } from "resource://services-common/observers.sys.mjs";
import { Service } from "resource://services-sync/service.sys.mjs";
import { Resource } from "resource://services-sync/resource.sys.mjs";
import { Svc } from "resource://services-sync/util.sys.mjs";

const log = Log.repository.getLogger("Sync.Doctor");

export var Doctor = {
  async consult(recentlySyncedEngines) {
    if (!Services.telemetry.canRecordBase) {
      log.info("Skipping consultation: telemetry reporting is disabled");
      return;
    }

    let engineInfos = this._getEnginesToValidate(recentlySyncedEngines);

    await this._runValidators(engineInfos);
  },

  _getEnginesToValidate(recentlySyncedEngines) {
    let result = {};
    for (let e of recentlySyncedEngines) {
      let prefPrefix = `engine.${e.name}.`;
      if (
        !Svc.PrefBranch.getBoolPref(prefPrefix + "validation.enabled", false)
      ) {
        log.info(`Skipping check of ${e.name} - disabled via preferences`);
        continue;
      }
      // Check the last validation time for the engine.
      let lastValidation = Svc.PrefBranch.getIntPref(
        prefPrefix + "validation.lastTime",
        0
      );
      let validationInterval = Svc.PrefBranch.getIntPref(
        prefPrefix + "validation.interval"
      );
      let nowSeconds = this._now();

      if (nowSeconds - lastValidation < validationInterval) {
        log.info(
          `Skipping validation of ${e.name}: too recent since last validation attempt`
        );
        continue;
      }
      // Update the time now, even if we decline to actually perform a
      // validation. We don't want to check the rest of these more frequently
      // than once a day.
      Svc.PrefBranch.setIntPref(
        prefPrefix + "validation.lastTime",
        Math.floor(nowSeconds)
      );

      // Validation only occurs a certain percentage of the time.
      let validationProbability =
        Svc.PrefBranch.getIntPref(
          prefPrefix + "validation.percentageChance",
          0
        ) / 100.0;
      if (validationProbability < Math.random()) {
        log.info(
          `Skipping validation of ${e.name}: Probability threshold not met`
        );
        continue;
      }

      let maxRecords = Svc.PrefBranch.getIntPref(
        prefPrefix + "validation.maxRecords"
      );
      if (!maxRecords) {
        log.info(`Skipping validation of ${e.name}: No maxRecords specified`);
        continue;
      }
      // OK, so this is a candidate - the final decision will be based on the
      // number of records actually found.
      result[e.name] = { engine: e, maxRecords };
    }
    return result;
  },

  async _runValidators(engineInfos) {
    if (!Object.keys(engineInfos).length) {
      log.info("Skipping validation: no engines qualify");
      return;
    }

    if (Object.values(engineInfos).filter(i => i.maxRecords != -1).length) {
      // at least some of the engines have maxRecord restrictions which require
      // us to ask the server for the counts.
      let countInfo = await this._fetchCollectionCounts();
      for (let [engineName, recordCount] of Object.entries(countInfo)) {
        if (engineName in engineInfos) {
          engineInfos[engineName].recordCount = recordCount;
        }
      }
    }

    for (let [
      engineName,
      { engine, maxRecords, recordCount },
    ] of Object.entries(engineInfos)) {
      // maxRecords of -1 means "any number", so we can skip asking the server.
      // Used for tests.
      if (maxRecords >= 0 && recordCount > maxRecords) {
        log.debug(
          `Skipping validation for ${engineName} because ` +
            `the number of records (${recordCount}) is greater ` +
            `than the maximum allowed (${maxRecords}).`
        );
        continue;
      }
      let validator = engine.getValidator();
      if (!validator) {
        // This is probably only possible in profile downgrade cases.
        log.warn(
          `engine.getValidator returned null for ${engineName} but the pref that controls validation is enabled.`
        );
        continue;
      }

      if (!(await validator.canValidate())) {
        log.debug(
          `Skipping validation for ${engineName} because validator.canValidate() is false`
        );
        continue;
      }

      // Let's do it!
      Services.console.logStringMessage(
        `Sync is about to run a consistency check of ${engine.name}. This may be slow, and ` +
          `can be controlled using the pref "services.sync.${engine.name}.validation.enabled".\n` +
          `If you encounter any problems because of this, please file a bug.`
      );

      try {
        log.info(`Running validator for ${engine.name}`);
        let result = await validator.validate(engine);
        let { problems, version, duration, recordCount } = result;
        Observers.notify(
          "weave:engine:validate:finish",
          {
            version,
            checked: recordCount,
            took: duration,
            problems: problems ? problems.getSummary(true) : null,
          },
          engine.name
        );
      } catch (ex) {
        if (Async.isShutdownException(ex)) {
          throw ex;
        }
        log.error(`Failed to run validation on ${engine.name}!`, ex);
        Observers.notify("weave:engine:validate:error", ex, engine.name);
        // Keep validating -- there's no reason to think that a failure for one
        // validator would mean the others will fail.
      }
    }
  },

  // mainly for mocking.
  async _fetchCollectionCounts() {
    let collectionCountsURL = Service.userBaseURL + "info/collection_counts";
    try {
      let infoResp = await Service._fetchInfo(collectionCountsURL);
      if (!infoResp.success) {
        log.error(
          "Can't fetch collection counts: request to info/collection_counts responded with " +
            infoResp.status
        );
        return {};
      }
      return infoResp.obj; // might throw because obj is a getter which parses json.
    } catch (ex) {
      if (Async.isShutdownException(ex)) {
        throw ex;
      }
      // Not running validation is totally fine, so we just write an error log and return.
      log.error("Caught error when fetching counts", ex);
      return {};
    }
  },

  // functions used so tests can mock them
  _now() {
    // We use the server time, which is SECONDS
    return Resource.serverTime;
  },
};