|
1 /* Any copyright is dedicated to the Public Domain. |
|
2 http://creativecommons.org/publicdomain/zero/1.0/ */ |
|
3 |
|
4 Cu.import("resource://gre/modules/Log.jsm"); |
|
5 Cu.import("resource://services-common/utils.js"); |
|
6 Cu.import("resource://services-sync/service.js"); |
|
7 Cu.import("resource://services-sync/util.js"); |
|
8 Cu.import("resource://gre/modules/FileUtils.jsm"); |
|
9 Cu.import("resource://gre/modules/NetUtil.jsm"); |
|
10 |
|
11 const logsdir = FileUtils.getDir("ProfD", ["weave", "logs"], true); |
|
12 const LOG_PREFIX_SUCCESS = "success-"; |
|
13 const LOG_PREFIX_ERROR = "error-"; |
|
14 |
|
15 // Delay to wait before cleanup, to allow files to age. |
|
16 // This is so large because the file timestamp granularity is per-second, and |
|
17 // so otherwise we can end up with all of our files -- the ones we want to |
|
18 // keep, and the ones we want to clean up -- having the same modified time. |
|
19 const CLEANUP_DELAY = 2000; |
|
20 const DELAY_BUFFER = 500; // Buffer for timers on different OS platforms. |
|
21 |
|
22 const PROLONGED_ERROR_DURATION = |
|
23 (Svc.Prefs.get('errorhandler.networkFailureReportTimeout') * 2) * 1000; |
|
24 |
|
25 let errorHandler = Service.errorHandler; |
|
26 |
|
27 function setLastSync(lastSyncValue) { |
|
28 Svc.Prefs.set("lastSync", (new Date(Date.now() - lastSyncValue)).toString()); |
|
29 } |
|
30 |
|
31 function run_test() { |
|
32 initTestLogging("Trace"); |
|
33 |
|
34 Log.repository.getLogger("Sync.Service").level = Log.Level.Trace; |
|
35 Log.repository.getLogger("Sync.SyncScheduler").level = Log.Level.Trace; |
|
36 Log.repository.getLogger("Sync.ErrorHandler").level = Log.Level.Trace; |
|
37 |
|
38 run_next_test(); |
|
39 } |
|
40 |
|
41 add_test(function test_noOutput() { |
|
42 // Ensure that the log appender won't print anything. |
|
43 errorHandler._logAppender.level = Log.Level.Fatal + 1; |
|
44 |
|
45 // Clear log output from startup. |
|
46 Svc.Prefs.set("log.appender.file.logOnSuccess", false); |
|
47 Svc.Obs.notify("weave:service:sync:finish"); |
|
48 |
|
49 // Clear again without having issued any output. |
|
50 Svc.Prefs.set("log.appender.file.logOnSuccess", true); |
|
51 |
|
52 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { |
|
53 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); |
|
54 |
|
55 errorHandler._logAppender.level = Log.Level.Trace; |
|
56 Svc.Prefs.resetBranch(""); |
|
57 run_next_test(); |
|
58 }); |
|
59 |
|
60 // Fake a successful sync. |
|
61 Svc.Obs.notify("weave:service:sync:finish"); |
|
62 }); |
|
63 |
|
64 add_test(function test_logOnSuccess_false() { |
|
65 Svc.Prefs.set("log.appender.file.logOnSuccess", false); |
|
66 |
|
67 let log = Log.repository.getLogger("Sync.Test.FileLog"); |
|
68 log.info("this won't show up"); |
|
69 |
|
70 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { |
|
71 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); |
|
72 // No log file was written. |
|
73 do_check_false(logsdir.directoryEntries.hasMoreElements()); |
|
74 |
|
75 Svc.Prefs.resetBranch(""); |
|
76 run_next_test(); |
|
77 }); |
|
78 |
|
79 // Fake a successful sync. |
|
80 Svc.Obs.notify("weave:service:sync:finish"); |
|
81 }); |
|
82 |
|
83 function readFile(file, callback) { |
|
84 NetUtil.asyncFetch(file, function (inputStream, statusCode, request) { |
|
85 let data = NetUtil.readInputStreamToString(inputStream, |
|
86 inputStream.available()); |
|
87 callback(statusCode, data); |
|
88 }); |
|
89 } |
|
90 |
|
91 add_test(function test_logOnSuccess_true() { |
|
92 Svc.Prefs.set("log.appender.file.logOnSuccess", true); |
|
93 |
|
94 let log = Log.repository.getLogger("Sync.Test.FileLog"); |
|
95 const MESSAGE = "this WILL show up"; |
|
96 log.info(MESSAGE); |
|
97 |
|
98 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { |
|
99 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); |
|
100 |
|
101 // Exactly one log file was written. |
|
102 let entries = logsdir.directoryEntries; |
|
103 do_check_true(entries.hasMoreElements()); |
|
104 let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile); |
|
105 do_check_eq(logfile.leafName.slice(-4), ".txt"); |
|
106 do_check_eq(logfile.leafName.slice(0, LOG_PREFIX_SUCCESS.length), |
|
107 LOG_PREFIX_SUCCESS); |
|
108 do_check_false(entries.hasMoreElements()); |
|
109 |
|
110 // Ensure the log message was actually written to file. |
|
111 readFile(logfile, function (error, data) { |
|
112 do_check_true(Components.isSuccessCode(error)); |
|
113 do_check_neq(data.indexOf(MESSAGE), -1); |
|
114 |
|
115 // Clean up. |
|
116 try { |
|
117 logfile.remove(false); |
|
118 } catch(ex) { |
|
119 dump("Couldn't delete file: " + ex + "\n"); |
|
120 // Stupid Windows box. |
|
121 } |
|
122 |
|
123 Svc.Prefs.resetBranch(""); |
|
124 run_next_test(); |
|
125 }); |
|
126 }); |
|
127 |
|
128 // Fake a successful sync. |
|
129 Svc.Obs.notify("weave:service:sync:finish"); |
|
130 }); |
|
131 |
|
132 add_test(function test_sync_error_logOnError_false() { |
|
133 Svc.Prefs.set("log.appender.file.logOnError", false); |
|
134 |
|
135 let log = Log.repository.getLogger("Sync.Test.FileLog"); |
|
136 log.info("this won't show up"); |
|
137 |
|
138 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { |
|
139 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); |
|
140 // No log file was written. |
|
141 do_check_false(logsdir.directoryEntries.hasMoreElements()); |
|
142 |
|
143 Svc.Prefs.resetBranch(""); |
|
144 run_next_test(); |
|
145 }); |
|
146 |
|
147 // Fake an unsuccessful sync due to prolonged failure. |
|
148 setLastSync(PROLONGED_ERROR_DURATION); |
|
149 Svc.Obs.notify("weave:service:sync:error"); |
|
150 }); |
|
151 |
|
152 add_test(function test_sync_error_logOnError_true() { |
|
153 Svc.Prefs.set("log.appender.file.logOnError", true); |
|
154 |
|
155 let log = Log.repository.getLogger("Sync.Test.FileLog"); |
|
156 const MESSAGE = "this WILL show up"; |
|
157 log.info(MESSAGE); |
|
158 |
|
159 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { |
|
160 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); |
|
161 |
|
162 // Exactly one log file was written. |
|
163 let entries = logsdir.directoryEntries; |
|
164 do_check_true(entries.hasMoreElements()); |
|
165 let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile); |
|
166 do_check_eq(logfile.leafName.slice(-4), ".txt"); |
|
167 do_check_eq(logfile.leafName.slice(0, LOG_PREFIX_ERROR.length), |
|
168 LOG_PREFIX_ERROR); |
|
169 do_check_false(entries.hasMoreElements()); |
|
170 |
|
171 // Ensure the log message was actually written to file. |
|
172 readFile(logfile, function (error, data) { |
|
173 do_check_true(Components.isSuccessCode(error)); |
|
174 do_check_neq(data.indexOf(MESSAGE), -1); |
|
175 |
|
176 // Clean up. |
|
177 try { |
|
178 logfile.remove(false); |
|
179 } catch(ex) { |
|
180 dump("Couldn't delete file: " + ex + "\n"); |
|
181 // Stupid Windows box. |
|
182 } |
|
183 |
|
184 Svc.Prefs.resetBranch(""); |
|
185 run_next_test(); |
|
186 }); |
|
187 }); |
|
188 |
|
189 // Fake an unsuccessful sync due to prolonged failure. |
|
190 setLastSync(PROLONGED_ERROR_DURATION); |
|
191 Svc.Obs.notify("weave:service:sync:error"); |
|
192 }); |
|
193 |
|
194 add_test(function test_login_error_logOnError_false() { |
|
195 Svc.Prefs.set("log.appender.file.logOnError", false); |
|
196 |
|
197 let log = Log.repository.getLogger("Sync.Test.FileLog"); |
|
198 log.info("this won't show up"); |
|
199 |
|
200 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { |
|
201 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); |
|
202 // No log file was written. |
|
203 do_check_false(logsdir.directoryEntries.hasMoreElements()); |
|
204 |
|
205 Svc.Prefs.resetBranch(""); |
|
206 run_next_test(); |
|
207 }); |
|
208 |
|
209 // Fake an unsuccessful login due to prolonged failure. |
|
210 setLastSync(PROLONGED_ERROR_DURATION); |
|
211 Svc.Obs.notify("weave:service:login:error"); |
|
212 }); |
|
213 |
|
214 add_test(function test_login_error_logOnError_true() { |
|
215 Svc.Prefs.set("log.appender.file.logOnError", true); |
|
216 |
|
217 let log = Log.repository.getLogger("Sync.Test.FileLog"); |
|
218 const MESSAGE = "this WILL show up"; |
|
219 log.info(MESSAGE); |
|
220 |
|
221 Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { |
|
222 Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); |
|
223 |
|
224 // Exactly one log file was written. |
|
225 let entries = logsdir.directoryEntries; |
|
226 do_check_true(entries.hasMoreElements()); |
|
227 let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile); |
|
228 do_check_eq(logfile.leafName.slice(-4), ".txt"); |
|
229 do_check_eq(logfile.leafName.slice(0, LOG_PREFIX_ERROR.length), |
|
230 LOG_PREFIX_ERROR); |
|
231 do_check_false(entries.hasMoreElements()); |
|
232 |
|
233 // Ensure the log message was actually written to file. |
|
234 readFile(logfile, function (error, data) { |
|
235 do_check_true(Components.isSuccessCode(error)); |
|
236 do_check_neq(data.indexOf(MESSAGE), -1); |
|
237 |
|
238 // Clean up. |
|
239 try { |
|
240 logfile.remove(false); |
|
241 } catch(ex) { |
|
242 dump("Couldn't delete file: " + ex + "\n"); |
|
243 // Stupid Windows box. |
|
244 } |
|
245 |
|
246 Svc.Prefs.resetBranch(""); |
|
247 run_next_test(); |
|
248 }); |
|
249 }); |
|
250 |
|
251 // Fake an unsuccessful login due to prolonged failure. |
|
252 setLastSync(PROLONGED_ERROR_DURATION); |
|
253 Svc.Obs.notify("weave:service:login:error"); |
|
254 }); |
|
255 |
|
256 // Check that error log files are deleted above an age threshold. |
|
257 add_test(function test_logErrorCleanup_age() { |
|
258 _("Beginning test_logErrorCleanup_age."); |
|
259 let maxAge = CLEANUP_DELAY / 1000; |
|
260 let oldLogs = []; |
|
261 let numLogs = 10; |
|
262 let errString = "some error log\n"; |
|
263 |
|
264 Svc.Prefs.set("log.appender.file.logOnError", true); |
|
265 Svc.Prefs.set("log.appender.file.maxErrorAge", maxAge); |
|
266 |
|
267 _("Making some files."); |
|
268 for (let i = 0; i < numLogs; i++) { |
|
269 let now = Date.now(); |
|
270 let filename = LOG_PREFIX_ERROR + now + "" + i + ".txt"; |
|
271 let newLog = FileUtils.getFile("ProfD", ["weave", "logs", filename]); |
|
272 let foStream = FileUtils.openFileOutputStream(newLog); |
|
273 foStream.write(errString, errString.length); |
|
274 foStream.close(); |
|
275 _(" > Created " + filename); |
|
276 oldLogs.push(newLog.leafName); |
|
277 } |
|
278 |
|
279 Svc.Obs.add("weave:service:cleanup-logs", function onCleanupLogs() { |
|
280 Svc.Obs.remove("weave:service:cleanup-logs", onCleanupLogs); |
|
281 |
|
282 // Only the newest created log file remains. |
|
283 let entries = logsdir.directoryEntries; |
|
284 do_check_true(entries.hasMoreElements()); |
|
285 let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile); |
|
286 do_check_true(oldLogs.every(function (e) { |
|
287 return e != logfile.leafName; |
|
288 })); |
|
289 do_check_false(entries.hasMoreElements()); |
|
290 |
|
291 // Clean up. |
|
292 try { |
|
293 logfile.remove(false); |
|
294 } catch(ex) { |
|
295 dump("Couldn't delete file: " + ex + "\n"); |
|
296 // Stupid Windows box. |
|
297 } |
|
298 |
|
299 Svc.Prefs.resetBranch(""); |
|
300 run_next_test(); |
|
301 }); |
|
302 |
|
303 let delay = CLEANUP_DELAY + DELAY_BUFFER; |
|
304 |
|
305 _("Cleaning up logs after " + delay + "msec."); |
|
306 CommonUtils.namedTimer(function onTimer() { |
|
307 Svc.Obs.notify("weave:service:sync:error"); |
|
308 }, delay, this, "cleanup-timer"); |
|
309 }); |