Fix: Uncaught exceptions cause a silent exit #721

amad-person · 2019-02-21T02:23:08Z

What is the purpose of this pull request? (put "X" next to an item, remove the rest)

• [X] Bug fix

What is the rationale for this request?

Errors in building files with nunjucks (as well as uncaught exceptions) were causing a silent exit. This information should be shown to the user on the console. It was previously shown in the log file only.

What changes did you make? (Give an overview)

Added a new Console transport to winston for logging errors to the console.

Also passed the path parameter to nunjucks.renderString() as errors thrown by Nunjucks were not showing the file paths.

Provide some example code that this change will affect:

Add the following statement to any file:

<!-- the following will cause an exception in Nunjucks -->
{% set error = " %}

Console output on markbind build:

error: uncaughtException: (/Users/aadyaamaddi/Desktop/BComp/Semester 6 1819/CS3281:2/markbind/docs/about.md) [Line 14, Column 19]
  expected block end in set statement date=Thu Feb 21 2019 10:22:03 GMT+0800 (Singapore Standard Time), pid=32358, uid=501, gid=20, cwd=/Users/aadyaamaddi/Desktop/BComp/Semester 6 1819/CS3281:2/markbind/docs, execPath=/usr/local/Cellar/node/11.10.0/bin/node, version=v11.10.0, argv=[/usr/local/Cellar/node/11.10.0/bin/node, /usr/local/bin/markbind, build], rss=85471232, heapTotal=64253952, heapUsed=37254224, external=2661243, loadavg=[2.04248046875, 2.189453125, 2.33935546875], uptime=310221
Template render error: (/Users/aadyaamaddi/Desktop/BComp/Semester 6 1819/CS3281:2/markbind/docs/about.md) [Line 14, Column 19]
  expected block end in set statement
    at Object.exports.prettifyError (/Users/aadyaamaddi/Desktop/BComp/Semester 6 1819/CS3281:2/markbind/src/lib/markbind/node_modules/nunjucks/src/lib.js:34:15)
    at new_cls.render (/Users/aadyaamaddi/Desktop/BComp/Semester 6 1819/CS3281:2/markbind/src/lib/markbind/node_modules/nunjucks/src/environment.js:472:27)
    at new_cls.renderString (/Users/aadyaamaddi/Desktop/BComp/Semester 6 1819/CS3281:2/markbind/src/lib/markbind/node_modules/nunjucks/src/environment.js:328:21)
    at Object.module.exports.renderString (/Users/aadyaamaddi/Desktop/BComp/Semester 6 1819/CS3281:2/markbind/src/lib/markbind/node_modules/nunjucks/index.js:80:14)
    at fs.readFile (/Users/aadyaamaddi/Desktop/BComp/Semester 6 1819/CS3281:2/markbind/src/lib/markbind/src/parser.js:508:36)
    at FSReqCallback.readFileAfterClose [as oncomplete] (internal/fs/read_file_context.js:54:3)

src/lib/markbind/src/parser.js

acjh · 2019-02-21T04:57:26Z

src/util/logger.js

+      humanReadableUnhandledException: true,
+      level: 'error',
+      showLevel: true,
+    }),


Is this different from console.error? Should we remove that?

Do you mean from this line:

markbind/src/lib/markbind/src/parser.js

Line 82 in 1686253

this._onError = this._options.errorHandler || console.error;

No, this line:

markbind/src/util/logger.js

Line 33 in 669325b

console.log(chalk.red(`error: ${text}`));

The current mechanism of logging is as follows:

We are using logger.js functions to print messages to the console with console.log() statements and a winston-daily-rotate-file transport set to level debug that writes messages to a log file.

