Bdtjtk

I recently pushed my node js and express server to the production.
After a few days of working on the production, I realized that sometimes with no reason my server stops responding for requests.

[31/Dec/2018:09:55:39 +0000] "GET /vehicles?user_lat=52.458876&user_lng=16.9006237 HTTP/1.1" - - ms

I was looking for an answer here but the only advice I found was to debug server and find out what is causing it crashes. Unfortunately, I am not able to find out where is the problem. I added listeners to the process to find unhandled promises rejection and uncaught exception but nothing was caught.

What I also found is when the server stops responding the CPU usage is
running high. Normally it takes 1-5%, but when it hangs it is around 20%.

The next strange thing for me is the output of pm2.log file. According to it, my server often restarts but I don't understand why.

pm2.log file:

        2018-12-22T10:12:10: PM2 log: pid=28427 msg=process killed

        2018-12-22T10:12:10: PM2 log: App [server:0] starting in -fork mode-

        2018-12-22T10:12:10: PM2 log: App [server:0] online

        2018-12-24T13:33:40: PM2 log: Stopping app:server id:0

        2018-12-24T13:33:40: PM2 log: App [server:0] exited with code [0] via signal [SIGINT]

        2018-12-24T13:33:41: PM2 log: pid=31380 msg=process killed

        2018-12-24T13:33:41: PM2 log: App [server:0] starting in -fork mode-

        2018-12-24T13:33:41: PM2 log: App [server:0] online

        2018-12-24T13:45:29: PM2 log: Stopping app:server id:0

        2018-12-24T13:45:29: PM2 log: App [server:0] exited with code [0] via signal [SIGINT]

        2018-12-24T13:45:29: PM2 log: pid=5521 msg=process killed

        2018-12-24T13:45:29: PM2 log: App [server:0] starting in -fork mode-

        2018-12-24T13:45:29: PM2 log: App [server:0] online

        2018-12-25T03:11:40: PM2 log: Stopping app:server id:0

        2018-12-25T03:11:40: PM2 log: App [server:0] exited with code [0] via signal [SIGINT]

        2018-12-25T03:11:40: PM2 log: pid=6049 msg=process killed

        2018-12-25T03:11:40: PM2 log: App [server:0] starting in -fork mode-

        2018-12-25T03:11:40: PM2 log: App [server:0] online

        2018-12-27T05:07:30: PM2 log: Stopping app:server id:0

        2018-12-27T05:07:30: PM2 log: App [server:0] exited with code [0] via signal [SIGINT]

        2018-12-27T05:07:30: PM2 log: pid=11531 msg=process killed

        2018-12-27T05:07:30: PM2 log: App [server:0] starting in -fork mode-

        2018-12-27T05:07:30: PM2 log: App [server:0] online

        2018-12-29T08:08:27: PM2 log: Stopping app:server id:0

        2018-12-29T08:08:27: PM2 log: App [server:0] exited with code [0] via signal [SIGINT]

        2018-12-29T08:08:27: PM2 log: pid=28263 msg=process killed

        2018-12-29T08:08:27: PM2 log: App [server:0] starting in -fork mode-

        2018-12-29T08:08:27: PM2 log: App [server:0] online

        2018-12-29T09:41:23: PM2 log: Stopping app:server id:0

        2018-12-29T09:41:23: PM2 log: App [server:0] exited with code [0] via signal [SIGINT]

        2018-12-29T09:41:23: PM2 log: pid=11341 msg=process killed

        2018-12-29T09:41:23: PM2 log: App [server:0] starting in -fork mode-

        2018-12-29T09:41:23: PM2 log: App [server:0] online

        2018-12-31T10:03:33: PM2 log: Stopping app:server id:0

        2018-12-31T10:03:33: PM2 log: App [server:0] exited with code [0] via signal [SIGINT]

        2018-12-31T10:03:33: PM2 log: pid=12337 msg=process killed

        2018-12-31T10:03:33: PM2 log: App [server:0] starting in -fork mode-

        2018-12-31T10:03:33: PM2 log: App [server:0] online

        2018-12-31T10:48:51: PM2 log: Stopping app:server id:0

        2018-12-31T10:48:51: PM2 log: App [server:0] exited with code [0] via signal [SIGINT]

        2018-12-31T10:48:51: PM2 log: pid=28552 msg=process killed

        2018-12-31T10:48:51: PM2 log: App [server:0] starting in -fork mode-

        2018-12-31T10:48:51: PM2 log: App [server:0] online

On the production, I use pm2 to start my server.

Here is my server.js file:

var express = require('express'),

app = express(),

port = process.env.PORT || 3000;



const morgan = require('morgan');



const routes = require('./api/routes/main_routes');



const authMiddleware = require('./api/authorization/auth');





bodyParser = require('body-parser');



