diff options
Diffstat (limited to 'services/sync/tests/unit/test_errorhandler_filelog.js')
| -rw-r--r-- | services/sync/tests/unit/test_errorhandler_filelog.js | 450 |
1 files changed, 450 insertions, 0 deletions
diff --git a/services/sync/tests/unit/test_errorhandler_filelog.js b/services/sync/tests/unit/test_errorhandler_filelog.js new file mode 100644 index 0000000000..5e1e36061f --- /dev/null +++ b/services/sync/tests/unit/test_errorhandler_filelog.js @@ -0,0 +1,450 @@ +/* Any copyright is dedicated to the Public Domain. + http://creativecommons.org/publicdomain/zero/1.0/ */ + +// `Service` is used as a global in head_helpers.js. +// eslint-disable-next-line no-unused-vars +const { Service } = ChromeUtils.importESModule( + "resource://services-sync/service.sys.mjs" +); +const { logManager } = ChromeUtils.import( + "resource://gre/modules/FxAccountsCommon.js" +); +const { FileUtils } = ChromeUtils.importESModule( + "resource://gre/modules/FileUtils.sys.mjs" +); + +const logsdir = FileUtils.getDir("ProfD", ["weave", "logs"], true); + +// Delay to wait before cleanup, to allow files to age. +// This is so large because the file timestamp granularity is per-second, and +// so otherwise we can end up with all of our files -- the ones we want to +// keep, and the ones we want to clean up -- having the same modified time. +const CLEANUP_DELAY = 2000; +const DELAY_BUFFER = 500; // Buffer for timers on different OS platforms. + +function run_test() { + validate_all_future_pings(); + run_next_test(); +} + +add_test(function test_noOutput() { + // Ensure that the log appender won't print anything. + logManager._fileAppender.level = Log.Level.Fatal + 1; + + // Clear log output from startup. + Svc.Prefs.set("log.appender.file.logOnSuccess", false); + Svc.Obs.notify("weave:service:sync:finish"); + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLogOuter() { + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLogOuter); + // Clear again without having issued any output. + Svc.Prefs.set("log.appender.file.logOnSuccess", true); + + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLogInner() { + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLogInner); + + logManager._fileAppender.level = Log.Level.Trace; + Svc.Prefs.resetBranch(""); + run_next_test(); + }); + + // Fake a successful sync. + Svc.Obs.notify("weave:service:sync:finish"); + }); +}); + +add_test(function test_logOnSuccess_false() { + Svc.Prefs.set("log.appender.file.logOnSuccess", false); + + let log = Log.repository.getLogger("Sync.Test.FileLog"); + log.info("this won't show up"); + + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); + // No log file was written. + Assert.ok(!logsdir.directoryEntries.hasMoreElements()); + + Svc.Prefs.resetBranch(""); + run_next_test(); + }); + + // Fake a successful sync. + Svc.Obs.notify("weave:service:sync:finish"); +}); + +function readFile(file, callback) { + NetUtil.asyncFetch( + { + uri: NetUtil.newURI(file), + loadUsingSystemPrincipal: true, + }, + function (inputStream, statusCode, request) { + let data = NetUtil.readInputStreamToString( + inputStream, + inputStream.available() + ); + callback(statusCode, data); + } + ); +} + +add_test(function test_logOnSuccess_true() { + Svc.Prefs.set("log.appender.file.logOnSuccess", true); + + let log = Log.repository.getLogger("Sync.Test.FileLog"); + const MESSAGE = "this WILL show up"; + log.info(MESSAGE); + + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); + + // Exactly one log file was written. + let entries = logsdir.directoryEntries; + Assert.ok(entries.hasMoreElements()); + let logfile = entries.getNext().QueryInterface(Ci.nsIFile); + Assert.equal(logfile.leafName.slice(-4), ".txt"); + Assert.ok(logfile.leafName.startsWith("success-sync-"), logfile.leafName); + Assert.ok(!entries.hasMoreElements()); + + // Ensure the log message was actually written to file. + readFile(logfile, function (error, data) { + Assert.ok(Components.isSuccessCode(error)); + Assert.notEqual(data.indexOf(MESSAGE), -1); + + // Clean up. + try { + logfile.remove(false); + } catch (ex) { + dump("Couldn't delete file: " + ex.message + "\n"); + // Stupid Windows box. + } + + Svc.Prefs.resetBranch(""); + run_next_test(); + }); + }); + + // Fake a successful sync. + Svc.Obs.notify("weave:service:sync:finish"); +}); + +add_test(function test_sync_error_logOnError_false() { + Svc.Prefs.set("log.appender.file.logOnError", false); + + let log = Log.repository.getLogger("Sync.Test.FileLog"); + log.info("this won't show up"); + + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); + // No log file was written. + Assert.ok(!logsdir.directoryEntries.hasMoreElements()); + + Svc.Prefs.resetBranch(""); + run_next_test(); + }); + + // Fake an unsuccessful sync. + Svc.Obs.notify("weave:service:sync:error"); +}); + +add_test(function test_sync_error_logOnError_true() { + Svc.Prefs.set("log.appender.file.logOnError", true); + + let log = Log.repository.getLogger("Sync.Test.FileLog"); + const MESSAGE = "this WILL show up"; + log.info(MESSAGE); + + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); + + // Exactly one log file was written. + let entries = logsdir.directoryEntries; + Assert.ok(entries.hasMoreElements()); + let logfile = entries.getNext().QueryInterface(Ci.nsIFile); + Assert.equal(logfile.leafName.slice(-4), ".txt"); + Assert.ok(logfile.leafName.startsWith("error-sync-"), logfile.leafName); + Assert.ok(!entries.hasMoreElements()); + + // Ensure the log message was actually written to file. + readFile(logfile, function (error, data) { + Assert.ok(Components.isSuccessCode(error)); + Assert.notEqual(data.indexOf(MESSAGE), -1); + + // Clean up. + try { + logfile.remove(false); + } catch (ex) { + dump("Couldn't delete file: " + ex.message + "\n"); + // Stupid Windows box. + } + + Svc.Prefs.resetBranch(""); + run_next_test(); + }); + }); + + // Fake an unsuccessful sync. + Svc.Obs.notify("weave:service:sync:error"); +}); + +add_test(function test_login_error_logOnError_false() { + Svc.Prefs.set("log.appender.file.logOnError", false); + + let log = Log.repository.getLogger("Sync.Test.FileLog"); + log.info("this won't show up"); + + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); + // No log file was written. + Assert.ok(!logsdir.directoryEntries.hasMoreElements()); + + Svc.Prefs.resetBranch(""); + run_next_test(); + }); + + // Fake an unsuccessful login. + Svc.Obs.notify("weave:service:login:error"); +}); + +add_test(function test_login_error_logOnError_true() { + Svc.Prefs.set("log.appender.file.logOnError", true); + + let log = Log.repository.getLogger("Sync.Test.FileLog"); + const MESSAGE = "this WILL show up"; + log.info(MESSAGE); + + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); + + // Exactly one log file was written. + let entries = logsdir.directoryEntries; + Assert.ok(entries.hasMoreElements()); + let logfile = entries.getNext().QueryInterface(Ci.nsIFile); + Assert.equal(logfile.leafName.slice(-4), ".txt"); + Assert.ok(logfile.leafName.startsWith("error-sync-"), logfile.leafName); + Assert.ok(!entries.hasMoreElements()); + + // Ensure the log message was actually written to file. + readFile(logfile, function (error, data) { + Assert.ok(Components.isSuccessCode(error)); + Assert.notEqual(data.indexOf(MESSAGE), -1); + + // Clean up. + try { + logfile.remove(false); + } catch (ex) { + dump("Couldn't delete file: " + ex.message + "\n"); + // Stupid Windows box. + } + + Svc.Prefs.resetBranch(""); + run_next_test(); + }); + }); + + // Fake an unsuccessful login. + Svc.Obs.notify("weave:service:login:error"); +}); + +add_test(function test_noNewFailed_noErrorLog() { + Svc.Prefs.set("log.appender.file.logOnError", true); + Svc.Prefs.set("log.appender.file.logOnSuccess", false); + + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); + // No log file was written. + Assert.ok(!logsdir.directoryEntries.hasMoreElements()); + + Svc.Prefs.resetBranch(""); + run_next_test(); + }); + // failed is nonzero and newFailed is zero -- shouldn't write a log. + let count = { + applied: 8, + succeeded: 4, + failed: 5, + newFailed: 0, + reconciled: 4, + }; + Svc.Obs.notify("weave:engine:sync:applied", count, "foobar-engine"); + Svc.Obs.notify("weave:service:sync:finish"); +}); + +add_test(function test_newFailed_errorLog() { + Svc.Prefs.set("log.appender.file.logOnError", true); + Svc.Prefs.set("log.appender.file.logOnSuccess", false); + + let log = Log.repository.getLogger("Sync.Test.FileLog"); + const MESSAGE = "this WILL show up 2"; + log.info(MESSAGE); + + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); + + // Exactly one log file was written. + let entries = logsdir.directoryEntries; + Assert.ok(entries.hasMoreElements()); + let logfile = entries.getNext().QueryInterface(Ci.nsIFile); + Assert.equal(logfile.leafName.slice(-4), ".txt"); + Assert.ok(logfile.leafName.startsWith("error-sync-"), logfile.leafName); + Assert.ok(!entries.hasMoreElements()); + + // Ensure the log message was actually written to file. + readFile(logfile, function (error, data) { + Assert.ok(Components.isSuccessCode(error)); + Assert.notEqual(data.indexOf(MESSAGE), -1); + + // Clean up. + try { + logfile.remove(false); + } catch (ex) { + dump("Couldn't delete file: " + ex.message + "\n"); + // Stupid Windows box. + } + + Svc.Prefs.resetBranch(""); + run_next_test(); + }); + }); + // newFailed is nonzero -- should write a log. + let count = { + applied: 8, + succeeded: 4, + failed: 5, + newFailed: 4, + reconciled: 4, + }; + + Svc.Obs.notify("weave:engine:sync:applied", count, "foobar-engine"); + Svc.Obs.notify("weave:service:sync:finish"); +}); + +add_test(function test_errorLog_dumpAddons() { + Svc.Prefs.set("log.logger", "Trace"); + Svc.Prefs.set("log.appender.file.logOnError", true); + + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); + + let entries = logsdir.directoryEntries; + Assert.ok(entries.hasMoreElements()); + let logfile = entries.getNext().QueryInterface(Ci.nsIFile); + Assert.equal(logfile.leafName.slice(-4), ".txt"); + Assert.ok(logfile.leafName.startsWith("error-sync-"), logfile.leafName); + Assert.ok(!entries.hasMoreElements()); + + // Ensure we logged some addon list (which is probably empty) + readFile(logfile, function (error, data) { + Assert.ok(Components.isSuccessCode(error)); + Assert.notEqual(data.indexOf("Addons installed"), -1); + + // Clean up. + try { + logfile.remove(false); + } catch (ex) { + dump("Couldn't delete file: " + ex.message + "\n"); + // Stupid Windows box. + } + + Svc.Prefs.resetBranch(""); + run_next_test(); + }); + }); + + // Fake an unsuccessful sync. + Svc.Obs.notify("weave:service:sync:error"); +}); + +// Check that error log files are deleted above an age threshold. +add_test(async function test_logErrorCleanup_age() { + _("Beginning test_logErrorCleanup_age."); + let maxAge = CLEANUP_DELAY / 1000; + let oldLogs = []; + let numLogs = 10; + let errString = "some error log\n"; + + Svc.Prefs.set("log.appender.file.logOnError", true); + Svc.Prefs.set("log.appender.file.maxErrorAge", maxAge); + + _("Making some files."); + const logsDir = PathUtils.join(PathUtils.profileDir, "weave", "logs"); + await IOUtils.makeDirectory(logsDir); + for (let i = 0; i < numLogs; i++) { + let now = Date.now(); + let filename = "error-sync-" + now + "" + i + ".txt"; + let newLog = new FileUtils.File(PathUtils.join(logsDir, filename)); + let foStream = FileUtils.openFileOutputStream(newLog); + foStream.write(errString, errString.length); + foStream.close(); + _(" > Created " + filename); + oldLogs.push(newLog.leafName); + } + + Svc.Obs.add( + "services-tests:common:log-manager:cleanup-logs", + function onCleanupLogs() { + Svc.Obs.remove( + "services-tests:common:log-manager:cleanup-logs", + onCleanupLogs + ); + + // Only the newest created log file remains. + let entries = logsdir.directoryEntries; + Assert.ok(entries.hasMoreElements()); + let logfile = entries.getNext().QueryInterface(Ci.nsIFile); + Assert.ok( + oldLogs.every(function (e) { + return e != logfile.leafName; + }) + ); + Assert.ok(!entries.hasMoreElements()); + + // Clean up. + try { + logfile.remove(false); + } catch (ex) { + dump("Couldn't delete file: " + ex.message + "\n"); + // Stupid Windows box. + } + + Svc.Prefs.resetBranch(""); + run_next_test(); + } + ); + + let delay = CLEANUP_DELAY + DELAY_BUFFER; + + _("Cleaning up logs after " + delay + "msec."); + CommonUtils.namedTimer( + function onTimer() { + Svc.Obs.notify("weave:service:sync:error"); + }, + delay, + this, + "cleanup-timer" + ); +}); + +add_task(async function test_remove_log_on_startOver() { + Svc.Prefs.set("log.appender.file.logOnError", true); + + let log = Log.repository.getLogger("Sync.Test.FileLog"); + const MESSAGE = "this WILL show up"; + log.info(MESSAGE); + + let promiseLogWritten = promiseOneObserver("weave:service:reset-file-log"); + // Fake an unsuccessful sync. + Svc.Obs.notify("weave:service:sync:error"); + + await promiseLogWritten; + // Should have at least 1 log file. + let entries = logsdir.directoryEntries; + Assert.ok(entries.hasMoreElements()); + + // Fake a reset. + let promiseRemoved = promiseOneObserver("weave:service:remove-file-log"); + Svc.Obs.notify("weave:service:start-over:finish"); + await promiseRemoved; + + // should be no files left. + Assert.ok(!logsdir.directoryEntries.hasMoreElements()); +}); |