Improve error stack trace for errors in filters.

[jonaslagoni]

Reason/Context

When developing templates sometimes you make an implementation mistake in a filter could be a simple cannot call method of undefined, however when that happens we receive no information about where in the filter the error occurred. It sometimes takes a lot of time to figure out where the error is really located, and sometimes the only approach is step by step console log and comment out functionality.

As an example with the html template if you add a check to the following line such as obj.oneOf().length > 0 || it gives you the stack trace:

Something went wrong:
Template render error: (PATH@asyncapi\generator\node_modules\@asyncapi\html-template\template\index.html)
  Template render error: (PATH@asyncapi\generator\node_modules\@asyncapi\html-template\partials\content.html)
  Template render error: (PATH@asyncapi\generator\node_modules\@asyncapi\html-template\partials\operations.html)
  TypeError: Cannot read property 'length' of null
    at Object._prettifyError (PATH@asyncapi\generator\node_modules\nunjucks\src\lib.js:36:11)
    at PATH@asyncapi\generator\node_modules\nunjucks\src\environment.js:561:19
    at eval (eval at _compile (PATH@asyncapi\generator\node_modules\nunjucks\src\environment.js:631:18), <anonymous>:49:11)
    at PATH@asyncapi\generator\node_modules\nunjucks\src\environment.js:569:11
    at eval (eval at _compile (PATH@asyncapi\generator\node_modules\nunjucks\src\environment.js:631:18), <anonymous>:64:12)
    at PATH@asyncapi\generator\node_modules\nunjucks\src\environment.js:569:11
    at eval (eval at _compile (PATH@asyncapi\generator\node_modules\nunjucks\src\environment.js:631:18), <anonymous>:10:11)
    at PATH@asyncapi\generator\node_modules\nunjucks\src\environment.js:611:9
    at eval (eval at _compile (PATH@asyncapi\generator\node_modules\nunjucks\src\environment.js:631:18), <anonymous>:54:12)
    at PATH@asyncapi\generator\node_modules\nunjucks\src\environment.js:611:9
    at eval (eval at _compile (PATH@asyncapi\generator\node_modules\nunjucks\src\environment.js:631:18), <anonymous>:10:11)
    at PATH@asyncapi\generator\node_modules\nunjucks\src\environment.js:611:9
    at Template.root [as rootRenderFunc] (eval at _compile (PATH@asyncapi\generator\node_modules\nunjucks\src\environment.js:631:18), <anonymous>:75:3)
    at Template.getExported (PATH@asyncapi\generator\node_modules\nunjucks\src\environment.js:609:10)
    at eval (eval at _compile (PATH@asyncapi\generator\node_modules\nunjucks\src\environment.js:631:18), <anonymous>:9:5)
    at Environment.getTemplate (PATH@asyncapi\generator\node_modules\nunjucks\src\environment.js:277:9)

Which does not give you any information about where in the filter the error is located. This issue is based on the following Slack discussion: https://asyncapi.slack.com/archives/CQVJXFNQL/p1588245326200400

[derberg]

I tried to break filter in my sandbox where I work with AsyncAPI and Nunjucks in an environment without the generator -> https://codesandbox.io/s/learning-nunjucks-wis89

Same result

Template render error: (/sandbox/views/index.html)
  TypeError: Cannot read property 'length' of undefined
    at Object._prettifyError (/sandbox/node_modules/nunjucks/src/lib.js:36:11)
    at /sandbox/node_modules/nunjucks/src/environment.js:567:19
    at eval (eval at _compile (/sandbox/node_modules/nunjucks/src/environment.js:637:18), <anonymous>:12:11)
    at /sandbox/node_modules/nunjucks/src/environment.js:617:9
    at Template.root [as rootRenderFunc] (eval at _compile (/sandbox/node_modules/nunjucks/src/environment.js:637:18), <anonymous>:76:3)
    at Template.getExported (/sandbox/node_modules/nunjucks/src/environment.js:615:10)
    at eval (eval at _compile (/sandbox/node_modules/nunjucks/src/environment.js:637:18), <anonymous>:11:5)
    at createTemplate (/sandbox/node_modules/nunjucks/src/environment.js:315:9)
    at handle (/sandbox/node_modules/nunjucks/src/environment.js:327:11)
    at /sandbox/node_modules/nunjucks/src/environment.js:339:9

