dfinity / motoko

Simple high-level language for writing Internet Computer canisters
Apache License 2.0
517 stars 97 forks source link

Print call stack on error #4253

Open ZenVoich opened 1 year ago

ZenVoich commented 1 year ago

Hi, I'm working on expect library, that helps to test and print expected/actual values in case of error.

I've run into a problem, that when I use assert or Debug.trap from a helper function I cannot get a stack trace to show in which test file(and which line and column) the error occured.

For example expect.test.mo:

let n = 20;
assert n == 22;

I get ./test/expect.test.mo:71.2-71.16: execution error, assertion failure error, so I parse it with mops and show failed line as follows:

 FAIL test/expect.test.mo:71:2: execution error, assertion failure
   ...
   70   |   let n = 20;
-> 71   |   assert n == 22;
   72   | 
   ...

also user can click on test/expect.test.mo:71:2 and navigate to the failed line in code editor.

But when I use helper function and fail inside that function:

let n = 20;
expect.int(n).equal(22);

I get this error:

I want to get a call stack trace and find *.test.mo:row.col-row.col to show it to the user.

Tried --error-detail 3 - no luck.

Using moc -r

crusso commented 1 year ago

Sorry about the delay, I only just noticed the issue.

moc -r runs the interpreter. The interpreter doesn't build an explicit stack so its hard to construct a trace and it would probably make it even less efficient if it maintained an explicit stack.

You might get a more meaningful stack trace running the (-wasi-system-api compiled) code in wasmtime, if you can.

The way asserts report traps is by reporting the physical source location of the assert. If you abstract several asserts into a function, the asserts will always be reported in the body of that function, because that's where the assert now takes place.

One thing you could play with is moc -r -t, which prints a trace of function calls during execution, but that might be more information than you want to show.

It's feasible that we could modify that functionality to construct a stack trace, shown only on error, but I'd have to revisit the code...

ZenVoich commented 1 year ago

Tried -t flag.

For example, I have ex.mo with assert helpers(where we trap) and te.mo with actual test.

ex.mo

import Debug "mo:base/Debug";
import Error "mo:base/Error";

module {
    public func printAssert() {
        let x = 1 + 2;
        Debug.print("print then assert");
        assert false;
    };

    public func trap() {
        Debug.trap("trappp");
    };

    public func reject() : async () {
        throw Error.reject("rejjj");
    };
};

te.mo

import Ex "ex";

Ex.printAssert();
// Ex.trap();
// await Ex.reject();

Output for assert false

printAssert()
  print("print then assert")
    debugPrint("print then assert")
print then assert
      <= ()
    <= ()
ex.mo:8.3-8.15: execution error, assertion failure

trap

trap()
  trap("trappp")
    trap("trappp")
prim:62.31-62.42: execution error, explicit trap: trappp

reject

reject()
  -> async ex.mo:15.34-17.3
  <= async _
=> await te.mo:5.1-5.18
<- async ex.mo:15.34-17.3
  error("rejjj")
    <= (#canister_reject, "rejjj")
<- await te.mo:5.1-5.18 threw (#canister_reject, "rejjj")
prim:299.3-299.47: execution error, uncaught throw

The problem is that there is no filename:line.column for trap and assert.

For reject there is <- await te.mo:5.1-5.18 threw (#canister_reject, "rejjj") which is helpful, but most of unit tests are not async. It would helpful if it will print filename:line.column for sync calls too.

Also would be cool to have one standard output format filename:line.column (where is it placed in line) for sync and async calls.

And it would be helpful to distinguish between the trace output line and the line printed by Debug.print, so I could run tests with -t flag in mops and filter out trace messages and show to user only Debug.print messages. Maybe start each line with TRACE or something like that...