Why Cloudfoundry (Bluemix) app crash is not detected

Question

Hi,

I have a node.js app running on Bluemix which is using Cloudfoundry. When my app detects a FATAL error, it stops accepting connections and will exit with exit code 1, if the logging is done.

I was thinking, that Bluemix will detect that and will try to restart the application, but currently it is not displaying any issues in the console, just the loadbalancer returns a 503 status code.

This is the output cf logs returns

TIMESTAMP [App/0]      OUT FATAL ERROR WITH STACKTRACE
TIMESTAMP [App/0]      ERR npm ERR! Linux 3.13.0-39-generic
TIMESTAMP [App/0]      ERR npm ERR! argv "/home/vcap/app/vendor/node/bin/node" "/home/vcap/app/vendor/node/bin/npm" "start"
TIMESTAMP [App/0]      ERR npm ERR! node v0.12.7
TIMESTAMP [App/0]      ERR npm ERR! npm  v2.11.3
TIMESTAMP [App/0]      ERR npm ERR! code ELIFECYCLE
TIMESTAMP [App/0]      ERR npm ERR! myapp@0.1.0 start: `node app/app.js`
TIMESTAMP [App/0]      ERR npm ERR! Exit status 1
TIMESTAMP [App/0]      ERR npm ERR! 
TIMESTAMP [App/0]      ERR npm ERR! Failed at the myapp@0.1.0 start script 'node app/app.js'.
TIMESTAMP [App/0]      ERR npm ERR! This is most likely a problem with the myapp package,
TIMESTAMP [App/0]      ERR npm ERR! not with npm itself.
TIMESTAMP [App/0]      ERR npm ERR! Tell the author that this fails on your system:
TIMESTAMP [App/0]      ERR npm ERR!     node app/app.js
TIMESTAMP [App/0]      ERR npm ERR! You can get their info via:
TIMESTAMP [App/0]      ERR npm ERR!     npm owner ls myapp
TIMESTAMP [App/0]      ERR npm ERR! There is likely additional logging output above.
TIMESTAMP [App/0]      ERR npm ERR! Please include the following file with any support request:
TIMESTAMP [App/0]      ERR npm ERR!     /home/vcap/app/npm-debug.log
TIMESTAMP [RTR/2]      OUT myapp.bluemix.net - [TIMESTAMP] "GET /myroute HTTP/1.1" 503 0 89 "-" "-" PUBLICIP:41145 x_forwarded_for:"IP" vcap_request_id:requestID response_time:0.002571320 app_id:myappId
TIMESTAMP [App/0]      OUT TIMESTAMP http: proxy error: dial tcp 127.0.0.1:61872: connection refused
TIMESTAMP [App/0]      OUT TIMESTAMP myapp.bluemix.net - [TIMESTAMP] GET /myroute HTTP/1.1 - 467.106us
TIMESTAMP [App/0]      OUT TIMESTAMP http: proxy error: dial tcp 127.0.0.1:61872: connection refused
TIMESTAMP [App/0]      OUT TIMESTAMP myapp.bluemix.net - [TIMESTAMP] GET /doc HTTP/1.1 - 289.874us
TIMESTAMP [RTR/0]      OUT TIMESTAMP - [TIMESTAMP] "GET /myroute HTTP/1.1" 503 0 89 "https://myapp.bluemix.net" (https://myapp.bluemix.net)  "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0" PUBLICIP:39419 x_forwarded_for:"IP" vcap_request_id:REQUESTID response_time:0.001849779 app_id:APP_ID
TIMESTAMP [App/0]      OUT TIMESTAMP http: proxy error: dial tcp 127.0.0.1:61872: connection refused
TIMESTAMP [App/0]      OUT TIMESTAMP TIMESTAMP - [TIMESTAMP] GET /static/swagger/images/favicon-16x16.png HTTP/1.1 - 1.150624ms
TIMESTAMP [RTR/1]      OUT myapp.bluemix.net - [TIMESTAMP] "GET /static/swagger/images/favicon-16x16.png HTTP/1.1" 503 0 89 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0" PUBLICIP:38110 x_forwarded_for:"IP" vcap_request_id:REQUESTID response_time:0.004067078 app_id:APPID

Any ideas what is going wrong here? I have tested it locally by running "npm start; echo $?". It returned 1, so the exit code should work.

Edit:

manifest.yml:

applications:
- disk_quota: 1024M
  host: myapp
  name: myapp
  path: .
  domain: mybluemix.net
  instances: 1
  memory: 512M
  env:
    BLUEMIX_APP_MGMT_ENABLE: devconsole+shell

The package.json looks like:

{
    "name": "myApp",
    "description": "MyDescription",
    "version": "0.1.0",
    "engines" : { "node" : ">=0.12.7" },
    "dependencies": {
        "express": "4.13.3",
        "express-session": "1.11.3",
    ...
    },
    "devDependencies": {
        "grunt": "0.4.5",
        "mocha": "2.2.5",
        ...
    },
    "scripts": {
        "test": "grunt dev-test",
        "start": "node app/app.js"
    },
    "repository": {
        "type": "git",
        "url": "..."
    }
}

Bluemix is generating a procfile on start by interpreting the npm start command.

I am calling in my app/app.js

var app = express();
app.set("port", process.env.VCAP_APP_PORT);
...
var server = http.createServer(app);
server.listen(app.get("port"), function () {
    logger.info("Express server listening on port" + app.get("port"));
});

The environment looks like:

cf env myapp
Getting env variables for app myapp in org myOrg / space mySpace as my@mail.com...
OK

System-Provided:


{
 "VCAP_APPLICATION": {
  "application_name": "myApp",
  "application_uris": [
    "myapp.mybluemix.net"
  ],
  "application_version": "HASH",
  "limits": {
   "disk": 1024,
   "fds": 16384,
   "mem": 512
  },
  "name": "myApp",
  "space_id": "HASH",
  "space_name": "mySpace",
  "uris": [
   "myapp.mybluemix.net",
  ],
  "users": null,
  "version": "HASH"
 }
}

User-Provided:
BLUEMIX_APP_MGMT_ENABLE: devconsole+shell

No running env variables have been set

No staging env variables have been set

Important to know is, the app is working for some minutes and after the fatal occurs it should be restarted.

The manifest file and the folder structure are working, so it is not misplaced in a wrong folder.

cf events shows up:

$ cf events myApp
Getting events for app myApp in org myOrg / space mySpace as my@mail.com...

time                          event                   actor                 description   
TIMESTAMP   audit.app.update        my@mail.com      
TIMESTAMP   audit.app.map-route     my@mail.com      
TIMESTAMP   audit.app.update        my@mail.com      
TIMESTAMP   audit.app.unmap-route   my@mail.com      
TIMESTAMP   audit.app.update        my@mail.com      
TIMESTAMP   audit.app.update        my@mail.com      
TIMESTAMP   audit.app.map-route     my@mail.com      
TIMESTAMP   audit.app.update        my@mail.com   state: STARTED   
TIMESTAMP   audit.app.update        my@mail.com      
TIMESTAMP   audit.app.map-route     my@mail.com      
TIMESTAMP   audit.app.create        my@mail.com   disk_quota: 1024, instances: 1, memory: 512, state: STOPPED, environment_json: PRIVATE DATA HIDDEN 

If I connect to it with the browser, the following is displayed:

503 Service Unavailable: The server is not available now. Please try your request later.

On Bluemix console it is displayed as running:

After running

cf restart myapp

the app works again.

Answer 1

Since you are requesting

BLUEMIX_APP_MGMT_ENABLE: devconsole+shell

it hinders the container from being killed and you want to debug it after a crash, right? Looks like works as expected.

HP