test_tracer.js (17826B)
1 /* Any copyright is dedicated to the Public Domain. 2 http://creativecommons.org/publicdomain/zero/1.0/ */ 3 4 "use strict"; 5 6 const { JSTracer } = ChromeUtils.importESModule( 7 "resource://devtools/server/tracer/tracer.sys.mjs", 8 { global: "shared" } 9 ); 10 11 add_task(async function () { 12 // Because this test uses evalInSandbox, we need to tweak the following prefs 13 Services.prefs.setBoolPref( 14 "security.allow_parent_unrestricted_js_loads", 15 true 16 ); 17 registerCleanupFunction(() => { 18 Services.prefs.clearUserPref("security.allow_parent_unrestricted_js_loads"); 19 }); 20 }); 21 22 add_task(async function testTracingContentGlobal() { 23 const toggles = []; 24 const frames = []; 25 const listener = { 26 onTracingToggled(state) { 27 toggles.push(state); 28 }, 29 onTracingFrame(frameInfo) { 30 frames.push(frameInfo); 31 }, 32 }; 33 34 info("Register a tracing listener"); 35 JSTracer.addTracingListener(listener); 36 37 const sandbox = Cu.Sandbox("https://example.com"); 38 Cu.evalInSandbox("function bar() {}; function foo() {bar()};", sandbox); 39 40 info("Start tracing"); 41 JSTracer.startTracing({ global: sandbox, prefix: "testContentPrefix" }); 42 Assert.equal(toggles.length, 1); 43 Assert.equal(toggles[0], true); 44 45 info("Call some code"); 46 sandbox.foo(); 47 48 Assert.equal(frames.length, 2); 49 const lastFrame = frames.pop(); 50 const beforeLastFrame = frames.pop(); 51 Assert.equal(beforeLastFrame.depth, 0); 52 Assert.equal(beforeLastFrame.formatedDisplayName, "λ foo"); 53 Assert.equal(beforeLastFrame.prefix, "testContentPrefix: "); 54 Assert.ok(beforeLastFrame.frame); 55 Assert.equal(lastFrame.depth, 1); 56 Assert.equal(lastFrame.formatedDisplayName, "λ bar"); 57 Assert.equal(lastFrame.prefix, "testContentPrefix: "); 58 Assert.ok(lastFrame.frame); 59 60 info("Stop tracing"); 61 JSTracer.stopTracing(); 62 Assert.equal(toggles.length, 2); 63 Assert.equal(toggles[1], false); 64 65 info("Recall code after stop, no more traces are logged"); 66 sandbox.foo(); 67 Assert.equal(frames.length, 0); 68 69 info("Start tracing again, and recall code"); 70 JSTracer.startTracing({ global: sandbox, prefix: "testContentPrefix" }); 71 sandbox.foo(); 72 info("New traces are logged"); 73 Assert.equal(frames.length, 2); 74 75 info("Unregister the listener and recall code"); 76 JSTracer.removeTracingListener(listener); 77 sandbox.foo(); 78 info("No more traces are logged"); 79 Assert.equal(frames.length, 2); 80 81 info("Stop tracing"); 82 JSTracer.stopTracing(); 83 }); 84 85 add_task(async function testTracingJSMGlobal() { 86 // We have to register the listener code in a sandbox, i.e. in a distinct global 87 // so that we aren't creating traces when tracer calls it. (and cause infinite loops) 88 const systemPrincipal = Services.scriptSecurityManager.getSystemPrincipal(); 89 const listenerSandbox = Cu.Sandbox(systemPrincipal); 90 Cu.evalInSandbox( 91 "new " + 92 function () { 93 globalThis.toggles = []; 94 globalThis.frames = []; 95 globalThis.listener = { 96 onTracingToggled(state) { 97 globalThis.toggles.push(state); 98 }, 99 onTracingFrame(frameInfo) { 100 globalThis.frames.push(frameInfo); 101 }, 102 }; 103 }, 104 listenerSandbox 105 ); 106 107 info("Register a tracing listener"); 108 JSTracer.addTracingListener(listenerSandbox.listener); 109 110 info("Start tracing"); 111 JSTracer.startTracing({ global: null, prefix: "testPrefix" }); 112 Assert.equal(listenerSandbox.toggles.length, 1); 113 Assert.equal(listenerSandbox.toggles[0], true); 114 115 info("Call some code"); 116 function bar() {} 117 function foo() { 118 bar(); 119 } 120 foo(); 121 122 // Note that the tracer will record the two Assert.equal and the info calls. 123 // So only assert the last two frames. 124 const lastFrame = listenerSandbox.frames.at(-1); 125 const beforeLastFrame = listenerSandbox.frames.at(-2); 126 Assert.equal(beforeLastFrame.depth, 7); 127 Assert.equal(beforeLastFrame.formatedDisplayName, "λ foo"); 128 Assert.equal(beforeLastFrame.prefix, "testPrefix: "); 129 Assert.ok(beforeLastFrame.frame); 130 Assert.equal(lastFrame.depth, 8); 131 Assert.equal(lastFrame.formatedDisplayName, "λ bar"); 132 Assert.equal(lastFrame.prefix, "testPrefix: "); 133 Assert.ok(lastFrame.frame); 134 135 info("Stop tracing"); 136 JSTracer.stopTracing(); 137 Assert.equal(listenerSandbox.toggles.length, 2); 138 Assert.equal(listenerSandbox.toggles[1], false); 139 140 JSTracer.removeTracingListener(listenerSandbox.listener); 141 }); 142 143 add_task(async function testTracingValues() { 144 // Test the `traceValues` flag 145 const sandbox = Cu.Sandbox("https://example.com"); 146 Cu.evalInSandbox( 147 `function foo() { bar(-0, 1, ["array"], { attribute: 3 }, "4", BigInt(5), Symbol("6"), Infinity, undefined, null, false, NaN, function foo() {}, function () {}, class MyClass {}); }; function bar(a, b, c) {}`, 148 sandbox 149 ); 150 151 // Pass an override method to catch all strings tentatively logged to stdout 152 const logs = []; 153 function loggingMethod(str) { 154 logs.push(str); 155 } 156 157 info("Start tracing"); 158 JSTracer.startTracing({ global: sandbox, traceValues: true, loggingMethod }); 159 160 info("Call some code"); 161 sandbox.foo(); 162 163 Assert.equal(logs.length, 3); 164 Assert.equal(logs[0], "Start tracing JavaScript\n"); 165 Assert.stringContains(logs[1], "λ foo()"); 166 Assert.stringContains( 167 logs[2], 168 `λ bar(-0, 1, Array(1), [object Object], "4", BigInt(5), Symbol(6), Infinity, undefined, null, false, NaN, function foo(), function anonymous(), class MyClass)` 169 ); 170 171 info("Stop tracing"); 172 JSTracer.stopTracing(); 173 }); 174 175 add_task(async function testTracingFunctionReturn() { 176 // Test the `traceFunctionReturn` flag 177 const sandbox = Cu.Sandbox("https://example.com"); 178 Cu.evalInSandbox( 179 `function foo() { bar(); return 0 } function bar() { return "string" }; foo();`, 180 sandbox 181 ); 182 183 // Pass an override method to catch all strings tentatively logged to stdout 184 const logs = []; 185 function loggingMethod(str) { 186 logs.push(str); 187 } 188 189 info("Start tracing"); 190 JSTracer.startTracing({ 191 global: sandbox, 192 traceFunctionReturn: true, 193 loggingMethod, 194 }); 195 196 info("Call some code"); 197 sandbox.foo(); 198 199 Assert.equal(logs.length, 5); 200 Assert.equal(logs[0], "Start tracing JavaScript\n"); 201 Assert.stringContains(logs[1], "λ foo"); 202 Assert.stringContains(logs[2], "λ bar"); 203 Assert.stringContains(logs[3], `λ bar return`); 204 Assert.stringContains(logs[4], "λ foo return"); 205 206 info("Stop tracing"); 207 JSTracer.stopTracing(); 208 }); 209 210 add_task(async function testTracingFunctionReturnAndValues() { 211 // Test the `traceFunctionReturn` and `traceValues` flag 212 const sandbox = Cu.Sandbox("https://example.com"); 213 Cu.evalInSandbox( 214 `function foo() { bar(); second(); } function bar() { return "string" }; function second() { return null; }; foo();`, 215 sandbox 216 ); 217 218 // Pass an override method to catch all strings tentatively logged to stdout 219 const logs = []; 220 function loggingMethod(str) { 221 logs.push(str); 222 } 223 224 info("Start tracing"); 225 JSTracer.startTracing({ 226 global: sandbox, 227 traceFunctionReturn: true, 228 traceValues: true, 229 loggingMethod, 230 }); 231 232 info("Call some code"); 233 sandbox.foo(); 234 235 Assert.equal(logs.length, 7); 236 Assert.equal(logs[0], "Start tracing JavaScript\n"); 237 Assert.stringContains(logs[1], "λ foo()"); 238 Assert.stringContains(logs[2], "λ bar()"); 239 Assert.stringContains(logs[3], `λ bar return "string"`); 240 Assert.stringContains(logs[4], "λ second()"); 241 Assert.stringContains(logs[5], `λ second return null`); 242 Assert.stringContains(logs[6], "λ foo return undefined"); 243 244 info("Stop tracing"); 245 JSTracer.stopTracing(); 246 }); 247 248 add_task(async function testTracingStep() { 249 // Test the `traceStep` flag 250 const sandbox = Cu.Sandbox("https://example.com"); 251 const source = ` 252 function foo() { 253 bar(); /* line 3 */ 254 second(); /* line 4 */ 255 dump("foo\\n"); 256 } 257 function bar() { 258 let res; /* line 8 */ 259 if (1 === 1) { /* line 9 */ 260 res = "string"; /* line 10 */ 261 } else { 262 res = "nope" 263 } 264 return res; /* line 14 */ 265 }; 266 function second() { 267 let x = 0; /* line 17 */ 268 for (let i = 0; i < 2; i++) { /* line 18 */ 269 x++; /* line 19 */ 270 } 271 return null; /* line 21 */ 272 }; 273 foo();`; 274 Cu.evalInSandbox(source, sandbox, null, "file.js", 1); 275 276 // Pass an override method to catch all strings tentatively logged to stdout 277 const logs = []; 278 function loggingMethod(str) { 279 logs.push(str); 280 } 281 282 info("Start tracing"); 283 JSTracer.startTracing({ 284 global: sandbox, 285 traceSteps: true, 286 loggingMethod, 287 }); 288 289 info("Call some code"); 290 sandbox.foo(); 291 292 Assert.equal(logs.length, 19); 293 Assert.equal(logs[0], "Start tracing JavaScript\n"); 294 Assert.stringContains(logs[1], "λ foo"); 295 Assert.stringContains(logs[1], "file.js:3:3"); 296 297 Assert.stringContains(logs[2], "λ bar"); 298 Assert.stringContains(logs[2], "file.js:7:16"); 299 300 // Each "step" only prints the location and nothing more 301 Assert.stringContains(logs[3], "file.js:9:7"); 302 303 Assert.stringContains(logs[4], "file.js:10:5"); 304 305 Assert.stringContains(logs[5], "file.js:14:3"); 306 307 Assert.stringContains(logs[6], "file.js:4:3"); 308 309 Assert.stringContains(logs[7], "λ second"); 310 Assert.stringContains(logs[7], "file.js:16:19"); 311 312 Assert.stringContains(logs[8], "file.js:17:11"); 313 314 // For loop 315 Assert.stringContains(logs[9], "file.js:18:16"); 316 317 Assert.stringContains(logs[10], "file.js:18:19"); 318 319 Assert.stringContains(logs[11], "file.js:19:5"); 320 321 Assert.stringContains(logs[12], "file.js:18:26"); 322 323 Assert.stringContains(logs[13], "file.js:18:19"); 324 325 Assert.stringContains(logs[14], "file.js:19:5"); 326 327 Assert.stringContains(logs[15], "file.js:18:26"); 328 329 Assert.stringContains(logs[16], "file.js:18:19"); 330 // End of for loop 331 332 Assert.stringContains(logs[17], "file.js:21:3"); 333 334 Assert.stringContains(logs[18], "file.js:5:3"); 335 info("Stop tracing"); 336 JSTracer.stopTracing(); 337 }); 338 339 add_task(async function testTracingPauseOnStep() { 340 // Test the `pauseOnStep` flag 341 const sandbox = Cu.Sandbox("https://example.com"); 342 sandbox.dump = dump; 343 const source = `var counter = 0; function incrementCounter() { let x = 0; dump("++\\n"); counter++; };`; 344 Cu.evalInSandbox(source, sandbox); 345 346 // Pass an override method to catch all strings tentatively logged to stdout 347 const logs = []; 348 let loggingMethodResolve; 349 function loggingMethod(str) { 350 logs.push(str); 351 if (loggingMethodResolve) { 352 loggingMethodResolve(); 353 } 354 } 355 356 info("Start tracing without pause"); 357 JSTracer.startTracing({ 358 global: sandbox, 359 loggingMethod, 360 }); 361 362 info("Call some code"); 363 sandbox.incrementCounter(); 364 365 Assert.equal(logs.length, 2); 366 Assert.equal(logs[0], "Start tracing JavaScript\n"); 367 Assert.stringContains(logs[1], "λ incrementCounter"); 368 369 info( 370 "When pauseOnStep isn't used, the traced code runs synchronously to completion" 371 ); 372 Assert.equal(sandbox.counter, 1); 373 374 info("Stop tracing"); 375 JSTracer.stopTracing(); 376 377 logs.length = 0; 378 sandbox.counter = 0; 379 380 info("Start tracing with 0ms pause"); 381 JSTracer.startTracing({ 382 global: sandbox, 383 pauseOnStep: 0, 384 loggingMethod, 385 }); 386 387 let onTraces = Promise.withResolvers(); 388 let onResumed = Promise.withResolvers(); 389 // This is used when receiving new traces in `loggingMethod()` 390 loggingMethodResolve = onTraces.resolve; 391 392 info( 393 "Run the to-be-traced code in a distinct event loop as it would be paused synchronously and would prevent further test script execution" 394 ); 395 Services.tm.dispatchToMainThread(() => { 396 sandbox.incrementCounter(); 397 onResumed.resolve(); 398 }); 399 400 info("Wait for tracer to call the listener"); 401 await onTraces.promise; 402 403 Assert.equal(logs.length, 2); 404 Assert.equal(logs[0], "Start tracing JavaScript\n"); 405 Assert.stringContains(logs[1], "λ incrementCounter"); 406 407 info( 408 "When pauseInStep is used, the tracer listener is called, but the traced function is paused and doesn't run synchronously to completion" 409 ); 410 Assert.equal( 411 sandbox.counter, 412 0, 413 "The increment method was called but its execution flow was blocked and couldn't increment" 414 ); 415 416 info("Wait for traced code to be resumed"); 417 await onResumed.promise; 418 info( 419 "If we release the event loop, we can see the traced function completion" 420 ); 421 Assert.equal(sandbox.counter, 1); 422 423 info("Stop tracing"); 424 JSTracer.stopTracing(); 425 426 logs.length = 0; 427 sandbox.counter = 0; 428 429 info("Start tracing with 250ms pause"); 430 JSTracer.startTracing({ 431 global: sandbox, 432 pauseOnStep: 250, 433 loggingMethod, 434 }); 435 436 onTraces = Promise.withResolvers(); 437 onResumed = Promise.withResolvers(); 438 // This is used when receiving new traces in `loggingMethod()` 439 loggingMethodResolve = onTraces.resolve; 440 441 info( 442 "Run the to-be-traced code in a distinct event loop as it would be paused synchronously and would prevent further test script execution" 443 ); 444 const startTimestamp = ChromeUtils.now(); 445 Services.tm.dispatchToMainThread(() => { 446 sandbox.incrementCounter(); 447 onResumed.resolve(); 448 }); 449 450 info("Wait for tracer to call the listener"); 451 await onTraces.promise; 452 453 Assert.equal(logs.length, 2); 454 Assert.equal(logs[0], "Start tracing JavaScript\n"); 455 Assert.stringContains(logs[1], "λ incrementCounter"); 456 457 info( 458 "When pauseInStep is used, the tracer lsitener is called, but the traced function is paused and doesn't run synchronously to completion" 459 ); 460 Assert.equal(sandbox.counter, 0); 461 462 info("Wait for traced code to be resumed"); 463 await onResumed.promise; 464 info( 465 "If we release the event loop, we can see the traced function completion" 466 ); 467 Assert.equal(sandbox.counter, 1); 468 info("The thread should have paused at least the pauseOnStep's duration"); 469 Assert.greater(ChromeUtils.now() - startTimestamp, 250); 470 471 info("Stop tracing"); 472 JSTracer.stopTracing(); 473 }); 474 475 add_task(async function testTracingFilterSourceUrl() { 476 // Test the `filterFrameSourceUrl` flag 477 const sandbox = Cu.Sandbox("https://example.com"); 478 479 // Use a unique global (sandbox), but with two distinct scripts (first.js and second.js) 480 const source1 = `function foo() { bar(); }`; 481 Cu.evalInSandbox(source1, sandbox, null, "first.js", 1); 482 483 // Only code running in that second source should be traced. 484 const source2 = `function bar() { }`; 485 Cu.evalInSandbox(source2, sandbox, null, "second.js", 1); 486 487 // Pass an override method to catch all strings tentatively logged to stdout 488 const logs = []; 489 function loggingMethod(str) { 490 logs.push(str); 491 } 492 493 info("Start tracing"); 494 JSTracer.startTracing({ 495 global: sandbox, 496 filterFrameSourceUrl: "second", 497 loggingMethod, 498 }); 499 500 info("Call some code"); 501 sandbox.foo(); 502 503 Assert.equal(logs.length, 2); 504 Assert.equal(logs[0], "Start tracing JavaScript\n"); 505 Assert.stringContains(logs[1], "λ bar"); 506 Assert.stringContains(logs[1], "second.js:1:18"); 507 508 info("Stop tracing"); 509 JSTracer.stopTracing(); 510 }); 511 512 add_task(async function testTracingAllGlobals() { 513 // Test the `traceAllGlobals` flag 514 515 // Create two distinct globals in order to verify that both are traced 516 const sandbox1 = Cu.Sandbox("https://example.com"); 517 const sandbox2 = Cu.Sandbox("https://example.com"); 518 519 const source1 = `function foo() { bar(); }`; 520 Cu.evalInSandbox(source1, sandbox1, null, "sandbox1.js", 1); 521 522 const source2 = `function bar() { }`; 523 Cu.evalInSandbox(source2, sandbox2, null, "sandbox2.js", 1); 524 // Expose `bar` from sandbox2 as global in sandbox1, so that `foo` from sandbox1 can call it. 525 sandbox1.bar = sandbox2.bar; 526 527 // Pass an override method to catch all strings tentatively logged to stdout 528 // 529 // But in this test, we have to evaluate it in a special sandbox which will be ignored by the tracer. 530 // Otherwise, the tracer would do an infinite loop on this loggingMethod. 531 const ignoredGlobal = new Cu.Sandbox(null, { invisibleToDebugger: true }); 532 const loggingMethodString = ` 533 var logs = []; 534 function loggingMethod(str) { 535 logs.push(str); 536 }; 537 `; 538 Cu.evalInSandbox( 539 loggingMethodString, 540 ignoredGlobal, 541 null, 542 "loggin-method.js", 543 1 544 ); 545 const { loggingMethod, logs } = ignoredGlobal; 546 547 info("Start tracing on all globals"); 548 JSTracer.startTracing({ 549 traceAllGlobals: true, 550 loggingMethod, 551 }); 552 553 // Call some code while being careful to not call anything else which may be traced 554 sandbox1.foo(); 555 556 JSTracer.stopTracing(); 557 558 Assert.equal(logs.length, 4); 559 Assert.equal(logs[0], "Start tracing JavaScript\n"); 560 Assert.stringContains(logs[1], "λ foo"); 561 Assert.stringContains(logs[1], "sandbox1.js:1:18"); 562 Assert.stringContains(logs[2], "λ bar"); 563 Assert.stringContains(logs[2], "sandbox2.js:1:18"); 564 Assert.equal(logs[3], "Stop tracing JavaScript\n"); 565 }); 566 567 add_task(async function testTracingInfiniteLoop() { 568 // Test that the tracer handles infinite loops 569 const sandbox = Cu.Sandbox("https://example.com"); 570 Cu.evalInSandbox( 571 `function foo() { bar(); }; function bar() { foo() };`, 572 sandbox 573 ); 574 575 // Pass an override method to catch all strings tentatively logged to stdout 576 const logs = []; 577 function loggingMethod(str) { 578 logs.push(str); 579 } 580 581 info("Start tracing"); 582 JSTracer.startTracing({ 583 global: sandbox, 584 loggingMethod, 585 }); 586 587 info("Call some code"); 588 try { 589 sandbox.foo(); 590 Assert.fail("Should have thrown error because of infinite loop"); 591 } catch (e) { 592 Assert.equal(e.message, "too much recursion"); 593 } 594 595 Assert.greater(logs.length, 1000); 596 Assert.equal(logs[0], "Start tracing JavaScript\n"); 597 598 // This will stop logging trace once spidermonkey stopped the execution 599 Assert.stringContains(logs[1], "λ foo"); 600 Assert.stringContains(logs[2], "λ bar"); 601 Assert.stringContains(logs[3], "λ foo"); 602 Assert.stringContains(logs[4], "λ bar"); 603 Assert.stringContains(logs[5], "λ foo"); 604 605 info("Stop tracing"); 606 JSTracer.stopTracing(); 607 });