Nunjucks errors were not being logged to the console because we are not calling logger.error() explicitly in nunjucks.renderString() (as we don't have error handlers for these calls). Other errors do get printed to the console because we call logger.error() when we catch them.

However, nunjucks errors were being printed to the log file because of the winston-daily-rotate-file transport.

If we want to remove console.error (and other console.log statements in logger.js), then we should use the winston console transport with the level set to debug. There is an option to use custom formats (color, etc.) too.

Correct me if I am wrong, nunjucks is actually using winston-daily-rotate-file internally? I am struggling to see how the pieces are connected here.

Our application does use winston through the logger, but we have also configured winston to handle logging uncaught exceptions.

markbind/src/util/logger.js

Line 15 in 6bbe1fa

handleExceptions: true,

That's how nunjucks errors were being logged to the log file, because we don't have error handlers for the renderString() calls.

Thanks for checking this. It answers the question originally raised by @yamgent.

How about this?

Just tested this.

// index.js logger.error('hi');

console.log(chalk.red(`error: ${text}`)); // console.log(chalk.red(`error: ${text}`));

Let's set winston.transports.Console level to 'info' and then remove console.log in logger.error, logger.warn and logger.info.

Sorry for the confusion regarding the console.error reference! I didn't realise logger.error was using console.log.

Let's set winston.transports.Console level to 'info' and then remove console.log in logger.error, logger.warn and logger.info.

May I do these changes in this PR itself?

Yes please.

* Change winston's console logging level to info * Remove console.log statements from error, warn, info to avoid duplication in logs

yamgent · 2019-02-25T03:13:33Z

~~Console seems to be more noisy now though since we now print everything. :/~~

> markbind build
error: No config file found in parent directories of D:\GitHub\yamgent\markbind
error: uncaughtException: Path must be a string. Received undefined
TypeError: Path must be a string. Received undefined
    at assertPath (path.js:28:11)
    at Object.join (path.js:489:7)
    at Command.program.command.alias.option.description.action (D:\GitHub\yamgent\markbind\index.js:199:36)
    at Command.listener (D:\GitHub\yamgent\markbind\node_modules\commander\index.js:300:8)
    at emitTwo (events.js:126:13)
    at Command.emit (events.js:214:7)
    at Command.parseArgs (D:\GitHub\yamgent\markbind\node_modules\commander\index.js:635:12)
    at Command.parse (D:\GitHub\yamgent\markbind\node_modules\commander\index.js:457:21)
    at Object.<anonymous> (D:\GitHub\yamgent\markbind\index.js:210:9)
    at Module._compile (module.js:652:30)
    at Object.Module._extensions..js (module.js:663:10)
    at Module.load (module.js:565:32)
    at tryModuleLoad (module.js:505:12)
    at Function.Module._load (module.js:497:3)
    at Function.Module.runMain (module.js:693:10)
    at startup (bootstrap_node.js:191:16)

acjh · 2019-02-25T04:40:21Z

Is that an actual error?

amad-person · 2019-02-25T05:13:08Z

Is that an actual error?

Yep, it happens when you run markbind build in a directory with no site.json (or if the parent directory doesn't have a site.json).

yamgent · 2019-02-25T07:53:43Z

Is that an actual error?

Looks like I have accidentally discovered something worth fixing. :P Never mind my original comment then; I thought it was something that was previously printed on our own on the log.

amad-person added 2 commits February 21, 2019 09:53

Show errors on console

7a762a8

List winston options in alphabetical order

669325b

acjh reviewed Feb 21, 2019

View reviewed changes

amad-person added 2 commits February 21, 2019 13:14

Move second arg to new line in fileContent renderString

154e07c

Update logger

ab39039

* Change winston's console logging level to info * Remove console.log statements from error, warn, info to avoid duplication in logs

acjh approved these changes Feb 24, 2019

View reviewed changes

yamgent approved these changes Feb 25, 2019

View reviewed changes

yamgent added this to the v1.19.1 milestone Feb 25, 2019

yamgent merged commit a91b2de into MarkBind:master Feb 25, 2019

yamgent mentioned this pull request Mar 2, 2019

Fix missing space in log output #738

Closed

yamgent pushed a commit to yamgent/markbind that referenced this pull request Mar 8, 2019

Fix: Uncaught exceptions cause a silent exit (MarkBind#721)

06478c4

amad-person deleted the fix-silent-errors branch December 7, 2019 07:27

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix: Uncaught exceptions cause a silent exit #721

Fix: Uncaught exceptions cause a silent exit #721

amad-person commented Feb 21, 2019

acjh Feb 21, 2019

amad-person Feb 21, 2019

acjh Feb 21, 2019

amad-person Feb 21, 2019 •

edited

Loading

yamgent Feb 21, 2019 •

edited

Loading

amad-person Feb 22, 2019 •

edited

Loading

acjh Feb 22, 2019

acjh Feb 23, 2019

amad-person Feb 24, 2019 •

edited

Loading

acjh Feb 24, 2019

yamgent commented Feb 25, 2019 •

edited

Loading

acjh commented Feb 25, 2019

amad-person commented Feb 25, 2019 •

edited

Loading

yamgent commented Feb 25, 2019

Fix: Uncaught exceptions cause a silent exit #721

Fix: Uncaught exceptions cause a silent exit #721

Conversation

amad-person commented Feb 21, 2019

acjh Feb 21, 2019

Choose a reason for hiding this comment

amad-person Feb 21, 2019

Choose a reason for hiding this comment

acjh Feb 21, 2019

Choose a reason for hiding this comment

amad-person Feb 21, 2019 • edited Loading

Choose a reason for hiding this comment

yamgent Feb 21, 2019 • edited Loading

Choose a reason for hiding this comment

amad-person Feb 22, 2019 • edited Loading

Choose a reason for hiding this comment

acjh Feb 22, 2019

Choose a reason for hiding this comment

acjh Feb 23, 2019

Choose a reason for hiding this comment

amad-person Feb 24, 2019 • edited Loading

Choose a reason for hiding this comment

acjh Feb 24, 2019

Choose a reason for hiding this comment

yamgent commented Feb 25, 2019 • edited Loading

acjh commented Feb 25, 2019

amad-person commented Feb 25, 2019 • edited Loading

yamgent commented Feb 25, 2019

amad-person Feb 21, 2019 •

edited

Loading

yamgent Feb 21, 2019 •

edited

Loading

amad-person Feb 22, 2019 •

edited

Loading

amad-person Feb 24, 2019 •

edited

Loading

yamgent commented Feb 25, 2019 •

edited

Loading

amad-person commented Feb 25, 2019 •

edited

Loading