test_errorhandler_2.js (16241B)
1 /* Any copyright is dedicated to the Public Domain. 2 http://creativecommons.org/publicdomain/zero/1.0/ */ 3 4 const { Service } = ChromeUtils.importESModule( 5 "resource://services-sync/service.sys.mjs" 6 ); 7 const { Status } = ChromeUtils.importESModule( 8 "resource://services-sync/status.sys.mjs" 9 ); 10 const { FileUtils } = ChromeUtils.importESModule( 11 "resource://gre/modules/FileUtils.sys.mjs" 12 ); 13 14 const fakeServer = new SyncServer(); 15 fakeServer.start(); 16 17 registerCleanupFunction(function () { 18 return promiseStopServer(fakeServer).finally(() => { 19 for (const pref of Svc.PrefBranch.getChildList("")) { 20 Svc.PrefBranch.clearUserPref(pref); 21 } 22 }); 23 }); 24 25 const logsdir = FileUtils.getDir("ProfD", ["weave", "logs"]); 26 logsdir.create(Ci.nsIFile.DIRECTORY_TYPE, FileUtils.PERMS_DIRECTORY); 27 28 function removeLogFiles() { 29 let entries = logsdir.directoryEntries; 30 while (entries.hasMoreElements()) { 31 let logfile = entries.getNext().QueryInterface(Ci.nsIFile); 32 logfile.remove(false); 33 } 34 } 35 36 function getLogFiles() { 37 let result = []; 38 let entries = logsdir.directoryEntries; 39 while (entries.hasMoreElements()) { 40 result.push(entries.getNext().QueryInterface(Ci.nsIFile)); 41 } 42 return result; 43 } 44 45 let engine; 46 add_task(async function setup() { 47 await Service.engineManager.clear(); 48 await Service.engineManager.register(EHTestsCommon.CatapultEngine); 49 engine = Service.engineManager.get("catapult"); 50 }); 51 52 async function clean() { 53 let promiseLogReset = promiseOneObserver("weave:service:reset-file-log"); 54 await Service.startOver(); 55 await promiseLogReset; 56 Status.resetSync(); 57 Status.resetBackoff(); 58 removeLogFiles(); 59 // Move log levels back to trace (startOver will have reversed this), sicne 60 syncTestLogging(); 61 } 62 63 add_task(async function test_crypto_keys_login_server_maintenance_error() { 64 enableValidationPrefs(); 65 66 Status.resetSync(); 67 // Test crypto/keys server maintenance errors are not reported. 68 let server = await EHTestsCommon.sync_httpd_setup(); 69 await EHTestsCommon.setUp(server); 70 71 await configureIdentity({ username: "broken.keys" }, server); 72 73 // Force re-download of keys 74 Service.collectionKeys.clear(); 75 76 let backoffInterval; 77 Svc.Obs.add("weave:service:backoff:interval", function observe(subject) { 78 Svc.Obs.remove("weave:service:backoff:interval", observe); 79 backoffInterval = subject; 80 }); 81 82 Assert.ok(!Status.enforceBackoff); 83 Assert.equal(Status.service, STATUS_OK); 84 85 let promiseObserved = promiseOneObserver("weave:service:reset-file-log"); 86 await Service.sync(); 87 await promiseObserved; 88 89 Assert.ok(Status.enforceBackoff); 90 Assert.equal(backoffInterval, 42); 91 Assert.equal(Status.service, LOGIN_FAILED); 92 Assert.equal(Status.login, SERVER_MAINTENANCE); 93 94 await clean(); 95 await promiseStopServer(server); 96 }); 97 98 add_task(async function test_lastSync_not_updated_on_complete_failure() { 99 enableValidationPrefs(); 100 101 // Test info/collections prolonged server maintenance errors are reported. 102 let server = await EHTestsCommon.sync_httpd_setup(); 103 await EHTestsCommon.setUp(server); 104 105 await configureIdentity({ username: "johndoe" }, server); 106 107 // Do an initial sync that we expect to be successful. 108 let promiseObserved = promiseOneObserver("weave:service:reset-file-log"); 109 await sync_and_validate_telem(); 110 await promiseObserved; 111 112 Assert.equal(Status.service, STATUS_OK); 113 Assert.equal(Status.sync, SYNC_SUCCEEDED); 114 115 let lastSync = Svc.PrefBranch.getStringPref("lastSync"); 116 117 Assert.ok(lastSync); 118 119 // Report server maintenance on info/collections requests 120 server.registerPathHandler( 121 "/1.1/johndoe/info/collections", 122 EHTestsCommon.service_unavailable 123 ); 124 125 promiseObserved = promiseOneObserver("weave:service:reset-file-log"); 126 await sync_and_validate_telem(() => {}); 127 await promiseObserved; 128 129 Assert.equal(Status.sync, SERVER_MAINTENANCE); 130 Assert.equal(Status.service, SYNC_FAILED); 131 132 // We shouldn't update lastSync on complete failure. 133 Assert.equal(lastSync, Svc.PrefBranch.getStringPref("lastSync")); 134 135 await clean(); 136 await promiseStopServer(server); 137 }); 138 139 add_task( 140 async function test_sync_syncAndReportErrors_server_maintenance_error() { 141 enableValidationPrefs(); 142 143 // Test server maintenance errors are reported 144 // when calling syncAndReportErrors. 145 let server = await EHTestsCommon.sync_httpd_setup(); 146 await EHTestsCommon.setUp(server); 147 148 const BACKOFF = 42; 149 engine.enabled = true; 150 engine.exception = { status: 503, headers: { "retry-after": BACKOFF } }; 151 152 Assert.equal(Status.service, STATUS_OK); 153 154 let promiseObserved = promiseOneObserver("weave:service:reset-file-log"); 155 await Service.sync(); 156 await promiseObserved; 157 158 Assert.equal(Status.service, SYNC_FAILED_PARTIAL); 159 Assert.equal(Status.sync, SERVER_MAINTENANCE); 160 161 await clean(); 162 await promiseStopServer(server); 163 } 164 ); 165 166 add_task( 167 async function test_info_collections_login_syncAndReportErrors_server_maintenance_error() { 168 enableValidationPrefs(); 169 170 // Test info/collections server maintenance errors are reported 171 // when calling syncAndReportErrors. 172 let server = await EHTestsCommon.sync_httpd_setup(); 173 await EHTestsCommon.setUp(server); 174 175 await configureIdentity({ username: "broken.info" }, server); 176 177 let backoffInterval; 178 Svc.Obs.add("weave:service:backoff:interval", function observe(subject) { 179 Svc.Obs.remove("weave:service:backoff:interval", observe); 180 backoffInterval = subject; 181 }); 182 183 Assert.ok(!Status.enforceBackoff); 184 Assert.equal(Status.service, STATUS_OK); 185 186 let promiseObserved = promiseOneObserver("weave:service:reset-file-log"); 187 await Service.sync(); 188 await promiseObserved; 189 190 Assert.ok(Status.enforceBackoff); 191 Assert.equal(backoffInterval, 42); 192 Assert.equal(Status.service, LOGIN_FAILED); 193 Assert.equal(Status.login, SERVER_MAINTENANCE); 194 195 await clean(); 196 await promiseStopServer(server); 197 } 198 ); 199 200 add_task( 201 async function test_meta_global_login_syncAndReportErrors_server_maintenance_error() { 202 enableValidationPrefs(); 203 204 // Test meta/global server maintenance errors are reported 205 // when calling syncAndReportErrors. 206 let server = await EHTestsCommon.sync_httpd_setup(); 207 await EHTestsCommon.setUp(server); 208 209 await configureIdentity({ username: "broken.meta" }, server); 210 211 let backoffInterval; 212 Svc.Obs.add("weave:service:backoff:interval", function observe(subject) { 213 Svc.Obs.remove("weave:service:backoff:interval", observe); 214 backoffInterval = subject; 215 }); 216 217 Assert.ok(!Status.enforceBackoff); 218 Assert.equal(Status.service, STATUS_OK); 219 220 let promiseObserved = promiseOneObserver("weave:service:reset-file-log"); 221 await Service.sync(); 222 await promiseObserved; 223 224 Assert.ok(Status.enforceBackoff); 225 Assert.equal(backoffInterval, 42); 226 Assert.equal(Status.service, LOGIN_FAILED); 227 Assert.equal(Status.login, SERVER_MAINTENANCE); 228 229 await clean(); 230 await promiseStopServer(server); 231 } 232 ); 233 234 add_task( 235 async function test_download_crypto_keys_login_syncAndReportErrors_server_maintenance_error() { 236 enableValidationPrefs(); 237 238 // Test crypto/keys server maintenance errors are reported 239 // when calling syncAndReportErrors. 240 let server = await EHTestsCommon.sync_httpd_setup(); 241 await EHTestsCommon.setUp(server); 242 243 await configureIdentity({ username: "broken.keys" }, server); 244 // Force re-download of keys 245 Service.collectionKeys.clear(); 246 247 let backoffInterval; 248 Svc.Obs.add("weave:service:backoff:interval", function observe(subject) { 249 Svc.Obs.remove("weave:service:backoff:interval", observe); 250 backoffInterval = subject; 251 }); 252 253 Assert.ok(!Status.enforceBackoff); 254 Assert.equal(Status.service, STATUS_OK); 255 256 let promiseObserved = promiseOneObserver("weave:service:reset-file-log"); 257 await Service.sync(); 258 await promiseObserved; 259 260 Assert.ok(Status.enforceBackoff); 261 Assert.equal(backoffInterval, 42); 262 Assert.equal(Status.service, LOGIN_FAILED); 263 Assert.equal(Status.login, SERVER_MAINTENANCE); 264 265 await clean(); 266 await promiseStopServer(server); 267 } 268 ); 269 270 add_task( 271 async function test_upload_crypto_keys_login_syncAndReportErrors_server_maintenance_error() { 272 enableValidationPrefs(); 273 274 // Test crypto/keys server maintenance errors are reported 275 // when calling syncAndReportErrors. 276 let server = await EHTestsCommon.sync_httpd_setup(); 277 278 // Start off with an empty account, do not upload a key. 279 await configureIdentity({ username: "broken.keys" }, server); 280 281 let backoffInterval; 282 Svc.Obs.add("weave:service:backoff:interval", function observe(subject) { 283 Svc.Obs.remove("weave:service:backoff:interval", observe); 284 backoffInterval = subject; 285 }); 286 287 Assert.ok(!Status.enforceBackoff); 288 Assert.equal(Status.service, STATUS_OK); 289 290 let promiseObserved = promiseOneObserver("weave:service:reset-file-log"); 291 await Service.sync(); 292 await promiseObserved; 293 294 Assert.ok(Status.enforceBackoff); 295 Assert.equal(backoffInterval, 42); 296 Assert.equal(Status.service, LOGIN_FAILED); 297 Assert.equal(Status.login, SERVER_MAINTENANCE); 298 299 await clean(); 300 await promiseStopServer(server); 301 } 302 ); 303 304 add_task( 305 async function test_wipeServer_login_syncAndReportErrors_server_maintenance_error() { 306 enableValidationPrefs(); 307 308 // Test crypto/keys server maintenance errors are reported 309 // when calling syncAndReportErrors. 310 let server = await EHTestsCommon.sync_httpd_setup(); 311 312 // Start off with an empty account, do not upload a key. 313 await configureIdentity({ username: "broken.wipe" }, server); 314 315 let backoffInterval; 316 Svc.Obs.add("weave:service:backoff:interval", function observe(subject) { 317 Svc.Obs.remove("weave:service:backoff:interval", observe); 318 backoffInterval = subject; 319 }); 320 321 Assert.ok(!Status.enforceBackoff); 322 Assert.equal(Status.service, STATUS_OK); 323 324 let promiseObserved = promiseOneObserver("weave:service:reset-file-log"); 325 await Service.sync(); 326 await promiseObserved; 327 328 Assert.ok(Status.enforceBackoff); 329 Assert.equal(backoffInterval, 42); 330 Assert.equal(Status.service, LOGIN_FAILED); 331 Assert.equal(Status.login, SERVER_MAINTENANCE); 332 333 await clean(); 334 await promiseStopServer(server); 335 } 336 ); 337 338 add_task( 339 async function test_wipeRemote_syncAndReportErrors_server_maintenance_error() { 340 enableValidationPrefs(); 341 342 // Test that we report prolonged server maintenance errors that occur whilst 343 // wiping all remote devices. 344 let server = await EHTestsCommon.sync_httpd_setup(); 345 346 await configureIdentity({ username: "broken.wipe" }, server); 347 await EHTestsCommon.generateAndUploadKeys(); 348 349 engine.exception = null; 350 engine.enabled = true; 351 352 let backoffInterval; 353 Svc.Obs.add("weave:service:backoff:interval", function observe(subject) { 354 Svc.Obs.remove("weave:service:backoff:interval", observe); 355 backoffInterval = subject; 356 }); 357 358 Assert.ok(!Status.enforceBackoff); 359 Assert.equal(Status.service, STATUS_OK); 360 361 Svc.PrefBranch.setStringPref("firstSync", "wipeRemote"); 362 363 let promiseObserved = promiseOneObserver("weave:service:reset-file-log"); 364 await Service.sync(); 365 await promiseObserved; 366 367 Assert.ok(Status.enforceBackoff); 368 Assert.equal(backoffInterval, 42); 369 Assert.equal(Status.service, SYNC_FAILED); 370 Assert.equal(Status.sync, SERVER_MAINTENANCE); 371 Assert.equal(Svc.PrefBranch.getStringPref("firstSync"), "wipeRemote"); 372 373 await clean(); 374 await promiseStopServer(server); 375 } 376 ); 377 378 add_task(async function test_sync_engine_generic_fail() { 379 enableValidationPrefs(); 380 381 equal(getLogFiles().length, 0); 382 383 let server = await EHTestsCommon.sync_httpd_setup(); 384 engine.enabled = true; 385 engine.sync = async function sync() { 386 Svc.Obs.notify("weave:engine:sync:error", ENGINE_UNKNOWN_FAIL, "catapult"); 387 }; 388 let lastSync = Svc.PrefBranch.getStringPref("lastSync", null); 389 let log = Log.repository.getLogger("Sync.ErrorHandler"); 390 Svc.PrefBranch.setBoolPref("log.appender.file.logOnError", true); 391 392 Assert.equal(Status.engines.catapult, undefined); 393 394 let promiseObserved = new Promise(res => { 395 Svc.Obs.add("weave:engine:sync:finish", function onEngineFinish() { 396 Svc.Obs.remove("weave:engine:sync:finish", onEngineFinish); 397 398 log.info("Adding reset-file-log observer."); 399 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { 400 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); 401 res(); 402 }); 403 }); 404 }); 405 406 Assert.ok(await EHTestsCommon.setUp(server)); 407 await sync_and_validate_telem(ping => { 408 deepEqual(ping.status.service, SYNC_FAILED_PARTIAL); 409 deepEqual(ping.engines.find(e => e.status).status, ENGINE_UNKNOWN_FAIL); 410 }); 411 412 await promiseObserved; 413 414 _("Status.engines: " + JSON.stringify(Status.engines)); 415 Assert.equal(Status.engines.catapult, ENGINE_UNKNOWN_FAIL); 416 Assert.equal(Status.service, SYNC_FAILED_PARTIAL); 417 418 // lastSync should update on partial failure. 419 Assert.notEqual(lastSync, Svc.PrefBranch.getStringPref("lastSync")); 420 421 // Test Error log was written on SYNC_FAILED_PARTIAL. 422 let logFiles = getLogFiles(); 423 equal(logFiles.length, 1); 424 Assert.ok( 425 logFiles[0].leafName.startsWith("error-sync-"), 426 logFiles[0].leafName 427 ); 428 429 await clean(); 430 431 await promiseStopServer(server); 432 }); 433 434 add_task(async function test_logs_on_sync_error() { 435 enableValidationPrefs(); 436 437 _( 438 "Ensure that an error is still logged when weave:service:sync:error " + 439 "is notified, despite shouldReportError returning false." 440 ); 441 442 let log = Log.repository.getLogger("Sync.ErrorHandler"); 443 Svc.PrefBranch.setBoolPref("log.appender.file.logOnError", true); 444 log.info("TESTING"); 445 446 // Ensure that we report no error. 447 Status.login = MASTER_PASSWORD_LOCKED; 448 449 let promiseObserved = promiseOneObserver("weave:service:reset-file-log"); 450 Svc.Obs.notify("weave:service:sync:error", {}); 451 await promiseObserved; 452 453 // Test that error log was written. 454 let logFiles = getLogFiles(); 455 equal(logFiles.length, 1); 456 Assert.ok( 457 logFiles[0].leafName.startsWith("error-sync-"), 458 logFiles[0].leafName 459 ); 460 461 await clean(); 462 }); 463 464 add_task(async function test_logs_on_login_error() { 465 enableValidationPrefs(); 466 467 _( 468 "Ensure that an error is still logged when weave:service:login:error " + 469 "is notified, despite shouldReportError returning false." 470 ); 471 472 let log = Log.repository.getLogger("Sync.ErrorHandler"); 473 Svc.PrefBranch.setBoolPref("log.appender.file.logOnError", true); 474 log.info("TESTING"); 475 476 // Ensure that we report no error. 477 Status.login = MASTER_PASSWORD_LOCKED; 478 479 let promiseObserved = promiseOneObserver("weave:service:reset-file-log"); 480 Svc.Obs.notify("weave:service:login:error", {}); 481 await promiseObserved; 482 483 // Test that error log was written. 484 let logFiles = getLogFiles(); 485 equal(logFiles.length, 1); 486 Assert.ok( 487 logFiles[0].leafName.startsWith("error-sync-"), 488 logFiles[0].leafName 489 ); 490 491 await clean(); 492 }); 493 494 // This test should be the last one since it monkeypatches the engine object 495 // and we should only have one engine object throughout the file (bug 629664). 496 add_task(async function test_engine_applyFailed() { 497 enableValidationPrefs(); 498 499 let server = await EHTestsCommon.sync_httpd_setup(); 500 501 engine.enabled = true; 502 delete engine.exception; 503 engine.sync = async function sync() { 504 Svc.Obs.notify("weave:engine:sync:applied", { newFailed: 1 }, "catapult"); 505 }; 506 507 Svc.PrefBranch.setBoolPref("log.appender.file.logOnError", true); 508 509 let promiseObserved = promiseOneObserver("weave:service:reset-file-log"); 510 511 Assert.equal(Status.engines.catapult, undefined); 512 Assert.ok(await EHTestsCommon.setUp(server)); 513 await Service.sync(); 514 await promiseObserved; 515 516 Assert.equal(Status.engines.catapult, ENGINE_APPLY_FAIL); 517 Assert.equal(Status.service, SYNC_FAILED_PARTIAL); 518 519 // Test Error log was written on SYNC_FAILED_PARTIAL. 520 let logFiles = getLogFiles(); 521 equal(logFiles.length, 1); 522 Assert.ok( 523 logFiles[0].leafName.startsWith("error-sync-"), 524 logFiles[0].leafName 525 ); 526 527 await clean(); 528 await promiseStopServer(server); 529 });