app.use(morgan(':remote-addr - :remote-user [:date[clf]] ":method :url 

HTTP/:http-version" :status :response-time ms'))

app.use('/images', express.static(__dirname + '/markers'));

app.use('/cars', express.static(__dirname + '/cars'));

app.use('/video', express.static(__dirname + '/video'));

app.use(bodyParser.urlencoded({ extended: true }));

app.use(bodyParser.json());



app.use(authMiddleware)

routes(app); //register the routes



app.use(function (err, req, res, next) {

 res.status(err.status || 500);

 res.send(err.message);

});



process.on('unhandledRejection', (reason, p) => {

 console.log("Unhandled Rejection at: Promise ", p, " reason: ", 

 reason);

});



process.on('uncaughtException', function (exception) {

 console.log(exception); 

});





app.listen(port);

console.log('server started on:' + port);

And package.json file:

   {

    "name": "api",

    "version": "1.0.0",

    "description": "",

    "main": "server.js",

    "scripts": {

      "start": "nodemon server.js"

    },

    "author": "",

    "license": "ISC",

    "devDependencies": {

      "nodemon": "^1.11.0"

    },

    "dependencies": {

      "axios": "^0.18.0",

      "axios-cache-adapter": "^2.1.1",

      "body-parser": "^1.17.2",

      "cachios": "^2.0.0",

      "cors": "^2.8.4",

      "express": "^4.15.4",

      "file-system": "^2.2.2",

      "form-data": "^2.3.3",

      "geolib": "^2.0.24",

      "lodash": "^4.17.4",

      "morgan": "^1.9.1",

      "nodemon": "^1.18.6",

      "path": "^0.12.7",

      "sharp": "^0.18.4",

      "websocket": "^1.0.28"

    }

  }

Full pm2 logs

            /root/.pm2/pm2.log last 15 lines:

            PM2        | 2018-12-29T09:41:23: PM2 log: Stopping app:server id:0

            PM2        | 2018-12-29T09:41:23: PM2 log: App [server:0] exited with code [0] via signal [SIGINT]

            PM2        | 2018-12-29T09:41:23: PM2 log: pid=11341 msg=process killed

            PM2        | 2018-12-29T09:41:23: PM2 log: App [server:0] starting in -fork mode-

            PM2        | 2018-12-29T09:41:23: PM2 log: App [server:0] online

            PM2        | 2018-12-31T10:03:33: PM2 log: Stopping app:server id:0

            PM2        | 2018-12-31T10:03:33: PM2 log: App [server:0] exited with code [0] via signal [SIGINT]

            PM2        | 2018-12-31T10:03:33: PM2 log: pid=12337 msg=process killed

            PM2        | 2018-12-31T10:03:33: PM2 log: App [server:0] starting in -fork mode-

            PM2        | 2018-12-31T10:03:33: PM2 log: App [server:0] online

            PM2        | 2018-12-31T10:48:51: PM2 log: Stopping app:server id:0

            PM2        | 2018-12-31T10:48:51: PM2 log: App [server:0] exited with code [0] via signal [SIGINT]

            PM2        | 2018-12-31T10:48:51: PM2 log: pid=28552 msg=process killed

            PM2        | 2018-12-31T10:48:51: PM2 log: App [server:0] starting in -fork mode-

            PM2        | 2018-12-31T10:48:51: PM2 log: App [server:0] online



            /root/.pm2/logs/server-error.log last 15 lines:

            /root/.pm2/logs/server-out.log last 15 lines:

            0|server   | ::ffff:127.0.0.1 - - [31/Dec/2018:16:11:27 +0000] "GET /images/marker_active.png HTTP/1.1" 200 0.849 ms

            0|server   | ::ffff:127.0.0.1 - - [31/Dec/2018:16:11:27 +0000] "GET /images/marker_active.png HTTP/1.1" 200 0.667 ms

            0|server   | ::ffff:127.0.0.1 - - [31/Dec/2018:16:11:27 +0000] "GET /images/marker_active.png HTTP/1.1" 200 0.567 ms

            0|server   | ::ffff:127.0.0.1 - - [31/Dec/2018:16:11:28 +0000] "GET /images/marker_inactive.png HTTP/1.1" 200 1.065 ms

            0|server   | ::ffff:127.0.0.1 - - [31/Dec/2018:16:11:28 +0000] "GET /images/marker_inactive.png HTTP/1.1" 200 1.302 ms

            0|server   | ::ffff:127.0.0.1 - - [31/Dec/2018:16:11:28 +0000] "GET /images/marker_inactive.png HTTP/1.1" 200 0.550 ms

            0|server   | ::ffff:127.0.0.1 - - [31/Dec/2018:16:11:28 +0000] "GET /images/marker_inactive.png HTTP/1.1" 200 0.566 ms

            0|server   | 211

            0|server   | ::ffff:127.0.0.1 - - [31/Dec/2018:16:11:30 +0000] "GET /vehicles?user_lat=52.14601814935841&user_lng=21.04796773265618&center_lng=21.047964502570746&center_lat=52.14602095031964 HTTP/1.1" 200 5357.940 ms

            0|server   | ::ffff:127.0.0.1 - - [31/Dec/2018:16:11:31 +0000] "GET /images/marker_active.png HTTP/1.1" 200 0.624 ms

            0|server   | ::ffff:127.0.0.1 - - [31/Dec/2018:16:11:31 +0000] "GET /images/marker_active.png HTTP/1.1" 200 0.613 ms

            0|server   | ::ffff:127.0.0.1 - - [31/Dec/2018:16:11:31 +0000] "GET /images/marker_inactive.png HTTP/1.1" 200 0.600 ms

            0|server   | ::ffff:127.0.0.1 - - [31/Dec/2018:16:11:31 +0000] "GET /images/marker_inactive.png HTTP/1.1" 200 0.520 ms

            0|server   | ::ffff:127.0.0.1 - - [31/Dec/2018:16:11:31 +0000] "GET /images/marker_active.png HTTP/1.1" 200 0.567 ms

            0|server   | ::ffff:127.0.0.1 - - [31/Dec/2018:16:11:31 +0000] "GET /images/marker_inactive.png HTTP/1.1" 200 0.416 ms