Bug 1329850 - Sync records creation failures are reported to telemetry. r=markh
authorEdouard Oger <eoger@fastmail.com>
Tue, 24 Jan 2017 17:05:12 -0500
changeset 360905 d6ec1eae0161be48653436dffa7ca0283d833102
parent 360904 1b4335b1b6e3c56b60b1d5fef40f096b9e7b79c5
child 360906 447b349f9143ace52b5bdf05e176e810173e3c94
push id10863
push userjlorenzo@mozilla.com
push dateMon, 06 Mar 2017 23:02:23 +0000
treeherdermozilla-aurora@0931190cd725 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmarkh
bugs1329850
milestone54.0a1
Bug 1329850 - Sync records creation failures are reported to telemetry. r=markh MozReview-Commit-ID: AEOlmkmyIvY
services/sync/modules/engines.js
services/sync/modules/engines/clients.js
services/sync/tests/unit/test_syncengine_sync.js
--- a/services/sync/modules/engines.js
+++ b/services/sync/modules/engines.js
@@ -1582,20 +1582,22 @@ SyncEngine.prototype = {
         try {
           out = this._createRecord(id);
           if (this._log.level <= Log.Level.Trace)
             this._log.trace("Outgoing: " + out);
 
           out.encrypt(this.service.collectionKeys.keyForCollection(this.name));
           ok = true;
         } catch (ex) {
-          if (Async.isShutdownException(ex)) {
+          this._log.warn("Error creating record", ex);
+          ++counts.failed;
+          if (Async.isShutdownException(ex) || !this.allowSkippedRecord) {
+            Observers.notify("weave:engine:sync:uploaded", counts, this.name);
             throw ex;
           }
-          this._log.warn("Error creating record", ex);
         }
         if (ok) {
           let { enqueued, error } = postQueue.enqueue(out);
           if (!enqueued) {
             ++counts.failed;
             if (!this.allowSkippedRecord) {
               throw error;
             }
--- a/services/sync/modules/engines/clients.js
+++ b/services/sync/modules/engines/clients.js
@@ -253,16 +253,22 @@ ClientEngine.prototype = {
     if (hasDupeCommand(clientCommands, command)) {
       return false;
     }
     allCommands[clientId] = clientCommands.concat(command);
     this._saveCommands(allCommands);
     return true;
   },
 
+  _removeClientCommands(clientId) {
+    const allCommands = this._readCommands();
+    delete allCommands[clientId];
+    this._saveCommands(allCommands);
+  },
+
   _syncStartup: function _syncStartup() {
     // Reupload new client record periodically.
     if (Date.now() / 1000 - this.lastRecordUpload > CLIENTS_TTL_REFRESH) {
       this._tracker.addChangedID(this.localID);
       this.lastRecordUpload = Date.now() / 1000;
     }
     SyncEngine.prototype._syncStartup.call(this);
   },
@@ -662,16 +668,18 @@ ClientEngine.prototype = {
    */
   _handleDisplayURIs: function _handleDisplayURIs(uris) {
     Svc.Obs.notify("weave:engine:clients:display-uris", uris);
   },
 
   _removeRemoteClient(id) {
     delete this._store._remoteClients[id];
     this._tracker.removeChangedID(id);
+    this._removeClientCommands(id);
+    this._modified.delete(id);
   },
 };
 
 function ClientStore(name, engine) {
   Store.call(this, name, engine);
 }
 ClientStore.prototype = {
   __proto__: Store.prototype,
--- a/services/sync/tests/unit/test_syncengine_sync.js
+++ b/services/sync/tests/unit/test_syncengine_sync.js
@@ -1512,16 +1512,106 @@ add_task(async function test_uploadOutgo
     // Ensure that the uploads were performed in batches of MAX_UPLOAD_RECORDS.
     do_check_eq(noOfUploads, Math.ceil(234 / MAX_UPLOAD_RECORDS));
 
   } finally {
     await cleanAndGo(engine, server);
   }
 });
 
+async function createRecordFailTelemetry(allowSkippedRecord) {
+  Service.identity.username = "foo";
+  let collection = new ServerCollection();
+  collection._wbos.flying = new ServerWBO("flying");
+  collection._wbos.scotsman = new ServerWBO("scotsman");
+
+  let server = sync_httpd_setup({
+      "/1.1/foo/storage/rotary": collection.handler()
+  });
+
+  await SyncTestingInfrastructure(server);
+
+  let engine = makeRotaryEngine();
+  engine.allowSkippedRecord = allowSkippedRecord;
+  let oldCreateRecord = engine._store.createRecord;
+  engine._store.createRecord = (id, col) => {
+    if (id != "flying") {
+      throw new Error("oops");
+    }
+    return oldCreateRecord.call(engine._store, id, col);
+  }
+  engine.lastSync = 123; // needs to be non-zero so that tracker is queried
+  engine._store.items = {flying: "LNER Class A3 4472",
+                         scotsman: "Flying Scotsman"};
+  // Mark these records as changed
+  const FLYING_CHANGED = 12345;
+  const SCOTSMAN_CHANGED = 23456;
+  engine._tracker.addChangedID("flying", FLYING_CHANGED);
+  engine._tracker.addChangedID("scotsman", SCOTSMAN_CHANGED);
+
+  let meta_global = Service.recordManager.set(engine.metaURL,
+                                              new WBORecord(engine.metaURL));
+  meta_global.payload.engines = {rotary: {version: engine.version,
+                                         syncID: engine.syncID}};
+
+  let ping;
+  try {
+    // Confirm initial environment
+    do_check_eq(engine.lastSyncLocal, 0);
+    do_check_eq(collection.payload("flying"), undefined);
+    do_check_eq(engine._tracker.changedIDs["flying"], FLYING_CHANGED);
+    do_check_eq(engine._tracker.changedIDs["scotsman"], SCOTSMAN_CHANGED);
+
+    engine.enabled = true;
+    ping = await sync_engine_and_validate_telem(engine, true, onErrorPing => {
+      ping = onErrorPing;
+    });
+
+    if (!allowSkippedRecord) {
+      do_throw("should not get here");
+    }
+
+    // Ensure the 'flying' record has been uploaded and is no longer marked.
+    do_check_true(!!collection.payload("flying"));
+    do_check_eq(engine._tracker.changedIDs["flying"], undefined);
+  } catch (err) {
+    if (allowSkippedRecord) {
+      do_throw("should not get here");
+    }
+
+    // Ensure the 'flying' record has not been uploaded and is still marked
+    do_check_false(collection.payload("flying"));
+    do_check_true(engine._tracker.changedIDs["flying"]);
+  } finally {
+    // Local timestamp has been set.
+    do_check_true(engine.lastSyncLocal > 0);
+
+    // We reported in telemetry that we failed a record
+    do_check_eq(ping.engines[0].outgoing[0].failed, 1);
+
+    // In any case, the 'scotsman' record couldn't be created so it wasn't
+    // uploaded nor it was not cleared from the tracker.
+    do_check_false(collection.payload("scotsman"));
+    do_check_eq(engine._tracker.changedIDs["scotsman"], SCOTSMAN_CHANGED);
+
+    engine._store.createRecord = oldCreateRecord;
+    await promiseClean(engine, server);
+  }
+}
+
+add_task(async function test_uploadOutgoing_createRecord_throws_reported_telemetry() {
+  _("SyncEngine._uploadOutgoing reports a failed record to telemetry if createRecord throws");
+  await createRecordFailTelemetry(true);
+});
+
+add_task(async function test_uploadOutgoing_createRecord_throws_dontAllowSkipRecord() {
+  _("SyncEngine._uploadOutgoing will throw if createRecord throws and allowSkipRecord is set to false");
+  await createRecordFailTelemetry(false);
+});
+
 add_task(async function test_uploadOutgoing_largeRecords() {
   _("SyncEngine._uploadOutgoing throws on records larger than MAX_UPLOAD_BYTES");
 
   let collection = new ServerCollection();
 
   let engine = makeRotaryEngine();
   engine.allowSkippedRecord = false;
   engine._store.items["large-item"] = "Y".repeat(MAX_UPLOAD_BYTES * 2);