Deno.test: shorter stack traces

[mfulton26]

Deno.test currently prints the entire stack for errors in failures but this is typically unnecessary and is noise (unless you're troubleshooting deno test itself).

I suggest omitting deno-cli-specific stack information and, if needed, provide an opt-in flag for printing the entire stack but to not print it by default.

This should make it easier for developers to understand why their tests failed and not be concerned about Deno's internal runtime details, etc.

e.g.

import { fail } from "https://deno.land/[email protected]/testing/asserts.ts";

Deno.test("example", () => fail());

current output:

% deno test test.ts
running 1 test from file:///path/to/test.ts
test example ... FAILED (8ms)

failures:

example
AssertionError: Failed assertion.
    at assert (https://deno.land/[email protected]/testing/asserts.ts:222:11)
    at fail (https://deno.land/[email protected]/testing/asserts.ts:597:3)
    at file:///path/to/test.ts:3:28
    at testStepSanitizer (deno:runtime/js/40_testing.js:186:13)
    at asyncOpSanitizer (deno:runtime/js/40_testing.js:67:15)
    at resourceSanitizer (deno:runtime/js/40_testing.js:137:13)
    at Object.exitSanitizer [as fn] (deno:runtime/js/40_testing.js:169:15)
    at runTest (deno:runtime/js/40_testing.js:427:18)
    at Object.runTests (deno:runtime/js/40_testing.js:540:28)
    at [deno:cli/tools/test.rs:505:6]:1:21

failures:

        example

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out (24ms)

error: Test failed

desired output:

% deno test test.ts
running 1 test from file:///path/to/test.ts
test example ... FAILED (8ms)

failures:

example
AssertionError: Failed assertion.
    at assert (https://deno.land/[email protected]/testing/asserts.ts:222:11)
    at fail (https://deno.land/[email protected]/testing/asserts.ts:597:3)
    at file:///path/to/test.ts:3:28

failures:

        example

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out (24ms)

error: Test failed

diff:

--- a.txt	2022-02-03 07:45:54.000000000 -0600
+++ b.txt	2022-02-03 07:46:04.000000000 -0600
@@ -9,13 +9,6 @@
     at assert (https://deno.land/[email protected]/testing/asserts.ts:222:11)
     at fail (https://deno.land/[email protected]/testing/asserts.ts:597:3)
     at file:///path/to/test.ts:3:28
-    at testStepSanitizer (deno:runtime/js/40_testing.js:186:13)
-    at asyncOpSanitizer (deno:runtime/js/40_testing.js:67:15)
-    at resourceSanitizer (deno:runtime/js/40_testing.js:137:13)
-    at Object.exitSanitizer [as fn] (deno:runtime/js/40_testing.js:169:15)
-    at runTest (deno:runtime/js/40_testing.js:427:18)
-    at Object.runTests (deno:runtime/js/40_testing.js:540:28)
-    at [deno:cli/tools/test.rs:505:6]:1:21
 
 failures:
 

[lucacasonato]

I have actually previously proposed we do this for all stack traces in the runtime (remove all stack entries coming from deno: source files), and only show them if DENO_STACKTRACES=full is used. I remember there being some pushback on that. I think it makes sense if we at least do this for testing though. The excessively long stack traces have always frustrated me too.

[lucasfcosta]

Personally, I think this would be a great idea.

A long time ago, I've written in detail about how chai does this.

This also seems like it's quite common behaviour everywhere else in the JS ecosystem. For reference, Jest also does it.

I'd be happy to contribute with this feature if maintainers do decide to go forward with it (in case they'd be happy for me to do so) 😊

[bartlomieju]

@lucasfcosta yes, this is desired behavior. If you'd like to work on it then great, PRs are always greatly appreciated!

[lucasfcosta]

I believe we can close this one because the desired behaviour has already been implemented.

It seems to be implemented through the op below which is called when formatting a callsite:

deno/cli/fmt_errors.rs

Lines 41 to 68 in 6fad5c3

	// Keep in sync with `/core/error.js`.
	pub fn format_location(frame: &JsStackFrame) -> String {
	let _internal = frame
	.file_name
	.as_ref()
	.map_or(false, |f| f.starts_with("deno:"));
	if frame.is_native {
	return cyan("native").to_string();
	}
	let mut result = String::new();
	let file_name = frame.file_name.clone().unwrap_or_default();
	if !file_name.is_empty() {
	result += &cyan(&format_file_name(&file_name)).to_string();
	} else {
	if frame.is_eval {
	result +=
	&(cyan(&frame.eval_origin.as_ref().unwrap()).to_string() + ", ");
	}
	result += &cyan("<anonymous>").to_string();
	}
	if let Some(line_number) = frame.line_number {
	result += &format!("{}{}", ":", yellow(&line_number.to_string()));
	if let Some(column_number) = frame.column_number {
	result += &format!("{}{}", ":", yellow(&column_number.to_string()));
	}
	}
	result
	}

We may want to implement this behaviour only when a particular flag is set though.

Also, I double-checked that internal frames are indeed cut-off by running the following two tests, one with deno test and the other with deno run (in this order).

function t() {
  throw new Error("example");
}

t();

import { fail } from "https://deno.land/[email protected]/testing/asserts.ts";

Deno.test("example", () => fail());

No internal frames appeared in both cases.

[bartlomieju]

Ah I was looking for this issue but couldn't find it. Indeed this issue was fixed by #14302

[dandv]

I've created a related feature request in #27553 and would welcome feedback.