A bug in process.on handlers' setup ?

17 views
Skip to first unread message

Jorge

unread,
Aug 26, 2010, 10:12:07 AM8/26/10
to nodejs
This error is not caught by the uncaughtException handler:

process.on('uncaughtException', function handler (err) {
console.log('Caught exception: ' + err);
});

function throwErr () { nonexistentFunc() }

process.nextTick(throwErr);
//or setTimeout(throwErr, 0);

throwErr(); //NOT CAUGHT

--> "function throwErr () { nonexistentFunc() }
^
ReferenceError: nonexistentFunc is not defined"
..
..

A hint: if the call to throwErr is postponed until the next event loop
then it gets caught properly:

process.on('uncaughtException', function handler (err) {
console.log('Caught exception: ' + err);
});

function throwErr () { nonexistentFunc() }

process.nextTick(throwErr);
//or setTimeout(throwErr, 0);

//throwErr(); **disabled

--> "Caught exception: ReferenceError: nonexistentFunc is not defined"
--
Jorge.

Russell

unread,
Aug 26, 2010, 2:00:17 PM8/26/10
to nod...@googlegroups.com
The problem is that in the first example you are calling throwErr
before the event loop starts. If you check the docs on the
'uncaughtException' event it notes that it is "'Emitted when an
exception bubbles all the way back to the event loop". The event loop
doesn't start until after your script has been evaluated, which
includes performing function calls made at the module level. By
postponing the function call until the next run of the event loop, you
push the exception inside there where it gets caught.

At least thats my understanding. This comment is a good starting
point: http://github.com/ry/node/blob/master/src/node.js#L759

-Russell

> --
> You received this message because you are subscribed to the Google Groups "nodejs" group.
> To post to this group, send email to nod...@googlegroups.com.
> To unsubscribe from this group, send email to nodejs+un...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/nodejs?hl=en.
>

Jorge

unread,
Aug 26, 2010, 2:54:23 PM8/26/10
to nodejs
On Aug 26, 8:00 pm, Russell <russellhaer...@gmail.com> wrote:
> The problem is that in the first example you are calling throwErr
> before the event loop starts. If you check the docs on the
> 'uncaughtException' event it notes that it is "'Emitted when an
> exception bubbles all the way back to the event loop". The event loop
> doesn't start until after your script has been evaluated, which
> includes performing function calls made at the module level. By
> postponing the function call until the next run of the event loop, you
> push the exception inside there where it gets caught.
>
> At least thats my understanding. This comment is a good starting
> point:http://github.com/ry/node/blob/master/src/node.js#L759
>
> -Russell

Yes, that might very well be the case.

The problem is that the example at http://nodejs.org/api.html :
process : Example of listening for uncaughtException :

process.on('uncaughtException', function (err) {
console.log('Caught exception: ' + err);
});

setTimeout(function () {
console.log('This will still run.');
}, 500);

// Intentionally cause an exception, but don't catch it.
nonexistentFunc();
console.log('This will not run.');

expects -as well- the call to nonexistentFunc() to be caught at this
point (before the event loop is started), soooo (?) :-)

Thanks,
--
Jorge.

Dean Landolt

unread,
Aug 26, 2010, 2:59:49 PM8/26/10
to nod...@googlegroups.com


If there's an error in your initialization code it never makes it to the event loop. I don't see how that's a bug uncaughtException handling -- would you expect a SyntaxError to get caught by your uncaughtException handler as well?

Russell

unread,
Aug 26, 2010, 3:21:43 PM8/26/10
to nod...@googlegroups.com

That looks like a documentation bug, good catch.

-Russell

Jorge

unread,
Aug 26, 2010, 7:02:06 PM8/26/10
to nodejs
On Aug 26, 8:59 pm, Dean Landolt <d...@deanlandolt.com> wrote:
>
> If there's an error in your initialization code it never makes it to the
> event loop. I don't see how that's a bug uncaughtException handling -- would
> you expect a SyntaxError to get caught by your uncaughtException handler as
> well?

Well, yes, if an error happens at runtime, after having had the chance
to setup -successfully- a handler for it, yes, I'd expect it to be
handed to its handler. Wouldn't you ?
--
Jorge.

Jorge

unread,
Aug 26, 2010, 7:37:50 PM8/26/10
to nodejs
On Aug 26, 8:00 pm, Russell <russellhaer...@gmail.com> wrote:
> The problem is that in the first example you are calling throwErr
> before the event loop starts. If you check the docs on the
> 'uncaughtException' event it notes that it is "'Emitted when an
> exception bubbles all the way back to the event loop". The event loop
> doesn't start until after your script has been evaluated, which
> includes performing function calls made at the module level. By
> postponing the function call until the next run of the event loop, you
> push the exception inside there where it gets caught.
>
> At least thats my understanding. This comment is a good starting
> point:http://github.com/ry/node/blob/master/src/node.js#L759

