test_errorhandler_filelog.js (15316B)
1 /* Any copyright is dedicated to the Public Domain. 2 http://creativecommons.org/publicdomain/zero/1.0/ */ 3 4 // `Service` is used as a global in head_helpers.js. 5 // eslint-disable-next-line no-unused-vars 6 const { Service } = ChromeUtils.importESModule( 7 "resource://services-sync/service.sys.mjs" 8 ); 9 const { logManager } = ChromeUtils.importESModule( 10 "resource://gre/modules/FxAccountsCommon.sys.mjs" 11 ); 12 const { FileUtils } = ChromeUtils.importESModule( 13 "resource://gre/modules/FileUtils.sys.mjs" 14 ); 15 16 const logsdir = FileUtils.getDir("ProfD", ["weave", "logs"]); 17 logsdir.create(Ci.nsIFile.DIRECTORY_TYPE, FileUtils.PERMS_DIRECTORY); 18 19 // Delay to wait before cleanup, to allow files to age. 20 // This is so large because the file timestamp granularity is per-second, and 21 // so otherwise we can end up with all of our files -- the ones we want to 22 // keep, and the ones we want to clean up -- having the same modified time. 23 const CLEANUP_DELAY = 2000; 24 const DELAY_BUFFER = 500; // Buffer for timers on different OS platforms. 25 26 function run_test() { 27 validate_all_future_pings(); 28 run_next_test(); 29 } 30 31 add_test(function test_noOutput() { 32 // Ensure that the log appender won't print anything. 33 logManager._fileAppender.level = Log.Level.Fatal + 1; 34 35 // Clear log output from startup. 36 Svc.PrefBranch.setBoolPref("log.appender.file.logOnSuccess", false); 37 Svc.Obs.notify("weave:service:sync:finish"); 38 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLogOuter() { 39 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLogOuter); 40 // Clear again without having issued any output. 41 Svc.PrefBranch.setBoolPref("log.appender.file.logOnSuccess", true); 42 43 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLogInner() { 44 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLogInner); 45 46 logManager._fileAppender.level = Log.Level.Trace; 47 for (const pref of Svc.PrefBranch.getChildList("")) { 48 Svc.PrefBranch.clearUserPref(pref); 49 } 50 run_next_test(); 51 }); 52 53 // Fake a successful sync. 54 Svc.Obs.notify("weave:service:sync:finish"); 55 }); 56 }); 57 58 add_test(function test_logOnSuccess_false() { 59 Svc.PrefBranch.setBoolPref("log.appender.file.logOnSuccess", false); 60 61 let log = Log.repository.getLogger("Sync.Test.FileLog"); 62 log.info("this won't show up"); 63 64 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { 65 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); 66 // No log file was written. 67 Assert.ok(!logsdir.directoryEntries.hasMoreElements()); 68 69 for (const pref of Svc.PrefBranch.getChildList("")) { 70 Svc.PrefBranch.clearUserPref(pref); 71 } 72 run_next_test(); 73 }); 74 75 // Fake a successful sync. 76 Svc.Obs.notify("weave:service:sync:finish"); 77 }); 78 79 function readFile(file, callback) { 80 NetUtil.asyncFetch( 81 { 82 uri: NetUtil.newURI(file), 83 loadUsingSystemPrincipal: true, 84 }, 85 function (inputStream, statusCode) { 86 let data = NetUtil.readInputStreamToString( 87 inputStream, 88 inputStream.available() 89 ); 90 callback(statusCode, data); 91 } 92 ); 93 } 94 95 add_test(function test_logOnSuccess_true() { 96 Svc.PrefBranch.setBoolPref("log.appender.file.logOnSuccess", true); 97 98 let log = Log.repository.getLogger("Sync.Test.FileLog"); 99 const MESSAGE = "this WILL show up"; 100 log.info(MESSAGE); 101 102 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { 103 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); 104 105 // Exactly one log file was written. 106 let entries = logsdir.directoryEntries; 107 Assert.ok(entries.hasMoreElements()); 108 let logfile = entries.getNext().QueryInterface(Ci.nsIFile); 109 Assert.equal(logfile.leafName.slice(-4), ".txt"); 110 Assert.ok(logfile.leafName.startsWith("success-sync-"), logfile.leafName); 111 Assert.ok(!entries.hasMoreElements()); 112 113 // Ensure the log message was actually written to file. 114 readFile(logfile, function (error, data) { 115 Assert.ok(Components.isSuccessCode(error)); 116 Assert.notEqual(data.indexOf(MESSAGE), -1); 117 118 // Clean up. 119 try { 120 logfile.remove(false); 121 } catch (ex) { 122 dump("Couldn't delete file: " + ex.message + "\n"); 123 // Stupid Windows box. 124 } 125 126 for (const pref of Svc.PrefBranch.getChildList("")) { 127 Svc.PrefBranch.clearUserPref(pref); 128 } 129 run_next_test(); 130 }); 131 }); 132 133 // Fake a successful sync. 134 Svc.Obs.notify("weave:service:sync:finish"); 135 }); 136 137 add_test(function test_sync_error_logOnError_false() { 138 Svc.PrefBranch.setBoolPref("log.appender.file.logOnError", false); 139 140 let log = Log.repository.getLogger("Sync.Test.FileLog"); 141 log.info("this won't show up"); 142 143 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { 144 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); 145 // No log file was written. 146 Assert.ok(!logsdir.directoryEntries.hasMoreElements()); 147 148 for (const pref of Svc.PrefBranch.getChildList("")) { 149 Svc.PrefBranch.clearUserPref(pref); 150 } 151 run_next_test(); 152 }); 153 154 // Fake an unsuccessful sync. 155 Svc.Obs.notify("weave:service:sync:error"); 156 }); 157 158 add_test(function test_sync_error_logOnError_true() { 159 Svc.PrefBranch.setBoolPref("log.appender.file.logOnError", true); 160 161 let log = Log.repository.getLogger("Sync.Test.FileLog"); 162 const MESSAGE = "this WILL show up"; 163 log.info(MESSAGE); 164 165 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { 166 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); 167 168 // Exactly one log file was written. 169 let entries = logsdir.directoryEntries; 170 Assert.ok(entries.hasMoreElements()); 171 let logfile = entries.getNext().QueryInterface(Ci.nsIFile); 172 Assert.equal(logfile.leafName.slice(-4), ".txt"); 173 Assert.ok(logfile.leafName.startsWith("error-sync-"), logfile.leafName); 174 Assert.ok(!entries.hasMoreElements()); 175 176 // Ensure the log message was actually written to file. 177 readFile(logfile, function (error, data) { 178 Assert.ok(Components.isSuccessCode(error)); 179 Assert.notEqual(data.indexOf(MESSAGE), -1); 180 181 // Clean up. 182 try { 183 logfile.remove(false); 184 } catch (ex) { 185 dump("Couldn't delete file: " + ex.message + "\n"); 186 // Stupid Windows box. 187 } 188 189 for (const pref of Svc.PrefBranch.getChildList("")) { 190 Svc.PrefBranch.clearUserPref(pref); 191 } 192 run_next_test(); 193 }); 194 }); 195 196 // Fake an unsuccessful sync. 197 Svc.Obs.notify("weave:service:sync:error"); 198 }); 199 200 add_test(function test_login_error_logOnError_false() { 201 Svc.PrefBranch.setBoolPref("log.appender.file.logOnError", false); 202 203 let log = Log.repository.getLogger("Sync.Test.FileLog"); 204 log.info("this won't show up"); 205 206 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { 207 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); 208 // No log file was written. 209 Assert.ok(!logsdir.directoryEntries.hasMoreElements()); 210 211 for (const pref of Svc.PrefBranch.getChildList("")) { 212 Svc.PrefBranch.clearUserPref(pref); 213 } 214 run_next_test(); 215 }); 216 217 // Fake an unsuccessful login. 218 Svc.Obs.notify("weave:service:login:error"); 219 }); 220 221 add_test(function test_login_error_logOnError_true() { 222 Svc.PrefBranch.setBoolPref("log.appender.file.logOnError", true); 223 224 let log = Log.repository.getLogger("Sync.Test.FileLog"); 225 const MESSAGE = "this WILL show up"; 226 log.info(MESSAGE); 227 228 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { 229 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); 230 231 // Exactly one log file was written. 232 let entries = logsdir.directoryEntries; 233 Assert.ok(entries.hasMoreElements()); 234 let logfile = entries.getNext().QueryInterface(Ci.nsIFile); 235 Assert.equal(logfile.leafName.slice(-4), ".txt"); 236 Assert.ok(logfile.leafName.startsWith("error-sync-"), logfile.leafName); 237 Assert.ok(!entries.hasMoreElements()); 238 239 // Ensure the log message was actually written to file. 240 readFile(logfile, function (error, data) { 241 Assert.ok(Components.isSuccessCode(error)); 242 Assert.notEqual(data.indexOf(MESSAGE), -1); 243 244 // Clean up. 245 try { 246 logfile.remove(false); 247 } catch (ex) { 248 dump("Couldn't delete file: " + ex.message + "\n"); 249 // Stupid Windows box. 250 } 251 252 for (const pref of Svc.PrefBranch.getChildList("")) { 253 Svc.PrefBranch.clearUserPref(pref); 254 } 255 run_next_test(); 256 }); 257 }); 258 259 // Fake an unsuccessful login. 260 Svc.Obs.notify("weave:service:login:error"); 261 }); 262 263 add_test(function test_noNewFailed_noErrorLog() { 264 Svc.PrefBranch.setBoolPref("log.appender.file.logOnError", true); 265 Svc.PrefBranch.setBoolPref("log.appender.file.logOnSuccess", false); 266 267 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { 268 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); 269 // No log file was written. 270 Assert.ok(!logsdir.directoryEntries.hasMoreElements()); 271 272 for (const pref of Svc.PrefBranch.getChildList("")) { 273 Svc.PrefBranch.clearUserPref(pref); 274 } 275 run_next_test(); 276 }); 277 // failed is nonzero and newFailed is zero -- shouldn't write a log. 278 let count = { 279 applied: 8, 280 succeeded: 4, 281 failed: 5, 282 newFailed: 0, 283 reconciled: 4, 284 }; 285 Svc.Obs.notify("weave:engine:sync:applied", count, "foobar-engine"); 286 Svc.Obs.notify("weave:service:sync:finish"); 287 }); 288 289 add_test(function test_newFailed_errorLog() { 290 Svc.PrefBranch.setBoolPref("log.appender.file.logOnError", true); 291 Svc.PrefBranch.setBoolPref("log.appender.file.logOnSuccess", false); 292 293 let log = Log.repository.getLogger("Sync.Test.FileLog"); 294 const MESSAGE = "this WILL show up 2"; 295 log.info(MESSAGE); 296 297 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { 298 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); 299 300 // Exactly one log file was written. 301 let entries = logsdir.directoryEntries; 302 Assert.ok(entries.hasMoreElements()); 303 let logfile = entries.getNext().QueryInterface(Ci.nsIFile); 304 Assert.equal(logfile.leafName.slice(-4), ".txt"); 305 Assert.ok(logfile.leafName.startsWith("error-sync-"), logfile.leafName); 306 Assert.ok(!entries.hasMoreElements()); 307 308 // Ensure the log message was actually written to file. 309 readFile(logfile, function (error, data) { 310 Assert.ok(Components.isSuccessCode(error)); 311 Assert.notEqual(data.indexOf(MESSAGE), -1); 312 313 // Clean up. 314 try { 315 logfile.remove(false); 316 } catch (ex) { 317 dump("Couldn't delete file: " + ex.message + "\n"); 318 // Stupid Windows box. 319 } 320 321 for (const pref of Svc.PrefBranch.getChildList("")) { 322 Svc.PrefBranch.clearUserPref(pref); 323 } 324 run_next_test(); 325 }); 326 }); 327 // newFailed is nonzero -- should write a log. 328 let count = { 329 applied: 8, 330 succeeded: 4, 331 failed: 5, 332 newFailed: 4, 333 reconciled: 4, 334 }; 335 336 Svc.Obs.notify("weave:engine:sync:applied", count, "foobar-engine"); 337 Svc.Obs.notify("weave:service:sync:finish"); 338 }); 339 340 add_test(function test_errorLog_dumpAddons() { 341 Svc.PrefBranch.setStringPref("log.logger", "Trace"); 342 Svc.PrefBranch.setBoolPref("log.appender.file.logOnError", true); 343 344 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { 345 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); 346 347 let entries = logsdir.directoryEntries; 348 Assert.ok(entries.hasMoreElements()); 349 let logfile = entries.getNext().QueryInterface(Ci.nsIFile); 350 Assert.equal(logfile.leafName.slice(-4), ".txt"); 351 Assert.ok(logfile.leafName.startsWith("error-sync-"), logfile.leafName); 352 Assert.ok(!entries.hasMoreElements()); 353 354 // Ensure we logged some addon list (which is probably empty) 355 readFile(logfile, function (error, data) { 356 Assert.ok(Components.isSuccessCode(error)); 357 Assert.notEqual(data.indexOf("Addons installed"), -1); 358 359 // Clean up. 360 try { 361 logfile.remove(false); 362 } catch (ex) { 363 dump("Couldn't delete file: " + ex.message + "\n"); 364 // Stupid Windows box. 365 } 366 367 for (const pref of Svc.PrefBranch.getChildList("")) { 368 Svc.PrefBranch.clearUserPref(pref); 369 } 370 run_next_test(); 371 }); 372 }); 373 374 // Fake an unsuccessful sync. 375 Svc.Obs.notify("weave:service:sync:error"); 376 }); 377 378 // Check that error log files are deleted above an age threshold. 379 add_test(async function test_logErrorCleanup_age() { 380 _("Beginning test_logErrorCleanup_age."); 381 let maxAge = CLEANUP_DELAY / 1000; 382 let oldLogs = []; 383 let numLogs = 10; 384 let errString = "some error log\n"; 385 386 Svc.PrefBranch.setBoolPref("log.appender.file.logOnError", true); 387 Svc.PrefBranch.setIntPref("log.appender.file.maxErrorAge", maxAge); 388 389 _("Making some files."); 390 const logsDir = PathUtils.join(PathUtils.profileDir, "weave", "logs"); 391 await IOUtils.makeDirectory(logsDir); 392 for (let i = 0; i < numLogs; i++) { 393 let now = Date.now(); 394 let filename = "error-sync-" + now + "" + i + ".txt"; 395 let newLog = new FileUtils.File(PathUtils.join(logsDir, filename)); 396 let foStream = FileUtils.openFileOutputStream(newLog); 397 foStream.write(errString, errString.length); 398 foStream.close(); 399 _(" > Created " + filename); 400 oldLogs.push(newLog.leafName); 401 } 402 403 Svc.Obs.add( 404 "services-tests:common:log-manager:cleanup-logs", 405 function onCleanupLogs() { 406 Svc.Obs.remove( 407 "services-tests:common:log-manager:cleanup-logs", 408 onCleanupLogs 409 ); 410 411 // Only the newest created log file remains. 412 let entries = logsdir.directoryEntries; 413 Assert.ok(entries.hasMoreElements()); 414 let logfile = entries.getNext().QueryInterface(Ci.nsIFile); 415 Assert.ok( 416 oldLogs.every(function (e) { 417 return e != logfile.leafName; 418 }) 419 ); 420 Assert.ok(!entries.hasMoreElements()); 421 422 // Clean up. 423 try { 424 logfile.remove(false); 425 } catch (ex) { 426 dump("Couldn't delete file: " + ex.message + "\n"); 427 // Stupid Windows box. 428 } 429 430 for (const pref of Svc.PrefBranch.getChildList("")) { 431 Svc.PrefBranch.clearUserPref(pref); 432 } 433 run_next_test(); 434 } 435 ); 436 437 let delay = CLEANUP_DELAY + DELAY_BUFFER; 438 439 _("Cleaning up logs after " + delay + "msec."); 440 CommonUtils.namedTimer( 441 function onTimer() { 442 Svc.Obs.notify("weave:service:sync:error"); 443 }, 444 delay, 445 this, 446 "cleanup-timer" 447 ); 448 }); 449 450 add_task(async function test_remove_log_on_startOver() { 451 Svc.PrefBranch.setBoolPref("log.appender.file.logOnError", true); 452 453 let log = Log.repository.getLogger("Sync.Test.FileLog"); 454 const MESSAGE = "this WILL show up"; 455 log.info(MESSAGE); 456 457 let promiseLogWritten = promiseOneObserver("weave:service:reset-file-log"); 458 // Fake an unsuccessful sync. 459 Svc.Obs.notify("weave:service:sync:error"); 460 461 await promiseLogWritten; 462 // Should have at least 1 log file. 463 let entries = logsdir.directoryEntries; 464 Assert.ok(entries.hasMoreElements()); 465 466 // Fake a reset. 467 let promiseRemoved = promiseOneObserver("weave:service:remove-file-log"); 468 Svc.Obs.notify("weave:service:start-over:finish"); 469 await promiseRemoved; 470 471 // should be no files left. 472 Assert.ok(!logsdir.directoryEntries.hasMoreElements()); 473 });