1.1 --- /dev/null Thu Jan 01 00:00:00 1970 +0000
1.2 +++ b/services/sync/tests/unit/test_errorhandler_filelog.js Wed Dec 31 06:09:35 2014 +0100
1.3 @@ -0,0 +1,309 @@
1.4 +/* Any copyright is dedicated to the Public Domain.
1.5 + http://creativecommons.org/publicdomain/zero/1.0/ */
1.6 +
1.7 +Cu.import("resource://gre/modules/Log.jsm");
1.8 +Cu.import("resource://services-common/utils.js");
1.9 +Cu.import("resource://services-sync/service.js");
1.10 +Cu.import("resource://services-sync/util.js");
1.11 +Cu.import("resource://gre/modules/FileUtils.jsm");
1.12 +Cu.import("resource://gre/modules/NetUtil.jsm");
1.13 +
1.14 +const logsdir = FileUtils.getDir("ProfD", ["weave", "logs"], true);
1.15 +const LOG_PREFIX_SUCCESS = "success-";
1.16 +const LOG_PREFIX_ERROR = "error-";
1.17 +
1.18 +// Delay to wait before cleanup, to allow files to age.
1.19 +// This is so large because the file timestamp granularity is per-second, and
1.20 +// so otherwise we can end up with all of our files -- the ones we want to
1.21 +// keep, and the ones we want to clean up -- having the same modified time.
1.22 +const CLEANUP_DELAY = 2000;
1.23 +const DELAY_BUFFER = 500; // Buffer for timers on different OS platforms.
1.24 +
1.25 +const PROLONGED_ERROR_DURATION =
1.26 + (Svc.Prefs.get('errorhandler.networkFailureReportTimeout') * 2) * 1000;
1.27 +
1.28 +let errorHandler = Service.errorHandler;
1.29 +
1.30 +function setLastSync(lastSyncValue) {
1.31 + Svc.Prefs.set("lastSync", (new Date(Date.now() - lastSyncValue)).toString());
1.32 +}
1.33 +
1.34 +function run_test() {
1.35 + initTestLogging("Trace");
1.36 +
1.37 + Log.repository.getLogger("Sync.Service").level = Log.Level.Trace;
1.38 + Log.repository.getLogger("Sync.SyncScheduler").level = Log.Level.Trace;
1.39 + Log.repository.getLogger("Sync.ErrorHandler").level = Log.Level.Trace;
1.40 +
1.41 + run_next_test();
1.42 +}
1.43 +
1.44 +add_test(function test_noOutput() {
1.45 + // Ensure that the log appender won't print anything.
1.46 + errorHandler._logAppender.level = Log.Level.Fatal + 1;
1.47 +
1.48 + // Clear log output from startup.
1.49 + Svc.Prefs.set("log.appender.file.logOnSuccess", false);
1.50 + Svc.Obs.notify("weave:service:sync:finish");
1.51 +
1.52 + // Clear again without having issued any output.
1.53 + Svc.Prefs.set("log.appender.file.logOnSuccess", true);
1.54 +
1.55 + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
1.56 + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
1.57 +
1.58 + errorHandler._logAppender.level = Log.Level.Trace;
1.59 + Svc.Prefs.resetBranch("");
1.60 + run_next_test();
1.61 + });
1.62 +
1.63 + // Fake a successful sync.
1.64 + Svc.Obs.notify("weave:service:sync:finish");
1.65 +});
1.66 +
1.67 +add_test(function test_logOnSuccess_false() {
1.68 + Svc.Prefs.set("log.appender.file.logOnSuccess", false);
1.69 +
1.70 + let log = Log.repository.getLogger("Sync.Test.FileLog");
1.71 + log.info("this won't show up");
1.72 +
1.73 + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
1.74 + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
1.75 + // No log file was written.
1.76 + do_check_false(logsdir.directoryEntries.hasMoreElements());
1.77 +
1.78 + Svc.Prefs.resetBranch("");
1.79 + run_next_test();
1.80 + });
1.81 +
1.82 + // Fake a successful sync.
1.83 + Svc.Obs.notify("weave:service:sync:finish");
1.84 +});
1.85 +
1.86 +function readFile(file, callback) {
1.87 + NetUtil.asyncFetch(file, function (inputStream, statusCode, request) {
1.88 + let data = NetUtil.readInputStreamToString(inputStream,
1.89 + inputStream.available());
1.90 + callback(statusCode, data);
1.91 + });
1.92 +}
1.93 +
1.94 +add_test(function test_logOnSuccess_true() {
1.95 + Svc.Prefs.set("log.appender.file.logOnSuccess", true);
1.96 +
1.97 + let log = Log.repository.getLogger("Sync.Test.FileLog");
1.98 + const MESSAGE = "this WILL show up";
1.99 + log.info(MESSAGE);
1.100 +
1.101 + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
1.102 + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
1.103 +
1.104 + // Exactly one log file was written.
1.105 + let entries = logsdir.directoryEntries;
1.106 + do_check_true(entries.hasMoreElements());
1.107 + let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile);
1.108 + do_check_eq(logfile.leafName.slice(-4), ".txt");
1.109 + do_check_eq(logfile.leafName.slice(0, LOG_PREFIX_SUCCESS.length),
1.110 + LOG_PREFIX_SUCCESS);
1.111 + do_check_false(entries.hasMoreElements());
1.112 +
1.113 + // Ensure the log message was actually written to file.
1.114 + readFile(logfile, function (error, data) {
1.115 + do_check_true(Components.isSuccessCode(error));
1.116 + do_check_neq(data.indexOf(MESSAGE), -1);
1.117 +
1.118 + // Clean up.
1.119 + try {
1.120 + logfile.remove(false);
1.121 + } catch(ex) {
1.122 + dump("Couldn't delete file: " + ex + "\n");
1.123 + // Stupid Windows box.
1.124 + }
1.125 +
1.126 + Svc.Prefs.resetBranch("");
1.127 + run_next_test();
1.128 + });
1.129 + });
1.130 +
1.131 + // Fake a successful sync.
1.132 + Svc.Obs.notify("weave:service:sync:finish");
1.133 +});
1.134 +
1.135 +add_test(function test_sync_error_logOnError_false() {
1.136 + Svc.Prefs.set("log.appender.file.logOnError", false);
1.137 +
1.138 + let log = Log.repository.getLogger("Sync.Test.FileLog");
1.139 + log.info("this won't show up");
1.140 +
1.141 + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
1.142 + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
1.143 + // No log file was written.
1.144 + do_check_false(logsdir.directoryEntries.hasMoreElements());
1.145 +
1.146 + Svc.Prefs.resetBranch("");
1.147 + run_next_test();
1.148 + });
1.149 +
1.150 + // Fake an unsuccessful sync due to prolonged failure.
1.151 + setLastSync(PROLONGED_ERROR_DURATION);
1.152 + Svc.Obs.notify("weave:service:sync:error");
1.153 +});
1.154 +
1.155 +add_test(function test_sync_error_logOnError_true() {
1.156 + Svc.Prefs.set("log.appender.file.logOnError", true);
1.157 +
1.158 + let log = Log.repository.getLogger("Sync.Test.FileLog");
1.159 + const MESSAGE = "this WILL show up";
1.160 + log.info(MESSAGE);
1.161 +
1.162 + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
1.163 + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
1.164 +
1.165 + // Exactly one log file was written.
1.166 + let entries = logsdir.directoryEntries;
1.167 + do_check_true(entries.hasMoreElements());
1.168 + let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile);
1.169 + do_check_eq(logfile.leafName.slice(-4), ".txt");
1.170 + do_check_eq(logfile.leafName.slice(0, LOG_PREFIX_ERROR.length),
1.171 + LOG_PREFIX_ERROR);
1.172 + do_check_false(entries.hasMoreElements());
1.173 +
1.174 + // Ensure the log message was actually written to file.
1.175 + readFile(logfile, function (error, data) {
1.176 + do_check_true(Components.isSuccessCode(error));
1.177 + do_check_neq(data.indexOf(MESSAGE), -1);
1.178 +
1.179 + // Clean up.
1.180 + try {
1.181 + logfile.remove(false);
1.182 + } catch(ex) {
1.183 + dump("Couldn't delete file: " + ex + "\n");
1.184 + // Stupid Windows box.
1.185 + }
1.186 +
1.187 + Svc.Prefs.resetBranch("");
1.188 + run_next_test();
1.189 + });
1.190 + });
1.191 +
1.192 + // Fake an unsuccessful sync due to prolonged failure.
1.193 + setLastSync(PROLONGED_ERROR_DURATION);
1.194 + Svc.Obs.notify("weave:service:sync:error");
1.195 +});
1.196 +
1.197 +add_test(function test_login_error_logOnError_false() {
1.198 + Svc.Prefs.set("log.appender.file.logOnError", false);
1.199 +
1.200 + let log = Log.repository.getLogger("Sync.Test.FileLog");
1.201 + log.info("this won't show up");
1.202 +
1.203 + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
1.204 + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
1.205 + // No log file was written.
1.206 + do_check_false(logsdir.directoryEntries.hasMoreElements());
1.207 +
1.208 + Svc.Prefs.resetBranch("");
1.209 + run_next_test();
1.210 + });
1.211 +
1.212 + // Fake an unsuccessful login due to prolonged failure.
1.213 + setLastSync(PROLONGED_ERROR_DURATION);
1.214 + Svc.Obs.notify("weave:service:login:error");
1.215 +});
1.216 +
1.217 +add_test(function test_login_error_logOnError_true() {
1.218 + Svc.Prefs.set("log.appender.file.logOnError", true);
1.219 +
1.220 + let log = Log.repository.getLogger("Sync.Test.FileLog");
1.221 + const MESSAGE = "this WILL show up";
1.222 + log.info(MESSAGE);
1.223 +
1.224 + Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
1.225 + Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
1.226 +
1.227 + // Exactly one log file was written.
1.228 + let entries = logsdir.directoryEntries;
1.229 + do_check_true(entries.hasMoreElements());
1.230 + let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile);
1.231 + do_check_eq(logfile.leafName.slice(-4), ".txt");
1.232 + do_check_eq(logfile.leafName.slice(0, LOG_PREFIX_ERROR.length),
1.233 + LOG_PREFIX_ERROR);
1.234 + do_check_false(entries.hasMoreElements());
1.235 +
1.236 + // Ensure the log message was actually written to file.
1.237 + readFile(logfile, function (error, data) {
1.238 + do_check_true(Components.isSuccessCode(error));
1.239 + do_check_neq(data.indexOf(MESSAGE), -1);
1.240 +
1.241 + // Clean up.
1.242 + try {
1.243 + logfile.remove(false);
1.244 + } catch(ex) {
1.245 + dump("Couldn't delete file: " + ex + "\n");
1.246 + // Stupid Windows box.
1.247 + }
1.248 +
1.249 + Svc.Prefs.resetBranch("");
1.250 + run_next_test();
1.251 + });
1.252 + });
1.253 +
1.254 + // Fake an unsuccessful login due to prolonged failure.
1.255 + setLastSync(PROLONGED_ERROR_DURATION);
1.256 + Svc.Obs.notify("weave:service:login:error");
1.257 +});
1.258 +
1.259 +// Check that error log files are deleted above an age threshold.
1.260 +add_test(function test_logErrorCleanup_age() {
1.261 + _("Beginning test_logErrorCleanup_age.");
1.262 + let maxAge = CLEANUP_DELAY / 1000;
1.263 + let oldLogs = [];
1.264 + let numLogs = 10;
1.265 + let errString = "some error log\n";
1.266 +
1.267 + Svc.Prefs.set("log.appender.file.logOnError", true);
1.268 + Svc.Prefs.set("log.appender.file.maxErrorAge", maxAge);
1.269 +
1.270 + _("Making some files.");
1.271 + for (let i = 0; i < numLogs; i++) {
1.272 + let now = Date.now();
1.273 + let filename = LOG_PREFIX_ERROR + now + "" + i + ".txt";
1.274 + let newLog = FileUtils.getFile("ProfD", ["weave", "logs", filename]);
1.275 + let foStream = FileUtils.openFileOutputStream(newLog);
1.276 + foStream.write(errString, errString.length);
1.277 + foStream.close();
1.278 + _(" > Created " + filename);
1.279 + oldLogs.push(newLog.leafName);
1.280 + }
1.281 +
1.282 + Svc.Obs.add("weave:service:cleanup-logs", function onCleanupLogs() {
1.283 + Svc.Obs.remove("weave:service:cleanup-logs", onCleanupLogs);
1.284 +
1.285 + // Only the newest created log file remains.
1.286 + let entries = logsdir.directoryEntries;
1.287 + do_check_true(entries.hasMoreElements());
1.288 + let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile);
1.289 + do_check_true(oldLogs.every(function (e) {
1.290 + return e != logfile.leafName;
1.291 + }));
1.292 + do_check_false(entries.hasMoreElements());
1.293 +
1.294 + // Clean up.
1.295 + try {
1.296 + logfile.remove(false);
1.297 + } catch(ex) {
1.298 + dump("Couldn't delete file: " + ex + "\n");
1.299 + // Stupid Windows box.
1.300 + }
1.301 +
1.302 + Svc.Prefs.resetBranch("");
1.303 + run_next_test();
1.304 + });
1.305 +
1.306 + let delay = CLEANUP_DELAY + DELAY_BUFFER;
1.307 +
1.308 + _("Cleaning up logs after " + delay + "msec.");
1.309 + CommonUtils.namedTimer(function onTimer() {
1.310 + Svc.Obs.notify("weave:service:sync:error");
1.311 + }, delay, this, "cleanup-timer");
1.312 +});
