test_structuredlog.js (5325B)
1 /* Any copyright is dedicated to the Public Domain. 2 http://creativecommons.org/publicdomain/zero/1.0/ */ 3 4 const { StructuredLogger } = ChromeUtils.importESModule( 5 "resource://testing-common/StructuredLog.sys.mjs" 6 ); 7 8 add_task(function test_StructuredLogger() { 9 let testBuffer = []; 10 11 let appendBuffer = function (msg) { 12 testBuffer.push(JSON.stringify(msg)); 13 }; 14 15 let assertLastMsg = function (refData) { 16 // Check all fields in refData agree with those in the 17 // last message logged, and pop that message. 18 let lastMsg = JSON.parse(testBuffer.pop()); 19 for (let field in refData) { 20 deepEqual(lastMsg[field], refData[field]); 21 } 22 // The logger should always set the source to the logger name. 23 equal(lastMsg.source, "test_log"); 24 }; 25 26 let logger = new StructuredLogger("test_log", appendBuffer); 27 28 // Test unstructured logging 29 logger.info("Test message"); 30 assertLastMsg({ 31 action: "log", 32 message: "Test message", 33 level: "INFO", 34 }); 35 36 logger.info("Test message", { foo: "bar" }); 37 assertLastMsg({ 38 action: "log", 39 message: "Test message", 40 level: "INFO", 41 extra: { foo: "bar" }, 42 }); 43 44 // Test end / start actions 45 logger.testStart("aTest"); 46 assertLastMsg({ 47 test: "aTest", 48 action: "test_start", 49 }); 50 51 logger.testEnd("aTest", "OK"); 52 assertLastMsg({ 53 test: "aTest", 54 action: "test_end", 55 status: "OK", 56 }); 57 58 // A failed test populates the "expected" field. 59 logger.testStart("aTest"); 60 logger.testEnd("aTest", "FAIL", "PASS"); 61 assertLastMsg({ 62 action: "test_end", 63 test: "aTest", 64 status: "FAIL", 65 expected: "PASS", 66 }); 67 68 // A failed test populates the "expected" field. 69 logger.testStart("aTest"); 70 logger.testEnd("aTest", "FAIL", "PASS", null, "Many\nlines\nof\nstack\n"); 71 assertLastMsg({ 72 action: "test_end", 73 test: "aTest", 74 status: "FAIL", 75 expected: "PASS", 76 stack: "Many\nlines\nof\nstack\n", 77 }); 78 79 // Skipped tests don't log failures 80 logger.testStart("aTest"); 81 logger.testEnd("aTest", "SKIP", "PASS"); 82 ok(!JSON.parse(testBuffer[testBuffer.length - 1]).hasOwnProperty("expected")); 83 assertLastMsg({ 84 action: "test_end", 85 test: "aTest", 86 status: "SKIP", 87 }); 88 89 logger.testStatus("aTest", "foo", "PASS", "PASS", "Passed test"); 90 ok(!JSON.parse(testBuffer[testBuffer.length - 1]).hasOwnProperty("expected")); 91 assertLastMsg({ 92 action: "test_status", 93 test: "aTest", 94 subtest: "foo", 95 status: "PASS", 96 message: "Passed test", 97 }); 98 99 logger.testStatus("aTest", "bar", "FAIL"); 100 assertLastMsg({ 101 action: "test_status", 102 test: "aTest", 103 subtest: "bar", 104 status: "FAIL", 105 expected: "PASS", 106 }); 107 108 logger.testStatus( 109 "aTest", 110 "bar", 111 "FAIL", 112 "PASS", 113 null, 114 "Many\nlines\nof\nstack\n" 115 ); 116 assertLastMsg({ 117 action: "test_status", 118 test: "aTest", 119 subtest: "bar", 120 status: "FAIL", 121 expected: "PASS", 122 stack: "Many\nlines\nof\nstack\n", 123 }); 124 125 // Skipped tests don't log failures 126 logger.testStatus("aTest", "baz", "SKIP"); 127 ok(!JSON.parse(testBuffer[testBuffer.length - 1]).hasOwnProperty("expected")); 128 assertLastMsg({ 129 action: "test_status", 130 test: "aTest", 131 subtest: "baz", 132 status: "SKIP", 133 }); 134 135 // Suite start and end messages. 136 var ids = { aManifest: ["aTest"] }; 137 logger.suiteStart(ids); 138 assertLastMsg({ 139 action: "suite_start", 140 tests: { aManifest: ["aTest"] }, 141 }); 142 143 logger.suiteEnd(); 144 assertLastMsg({ 145 action: "suite_end", 146 }); 147 }); 148 149 add_task(function test_StructuredLogger_with_dumpScope() { 150 let testBuffer = []; 151 let appendBuffer2 = msg => { 152 testBuffer.push(msg); 153 }; 154 155 let assertSeenMsg = (expected, checkExtra) => { 156 const { action, message, level, extra } = testBuffer.shift(); 157 deepEqual({ action, message, level }, expected); 158 ok(checkExtra(extra), `Extra: ${uneval(extra)}`); 159 }; 160 161 // Regression test for bug 2007587: Logger gracefully handles clone failures. 162 let logger2 = new StructuredLogger("test_dump", appendBuffer2, globalThis); 163 const extraNotCloneable = { notCloneable: () => {} }; 164 logger2.info("Test non-cloneable", extraNotCloneable); 165 166 assertSeenMsg( 167 { 168 action: "log", 169 message: 170 "Failed to cloneInto: Error: Permission denied to pass a Function via structured clone", 171 level: "ERROR", 172 }, 173 extra => extra === undefined 174 ); 175 176 testBuffer[0].message = testBuffer[0].message.replace(/time:\d+/, "time:123"); 177 assertSeenMsg( 178 { 179 action: "log", 180 message: `Tried to clone: ({action:"log", time:123, thread:null, pid:null, source:"test_dump", level:"INFO", message:"Test non-cloneable", extra:{notCloneable:() => {}}})`, 181 level: "WARNING", 182 }, 183 extra => extra === undefined 184 ); 185 186 assertSeenMsg( 187 { action: "log", message: "Test non-cloneable", level: "INFO" }, 188 extra => extra === extraNotCloneable 189 ); 190 191 // Now verify the most common / desired behavior: clone where possible. 192 const extraCloneable = { cloneable: "Yes I am" }; 193 logger2.info("Test cloneable", extraCloneable); 194 195 assertSeenMsg( 196 { action: "log", message: "Test cloneable", level: "INFO" }, 197 extra => { 198 deepEqual(extra, extraCloneable); 199 return extra !== extraCloneable; 200 } 201 ); 202 203 equal(testBuffer.length, 0, "No messages unaccounted for"); 204 });