This might fix it:

Replace: http://github.com/ry/node/blob/master/src/node.js#L751

LINE 751: module.runMain();

with

LINE 751: process.nextTick(module.runMain);

But I have no idea if such a change has/might have any undesirable
side effects.

After that the error is caught properly:

$ cat ex.js
-->
process.on('uncaughtException', function handler (err) {
console.log('Caught exception: ' + err);
});

nonexistentFunc();

$ node ex.js

Vitali Lovich

unread,
Aug 26, 2010, 7:53:03 PM8/26/10
to nod...@googlegroups.com
That's a clever idea - that ensures the event loop is always up.

Isaac Schlueter

unread,
Aug 26, 2010, 10:35:20 PM8/26/10
to nod...@googlegroups.com
> On Thu, Aug 26, 2010 at 4:37 PM, Jorge <jo...@jorgechamorro.com> wrote:
>> Replace: http://github.com/ry/node/blob/master/src/node.js#L751
>>
>> LINE 751: module.runMain();
>>
>> with
>>
>> LINE 751: process.nextTick(module.runMain);
>>
>> But I have no idea if such a change has/might have any undesirable
>> side effects.

It shouldn't.

You should submit a patch.

--i

Jorge

unread,
Aug 27, 2010, 6:37:12 AM8/27/10
to nodejs
The test-next-tick-ordering.js fails... :-(
--
Jorge.

Vitali Lovich

unread,
Aug 27, 2010, 10:28:09 PM8/27/10
to nod...@googlegroups.com
Fails how? It could be an invalid test.

Jorge

unread,
Aug 28, 2010, 5:24:56 AM8/28/10
to nodejs
On Aug 28, 4:28 am, Vitali Lovich <vlov...@gmail.com> wrote:
> Fails how?  It could be an invalid test.

Fails because there are several setTimeouts that get triggered
*before* the nextTick. Maybe I've done something wrong. Here's what I
did step by step :

1.- cloned git clone git://github.com/ry/node.git
2.- changed line 751 in node.js to "process.nextTick(module.runMain);"
3.- ./configure
4.- make test-all

And it threw at the assertion in http://github.com/ry/node/blob/master/test/simple/test-next-tick-ordering.js
: it expected the nexttick to be run in the first place, but it
wasn't.

?
--
Jorge.

Vitali Lovich

unread,
Aug 29, 2010, 8:02:31 PM8/29/10
to nod...@googlegroups.com
Can you print what the output for that test case is?

Thanks,
Vitali

Jorge

unread,
Aug 30, 2010, 7:02:17 AM8/30/10
to nod...@googlegroups.com
On 30/08/2010, at 02:02, Vitali Lovich wrote:
> On Sat, Aug 28, 2010 at 2:24 AM, Jorge <jo...@jorgechamorro.com> wrote:
>> On Aug 28, 4:28 am, Vitali Lovich <vlov...@gmail.com> wrote:
>>> Fails how? It could be an invalid test.
>>
>> Fails because there are several setTimeouts that get triggered
>> *before* the nextTick. Maybe I've done something wrong. Here's what I
>> did step by step :
>>
>> 1.- cloned git clone git://github.com/ry/node.git
>> 2.- changed line 751 in node.js to "process.nextTick(module.runMain);"
>> 3.- ./configure
>> 4.- make test-all
>>
>> And it threw at the assertion in http://github.com/ry/node/blob/master/test/simple/test-next-tick-ordering.js
>> : it expected the nexttick to be run in the first place, but it
>> wasn't.
>>
>> ?
>

> Can you print what the output for that test case is?

Yep, this is what it gives :-(

=== release test-next-tick-ordering ===
Path: simple/test-next-tick-ordering
Running from main.
Running from setTimeout 0
Running from setTimeout 1
Running from setTimeout 2
Running from setTimeout 3
Running from setTimeout 4
Running from setTimeout 5
Running from setTimeout 6
Running from setTimeout 7
Running from setTimeout 8
Running from setTimeout 9
Running from setTimeout 10
Running from setTimeout 11
Running from setTimeout 12
Running from setTimeout 13
Running from setTimeout 14
Running from setTimeout 15
Running from setTimeout 16
Running from setTimeout 17
Running from setTimeout 18
Running from setTimeout 19
Running from nextTick
Running from setTimeout 20
Running from setTimeout 21
Running from setTimeout 22
Running from setTimeout 23
Running from setTimeout 24
Running from setTimeout 25
Running from setTimeout 26
Running from setTimeout 27
Running from setTimeout 28
Running from setTimeout 29
assert:80
throw new assert.AssertionError({
^
AssertionError: 0 == "nextTick"
at EventEmitter.<anonymous> (/Users/jorge/JAVASCRIPT/node/test/simple/test-next-tick-ordering.js:28:10)
at EventEmitter.emit (events:26:26)
at node.js:775:9
Command: build/default/node /Users/jorge/JAVASCRIPT/node/test/simple/test-next-tick-ordering.js

--
Jorge.

Vitali Lovich

unread,
Aug 30, 2010, 7:51:17 AM8/30/10
to nod...@googlegroups.com
You don't have your setTimeout patch applied right?  I'll have to look at it in some more detail if it's not.  I've got no clue why nextTick is taking so long - it could be a bug or there's some weird undocumented corner case regarding nextTick within a tick.

Jorge

unread,
Aug 30, 2010, 8:48:11 AM8/30/10
to nod...@googlegroups.com
With the timers patch plus line 751 in node.js set to "process.nextTick(module.runMain);" the setTimeout(,0) goes right after the nextTick :

=== release test-next-tick-ordering ===                                
Path: simple/test-next-tick-ordering
Running from main.
Running from setTimeout 1
Running from setTimeout 2
Running from setTimeout 3
Running from setTimeout 4
Running from setTimeout 5
Running from setTimeout 6
Running from setTimeout 7
Running from setTimeout 8
Running from setTimeout 9
Running from setTimeout 10
Running from setTimeout 11
Running from setTimeout 12
Running from setTimeout 13
Running from setTimeout 14
Running from setTimeout 15
Running from setTimeout 16
Running from setTimeout 17
Running from setTimeout 18
Running from setTimeout 19
Running from nextTick
Running from setTimeout 0
Running from setTimeout 20
Running from setTimeout 21
Running from setTimeout 22
Running from setTimeout 23
Running from setTimeout 24
Running from setTimeout 25
Running from setTimeout 26
Running from setTimeout 27
Running from setTimeout 28
Running from setTimeout 29
assert:80
  throw new assert.AssertionError({
        ^
AssertionError: 1 == "nextTick"
    at EventEmitter.<anonymous> (/Users/jorge/JAVASCRIPT/newNode/node/test/simple/test-next-tick-ordering.js:28:10)
    at EventEmitter.emit (events:26:26)
    at node.js:813:9
Command: build/default/node /Users/jorge/JAVASCRIPT/newNode/node/test/simple/test-next-tick-ordering.js


Why is the first nextTick delayed so much ? Weird, isn't it ?
-- 
Jorge.

mscdex

unread,
Aug 30, 2010, 11:15:46 AM8/30/10
to nodejs
I'm not able to reproduce this with v0.2.0. What version are you
running? Here's what I get:

Running from main.
Running from nextTick
Running from setTimeout 0
Running from setTimeout 1
Running from setTimeout 2
Running from setTimeout 3
Running from setTimeout 4
Running from setTimeout 5
Running from setTimeout 6
Running from setTimeout 7
Running from setTimeout 8
Running from setTimeout 9
Running from setTimeout 10
Running from setTimeout 11
Running from setTimeout 12
Running from setTimeout 13
Running from setTimeout 14
Running from setTimeout 15
Running from setTimeout 16
Running from setTimeout 17
Running from setTimeout 18
Running from setTimeout 19

Jorge

unread,
Aug 30, 2010, 11:22:10 AM8/30/10
to nod...@googlegroups.com
On 30/08/2010, at 17:15, mscdex wrote:

> I'm not able to reproduce this with v0.2.0. What version are you
> running? Here's what I get:

For it to happen you've got to patch line 751 in node.js to read "process.nextTick(module.runMain);" : http://github.com/xk/node/commit/7fdb7cb46e8ab53528ac2a42f5907f6a93ebad58
--
Jorge.

Jorge Chamorro

unread,
Aug 30, 2010, 11:26:00 AM8/30/10
to nod...@googlegroups.com

Oh, well, maybe it's no longer @ line 751. This is it:

if (process.argv[1]) {
if (process.argv[1].charAt(0) != "/" && !(/^http:\/\//).exec(process.argv[1])) {
process.argv[1] = path.join(cwd, process.argv[1]);
}

//module.runMain(); // *** disable this
process.nextTick(module.runMain); // *** put this instead

} else {
// No arguments, run the repl
var repl = module.requireNative('repl');
console.log("Type '.help' for options.");
repl.start();
}

--
Jorge.

Vitali Lovich

unread,
Aug 30, 2010, 3:15:46 PM8/30/10
to nod...@googlegroups.com
No - the main problem is that setTimeout(, 1) appears to be getting called before nextTick.  Not sure why that is.

--

r...@tinyclouds.org

unread,
Aug 31, 2010, 2:00:31 PM8/31/10
to nod...@googlegroups.com

I added the broken test in 635986e4338cf34cf8e1abc4343ffd69d109bb4e

Rather than nextTick the loading, just load the main file
asynchronously. It breaks some things, and those issues need to be
worked out.

Reply all
Reply to author
Forward
0 new messages