BadgeKit times out during startup

[pbunyasrie]

I'm trying to run a nodejs app called badgekit under phusion passenger 5.0.5 (and nodejs v0.10.33), but get this error:

App 9560 stdout:
App 9560 stdout: [Function]
App 9560 stderr: connect.multipart() will be removed in connect 3.0
App 9560 stderr: visit https://github.com/senchalabs/connect/wiki/Connect-3.0 for alternatives
App 9560 stderr: connect.limit() will be removed in connect 3.0
[ 2015-03-30 13:46:11.3136 9479/7fac4818b700 App/Implementation.cpp:287 ]: Could not spawn process for application /www/badgekit.local/html: An error occurred while starting the web application: it did not write a startup response in time.
  Error ID: f3e2ea58
  Error details saved to: /tmp/passenger-error-nE1kpZ.html
  Message from application: An error occurred while starting the web application: it did not write a startup response in time. Please read <a href="https://github.com/phusion/passenger/wiki/Debugging-application-startup-problems">this article</a> for more information about this problem.<br>
<h2>Raw process output:</h2>
<pre>
[Function]
connect.multipart() will be removed in connect 3.0
visit https://github.com/senchalabs/connect/wiki/Connect-3.0 for alternatives
connect.limit() will be removed in connect 3.0
</pre>

[ 2015-03-30 13:46:11.3268 9479/7fac4a2cd700 age/Hel/Req/CheckoutSession.cpp:252 ]: [Client 2-1] Cannot checkout session because a spawning error occurred. The identifier of the error is f3e2ea58. Please see earlier logs for details about the error.

I have the badgekit-api running in a separete process (independent of phusion passenger).
Badgekit-web works fine if I use forever/node instead of passenger.

I've confirmed that node.js is working under phusion passenger by creating a quick Express app.
Any advice on how to debug this further? I have a feeling that something in the application is causing problems in passenger.

[FooBarWidget]

Passenger works by waiting for an 'http.Server.listen' call. At that point, the app is considered initialized. The error message "it did not write a startup response in time" means that an 'http.Server.listen' call was not encountered in the configured timeout (60 seconds by default). Do you have any idea what may cause the app not to call listen quickly enough? Could it be stuck somewhere during startup?

[FooBarWidget]

@pbunyasrie, any updates on this?

[pbunyasrie]

The application is on express 3.4.8
Based on what you said, I found out that the application is using express.listen (via the app variable) instead of http.Server.listen on in https://github.com/mozilla/openbadges-badges/blob/master/app/index.js

Correct me if I'm wrong, but I believe express uses the http.Listen call:
https://github.com/strongloop/express/blob/3.x/lib/application.js

The application runs fine when running node app/index.js, and starts in less than 5 seconds - well within the 60 second timeout.
I will place some debug messages to see if they appear in the Passenger output/logs.

[FooBarWidget]

Application.listen calls http.Server.listen under the hood, so it should still work:

app.listen = function(){
  var server = http.createServer(this);
  return server.listen.apply(server, arguments);    // <-----------------
};

You are using badgekit unmodified, right? I'll investigate this and see whether I can reproduce the problem.

[pbunyasrie]

Yes. The only files modified were HTML template files, but those should have nothing to do with the main application itself.

[FooBarWidget]

I have reproduced this problem. The investigation continues.

[FooBarWidget]

Ah yes, I see the problem. It's quite trivial. The offending code block is in app/index.js:

if (!module.parent) {
  const port = config('PORT', 3000);

  app.listen(port, function(err) {
    if (err) {
      throw err;
    }

    console.log('Listening on port ' + port + '.');
  });
} ...

As you can see, the app.listen() is only called if module.parent is null. But this is not the case with Passenger because Passenger does not invoke index.js directly, but require()s it from another file.

This is the exact same issue as the one CompoundJS suffered from, as documented here: https://groups.google.com/forum/#!topic/phusion-passenger/6Cojr55tzfw

This issue cannot be fixed without help from the application. Back in version 4.0.34 we introduced a better mechanism for this: https://github.com/phusion/passenger/blob/master/CHANGELOG#L587-L599

I'll send a pull request to Badgekit.