michael@0: /* Any copyright is dedicated to the Public Domain.
michael@0:    http://creativecommons.org/publicdomain/zero/1.0/ */
michael@0: 
michael@0: Cu.import("resource://gre/modules/Log.jsm");
michael@0: Cu.import("resource://services-common/utils.js");
michael@0: Cu.import("resource://services-sync/service.js");
michael@0: Cu.import("resource://services-sync/util.js");
michael@0: Cu.import("resource://gre/modules/FileUtils.jsm");
michael@0: Cu.import("resource://gre/modules/NetUtil.jsm");
michael@0: 
michael@0: const logsdir            = FileUtils.getDir("ProfD", ["weave", "logs"], true);
michael@0: const LOG_PREFIX_SUCCESS = "success-";
michael@0: const LOG_PREFIX_ERROR   = "error-";
michael@0: 
michael@0: // Delay to wait before cleanup, to allow files to age.
michael@0: // This is so large because the file timestamp granularity is per-second, and
michael@0: // so otherwise we can end up with all of our files -- the ones we want to
michael@0: // keep, and the ones we want to clean up -- having the same modified time.
michael@0: const CLEANUP_DELAY      = 2000;
michael@0: const DELAY_BUFFER       = 500;  // Buffer for timers on different OS platforms.
michael@0: 
michael@0: const PROLONGED_ERROR_DURATION =
michael@0:   (Svc.Prefs.get('errorhandler.networkFailureReportTimeout') * 2) * 1000;
michael@0: 
michael@0: let errorHandler = Service.errorHandler;
michael@0: 
michael@0: function setLastSync(lastSyncValue) {
michael@0:   Svc.Prefs.set("lastSync", (new Date(Date.now() - lastSyncValue)).toString());
michael@0: }
michael@0: 
michael@0: function run_test() {
michael@0:   initTestLogging("Trace");
michael@0: 
michael@0:   Log.repository.getLogger("Sync.Service").level = Log.Level.Trace;
michael@0:   Log.repository.getLogger("Sync.SyncScheduler").level = Log.Level.Trace;
michael@0:   Log.repository.getLogger("Sync.ErrorHandler").level = Log.Level.Trace;
michael@0: 
michael@0:   run_next_test();
michael@0: }
michael@0: 
michael@0: add_test(function test_noOutput() {
michael@0:   // Ensure that the log appender won't print anything.
michael@0:   errorHandler._logAppender.level = Log.Level.Fatal + 1;
michael@0: 
michael@0:   // Clear log output from startup.
michael@0:   Svc.Prefs.set("log.appender.file.logOnSuccess", false);
michael@0:   Svc.Obs.notify("weave:service:sync:finish");
michael@0: 
michael@0:   // Clear again without having issued any output.
michael@0:   Svc.Prefs.set("log.appender.file.logOnSuccess", true);
michael@0: 
michael@0:   Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
michael@0:     Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
michael@0: 
michael@0:     errorHandler._logAppender.level = Log.Level.Trace;
michael@0:     Svc.Prefs.resetBranch("");
michael@0:     run_next_test();
michael@0:   });
michael@0: 
michael@0:   // Fake a successful sync.
michael@0:   Svc.Obs.notify("weave:service:sync:finish");
michael@0: });
michael@0: 
michael@0: add_test(function test_logOnSuccess_false() {
michael@0:   Svc.Prefs.set("log.appender.file.logOnSuccess", false);
michael@0: 
michael@0:   let log = Log.repository.getLogger("Sync.Test.FileLog");
michael@0:   log.info("this won't show up");
michael@0: 
michael@0:   Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
michael@0:     Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
michael@0:     // No log file was written.
michael@0:     do_check_false(logsdir.directoryEntries.hasMoreElements());
michael@0: 
michael@0:     Svc.Prefs.resetBranch("");
michael@0:     run_next_test();
michael@0:   });
michael@0: 
michael@0:   // Fake a successful sync.
michael@0:   Svc.Obs.notify("weave:service:sync:finish");
michael@0: });
michael@0: 
michael@0: function readFile(file, callback) {
michael@0:   NetUtil.asyncFetch(file, function (inputStream, statusCode, request) {
michael@0:     let data = NetUtil.readInputStreamToString(inputStream,
michael@0:                                                inputStream.available());
michael@0:     callback(statusCode, data);
michael@0:   });
michael@0: }
michael@0: 
michael@0: add_test(function test_logOnSuccess_true() {
michael@0:   Svc.Prefs.set("log.appender.file.logOnSuccess", true);
michael@0: 
michael@0:   let log = Log.repository.getLogger("Sync.Test.FileLog");
michael@0:   const MESSAGE = "this WILL show up";
michael@0:   log.info(MESSAGE);
michael@0: 
michael@0:   Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
michael@0:     Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
michael@0: 
michael@0:     // Exactly one log file was written.
michael@0:     let entries = logsdir.directoryEntries;
michael@0:     do_check_true(entries.hasMoreElements());
michael@0:     let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile);
michael@0:     do_check_eq(logfile.leafName.slice(-4), ".txt");
michael@0:     do_check_eq(logfile.leafName.slice(0, LOG_PREFIX_SUCCESS.length),
michael@0:                 LOG_PREFIX_SUCCESS);
michael@0:     do_check_false(entries.hasMoreElements());
michael@0: 
michael@0:     // Ensure the log message was actually written to file.
michael@0:     readFile(logfile, function (error, data) {
michael@0:       do_check_true(Components.isSuccessCode(error));
michael@0:       do_check_neq(data.indexOf(MESSAGE), -1);
michael@0: 
michael@0:       // Clean up.
michael@0:       try {
michael@0:         logfile.remove(false);
michael@0:       } catch(ex) {
michael@0:         dump("Couldn't delete file: " + ex + "\n");
michael@0:         // Stupid Windows box.
michael@0:       }
michael@0: 
michael@0:       Svc.Prefs.resetBranch("");
michael@0:       run_next_test();
michael@0:     });
michael@0:   });
michael@0: 
michael@0:   // Fake a successful sync.
michael@0:   Svc.Obs.notify("weave:service:sync:finish");
michael@0: });
michael@0: 
michael@0: add_test(function test_sync_error_logOnError_false() {
michael@0:   Svc.Prefs.set("log.appender.file.logOnError", false);
michael@0: 
michael@0:   let log = Log.repository.getLogger("Sync.Test.FileLog");
michael@0:   log.info("this won't show up");
michael@0: 
michael@0:   Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
michael@0:     Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
michael@0:     // No log file was written.
michael@0:     do_check_false(logsdir.directoryEntries.hasMoreElements());
michael@0: 
michael@0:     Svc.Prefs.resetBranch("");
michael@0:     run_next_test();
michael@0:   });
michael@0: 
michael@0:   // Fake an unsuccessful sync due to prolonged failure.
michael@0:   setLastSync(PROLONGED_ERROR_DURATION);
michael@0:   Svc.Obs.notify("weave:service:sync:error");
michael@0: });
michael@0: 
michael@0: add_test(function test_sync_error_logOnError_true() {
michael@0:   Svc.Prefs.set("log.appender.file.logOnError", true);
michael@0: 
michael@0:   let log = Log.repository.getLogger("Sync.Test.FileLog");
michael@0:   const MESSAGE = "this WILL show up";
michael@0:   log.info(MESSAGE);
michael@0: 
michael@0:   Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
michael@0:     Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
michael@0: 
michael@0:     // Exactly one log file was written.
michael@0:     let entries = logsdir.directoryEntries;
michael@0:     do_check_true(entries.hasMoreElements());
michael@0:     let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile);
michael@0:     do_check_eq(logfile.leafName.slice(-4), ".txt");
michael@0:     do_check_eq(logfile.leafName.slice(0, LOG_PREFIX_ERROR.length),
michael@0:                 LOG_PREFIX_ERROR);
michael@0:     do_check_false(entries.hasMoreElements());
michael@0: 
michael@0:     // Ensure the log message was actually written to file.
michael@0:     readFile(logfile, function (error, data) {
michael@0:       do_check_true(Components.isSuccessCode(error));
michael@0:       do_check_neq(data.indexOf(MESSAGE), -1);
michael@0: 
michael@0:       // Clean up.
michael@0:       try {
michael@0:         logfile.remove(false);
michael@0:       } catch(ex) {
michael@0:         dump("Couldn't delete file: " + ex + "\n");
michael@0:         // Stupid Windows box.
michael@0:       }
michael@0: 
michael@0:       Svc.Prefs.resetBranch("");
michael@0:       run_next_test();
michael@0:     });
michael@0:   });
michael@0: 
michael@0:   // Fake an unsuccessful sync due to prolonged failure.
michael@0:   setLastSync(PROLONGED_ERROR_DURATION);
michael@0:   Svc.Obs.notify("weave:service:sync:error");
michael@0: });
michael@0: 
michael@0: add_test(function test_login_error_logOnError_false() {
michael@0:   Svc.Prefs.set("log.appender.file.logOnError", false);
michael@0: 
michael@0:   let log = Log.repository.getLogger("Sync.Test.FileLog");
michael@0:   log.info("this won't show up");
michael@0: 
michael@0:   Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
michael@0:     Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
michael@0:     // No log file was written.
michael@0:     do_check_false(logsdir.directoryEntries.hasMoreElements());
michael@0: 
michael@0:     Svc.Prefs.resetBranch("");
michael@0:     run_next_test();
michael@0:   });
michael@0: 
michael@0:   // Fake an unsuccessful login due to prolonged failure.
michael@0:   setLastSync(PROLONGED_ERROR_DURATION);
michael@0:   Svc.Obs.notify("weave:service:login:error");
michael@0: });
michael@0: 
michael@0: add_test(function test_login_error_logOnError_true() {
michael@0:   Svc.Prefs.set("log.appender.file.logOnError", true);
michael@0: 
michael@0:   let log = Log.repository.getLogger("Sync.Test.FileLog");
michael@0:   const MESSAGE = "this WILL show up";
michael@0:   log.info(MESSAGE);
michael@0: 
michael@0:   Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
michael@0:     Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
michael@0: 
michael@0:     // Exactly one log file was written.
michael@0:     let entries = logsdir.directoryEntries;
michael@0:     do_check_true(entries.hasMoreElements());
michael@0:     let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile);
michael@0:     do_check_eq(logfile.leafName.slice(-4), ".txt");
michael@0:     do_check_eq(logfile.leafName.slice(0, LOG_PREFIX_ERROR.length),
michael@0:                 LOG_PREFIX_ERROR);
michael@0:     do_check_false(entries.hasMoreElements());
michael@0: 
michael@0:     // Ensure the log message was actually written to file.
michael@0:     readFile(logfile, function (error, data) {
michael@0:       do_check_true(Components.isSuccessCode(error));
michael@0:       do_check_neq(data.indexOf(MESSAGE), -1);
michael@0: 
michael@0:       // Clean up.
michael@0:       try {
michael@0:         logfile.remove(false);
michael@0:       } catch(ex) {
michael@0:         dump("Couldn't delete file: " + ex + "\n");
michael@0:         // Stupid Windows box.
michael@0:       }
michael@0: 
michael@0:       Svc.Prefs.resetBranch("");
michael@0:       run_next_test();
michael@0:     });
michael@0:   });
michael@0: 
michael@0:   // Fake an unsuccessful login due to prolonged failure.
michael@0:   setLastSync(PROLONGED_ERROR_DURATION);
michael@0:   Svc.Obs.notify("weave:service:login:error");
michael@0: });
michael@0: 
michael@0: // Check that error log files are deleted above an age threshold.
michael@0: add_test(function test_logErrorCleanup_age() {
michael@0:   _("Beginning test_logErrorCleanup_age.");
michael@0:   let maxAge = CLEANUP_DELAY / 1000;
michael@0:   let oldLogs = [];
michael@0:   let numLogs = 10;
michael@0:   let errString = "some error log\n";
michael@0: 
michael@0:   Svc.Prefs.set("log.appender.file.logOnError", true);
michael@0:   Svc.Prefs.set("log.appender.file.maxErrorAge", maxAge);
michael@0: 
michael@0:   _("Making some files.");
michael@0:   for (let i = 0; i < numLogs; i++) {
michael@0:     let now = Date.now();
michael@0:     let filename = LOG_PREFIX_ERROR + now + "" + i + ".txt";
michael@0:     let newLog = FileUtils.getFile("ProfD", ["weave", "logs", filename]);
michael@0:     let foStream = FileUtils.openFileOutputStream(newLog);
michael@0:     foStream.write(errString, errString.length);
michael@0:     foStream.close();
michael@0:     _("  > Created " + filename);
michael@0:     oldLogs.push(newLog.leafName);
michael@0:   }
michael@0: 
michael@0:   Svc.Obs.add("weave:service:cleanup-logs", function onCleanupLogs() {
michael@0:     Svc.Obs.remove("weave:service:cleanup-logs", onCleanupLogs);
michael@0: 
michael@0:     // Only the newest created log file remains.
michael@0:     let entries = logsdir.directoryEntries;
michael@0:     do_check_true(entries.hasMoreElements());
michael@0:     let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile);
michael@0:     do_check_true(oldLogs.every(function (e) {
michael@0:       return e != logfile.leafName;
michael@0:     }));
michael@0:     do_check_false(entries.hasMoreElements());
michael@0: 
michael@0:     // Clean up.
michael@0:     try {
michael@0:       logfile.remove(false);
michael@0:     } catch(ex) {
michael@0:       dump("Couldn't delete file: " + ex + "\n");
michael@0:       // Stupid Windows box.
michael@0:     }
michael@0: 
michael@0:     Svc.Prefs.resetBranch("");
michael@0:     run_next_test();
michael@0:   });
michael@0: 
michael@0:   let delay = CLEANUP_DELAY + DELAY_BUFFER;
michael@0: 
michael@0:   _("Cleaning up logs after " + delay + "msec.");
michael@0:   CommonUtils.namedTimer(function onTimer() {
michael@0:     Svc.Obs.notify("weave:service:sync:error");
michael@0:   }, delay, this, "cleanup-timer");
michael@0: });