I am learning node.js, and have a fairly simple application which seems to be leaking memory when deployed to Bluemix. I need assistance in determining if this is caused by my code, or a module I am using.
When deployed with the Monitoring and Cloudant services it would crash with an out of memory error, and be restarted by Bluemix every 12-14 hours - with 256 megs of RAM. I upped the RAM to 1 gig and it still occurs (although less frequently).
When I deploy the app to Bluemix and issue calls to the / route I can see the memory climb slowly up. When testing locally in windows, I do not see the same behavior (testing via process explorer and seeing the amount of private bytes & working set)
I have simplified my app (and removed the monitoring service) and can still reproduce, though the increase is slower with the simplified app.
/*jshint node:true*/
//------------------------------------------------------------------------------
// app.js - Middleware routing
//------------------------------------------------------------------------------
// This application uses express as it's web server
// for more info, see: http://expressjs.com
var express = require( 'express' );
// For handling the POST bodies and multi-part bodies0
var bodyParser = require( 'body-parser' );
var multer = require( 'multer' );
// Create a new express server
var app = express();
// Get the app environment from Cloud Foundry
var cfenv = require( 'cfenv' );
var appEnv = cfenv.getAppEnv();
// Catch all handlers for unhandled URLs
//
app.post( '/*', function( req, res ){
logRequest( req );
res.send( 'Unhandled POST received' );
});
app.get( '/*', function( req, res ){
logRequest( req );
res.send( 'Unhandled GET received' );
});
// start server on the specified port and binding host
app.listen(appEnv.port, appEnv.bind, function() {
// print a message when the server starts listening
console.log("server starting on -- " + appEnv.url);
});
function logRequest(req){
console.log("Received,"+new Date().toLocaleString()+","+req.method+","+req.originalUrl);
}
Here is the data I gathered, memory is listed in Megs, and I issued requests to the / route:
I tried using the heapdump module, but it fails when being deployed to Bluemix.
cf-node-debug installation now successful - see bottom of question Installed cf-node-debug as suggested, in package.json specified:
"scripts": {
"start": "node_modules/.bin/cf-node-debug app.js"
},
When I pushed the app I got the following:
T13:19:44.08-0400 [STG/39] OUT -----> Downloaded app package (36K)
T13:19:44.46-0400 [STG/39] OUT -----> Downloaded app buildpack cache (2.6M)
T13:19:44.80-0400 [STG/0] OUT -----> Node.js Buildpack Version: v1.18-20150519-1759
T13:19:44.85-0400 [STG/0] OUT -----> Resetting git environment
T13:19:45.35-0400 [STG/0] OUT TIP: Specify a node version in package.json
T13:19:45.35-0400 [STG/0] OUT -----> Defaulting to latest stable node: 0.12.2
T13:19:45.35-0400 [STG/0] OUT -----> Installing IBM SDK for Node.js from cache
T13:19:45.78-0400 [STG/0] OUT -----> Checking and configuring service extensions
T13:19:45.95-0400 [STG/0] OUT -----> Restoring node_modules directory from cache
T13:19:46.21-0400 [STG/0] OUT -----> Pruning cached dependencies not specified in package.json
T13:19:47.22-0400 [STG/0] OUT -----> Installing dependencies
T13:19:54.50-0400 [STG/0] OUT > [email protected] install /tmp/staged/app/node_modules/cf-node-debug/node_modules/node-inspector/node_modules/ws
T13:19:54.50-0400 [STG/0] OUT > (node-gyp rebuild 2> builderror.log) || (exit 0)
T13:20:04.31-0400 [STG/0] OUT make: Entering directory `/tmp/staged/app/node_modules/cf-node-debug/node_modules/node-inspector/node_modules/ws/build'
T13:20:04.32-0400 [STG/0] OUT CXX(target) Release/obj.target/bufferutil/src/bufferutil.o
T13:20:04.71-0400 [STG/0] OUT SOLINK_MODULE(target) Release/obj.target/bufferutil.node
T13:20:04.76-0400 [STG/0] OUT SOLINK_MODULE(target) Release/obj.target/bufferutil.node: Finished
T13:20:04.77-0400 [STG/0] OUT COPY Release/bufferutil.node
T13:20:04.78-0400 [STG/0] OUT CXX(target) Release/obj.target/validation/src/validation.o
T13:20:05.15-0400 [STG/0] OUT SOLINK_MODULE(target) Release/obj.target/validation.node
T13:20:05.21-0400 [STG/0] OUT SOLINK_MODULE(target) Release/obj.target/validation.node: Finished
T13:20:05.21-0400 [STG/0] OUT COPY Release/validation.node
T13:20:05.24-0400 [STG/0] OUT make: Leaving directory `/tmp/staged/app/node_modules/cf-node-debug/node_modules/node-inspector/node_modules/ws/build'
T13:20:05.29-0400 [STG/0] OUT npm WARN deprecated [email protected]: use serve-favicon module
T13:20:05.80-0400 [STG/0] OUT [email protected] node_modules/cf-node-debug
T13:20:05.80-0400 [STG/0] OUT ├── [email protected]
T13:20:05.80-0400 [STG/0] OUT ├── [email protected]
T13:20:05.80-0400 [STG/0] OUT ├── [email protected] ([email protected])
T13:20:05.80-0400 [STG/0] OUT ├── [email protected] ([email protected])
T13:20:05.80-0400 [STG/0] OUT ├── [email protected] ([email protected], [email protected])
T13:20:05.80-0400 [STG/0] OUT ├── [email protected] ([email protected])
T13:20:05.80-0400 [STG/0] OUT ├── [email protected] ([email protected])
T13:20:05.80-0400 [STG/0] OUT ├── [email protected] ([email protected], [email protected], [email protected], [email protected])
T13:20:05.80-0400 [STG/0] OUT ├── [email protected] ([email protected], [email protected], [email protected], [email protected], [email protected], [email protected], cookie-signature@1.
@1.0.0, [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected])
T13:20:05.80-0400 [STG/0] OUT ├── [email protected] ([email protected], [email protected])
T13:20:05.80-0400 [STG/0] OUT ├── [email protected] ([email protected], [email protected])
T13:20:05.80-0400 [STG/0] OUT └── [email protected] ([email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], exp
4.32)
T13:20:06.02-0400 [STG/0] OUT -----> Caching node_modules directory for future builds
T13:20:06.59-0400 [STG/0] OUT -----> Cleaning up node-gyp and npm artifacts
T13:20:06.60-0400 [STG/0] OUT -----> No Procfile found; Adding npm start to new Procfile
T13:20:06.60-0400 [STG/0] OUT -----> Building runtime environment
T13:20:06.60-0400 [STG/0] OUT -----> Checking and configuring service extensions
T13:20:06.85-0400 [STG/0] OUT -----> Installing App Management
T13:20:06.90-0400 [STG/0] OUT -----> WARN: App Management (Development Mode) cannot be installed because the start script cannot be found.
T13:20:06.91-0400 [STG/0] OUT TIP: Specify your start script in 'package.json' or 'Procfile'.
T13:20:06.92-0400 [STG/0] ERR
T13:20:11.28-0400 [STG/39] OUT -----> Uploading droplet (20M)
T13:20:20.47-0400 [DEA/39] OUT Starting app instance (index 0) with guid 1dde346e-4e51-407f-af7b-607772826e72
T13:20:32.91-0400 [App/0] OUT
T13:20:32.91-0400 [App/0] OUT > [email protected] start /home/vcap/app
T13:20:32.91-0400 [App/0] OUT > cf-node-debug app.js
T13:20:33.38-0400 [App/0] ERR util.js:634
T13:20:33.38-0400 [App/0] ERR ctor.prototype = Object.create(superCtor.prototype, {
T13:20:33.38-0400 [App/0] ERR ^
T13:20:33.38-0400 [App/0] ERR TypeError: Cannot read property 'prototype' of undefined
T13:20:33.38-0400 [App/0] ERR at Object.exports.inherits (util.js:634:43)
T13:20:33.38-0400 [App/0] ERR at Object.<anonymous> (/home/vcap/app/node_modules/cf-node-debug/node_modules/http-proxy/lib/http-proxy/index.js:106:17)
T13:20:33.38-0400 [App/0] ERR at Module._compile (module.js:460:26)
T13:20:33.38-0400 [App/0] ERR at Object.Module._extensions..js (module.js:478:10)
T13:20:33.38-0400 [App/0] ERR at Module.load (module.js:355:32)
T13:20:33.38-0400 [App/0] ERR at Function.Module._load (module.js:310:12)
T13:20:33.38-0400 [App/0] ERR at Module.require (module.js:365:17)
T13:20:33.38-0400 [App/0] ERR at require (module.js:384:17)
T13:20:33.38-0400 [App/0] ERR at Object.<anonymous> (/home/vcap/app/node_modules/cf-node-debug/node_modules/http-proxy/lib/http-proxy.js:4:17)
T13:20:33.38-0400 [App/0] ERR at Module._compile (module.js:460:26)
T13:20:33.40-0400 [App/0] ERR npm ERR! Linux 3.13.0-39-generic
T13:20:33.40-0400 [App/0] ERR npm ERR! argv "/home/vcap/app/vendor/node/bin/node" "/home/vcap/app/vendor/node/bin/npm" "start"
T13:20:33.40-0400 [App/0] ERR npm ERR! node v0.12.2
T13:20:33.40-0400 [App/0] ERR npm ERR! npm v2.7.4
T13:20:33.40-0400 [App/0] ERR npm ERR! code ELIFECYCLE
T13:20:33.40-0400 [App/0] ERR npm ERR! [email protected] start: `cf-node-debug app.js`
T13:20:33.40-0400 [App/0] ERR npm ERR! Exit status 1
T13:20:33.40-0400 [App/0] ERR npm ERR!
T13:20:33.40-0400 [App/0] ERR npm ERR! Failed at the [email protected] start script 'cf-node-debug app.js'.
T13:20:33.41-0400 [App/0] ERR npm ERR! This is most likely a problem with the NodejsStarterApp package,
T13:20:33.41-0400 [App/0] ERR npm ERR! not with npm itself.
T13:20:33.41-0400 [App/0] ERR npm ERR! Tell the author that this fails on your system:
T13:20:33.41-0400 [App/0] ERR npm ERR! cf-node-debug app.js
T13:20:33.41-0400 [App/0] ERR npm ERR! You can get their info via:
T13:20:33.41-0400 [App/0] ERR npm ERR! npm owner ls NodejsStarterApp
T13:20:33.41-0400 [App/0] ERR npm ERR! There is likely additional logging output above.
T13:20:33.41-0400 [App/0] ERR npm ERR! Please include the following file with any support request:
T13:20:33.41-0400 [App/0] ERR npm ERR! /home/vcap/app/npm-debug.log
T13:20:33.47-0400 [DEA/39] ERR Instance (index 0) failed to start accepting connections
$ npm --version
1.4.28
$ node --version
v0.10.33
Looks like [email protected] ([email protected])
Note: Using SDK for Node.js from IBM
At Jack's suggestion I tried specifying the engine like:
"engines": {
"node": "0.10.x",
"npm": "2.7.4"
},
The staging reported:
2015-06-04T14:27:41.87-0400 [STG/0] OUT -----> Resetting git environment
2015-06-04T14:27:42.31-0400 [STG/0] OUT -----> Requested node range: 0.10.x
2015-06-04T14:27:42.31-0400 [STG/0] OUT -----> Resolved node version: 0.10.38
2015-06-04T14:27:42.31-0400 [STG/0] OUT -----> Installing IBM SDK for Node.js from cache
but I obtained the same error as before:
2015-06-04T14:28:12.89-0400 [App/0] ERR util.js:556
2015-06-04T14:28:12.89-0400 [App/0] ERR ctor.prototype = Object.create(superCtor.prototype, {
2015-06-04T14:28:12.89-0400 [App/0] ERR ^
2015-06-04T14:28:12.89-0400 [App/0] ERR TypeError: Cannot read property 'prototype' of undefined
Update 3:35pm EST
I forked cf-node-debug and modified the http-proxy to 1.11.x. I updated package.json to:
"cf-node-debug": "git://github.com/retinaburn/cf-node-debug.git",
I pushed the app, and now have access to the debug console, but there does not seem to be any heap dumps that I can use to investigate memory leaks.
I have confirmed that the specified sample app does perform garbage collection in Bluemix with the memory set to 1gb.
I tested using apache bench with 1000 requests to '/' with 10 concurrent transactions.
I suspect the earlier volume tests were too low to trigger a gc.