DocPad v6.55.1 — Node error: "Please use setImmediate in place of process.nextTick"

[mikeumus]

Just upgraded to DocPad 6.55.1 and upon running I'm getting a long repeat of this during the generation passes:

(node) warning: Recursive process.nextTick detected. This will break in the next version of node. 
Please use setImmediate for recursive deferral.

Seems DocPad is running locally but live-reload isn't reloading and any changes made to the local source, after a refresh, aren't showing up for work.

[balupton]

I looked into this the other day but I have no clue on what is the cause of this issue. It happens everytime on the DocPad Website with DocPad v6.55. Would really appreciate if others could look into it as well. The sooner this is fixed the better.

[balupton]

Fixed in v6.55.3

[mikeumus]

Upgrading to 6.55.3 lead to this issue: MassDistributionMedia/arkivum.docpad/issues/28

[mikeumus]

Upgrading to 6.55.8 and removing the related plugin is producing the error again for arkivum.docpad.

(node) warning: Recursive process.nextTick detected. This will break in the next
 version of node. Please use setImmediate for recursive deferral.

[pflannery]

It seems that process.nextTick is deprecated and annoyingly someone decided it was a good idea to output this fact to the console every-time it's run. There's catch This message doesn't make sense, I don't get this message with my docpad sites and process.nextTick is used a lot. So why is this message appearing here for you?

My hunch is that this message is bit of a red herring and an error is occurring somewhere and silently fails in the render process.

The solution could be as simple as just changing process.nextTick to setImmediate (in taskGroup I believe) the only problem with that is backward compatibility with node 0.8 would be broken.

I looked at this project on my pc and I get the same warning over and over. I've had this error message recently before with a project not related to docpad but related with taskGroup...it was a scenario where it was calling an empty task 1000's of times via process.nextTick.

I discovered there is a way to throw an exception when this warning occurs by running

node --throw-deprecation ./node_modules/docpad/bin/docpad generate

This is the error that was spat out with your project:

Performing renderFiles (pass 1) at 75/122 61% ==============================-------------------
node.js:375
        throw new Error(msg);
              ^
Error: (node) warning: Recursive process.nextTick detected. This will break in the next version of node. Please use setImmediate for recursive deferral.
    at maxTickWarn (node.js:375:15)
    at process._nextDomainTick (node.js:498:9)
    at new TaskGroup (f:\github\temp\test\node_modules\docpad\node_modules\taskgroup\out\lib\taskgroup.js:268:15)
    at DocPad.EventEmitterGrouped.getListenerGroup (f:\github\temp\test\node_modules\docpad\node_modules\event-emitter-grouped\out\lib\event-emitter-grouped.js:27:15)
    at DocPad.EventEmitterGrouped.emitSerial (f:\github\temp\test\node_modules\docpad\node_modules\event-emitter-grouped\out\lib\event-emitter-grouped.js:53:36)
    at DocPad.emitSerial (f:\github\temp\test\node_modules\docpad\out\lib\docpad.js:1100:35)
    at DocPad.notify (f:\github\temp\test\node_modules\docpad\out\lib\docpad.js:1936:14)
    at DocPad.notify (f:\github\temp\test\node_modules\docpad\out\lib\docpad.js:5:61)
    at DocPad.error (f:\github\temp\test\node_modules\docpad\out\lib\docpad.js:1887:16)
    at process.<anonymous> (f:\github\temp\test\node_modules\docpad\out\lib\docpad.js:5:61)
    at process.EventEmitter.emit (events.js:95:17)
    at process._fatalException (node.js:272:26)

when I run node --throw-deprecation ./node_modules/docpad/bin/docpad generate -d
weirdly it doesn't throw the exception but just ends, this is the last output

debug: Rendering completed for: message-of-the-day.html
    → [2013-11-29 05:02:24.682] [f:\github\temp\test\node_modules\docpad\out\lib\docpad.js] [DocumentModel.<anonymous>]
debug: Rendering applied to: menu.html.eco
    → [2013-11-29 05:02:24.686] [f:\github\temp\test\node_modules\docpad\out\lib\docpad.js] [DocumentModel.<anonymous>]
debug: Rendering completed for: menu.html.eco
    → [2013-11-29 05:02:24.690] [f:\github\temp\test\node_modules\docpad\out\lib\docpad.js] [DocumentModel.<anonymous>]
debug: Emitted the event: renderDocument
    → [2013-11-29 05:02:24.694] [f:\github\temp\test\node_modules\docpad\out\lib\docpad.js] [TaskGroup.<anonymous>]
debug: Emitted the event: renderDocument
    → [2013-11-29 05:02:24.697] [f:\github\temp\test\node_modules\docpad\out\lib\docpad.js] [TaskGroup.<anonymous>]
debug: Rendering applied to: right-sidebar.html.eco
    → [2013-11-29 05:02:24.700] [f:\github\temp\test\node_modules\docpad\out\lib\docpad.js] [DocumentModel.<anonymous>]
debug: Rendering completed for: right-sidebar.html.eco
    → [2013-11-29 05:02:24.704] [f:\github\temp\test\node_modules\docpad\out\lib\docpad.js] [DocumentModel.<anonymous>]

I know it's not fixing the problem but hopefully shedding some light on where the problem is

[pflannery]

I run node-inspector and put a break on [email protected]:375
You can see it's stack on the right, the only thing I noticed different from above error stack is that this time it passed through the partials plugin

[pflannery]

Found the fix. Turned out TaskGroup is trying to use setImmediate but fails because coffee-script conveniently generates local variable statements and was overriding setImmediate with var setImmediate, so therefore taskGroup would always use process.nextTick regardless..

see TaskGroup pull request for fix details here

Though this problem will still exist for node 0.8, it is a fix for 0.10

[mikeumus]

[balupton]

Will merge in shortly.

[pflannery]

👍

[pflannery]

before I forget, this project seems to have generated so many tasks that when it starts to execute them all it surpasses theprocess.maxTickDepth who's default is 1000.

I found that inspecting the first maxTick warning there were always two tick entries that were around 5000 or 10000 (which is why it was outputting all the warnings)

I think we still need to find the reason why docpad is overloading process.nextTick. I was thinking that it may be useful to have counter stats for all the tasks, who created them etc... or something like that.

In the meantime if any node 0.8 users encounter this scenario they can up their process.maxTickDepth. Say for example 10000 should be enough for this project.

[balupton]

Released to v6.55.9. Cheers!