zero info what filter and where located was broken.

Digging into Nunjucks...

[derberg]

So far found https://github.com/mozilla/nunjucks/issues/1137 and https://github.com/mozilla/nunjucks/issues/975

I'm able to throw proper errors only if I do it from inside the filter, and console.log out the errors

function isExpandable(obj) {
    try {

        if (
            obj.type() === 'object' ||
            obj.oneOf().length > 0 ||
            obj.type() === 'array' ||
            (obj.oneOf() && obj.oneOf().length) ||
            (obj.anyOf() && obj.anyOf().length) ||
            (obj.allOf() && obj.allOf().length) ||
            obj.items() ||
            obj.additionalItems() ||
            (obj.properties() && Object.keys(obj.properties()).length) ||
            obj.additionalProperties() ||
            (obj.extensions() && Object.keys(obj.extensions()).filter(e => !e.startsWith('x-parser-')).length) ||
            obj.patternProperties()
        ) return true;

        return false;
    } catch (error) {
        console.log(error)
        process.exit(1)
    }
}

Then I get error:

TypeError: Cannot read property 'length' of null
    at Context.isExpandable (/Users/wookiee/Documents/sources/html-template/filters/all.js:9:16)
    at Object.eval (eval at _compile (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:631:18), <anonymous>:49:34)
    at Context.<anonymous> (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/runtime.js:131:17)
    at Object.callWrap (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/runtime.js:273:14)
    at Object.eval (eval at _compile (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:631:18), <anonymous>:139:87)
    at Context.<anonymous> (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/runtime.js:131:17)
    at Object.callWrap (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/runtime.js:273:14)
    at eval (eval at _compile (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:631:18), <anonymous>:71:88)
    at /Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:613:9
    at eval (eval at _compile (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:631:18), <anonymous>:228:1)

Pretty much what we need, but yeah, you have to manually add it to a specific filter 🤔

[jonaslagoni]

Yea figured we might end up with that as a temporary fix for now, at least until Nunjucks addresses the issue.

[derberg]

@jonaslagoni I think I got it, we only need to discuss on how to implement a fix, probably another flag.

So the thing is they have a hidden feature to configure Nunjucks that is not described here https://mozilla.github.io/nunjucks/api.html#configure You can set dev: true mode, which means if you change this line to

this.nunjucks = new Nunjucks.Environment(new Nunjucks.FileSystemLoader(this.templateDir),{dev: true});

The error you get is suddenly:

Something went wrong:
TypeError: Cannot read property 'length' of null
    at Context.isExpandable (/Users/wookiee/Documents/sources/html-template/filters/all.js:9:16)
    at Object.eval (eval at _compile (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:637:18), <anonymous>:49:34)
    at Context.<anonymous> (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/runtime.js:131:17)
    at Object.callWrap (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/runtime.js:273:14)
    at Object.eval (eval at _compile (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:637:18), <anonymous>:139:65)
    at Context.<anonymous> (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/runtime.js:131:17)
    at Object.callWrap (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/runtime.js:273:14)
    at eval (eval at _compile (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:637:18), <anonymous>:71:66)
    at /Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:619:9
    at eval (eval at _compile (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:637:18), <anonymous>:228:1)

It is like this because without dev flag they are prettifying the error like this. For them, filter-level errors are the internals that should be hidden from the user. It kind of makes sense, as a person that uses the template, feeds it with AsyncAPI and cares to get an error about the template and not filter. This is why I think that for us it should be enough to just enable usage of dev mode.

I'm out now, have to go to bed, too tired after beers 😄 Let me know what you think

[jonaslagoni]

Nice catch @derberg ! Quick question in which cases are the dev error message not better then the regular one? I mean the regular error message tells you nothing useful and when users create issues they will be harder to solve if the development error message is not provided.

[derberg]

the thing is that if I leave dev flag, the error made inside the template (not filter) looks like:

