diff options
Diffstat (limited to 'services/sync/tests/unit/test_errorhandler_filelog.js')
| -rw-r--r-- | services/sync/tests/unit/test_errorhandler_filelog.js | 370 |
1 files changed, 370 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 000000000..993a478fd --- /dev/null +++ b/services/sync/tests/unit/test_errorhandler_filelog.js @@ -0,0 +1,370 @@ +/* Any copyright is dedicated to the Public Domain. + http://creativecommons.org/publicdomain/zero/1.0/ */ + +Cu.import("resource://gre/modules/Log.jsm"); +Cu.import("resource://services-common/utils.js"); +Cu.import("resource://services-sync/service.js"); +Cu.import("resource://services-sync/util.js"); +Cu.import("resource://gre/modules/FileUtils.jsm"); +Cu.import("resource://gre/modules/NetUtil.jsm"); +Cu.import("resource://gre/modules/Services.jsm"); + +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. + +const PROLONGED_ERROR_DURATION = + (Svc.Prefs.get('errorhandler.networkFailureReportTimeout') * 2) * 1000; + +var errorHandler = Service.errorHandler; + +function setLastSync(lastSyncValue) { + Svc.Prefs.set("lastSync", (new Date(Date.now() - lastSyncValue)).toString()); +} + +function run_test() { + initTestLogging("Trace"); + + Log.repository.getLogger("Sync.LogManager").level = Log.Level.Trace; + Log.repository.getLogger("Sync.Service").level = Log.Level.Trace; + Log.repository.getLogger("Sync.SyncScheduler").level = Log.Level.Trace; + Log.repository.getLogger("Sync.ErrorHandler").level = Log.Level.Trace; + + validate_all_future_pings(); + + run_next_test(); +} + +add_test(function test_noOutput() { + // Ensure that the log appender won't print anything. + errorHandler._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); + + errorHandler._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. + do_check_false(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; + do_check_true(entries.hasMoreElements()); + let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile); + do_check_eq(logfile.leafName.slice(-4), ".txt"); + do_check_true(logfile.leafName.startsWith("success-sync-"), logfile.leafName); + do_check_false(entries.hasMoreElements()); + + // Ensure the log message was actually written to file. + readFile(logfile, function (error, data) { + do_check_true(Components.isSuccessCode(error)); + do_check_neq(data.indexOf(MESSAGE), -1); + + // Clean up. + try { + logfile.remove(false); + } catch(ex) { + dump("Couldn't delete file: " + ex + "\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. + do_check_false(logsdir.directoryEntries.hasMoreElements()); + + Svc.Prefs.resetBranch(""); + run_next_test(); + }); + + // Fake an unsuccessful sync due to prolonged failure. + setLastSync(PROLONGED_ERROR_DURATION); + 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); + + // We need to wait until the log cleanup started by this test is complete + // or the next test will fail as it is ongoing. + Svc.Obs.add("services-tests:common:log-manager:cleanup-logs", function onCleanupLogs() { + Svc.Obs.remove("services-tests:common:log-manager:cleanup-logs", onCleanupLogs); + run_next_test(); + }); + + 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; + do_check_true(entries.hasMoreElements()); + let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile); + do_check_eq(logfile.leafName.slice(-4), ".txt"); + do_check_true(logfile.leafName.startsWith("error-sync-"), logfile.leafName); + do_check_false(entries.hasMoreElements()); + + // Ensure the log message was actually written to file. + readFile(logfile, function (error, data) { + do_check_true(Components.isSuccessCode(error)); + do_check_neq(data.indexOf(MESSAGE), -1); + + // Clean up. + try { + logfile.remove(false); + } catch(ex) { + dump("Couldn't delete file: " + ex + "\n"); + // Stupid Windows box. + } + + Svc.Prefs.resetBranch(""); + }); + }); + + // Fake an unsuccessful sync due to prolonged failure. + setLastSync(PROLONGED_ERROR_DURATION); + 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. + do_check_false(logsdir.directoryEntries.hasMoreElements()); + + Svc.Prefs.resetBranch(""); + run_next_test(); + }); + + // Fake an unsuccessful login due to prolonged failure. + setLastSync(PROLONGED_ERROR_DURATION); + 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); + + // We need to wait until the log cleanup started by this test is complete + // or the next test will fail as it is ongoing. + Svc.Obs.add("services-tests:common:log-manager:cleanup-logs", function onCleanupLogs() { + Svc.Obs.remove("services-tests:common:log-manager:cleanup-logs", onCleanupLogs); + run_next_test(); + }); + + 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; + do_check_true(entries.hasMoreElements()); + let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile); + do_check_eq(logfile.leafName.slice(-4), ".txt"); + do_check_true(logfile.leafName.startsWith("error-sync-"), logfile.leafName); + do_check_false(entries.hasMoreElements()); + + // Ensure the log message was actually written to file. + readFile(logfile, function (error, data) { + do_check_true(Components.isSuccessCode(error)); + do_check_neq(data.indexOf(MESSAGE), -1); + + // Clean up. + try { + logfile.remove(false); + } catch(ex) { + dump("Couldn't delete file: " + ex + "\n"); + // Stupid Windows box. + } + + Svc.Prefs.resetBranch(""); + }); + }); + + // Fake an unsuccessful login due to prolonged failure. + setLastSync(PROLONGED_ERROR_DURATION); + Svc.Obs.notify("weave:service:login:error"); +}); + + +add_test(function test_errorLog_dumpAddons() { + Svc.Prefs.set("log.appender.file.logOnError", true); + + let log = Log.repository.getLogger("Sync.Test.FileLog"); + + // We need to wait until the log cleanup started by this test is complete + // or the next test will fail as it is ongoing. + Svc.Obs.add("services-tests:common:log-manager:cleanup-logs", function onCleanupLogs() { + Svc.Obs.remove("services-tests:common:log-manager:cleanup-logs", onCleanupLogs); + run_next_test(); + }); + + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); + + let entries = logsdir.directoryEntries; + do_check_true(entries.hasMoreElements()); + let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile); + do_check_eq(logfile.leafName.slice(-4), ".txt"); + do_check_true(logfile.leafName.startsWith("error-sync-"), logfile.leafName); + do_check_false(entries.hasMoreElements()); + + // Ensure we logged some addon list (which is probably empty) + readFile(logfile, function (error, data) { + do_check_true(Components.isSuccessCode(error)); + do_check_neq(data.indexOf("Addons installed"), -1); + + // Clean up. + try { + logfile.remove(false); + } catch(ex) { + dump("Couldn't delete file: " + ex + "\n"); + // Stupid Windows box. + } + + Svc.Prefs.resetBranch(""); + }); + }); + + // Fake an unsuccessful sync due to prolonged failure. + setLastSync(PROLONGED_ERROR_DURATION); + Svc.Obs.notify("weave:service:sync:error"); +}); + +// Check that error log files are deleted above an age threshold. +add_test(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."); + for (let i = 0; i < numLogs; i++) { + let now = Date.now(); + let filename = "error-sync-" + now + "" + i + ".txt"; + let newLog = FileUtils.getFile("ProfD", ["weave", "logs", 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; + do_check_true(entries.hasMoreElements()); + let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile); + do_check_true(oldLogs.every(function (e) { + return e != logfile.leafName; + })); + do_check_false(entries.hasMoreElements()); + + // Clean up. + try { + logfile.remove(false); + } catch(ex) { + dump("Couldn't delete file: " + ex + "\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"); +}); |