Приложение Node перестает отвечать через некоторое время - PullRequest
Новая
       12

Приложение Node перестает отвечать через некоторое время

0 голосов
/ 31 декабря 2018

Я недавно отправил свой узел js и экспресс-сервер в производство.После нескольких дней работы над производством я понял, что иногда без причины мой сервер перестает отвечать на запросы.

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

Я искал здесь ответ, но единственный совет, который я нашел, был отладить сервер и выяснить причину его сбоя.К сожалению, я не могу выяснить, в чем проблема.Я добавил слушателей в процесс, чтобы найти отклонение необработанных обещаний и необдуманное исключение, но ничего не было поймано.

Я также обнаружил, что когда сервер перестает отвечать на запросы, нагрузка на процессор становится высокой.Обычно это занимает 1-5%, но когда зависает, это около 20%.

Следующая странная вещь для меня - вывод файла pm2.log.В соответствии с этим мой сервер часто перезагружается, но я не понимаю, почему.

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

На производстве я использую pm2 для запуска своего сервера.

Вот мой файл server.js: 

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);

И файл package.json: 

   {
    "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"
    }
  }

Полные журналы pm2 

            /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
...