Something went wrong:
Error: expected symbol, got pipe
    at new TemplateError (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/lib.js:90:17)
    at Parser.error (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/parser.js:83:12)
    at Parser.fail (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/parser.js:88:16)
    at Parser.expect (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/parser.js:106:12)
    at Parser.parseFilterName (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/parser.js:1015:20)
    at Parser.parseFilter (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/parser.js:1038:23)
    at Parser.parseUnary (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/parser.js:959:19)
    at Parser.parsePow (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/parser.js:936:21)
    at Parser.parseMod (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/parser.js:925:21)
    at Parser.parseFloorDiv (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/parser.js:914:21)

which is much more useless than:

Something went wrong:
Template render error: (/Users/wookiee/Documents/sources/generator/node_modules/@asyncapi/html-template/template/index.html)
  Template render error: (/Users/wookiee/Documents/sources/generator/node_modules/@asyncapi/html-template/partials/content.html)
  Template render error: (/Users/wookiee/Documents/sources/generator/node_modules/@asyncapi/html-template/partials/operations.html) [Line 26, Column 26]
  expected symbol, got pipe
    at Object._prettifyError (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/lib.js:37:11)
    at /Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:567:19
    at eval (eval at _compile (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:639:18), <anonymous>:49:11)
    at /Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:577:11
    at eval (eval at _compile (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:639:18), <anonymous>:64:12)
    at /Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:577:11
    at eval (eval at _compile (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:639:18), <anonymous>:10:11)
    at /Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:619:9
    at eval (eval at _compile (/Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:639:18), <anonymous>:32:12)
    at /Users/wookiee/Documents/sources/generator/node_modules/nunjucks/src/environment.js:619:9

I really go now 😝

[derberg]

Created this in the upstream https://github.com/mozilla/nunjucks/issues/1287

[jonaslagoni]

Great! I think we should as a temporary fix add our own development flag / debug flag as you suggested since we have no idea when or if they will change it 😄

[derberg]

@jonaslagoni yeap, this is why I'm working on it at the moment 😄

[derberg]

@jonaslagoni PR ready https://github.com/asyncapi/generator/pull/327

I'd like to get more people here in the discussion as I have some doubts. Let's say in 2 months, theoretically, Nunjucks get a release that fixes errors and makes dev flag obsolete, what will we do with debug flag 🤔 removing is not nice as we will be with 1.0 release already and it will trigger us to do 2.0.... just 🤔 🔊 here

[jonaslagoni]

I mean, a debug flag can easily be used in regards to printing out more information from our own generator i.e. when file templates are used, print configurations used to launch the generator, what hooks are loaded, etc. to easy the debugging of issues, so no alarms from me. As long as we don't implement the debug flag ONLY for this exact issue 😄

[derberg]

@jonaslagoni if you already see other options for debug then awesome, my doubts go away and once we merge my PR just create a followup issue with things that we can add to it

[derberg]

@jonaslagoni debug merged in, you can add issues ;)

[github-actions[bot]]

This issue has been automatically marked as stale because it has not had recent activity :sleeping: It will be closed in 30 days if no further activity occurs. To unstale this issue, add a comment with detailed explanation. Thank you for your contributions :heart:

[derberg]

@jonaslagoni doesn't look like we can do more here, basically no response here mozilla/nunjucks#1287

[github-actions[bot]]

This issue has been automatically marked as stale because it has not had recent activity :sleeping: It will be closed in 30 days if no further activity occurs. To unstale this issue, add a comment with detailed explanation. Thank you for your contributions :heart:

[github-actions[bot]]

This issue has been automatically marked as stale because it has not had recent activity :sleeping: It will be closed in 30 days if no further activity occurs. To unstale this issue, add a comment with detailed explanation. Thank you for your contributions :heart:

[derberg]

@jonaslagoni I guess we can close this one or you want to keep it open until we are done with PoC on adding React as template engine?

[github-actions[bot]]

This issue has been automatically marked as stale because it has not had recent activity :sleeping: It will be closed in 60 days if no further activity occurs. To unstale this issue, add a comment with detailed explanation. Thank you for your contributions :heart:

[derberg]

Closing. Nunjucks render engine is not something we will invest in imho and the new React engine has everything that is needed already