The Tor Browser / file comparison

comparison: toolkit/modules/tests/xpcshell/test_Log.js

toolkit/modules/tests/xpcshell/test_Log.js

changeset 0
6474c204b198
equal deleted inserted replaced
-1:000000000000 0:9032a0ec2688
1 /* Any copyright is dedicated to the Public Domain.
2 http://creativecommons.org/publicdomain/zero/1.0/ */
3
4 const {utils: Cu} = Components;
5
6 Cu.import("resource://gre/modules/NetUtil.jsm");
7 Cu.import("resource://gre/modules/osfile.jsm");
8
9 Cu.import("resource://gre/modules/Log.jsm");
10
11 let testFormatter = {
12 format: function format(message) {
13 return message.loggerName + "\t" +
14 message.levelDesc + "\t" +
15 message.message;
16 }
17 };
18
19 function MockAppender(formatter) {
20 Log.Appender.call(this, formatter);
21 this.messages = [];
22 }
23 MockAppender.prototype = {
24 __proto__: Log.Appender.prototype,
25
26 doAppend: function DApp_doAppend(message) {
27 this.messages.push(message);
28 }
29 };
30
31 function run_test() {
32 run_next_test();
33 }
34
35 add_task(function test_Logger() {
36 let log = Log.repository.getLogger("test.logger");
37 let appender = new MockAppender(new Log.BasicFormatter());
38
39 log.level = Log.Level.Debug;
40 appender.level = Log.Level.Info;
41 log.addAppender(appender);
42 log.info("info test");
43 log.debug("this should be logged but not appended.");
44
45 do_check_eq(appender.messages.length, 1);
46
47 let msgRe = /\d+\ttest.logger\t\INFO\tinfo test/;
48 do_check_true(msgRe.test(appender.messages[0]));
49 });
50
51 add_task(function test_Logger_parent() {
52 // Check whether parenting is correct
53 let grandparentLog = Log.repository.getLogger("grandparent");
54 let childLog = Log.repository.getLogger("grandparent.parent.child");
55 do_check_eq(childLog.parent.name, "grandparent");
56
57 let parentLog = Log.repository.getLogger("grandparent.parent");
58 do_check_eq(childLog.parent.name, "grandparent.parent");
59
60 // Check that appends are exactly in scope
61 let gpAppender = new MockAppender(new Log.BasicFormatter());
62 gpAppender.level = Log.Level.Info;
63 grandparentLog.addAppender(gpAppender);
64 childLog.info("child info test");
65 Log.repository.rootLogger.info("this shouldn't show up in gpAppender");
66
67 do_check_eq(gpAppender.messages.length, 1);
68 do_check_true(gpAppender.messages[0].indexOf("child info test") > 0);
69 });
70
71 add_test(function test_LoggerWithMessagePrefix() {
72 let log = Log.repository.getLogger("test.logger.prefix");
73 let appender = new MockAppender(new Log.MessageOnlyFormatter());
74 log.addAppender(appender);
75
76 let prefixed = Log.repository.getLoggerWithMessagePrefix(
77 "test.logger.prefix", "prefix: ");
78
79 log.warn("no prefix");
80 prefixed.warn("with prefix");
81
82 Assert.equal(appender.messages.length, 2, "2 messages were logged.");
83 Assert.deepEqual(appender.messages, [
84 "no prefix",
85 "prefix: with prefix",
86 ], "Prefix logger works.");
87
88 run_next_test();
89 });
90
91 /*
92 * A utility method for checking object equivalence.
93 * Fields with a reqular expression value in expected will be tested
94 * against the corresponding value in actual. Otherwise objects
95 * are expected to have the same keys and equal values.
96 */
97 function checkObjects(expected, actual) {
98 do_check_true(expected instanceof Object);
99 do_check_true(actual instanceof Object);
100 for (let key in expected) {
101 do_check_neq(actual[key], undefined);
102 if (expected[key] instanceof RegExp) {
103 do_check_true(expected[key].test(actual[key].toString()));
104 } else {
105 if (expected[key] instanceof Object) {
106 checkObjects(expected[key], actual[key]);
107 } else {
108 do_check_eq(expected[key], actual[key]);
109 }
110 }
111 }
112
113 for (let key in actual) {
114 do_check_neq(expected[key], undefined);
115 }
116 }
117
118 add_task(function test_StructuredLogCommands() {
119 let appender = new MockAppender(new Log.StructuredFormatter());
120 let logger = Log.repository.getLogger("test.StructuredOutput");
121 logger.addAppender(appender);
122 logger.level = Log.Level.Info;
123
124 logger.logStructured("test_message", {_message: "message string one"});
125 logger.logStructured("test_message", {_message: "message string two",
126 _level: "ERROR",
127 source_file: "test_Log.js"});
128 logger.logStructured("test_message");
129 logger.logStructured("test_message", {source_file: "test_Log.js",
130 message_position: 4});
131
132 let messageOne = {"_time": /\d+/,
133 "_namespace": "test.StructuredOutput",
134 "_level": "INFO",
135 "_message": "message string one",
136 "action": "test_message"};
137
138 let messageTwo = {"_time": /\d+/,
139 "_namespace": "test.StructuredOutput",
140 "_level": "ERROR",
141 "_message": "message string two",
142 "action": "test_message",
143 "source_file": "test_Log.js"};
144
145 let messageThree = {"_time": /\d+/,
146 "_namespace": "test.StructuredOutput",
147 "_level": "INFO",
148 "action": "test_message"};
149
150 let messageFour = {"_time": /\d+/,
151 "_namespace": "test.StructuredOutput",
152 "_level": "INFO",
153 "action": "test_message",
154 "source_file": "test_Log.js",
155 "message_position": 4};
156
157 checkObjects(messageOne, JSON.parse(appender.messages[0]));
158 checkObjects(messageTwo, JSON.parse(appender.messages[1]));
159 checkObjects(messageThree, JSON.parse(appender.messages[2]));
160 checkObjects(messageFour, JSON.parse(appender.messages[3]));
161
162 let errored = false;
163 try {
164 logger.logStructured("", {_message: "invalid message"});
165 } catch (e) {
166 errored = true;
167 do_check_eq(e, "An action is required when logging a structured message.");
168 } finally {
169 do_check_true(errored);
170 }
171
172 let errored = false;
173 try {
174 logger.logStructured("message_action", "invalid params");
175 } catch (e) {
176 errored = true;
177 do_check_eq(e, "The params argument is required to be an object.");
178 } finally {
179 do_check_true(errored);
180 }
181
182 // Logging with unstructured interface should produce the same messages
183 // as the structured interface for these cases.
184 let appender = new MockAppender(new Log.StructuredFormatter());
185 let logger = Log.repository.getLogger("test.StructuredOutput1");
186 messageOne._namespace = "test.StructuredOutput1";
187 messageTwo._namespace = "test.StructuredOutput1";
188 logger.addAppender(appender);
189 logger.level = Log.Level.All;
190 logger.info("message string one", {action: "test_message"});
191 logger.error("message string two", {action: "test_message",
192 source_file: "test_Log.js"});
193
194 checkObjects(messageOne, JSON.parse(appender.messages[0]));
195 checkObjects(messageTwo, JSON.parse(appender.messages[1]));
196 });
197
198 add_task(function test_StorageStreamAppender() {
199 let appender = new Log.StorageStreamAppender(testFormatter);
200 do_check_eq(appender.getInputStream(), null);
201
202 // Log to the storage stream and verify the log was written and can be
203 // read back.
204 let logger = Log.repository.getLogger("test.StorageStreamAppender");
205 logger.addAppender(appender);
206 logger.info("OHAI");
207 let inputStream = appender.getInputStream();
208 let data = NetUtil.readInputStreamToString(inputStream,
209 inputStream.available());
210 do_check_eq(data, "test.StorageStreamAppender\tINFO\tOHAI\n");
211
212 // We can read it again even.
213 let sndInputStream = appender.getInputStream();
214 let sameData = NetUtil.readInputStreamToString(sndInputStream,
215 sndInputStream.available());
216 do_check_eq(data, sameData);
217
218 // Reset the appender and log some more.
219 appender.reset();
220 do_check_eq(appender.getInputStream(), null);
221 logger.debug("wut?!?");
222 inputStream = appender.getInputStream();
223 data = NetUtil.readInputStreamToString(inputStream,
224 inputStream.available());
225 do_check_eq(data, "test.StorageStreamAppender\tDEBUG\twut?!?\n");
226 });
227
228 function fileContents(path) {
229 let decoder = new TextDecoder();
230 return OS.File.read(path).then(array => {
231 return decoder.decode(array);
232 });
233 }
234
235 add_task(function test_FileAppender() {
236 // This directory does not exist yet
237 let dir = OS.Path.join(do_get_profile().path, "test_Log");
238 do_check_false(yield OS.File.exists(dir));
239 let path = OS.Path.join(dir, "test_FileAppender");
240 let appender = new Log.FileAppender(path, testFormatter);
241 let logger = Log.repository.getLogger("test.FileAppender");
242 logger.addAppender(appender);
243
244 // Logging to a file that can't be created won't do harm.
245 do_check_false(yield OS.File.exists(path));
246 logger.info("OHAI!");
247
248 yield OS.File.makeDir(dir);
249 logger.info("OHAI");
250 yield appender._lastWritePromise;
251
252 do_check_eq((yield fileContents(path)),
253 "test.FileAppender\tINFO\tOHAI\n");
254
255 logger.info("OHAI");
256 yield appender._lastWritePromise;
257
258 do_check_eq((yield fileContents(path)),
259 "test.FileAppender\tINFO\tOHAI\n" +
260 "test.FileAppender\tINFO\tOHAI\n");
261
262 // Reset the appender and log some more.
263 yield appender.reset();
264 do_check_false(yield OS.File.exists(path));
265
266 logger.debug("O RLY?!?");
267 yield appender._lastWritePromise;
268 do_check_eq((yield fileContents(path)),
269 "test.FileAppender\tDEBUG\tO RLY?!?\n");
270
271 yield appender.reset();
272 logger.debug("1");
273 logger.info("2");
274 logger.info("3");
275 logger.info("4");
276 logger.info("5");
277 // Waiting on only the last promise should account for all of these.
278 yield appender._lastWritePromise;
279
280 // Messages ought to be logged in order.
281 do_check_eq((yield fileContents(path)),
282 "test.FileAppender\tDEBUG\t1\n" +
283 "test.FileAppender\tINFO\t2\n" +
284 "test.FileAppender\tINFO\t3\n" +
285 "test.FileAppender\tINFO\t4\n" +
286 "test.FileAppender\tINFO\t5\n");
287 });
288
289 add_task(function test_BoundedFileAppender() {
290 let dir = OS.Path.join(do_get_profile().path, "test_Log");
291 let path = OS.Path.join(dir, "test_BoundedFileAppender");
292 // This appender will hold about two lines at a time.
293 let appender = new Log.BoundedFileAppender(path, testFormatter, 40);
294 let logger = Log.repository.getLogger("test.BoundedFileAppender");
295 logger.addAppender(appender);
296
297 logger.info("ONE");
298 logger.info("TWO");
299 yield appender._lastWritePromise;
300
301 do_check_eq((yield fileContents(path)),
302 "test.BoundedFileAppender\tINFO\tONE\n" +
303 "test.BoundedFileAppender\tINFO\tTWO\n");
304
305 logger.info("THREE");
306 logger.info("FOUR");
307
308 do_check_neq(appender._removeFilePromise, undefined);
309 yield appender._removeFilePromise;
310 yield appender._lastWritePromise;
311
312 do_check_eq((yield fileContents(path)),
313 "test.BoundedFileAppender\tINFO\tTHREE\n" +
314 "test.BoundedFileAppender\tINFO\tFOUR\n");
315
316 yield appender.reset();
317 logger.info("ONE");
318 logger.info("TWO");
319 logger.info("THREE");
320 logger.info("FOUR");
321
322 do_check_neq(appender._removeFilePromise, undefined);
323 yield appender._removeFilePromise;
324 yield appender._lastWritePromise;
325
326 do_check_eq((yield fileContents(path)),
327 "test.BoundedFileAppender\tINFO\tTHREE\n" +
328 "test.BoundedFileAppender\tINFO\tFOUR\n");
329
330 });
331
332 /*
333 * Test parameter formatting.
334 */
335 add_task(function log_message_with_params() {
336 let formatter = new Log.BasicFormatter();
337
338 function formatMessage(text, params) {
339 let full = formatter.format(new Log.LogMessage("test.logger", Log.Level.Warn, text, params));
340 return full.split("\t")[3];
341 }
342
343 // Strings are substituted directly.
344 do_check_eq(formatMessage("String is ${foo}", {foo: "bar"}),
345 "String is bar");
346
347 // Numbers are substituted.
348 do_check_eq(formatMessage("Number is ${number}", {number: 47}),
349 "Number is 47")
350
351 // The entire params object is JSON-formatted and substituted.
352 do_check_eq(formatMessage("Object is ${}", {foo: "bar"}),
353 'Object is {"foo":"bar"}');
354
355 // An object nested inside params is JSON-formatted and substituted.
356 do_check_eq(formatMessage("Sub object is ${sub}", {sub: {foo: "bar"}}),
357 'Sub object is {"foo":"bar"}');
358
359 // The substitution field is missing from params. Leave the placeholder behind
360 // to make the mistake obvious.
361 do_check_eq(formatMessage("Missing object is ${missing}", {}),
362 'Missing object is ${missing}');
363
364 // Make sure we don't treat the parameter name 'false' as a falsey value.
365 do_check_eq(formatMessage("False is ${false}", {false: true}),
366 'False is true');
367
368 // If an object has a .toJSON method, the formatter uses it.
369 let ob = function() {};
370 ob.toJSON = function() {return {sneaky: "value"}};
371 do_check_eq(formatMessage("JSON is ${sub}", {sub: ob}),
372 'JSON is {"sneaky":"value"}');
373
374 // Fall back to .toSource() if JSON.stringify() fails on an object.
375 let ob = function() {};
376 ob.toJSON = function() {throw "oh noes JSON"};
377 do_check_eq(formatMessage("Fail is ${sub}", {sub: ob}),
378 'Fail is (function () {})');
379
380 // Fall back to .toString if both .toJSON and .toSource fail.
381 ob.toSource = function() {throw "oh noes SOURCE"};
382 do_check_eq(formatMessage("Fail is ${sub}", {sub: ob}),
383 'Fail is function () {}');
384
385 // Fall back to '[object]' if .toJSON, .toSource and .toString fail.
386 ob.toString = function() {throw "oh noes STRING"};
387 do_check_eq(formatMessage("Fail is ${sub}", {sub: ob}),
388 'Fail is [object]');
389
390 // If params are passed but there are no substitution in the text
391 // we JSON format and append the entire parameters object.
392 do_check_eq(formatMessage("Text with no subs", {a: "b", c: "d"}),
393 'Text with no subs: {"a":"b","c":"d"}');
394
395 // If we substitute one parameter but not the other,
396 // we ignore any params that aren't substituted.
397 do_check_eq(formatMessage("Text with partial sub ${a}", {a: "b", c: "d"}),
398 'Text with partial sub b');
399
400 // We don't format internal fields stored in params.
401 do_check_eq(formatMessage("Params with _ ${}", {a: "b", _c: "d", _level:20, _message:"froo",
402 _time:123456, _namespace:"here.there"}),
403 'Params with _ {"a":"b","_c":"d"}');
404
405 // Don't print an empty params holder if all params are internal.
406 do_check_eq(formatMessage("All params internal", {_level:20, _message:"froo",
407 _time:123456, _namespace:"here.there"}),
408 'All params internal');
409
410 // Format params with null and undefined values.
411 do_check_eq(formatMessage("Null ${n} undefined ${u}", {n: null, u: undefined}),
412 'Null null undefined undefined');
413
414 // Format params with number, bool, and Object/String type.
415 do_check_eq(formatMessage("number ${n} boolean ${b} boxed Boolean ${bx} String ${s}",
416 {n: 45, b: false, bx: new Boolean(true), s: new String("whatevs")}),
417 'number 45 boolean false boxed Boolean true String whatevs');
418
419 /*
420 * Check that errors get special formatting if they're formatted directly as
421 * a named param or they're the only param, but not if they're a field in a
422 * larger structure.
423 */
424 let err = Components.Exception("test exception", Components.results.NS_ERROR_FAILURE);
425 let str = formatMessage("Exception is ${}", err);
426 do_check_true(str.contains('Exception is [Exception... "test exception"'));
427 do_check_true(str.contains("(NS_ERROR_FAILURE)"));
428 let str = formatMessage("Exception is", err);
429 do_check_true(str.contains('Exception is: [Exception... "test exception"'));
430 let str = formatMessage("Exception is ${error}", {error: err});
431 do_check_true(str.contains('Exception is [Exception... "test exception"'));
432 let str = formatMessage("Exception is", {_error: err});
433 do_print(str);
434 // Exceptions buried inside objects are formatted badly.
435 do_check_true(str.contains('Exception is: {"_error":{}'));
436 // If the message text is null, the message contains only the formatted params object.
437 let str = formatMessage(null, err);
438 do_check_true(str.startsWith('[Exception... "test exception"'));
439 // If the text is null and 'params' is a String object, the message is exactly that string.
440 let str = formatMessage(null, new String("String in place of params"));
441 do_check_eq(str, "String in place of params");
442
443 // We use object.valueOf() internally; make sure a broken valueOf() method
444 // doesn't cause the logger to fail.
445 let vOf = {a: 1, valueOf: function() {throw "oh noes valueOf"}};
446 do_check_eq(formatMessage("Broken valueOf ${}", vOf),
447 'Broken valueOf ({a:1, valueOf:(function () {throw "oh noes valueOf"})})');
448
449 // Test edge cases of bad data to formatter:
450 // If 'params' is not an object, format it as a basic type.
451 do_check_eq(formatMessage("non-object no subst", 1),
452 'non-object no subst: 1');
453 do_check_eq(formatMessage("non-object all subst ${}", 2),
454 'non-object all subst 2');
455 // If 'params' is not an object, no named substitutions can succeed;
456 // therefore we leave the placeholder and append the formatted params.
457 do_check_eq(formatMessage("non-object named subst ${junk} space", 3),
458 'non-object named subst ${junk} space: 3');
459 // If there are no params, we leave behind the placeholders in the text.
460 do_check_eq(formatMessage("no params ${missing}", undefined),
461 'no params ${missing}');
462 // If params doesn't contain any of the tags requested in the text,
463 // we leave them all behind and append the formatted params.
464 do_check_eq(formatMessage("object missing tag ${missing} space", {mising: "not here"}),
465 'object missing tag ${missing} space: {"mising":"not here"}');
466 // If we are given null text and no params, the resulting formatted message is empty.
467 do_check_eq(formatMessage(null), '');
468 });
469
470 /*
471 * If we call a log function with a non-string object in place of the text
472 * argument, and no parameters, treat that the same as logging empty text
473 * with the object argument as parameters. This makes the log useful when the
474 * caller does "catch(err) {logger.error(err)}"
475 */
476 add_task(function test_log_err_only() {
477 let log = Log.repository.getLogger("error.only");
478 let testFormatter = { format: msg => msg };
479 let appender = new MockAppender(testFormatter);
480 log.addAppender(appender);
481
482 /*
483 * Check that log.error(err) is treated the same as
484 * log.error(null, err) by the logMessage constructor; the formatMessage()
485 * tests above ensure that the combination of null text and an error object
486 * is formatted correctly.
487 */
488 try {
489 eval("javascript syntax error");
490 }
491 catch (e) {
492 log.error(e);
493 msg = appender.messages.pop();
494 do_check_eq(msg.message, null);
495 do_check_eq(msg.params, e);
496 }
497 });
498
499 /*
500 * Test logStructured() messages through basic formatter.
501 */
502 add_task(function test_structured_basic() {
503 let log = Log.repository.getLogger("test.logger");
504 let appender = new MockAppender(new Log.BasicFormatter());
505
506 log.level = Log.Level.Info;
507 appender.level = Log.Level.Info;
508 log.addAppender(appender);
509
510 // A structured entry with no _message is treated the same as log./level/(null, params)
511 // except the 'action' field is added to the object.
512 log.logStructured("action", {data: "structure"});
513 do_check_eq(appender.messages.length, 1);
514 do_check_true(appender.messages[0].contains('{"data":"structure","action":"action"}'));
515
516 // A structured entry with _message and substitution is treated the same as
517 // log./level/(null, params).
518 log.logStructured("action", {_message: "Structured sub ${data}", data: "structure"});
519 do_check_eq(appender.messages.length, 2);
520 do_print(appender.messages[1]);
521 do_check_true(appender.messages[1].contains('Structured sub structure'));
522 });
523
524 /*
525 * Test that all the basic logger methods pass the message and params through to the appender.
526 */
527 add_task(function log_message_with_params() {
528 let log = Log.repository.getLogger("error.logger");
529 let testFormatter = { format: msg => msg };
530 let appender = new MockAppender(testFormatter);
531 log.addAppender(appender);
532
533 let testParams = {a:1, b:2};
534 log.fatal("Test fatal", testParams);
535 log.error("Test error", testParams);
536 log.warn("Test warn", testParams);
537 log.info("Test info", testParams);
538 log.config("Test config", testParams);
539 log.debug("Test debug", testParams);
540 log.trace("Test trace", testParams);
541 do_check_eq(appender.messages.length, 7);
542 for (let msg of appender.messages) {
543 do_check_true(msg.params === testParams);
544 do_check_true(msg.message.startsWith("Test "));
545 }
546 });
547
548 /*
549 * Check that we format JS Errors reasonably.
550 */
551 add_task(function format_errors() {
552 let pFormat = new Log.ParameterFormatter();
553
554 // Test that subclasses of Error are recognized as errors.
555 err = new ReferenceError("Ref Error", "ERROR_FILE", 28);
556 str = pFormat.format(err);
557 do_check_true(str.contains("ReferenceError"));
558 do_check_true(str.contains("ERROR_FILE:28"));
559 do_check_true(str.contains("Ref Error"));
560
561 // Test that JS-generated Errors are recognized and formatted.
562 try {
563 eval("javascript syntax error");
564 }
565 catch (e) {
566 str = pFormat.format(e);
567 do_check_true(str.contains("SyntaxError: missing ;"));
568 // Make sure we identified it as an Error and formatted the error location as
569 // lineNumber:columnNumber.
570 do_check_true(str.contains(":1:11)"));
571 }
572 });

Mercurial Repository: The Tor Browser

Europalab SCM Repository Server

mercurial