ValYouW / njsTrace

A Node.js tracing and instrumentation utility
MIT License
366 stars 41 forks source link

Error instrumenting OWASP's juice-shop #17

Closed christophschw closed 5 years ago

christophschw commented 5 years ago

Hey, thank you for offering such a nice project! I appreciate the work you do with this module.

Currently, I'm trying to integrate njstrace in OWASP's juice-shop for a student project (Novice here – sorry ;)). I wrote a custom logger which works fine when I don't trace the node_modules. But when I do, it get following error:

(node:65302) UnhandledPromiseRejectionWarning: /Users/de1630871/Spielwiese/juice-shop/node_modules/graceful-fs/graceful-fs.js:595

var njsTmp9244 = fs$ReadStream.apply(this, arguments), this; ^^^^

SyntaxError: Unexpected token this at new Script (vm.js:80:7) at createScript (vm.js:274:10) at Object.runInThisContext (vm.js:326:10) at Module._compile (internal/modules/cjs/loader.js:664:28) at Module._compile (/Users/de1630871/Spielwiese/juice-shop/node_modules/njstrace/njsTrace.js:158:15) at Object.Module._extensions..js (internal/modules/cjs/loader.js:712:10) at Module.load (internal/modules/cjs/loader.js:600:32) at tryModuleLoad (internal/modules/cjs/loader.js:539:12) at Function.Module._load (internal/modules/cjs/loader.js:531:3) at Module.require (internal/modules/cjs/loader.js:637:17) (node:65302) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1) (node:65302) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

I forked the juice-shop-repo and made a minimal working version of the project: https://github.com/christophschw/juice-shop

The formatter / chainloader: https://github.com/christophschw/juice-shop/blob/master/njstrace.js Comment out line 50 and it works ...

And the npm script is npm run start:njstrace

Thank you for your help!

ValYouW commented 5 years ago

Hi, seems like a bug where njstrace is not handling return statements that uses the comma operator.

Since you mentioned you're a student I'll elaborate :) You can see it is complaining about graceful-fs.js, open that file and look for function ReadStream, in that method you can see a quite unusual "return" statement: return fs$ReadStream.apply(this, arguments), this It uses the comma operator in the return statement, quite bad IMHO, basically it evaluates fs$ReadStream.apply(this, arguments) and return this.

When njstrace inject itself into code it stores the "Return" value in some temporary variable, do the tracing stuff, and return the value stored in the temporary variable. So the above "return" statement is modified by njstrace to:

var __njsTmp523__ = fs$ReadStream.apply(this, arguments), this;
__njsTraceExit__({entryData: __njsEntryData__, exception: false, line: 262, returnValue: __njsTmp523__});
return __njsTmp523__;

And as you can see, the first line above, which tries to store the original "return" statement in temp variable, is invalid - BUG. The fix is obviously to wrap the entire return statement in parenthesis: var __njsTmp523__ = (fs$ReadStream.apply(this, arguments), this;)

I will need to fix this, test, and release a new version, hopefully will find time for that soon...

christophschw commented 5 years ago

Thank you very much for looking into this and the detailed answer! This is very helpful for me.

I tried to workaround by skipping all affected modules this way:

    var njstrace = require('njstrace').inject({
        files: ["**/*.js", "!**/graceful-fs/**", "!**/bowser/**", "!**/batch/**", "!**/eventemitter3/**"],
        formatter: new TSVFormatter()
    });

Now, I received following error:

(node:18978) UnhandledPromiseRejectionWarning: SyntaxError: Identifier 'validate' has already been declared
    at /Users/de1630871/Spielwiese/juice-shop/node_modules/json-schema/lib/validate.js:43:26
    at Object.<anonymous> (/Users/de1630871/Spielwiese/juice-shop/node_modules/json-schema/lib/validate.js:54:2)
    at Module._compile (internal/modules/cjs/loader.js:701:30)
    at Module._compile (/Users/de1630871/Spielwiese/juice-shop/node_modules/njstrace/njsTrace.js:158:15)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:712:10)
    at Module.load (internal/modules/cjs/loader.js:600:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:539:12)
    at Function.Module._load (internal/modules/cjs/loader.js:531:3)
    at Module.require (internal/modules/cjs/loader.js:637:17)
    at require (internal/modules/cjs/helpers.js:22:18)
    at Object.<anonymous> (/Users/de1630871/Spielwiese/juice-shop/node_modules/jsprim/lib/jsprim.js:11:22)
    at Module._compile (internal/modules/cjs/loader.js:701:30)
    at Module._compile (/Users/de1630871/Spielwiese/juice-shop/node_modules/njstrace/njsTrace.js:158:15)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:712:10)
    at Module.load (internal/modules/cjs/loader.js:600:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:539:12)
    at Function.Module._load (internal/modules/cjs/loader.js:531:3)
    at Module.require (internal/modules/cjs/loader.js:637:17)
    at require (internal/modules/cjs/helpers.js:22:18)
    at Object.<anonymous> (/Users/de1630871/Spielwiese/juice-shop/node_modules/http-signature/lib/signer.js:9:14)
    at Module._compile (internal/modules/cjs/loader.js:701:30)
    at Module._compile (/Users/de1630871/Spielwiese/juice-shop/node_modules/njstrace/njsTrace.js:158:15)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:712:10)
    at Module.load (internal/modules/cjs/loader.js:600:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:539:12)
    at Function.Module._load (internal/modules/cjs/loader.js:531:3)
    at Module.require (internal/modules/cjs/loader.js:637:17)
    at require (internal/modules/cjs/helpers.js:22:18)
(node:18978) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
(node:18978) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

Tomorrow, I try to better understand the second error, but maybe this is already helpful for you.

Again, thank you!

ValYouW commented 5 years ago

I guess njstrace is modifying the code of node_modules/json-schema/lib/validate.js which results invalid javascript, I'll have to see why (and on the way handle all these unhandeled errors and better log the error...). From my personal experience, it's quite a mess to trace all node_modules, the main purpose of this module is to trace your own code...

christophschw commented 5 years ago

Yes, I know, but for this project it is crucial to trace even node_modules... I think, those two issues are the only ones for juice-shop's node_modules.

FYI: It is about anomaly detection in Node.js applications. I want to compare method calls of benign use and those of intrusions. Therefore, I instrument vulnerable applications :) So this module is a huge ease to master that project.

ValYouW commented 5 years ago

Fixed the first issue. The second issue is not something I can fix, what happens is that in json-schema/lib/validate.js there is a redeclaration of some variable, which is OK when it happens on top-level, but since njstrace wrap all function in try-catch that redeclaration is not top-level anymore and that's invalid syntax. What you can do is pass wrapFunctions: false in njstrace options, that will not wrap all functions in try-catch

christophschw commented 5 years ago

Hey @ValYouW, thank your very much for the fix and the explanation! I'll try it. If you send me your PayPal via mail I'll buy you a virtual beer or something you'd like :)

ValYouW commented 5 years ago

@christophschw Thank you! it's very kind of you, but that's ok... good luck with your work!