--- a/services/sync/modules/bookmark_repair.js
+++ b/services/sync/modules/bookmark_repair.js
@@ -13,16 +13,17 @@ Cu.import("resource://gre/modules/Prefer
Cu.import("resource://gre/modules/Log.jsm");
Cu.import("resource://gre/modules/PlacesUtils.jsm");
Cu.import("resource://gre/modules/PlacesSyncUtils.jsm");
Cu.import("resource://services-sync/util.js");
Cu.import("resource://services-sync/collection_repair.js");
Cu.import("resource://services-sync/constants.js");
Cu.import("resource://services-sync/resource.js");
Cu.import("resource://services-sync/doctor.js");
+Cu.import("resource://services-sync/telemetry.js");
Cu.import("resource://services-common/utils.js");
const log = Log.repository.getLogger("Sync.Engine.Bookmarks.Repair");
const PREF_BRANCH = "services.sync.repairs.bookmarks.";
// How long should we wait after sending a repair request before we give up?
const RESPONSE_INTERVAL_TIMEOUT = 60 * 60 * 24 * 3; // 3 days
@@ -546,103 +547,132 @@ class BookmarkRepairResponder extends Co
}
// Note that we don't try and guard against multiple repairs being in
// progress as we don't do anything too smart that could cause problems,
// but just upload items. If we get any smarter we should re-think this
// (but when we do, note that checking this._currentState isn't enough as
// this responder is not a singleton)
- let engine = this.service.engineManager.get("bookmarks");
-
- // Some items have been requested, but we need to be careful about how we
- // handle them:
- // * The item exists locally, but isn't in the tree of items we sync (eg, it
- // might be a left-pane item or similar.) We write a tombstone for these.
- // * The item exists locally as a folder - and the children of the folder
- // also don't exist on the server - just uploading the folder isn't going
- // to help. (Note that we assume the parents *do* exist, otherwise the
- // device requesting the item be uploaded wouldn't be aware it exists)
- // Bug 1343101 covers additional issues we might repair in the future.
-
- let allIDs = new Set(); // all items we discovered inspecting the requested IDs.
- let maybeToDelete = new Set(); // items we *may* delete.
- let toUpload = new Set(); // items we will upload.
- let results = await PlacesSyncUtils.bookmarks.fetchSyncIdsForRepair(request.ids);
- for (let { syncId: id, syncable } of results) {
- allIDs.add(id);
- if (syncable) {
- toUpload.add(id);
- } else {
- log.debug(`repair request to upload item ${id} but it isn't under a syncable root`);
- maybeToDelete.add(id);
- }
- }
- if (log.level <= Log.Level.Debug) {
- let missingItems = request.ids.filter(id =>
- !toUpload.has(id) && !maybeToDelete.has(id)
- );
- if (missingItems.length) {
- log.debug("repair request to upload items that don't exist locally",
- missingItems);
- }
- }
- // So we've now got items we know should potentially be uploaded or deleted.
- // Query the server to find out what it actually has.
- let existsRemotely = new Set(); // items we determine already exist on the server
- let itemSource = engine.itemSource();
- itemSource.ids = Array.from(allIDs);
- log.trace(`checking the server for items`, itemSource.ids);
- for (let remoteID of JSON.parse(itemSource.get())) {
- log.trace(`the server has "${remoteID}"`);
- existsRemotely.add(remoteID);
- // This item exists on the server, so remove it from toUpload if it wasn't
- // explicitly requested (ie, if it's just a child of a requested item and
- // it exists then there's no need to upload it, but if it was explicitly
- // requested, that may be due to the requestor believing it is corrupt.
- if (request.ids.indexOf(remoteID) == -1) {
- toUpload.delete(remoteID);
- }
- }
- // We only need to flag as deleted items that actually are on the server.
- let toDelete = CommonUtils.difference(maybeToDelete, existsRemotely);
- // whew - now add these items to the tracker "weakly" (ie, they will not
- // persist in the case of a restart, but that's OK - we'll then end up here
- // again.)
- log.debug(`repair request will upload ${toUpload.size} items and delete ${toDelete.size} items`);
- for (let id of toUpload) {
- engine._modified.setWeak(id, { tombstone: false });
- }
- for (let id of toDelete) {
- engine._modified.setWeak(id, { tombstone: true });
- }
-
- // Add an observer for the engine sync being complete.
this._currentState = {
request,
rawCommand,
- toUpload,
- toDelete,
+ ids: [],
}
- if (toUpload.size || toDelete.size) {
- // We have arranged for stuff to be uploaded, so wait until that's done.
- Svc.Obs.add("weave:engine:sync:uploaded", this.onUploaded, this);
- // and record in telemetry that we got this far - just incase we never
- // end up doing the upload for some obscure reason.
- let eventExtra = {
- flowID: request.flowID,
- numIDs: (toUpload.size + toDelete.size).toString(),
- };
- this.service.recordTelemetryEvent("repairResponse", "uploading", undefined, eventExtra);
- } else {
- // We were unable to help with the repair, so report that we are done.
+
+ try {
+ let engine = this.service.engineManager.get("bookmarks");
+ let { toUpload, toDelete } = await this._fetchItemsToUpload(request);
+
+ if (toUpload.size || toDelete.size) {
+ log.debug(`repair request will upload ${toUpload.size} items and delete ${toDelete.size} items`);
+ // whew - now add these items to the tracker "weakly" (ie, they will not
+ // persist in the case of a restart, but that's OK - we'll then end up here
+ // again) and also record them in the response we send back.
+ for (let id of toUpload) {
+ engine._modified.setWeak(id, { tombstone: false });
+ this._currentState.ids.push(id);
+ }
+ for (let id of toDelete) {
+ engine._modified.setWeak(id, { tombstone: true });
+ this._currentState.ids.push(id);
+ }
+
+ // We have arranged for stuff to be uploaded, so wait until that's done.
+ Svc.Obs.add("weave:engine:sync:uploaded", this.onUploaded, this);
+ // and record in telemetry that we got this far - just incase we never
+ // end up doing the upload for some obscure reason.
+ let eventExtra = {
+ flowID: request.flowID,
+ numIDs: this._currentState.ids.length.toString(),
+ };
+ this.service.recordTelemetryEvent("repairResponse", "uploading", undefined, eventExtra);
+ } else {
+ // We were unable to help with the repair, so report that we are done.
+ this._finishRepair();
+ }
+ } catch (ex) {
+ if (Async.isShutdownException(ex)) {
+ // this repair request will be tried next time.
+ throw ex;
+ }
+ // On failure, we still write a response so the requestor knows to move
+ // on, but we record the failure reason in telemetry.
+ log.error("Failed to respond to the repair request", ex);
+ this._currentState.failureReason = SyncTelemetry.transformError(ex);
this._finishRepair();
}
}
+ async _fetchItemsToUpload(request) {
+ let toUpload = new Set(); // items we will upload.
+ let toDelete = new Set(); // items we will delete.
+
+ let requested = new Set(request.ids);
+
+ let engine = this.service.engineManager.get("bookmarks");
+ // Determine every item that may be impacted by the requested IDs - eg,
+ // this may include children if a requested ID is a folder.
+ // Turn an array of { syncId, syncable } into a map of syncId -> syncable.
+ let repairable = await PlacesSyncUtils.bookmarks.fetchSyncIdsForRepair(request.ids);
+ if (repairable.length == 0) {
+ // server will get upset if we request an empty set, and we can't do
+ // anything in that case, so bail now.
+ return { toUpload, toDelete };
+ }
+
+ // which of these items exist on the server?
+ let itemSource = engine.itemSource();
+ itemSource.ids = repairable.map(item => item.syncId);
+ log.trace(`checking the server for items`, itemSource.ids);
+ let itemsResponse = itemSource.get();
+ // If the response failed, don't bother trying to parse the output.
+ // Throwing here means we abort the repair, which isn't ideal for transient
+ // errors (eg, no network, 500 service outage etc), but we don't currently
+ // have a sane/safe way to try again later (we'd need to implement a kind
+ // of timeout, otherwise we might end up retrying forever and never remove
+ // our request command.) Bug 1347805.
+ if (!itemsResponse.success) {
+ throw new Error(`request for server IDs failed: ${itemsResponse.status}`);
+ }
+ let existRemotely = new Set(JSON.parse(itemsResponse));
+ // We need to be careful about handing the requested items:
+ // * If the item exists locally but isn't in the tree of items we sync
+ // (eg, it might be a left-pane item or similar, we write a tombstone.
+ // * If the item exists locally as a folder, we upload the folder and any
+ // children which don't exist on the server. (Note that we assume the
+ // parents *do* exist)
+ // Bug 1343101 covers additional issues we might repair in the future.
+ for (let { syncId: id, syncable } of repairable) {
+ if (requested.has(id)) {
+ if (syncable) {
+ log.debug(`repair request to upload item '${id}' which exists locally; uploading`);
+ toUpload.add(id);
+ } else {
+ // explicitly requested and not syncable, so tombstone.
+ log.debug(`repair request to upload item '${id}' but it isn't under a syncable root; writing a tombstone`);
+ toDelete.add(id);
+ }
+ } else {
+ // The item wasn't explicitly requested - only upload if it is syncable
+ // and doesn't exist on the server.
+ if (syncable && !existRemotely.has(id)) {
+ log.debug(`repair request found related item '${id}' which isn't on the server; uploading`);
+ toUpload.add(id);
+ } else if (!syncable && existRemotely.has(id)) {
+ log.debug(`repair request found non-syncable related item '${id}' on the server; writing a tombstone`);
+ toDelete.add(id);
+ } else {
+ log.debug(`repair request found related item '${id}' which we will not upload; ignoring`);
+ }
+ }
+ }
+ return { toUpload, toDelete };
+ }
+
onUploaded(subject, data) {
if (data != "bookmarks") {
return;
}
Svc.Obs.remove("weave:engine:sync:uploaded", this.onUploaded, this);
log.debug(`bookmarks engine has uploaded stuff - creating a repair response`);
this._finishRepair();
}
@@ -650,33 +680,34 @@ class BookmarkRepairResponder extends Co
_finishRepair() {
let clientsEngine = this.service.clientsEngine;
let flowID = this._currentState.request.flowID;
let response = {
request: this._currentState.request.request,
collection: "bookmarks",
clientID: clientsEngine.localID,
flowID,
- ids: [],
- }
- for (let id of this._currentState.toUpload) {
- response.ids.push(id);
- }
- for (let id of this._currentState.toDelete) {
- response.ids.push(id);
+ ids: this._currentState.ids,
}
let clientID = this._currentState.request.requestor;
clientsEngine.sendCommand("repairResponse", [response], clientID, { flowID });
// and nuke the request from our client.
clientsEngine.removeLocalCommand(this._currentState.rawCommand);
let eventExtra = {
flowID,
numIDs: response.ids.length.toString(),
}
- this.service.recordTelemetryEvent("repairResponse", "finished", undefined, eventExtra);
+ if (this._currentState.failureReason) {
+ // *sob* - recording this in "extra" means the value must be a string of
+ // max 85 chars.
+ eventExtra.failureReason = JSON.stringify(this._currentState.failureReason).substring(0, 85)
+ this.service.recordTelemetryEvent("repairResponse", "failed", undefined, eventExtra);
+ } else {
+ this.service.recordTelemetryEvent("repairResponse", "finished", undefined, eventExtra);
+ }
this._currentState = null;
}
_abortRepair(request, rawCommand, why) {
log.warn(`aborting repair request: ${why}`);
this.service.clientsEngine.removeLocalCommand(rawCommand);
// record telemetry for this.
let eventExtra = {
--- a/services/sync/modules/telemetry.js
+++ b/services/sync/modules/telemetry.js
@@ -60,63 +60,16 @@ const ENGINES = new Set(["addons", "book
// A regex we can use to replace the profile dir in error messages. We use a
// regexp so we can simply replace all case-insensitive occurences.
// This escaping function is from:
// https://developer.mozilla.org/en/docs/Web/JavaScript/Guide/Regular_Expressions
const reProfileDir = new RegExp(
OS.Constants.Path.profileDir.replace(/[.*+?^${}()|[\]\\]/g, "\\$&"),
"gi");
-function transformError(error, engineName) {
- if (Async.isShutdownException(error)) {
- return { name: "shutdownerror" };
- }
-
- if (typeof error === "string") {
- if (error.startsWith("error.")) {
- // This is hacky, but I can't imagine that it's not also accurate.
- return { name: "othererror", error };
- }
- // There's a chance the profiledir is in the error string which is PII we
- // want to avoid including in the ping.
- error = error.replace(reProfileDir, "[profileDir]");
- return { name: "unexpectederror", error };
- }
-
- if (error.failureCode) {
- return { name: "othererror", error: error.failureCode };
- }
-
- if (error instanceof AuthenticationError) {
- return { name: "autherror", from: error.source };
- }
-
- if (error instanceof Ci.mozIStorageError) {
- return { name: "sqlerror", code: error.result };
- }
-
- let httpCode = error.status ||
- (error.response && error.response.status) ||
- error.code;
-
- if (httpCode) {
- return { name: "httperror", code: httpCode };
- }
-
- if (error.result) {
- return { name: "nserror", code: error.result };
- }
-
- return {
- name: "unexpectederror",
- // as above, remove the profile dir value.
- error: String(error).replace(reProfileDir, "[profileDir]")
- }
-}
-
function tryGetMonotonicTimestamp() {
try {
return Telemetry.msSinceProcessStart();
} catch (e) {
log.warn("Unable to get a monotonic timestamp!");
return -1;
}
}
@@ -182,17 +135,17 @@ class EngineRecord {
}
finished(error) {
let took = timeDeltaFrom(this.startTime);
if (took > 0) {
this.took = took;
}
if (error) {
- this.failureReason = transformError(error, this.name);
+ this.failureReason = SyncTelemetry.transformError(error);
}
}
recordApplied(counts) {
if (this.incoming) {
log.error(`Incoming records applied multiple times for engine ${this.name}!`);
return;
}
@@ -236,17 +189,17 @@ class EngineRecord {
recordValidationError(e) {
if (this.validation) {
log.error(`Multiple validations occurred for engine ${this.name}!`);
return;
}
this.validation = {
- failureReason: transformError(e)
+ failureReason: SyncTelemetry.transformError(e)
};
}
recordUploaded(counts) {
if (counts.sent || counts.failed) {
if (!this.outgoing) {
this.outgoing = [];
}
@@ -297,17 +250,17 @@ class TelemetryRecord {
finished(error) {
this.took = timeDeltaFrom(this.startTime);
if (this.currentEngine != null) {
log.error("Finished called for the sync before the current engine finished");
this.currentEngine.finished(null);
this.onEngineStop(this.currentEngine.name);
}
if (error) {
- this.failureReason = transformError(error);
+ this.failureReason = SyncTelemetry.transformError(error);
}
// We don't bother including the "devices" field if we can't come up with a
// UID or device ID for *this* device -- If that's the case, any data we'd
// put there would be likely to be full of garbage anyway.
// Note that we currently use the "sync device GUID" rather than the "FxA
// device ID" as the latter isn't stable enough for our purposes - see bug
// 1316535.
@@ -683,11 +636,63 @@ class SyncTelemetryImpl {
this._recordEvent(subject);
break;
default:
log.warn(`unexpected observer topic ${topic}`);
break;
}
}
+
+ // Transform an exception into a standard description. Exposed here for when
+ // this module isn't directly responsible for knowing the transform should
+ // happen (for example, when including an error in the |extra| field of
+ // event telemetry)
+ transformError(error) {
+ if (Async.isShutdownException(error)) {
+ return { name: "shutdownerror" };
+ }
+
+ if (typeof error === "string") {
+ if (error.startsWith("error.")) {
+ // This is hacky, but I can't imagine that it's not also accurate.
+ return { name: "othererror", error };
+ }
+ // There's a chance the profiledir is in the error string which is PII we
+ // want to avoid including in the ping.
+ error = error.replace(reProfileDir, "[profileDir]");
+ return { name: "unexpectederror", error };
+ }
+
+ if (error.failureCode) {
+ return { name: "othererror", error: error.failureCode };
+ }
+
+ if (error instanceof AuthenticationError) {
+ return { name: "autherror", from: error.source };
+ }
+
+ if (error instanceof Ci.mozIStorageError) {
+ return { name: "sqlerror", code: error.result };
+ }
+
+ let httpCode = error.status ||
+ (error.response && error.response.status) ||
+ error.code;
+
+ if (httpCode) {
+ return { name: "httperror", code: httpCode };
+ }
+
+ if (error.result) {
+ return { name: "nserror", code: error.result };
+ }
+
+ return {
+ name: "unexpectederror",
+ // as above, remove the profile dir value.
+ error: String(error).replace(reProfileDir, "[profileDir]")
+ }
+ }
+
}
this.SyncTelemetry = new SyncTelemetryImpl(ENGINES);
--- a/services/sync/tests/unit/head_http_server.js
+++ b/services/sync/tests/unit/head_http_server.js
@@ -398,17 +398,24 @@ ServerCollection.prototype = {
}
chunk = chunk.split("=");
if (chunk.length == 1) {
options[chunk[0]] = "";
} else {
options[chunk[0]] = chunk[1];
}
}
- if (options.ids) {
+ // The real servers return 400 if ids= is specified without a list of IDs.
+ if (options.hasOwnProperty("ids")) {
+ if (!options.ids) {
+ response.setStatusLine(request.httpVersion, "400", "Bad Request");
+ body = "Bad Request";
+ response.bodyOutputStream.write(body, body.length);
+ return;
+ }
options.ids = options.ids.split(",");
}
if (options.newer) {
options.newer = parseFloat(options.newer);
}
if (options.limit) {
options.limit = parseInt(options.limit, 10);
}
@@ -929,17 +936,19 @@ SyncServer.prototype = {
let coll = this.getCollection(username, collection);
switch (req.method) {
case "GET": {
if (!coll) {
if (wboID) {
respond(404, "Not found", "Not found");
return undefined;
}
- // *cries inside*: Bug 687299.
+ // *cries inside*: Bug 687299 - now fixed, so apparently the real
+ // sync server *will* 404 in this case - bug 1347807 is to change
+ // this to a 404 and fix a handful of test failures it causes.
respond(200, "OK", "[]");
return undefined;
}
if (!wboID) {
return coll.collectionHandler(req, resp);
}
let wbo = coll.wbo(wboID);
if (!wbo) {
--- a/services/sync/tests/unit/test_bookmark_repair_responder.js
+++ b/services/sync/tests/unit/test_bookmark_repair_responder.js
@@ -9,16 +9,18 @@ Cu.import("resource://gre/modules/Log.js
Cu.import("resource://services-sync/engines/bookmarks.js");
Cu.import("resource://services-sync/service.js");
Cu.import("resource://services-sync/bookmark_repair.js");
Cu.import("resource://testing-common/services/sync/utils.js");
initTestLogging("Trace");
Log.repository.getLogger("Sync.Engine.Bookmarks").level = Log.Level.Trace;
+// sqlite logging generates lots of noise and typically isn't helpful here.
+Log.repository.getLogger("Sqlite").level = Log.Level.Error;
// stub telemetry so we can easily check the right things are recorded.
var recordedEvents = [];
Service.recordTelemetryEvent = (object, method, value, extra = undefined) => {
recordedEvents.push({ object, method, value, extra });
}
function checkRecordedEvents(expected) {
@@ -73,21 +75,58 @@ async function setup() {
return server;
}
async function cleanup(server) {
await promiseStopServer(server);
await PlacesSyncUtils.bookmarks.wipe();
Svc.Prefs.reset("engine.bookmarks.validation.enabled");
+ // clear keys so when each test finds a different server it accepts its keys.
+ Service.collectionKeys.clear();
}
+add_task(async function test_responder_error() {
+ let server = await setup();
+
+ // sync so the collection is created.
+ Service.sync();
+
+ let request = {
+ request: "upload",
+ ids: [Utils.makeGUID()],
+ flowID: Utils.makeGUID(),
+ }
+ let responder = new BookmarkRepairResponder();
+ // mock the responder to simulate an error.
+ responder._fetchItemsToUpload = async function() {
+ throw new Error("oh no!");
+ }
+ await responder.repair(request, null);
+
+ checkRecordedEvents([
+ { object: "repairResponse",
+ method: "failed",
+ value: undefined,
+ extra: { flowID: request.flowID,
+ numIDs: "0",
+ failureReason: '{"name":"unexpectederror","error":"Error: oh no!"}',
+ }
+ },
+ ]);
+
+ await cleanup(server);
+});
+
add_task(async function test_responder_no_items() {
let server = await setup();
+ // sync so the collection is created.
+ Service.sync();
+
let request = {
request: "upload",
ids: [Utils.makeGUID()],
flowID: Utils.makeGUID(),
}
let responder = new BookmarkRepairResponder();
await responder.repair(request, null);
@@ -274,81 +313,98 @@ add_task(async function test_responder_m
]);
await cleanup(server);
});
add_task(async function test_non_syncable() {
let server = await setup();
+ Service.sync(); // to create the collections on the server.
+
// Creates the left pane queries as a side effect.
let leftPaneId = PlacesUIUtils.leftPaneFolderId;
_(`Left pane root ID: ${leftPaneId}`);
await PlacesTestUtils.promiseAsyncUpdates();
// A child folder of the left pane root, containing queries for the menu,
// toolbar, and unfiled queries.
let allBookmarksId = PlacesUIUtils.leftPaneQueries.AllBookmarks;
let allBookmarksGuid = await PlacesUtils.promiseItemGuid(allBookmarksId);
- // Explicitly request the unfiled query; we should also upload tombstones
- // for the menu and toolbar queries.
let unfiledQueryId = PlacesUIUtils.leftPaneQueries.UnfiledBookmarks;
let unfiledQueryGuid = await PlacesUtils.promiseItemGuid(unfiledQueryId);
+ // Put the "Bookmarks Menu" on the server to simulate old bugs.
+ let bookmarksMenuQueryId = PlacesUIUtils.leftPaneQueries.BookmarksMenu;
+ let bookmarksMenuQueryGuid = await PlacesUtils.promiseItemGuid(bookmarksMenuQueryId);
+ let collection = getServerBookmarks(server);
+ collection.insert(bookmarksMenuQueryGuid, "doesn't matter");
+
+ // Explicitly request the unfiled and allBookmarksGuid queries; these will
+ // get tombstones. Because the BookmarksMenu is already on the server it
+ // should be removed even though it wasn't requested. We should ignore the
+ // toolbar query as it wasn't explicitly requested and isn't on the server.
let request = {
request: "upload",
ids: [allBookmarksGuid, unfiledQueryGuid],
flowID: Utils.makeGUID(),
}
let responder = new BookmarkRepairResponder();
await responder.repair(request, null);
checkRecordedEvents([
{ object: "repairResponse",
method: "uploading",
value: undefined,
- // Tombstones for the folder and its 3 children.
- extra: {flowID: request.flowID, numIDs: "4"},
+ // Tombstones for the 2 items we requested and for bookmarksMenu
+ extra: {flowID: request.flowID, numIDs: "3"},
},
]);
_("Sync to upload tombstones for items");
Service.sync();
let toolbarQueryId = PlacesUIUtils.leftPaneQueries.BookmarksToolbar;
let menuQueryId = PlacesUIUtils.leftPaneQueries.BookmarksMenu;
let queryGuids = [
allBookmarksGuid,
await PlacesUtils.promiseItemGuid(toolbarQueryId),
await PlacesUtils.promiseItemGuid(menuQueryId),
unfiledQueryGuid,
];
- let collection = getServerBookmarks(server);
deepEqual(collection.keys().sort(), [
// We always upload roots on the first sync.
"menu",
"mobile",
"toolbar",
"unfiled",
- ...queryGuids,
+ ...request.ids,
+ bookmarksMenuQueryGuid,
].sort(), "Should upload roots and queries on first sync");
for (let guid of queryGuids) {
let wbo = collection.wbo(guid);
- let payload = JSON.parse(JSON.parse(wbo.payload).ciphertext);
- ok(payload.deleted, `Should upload tombstone for left pane query ${guid}`);
+ if (request.ids.indexOf(guid) >= 0 || guid == bookmarksMenuQueryGuid) {
+ // explicitly requested or already on the server, so should have a tombstone.
+ let payload = JSON.parse(JSON.parse(wbo.payload).ciphertext);
+ ok(payload.deleted, `Should upload tombstone for left pane query ${guid}`);
+ } else {
+ // not explicitly requested and not on the server at the start, so should
+ // not be on the server now.
+ ok(!wbo, `Should not upload anything for left pane query ${guid}`);
+ }
}
checkRecordedEvents([
{ object: "repairResponse",
method: "finished",
value: undefined,
- extra: {flowID: request.flowID, numIDs: "4"},
+ extra: {flowID: request.flowID, numIDs: "3"},
},
]);
await cleanup(server);
});
add_task(async function test_folder_descendants() {
let server = await setup();