bot hosted on heroku keeps crashing

Question

when i hosted messenger bot application on heroku, it works well for a while but after several minutes it crashes and then i have to restart the heroku app again through the cli, sometimes it starts working again automatically. i do not knw why this is happening

this is my procfile

web: node index.js

i have tried several solution but it keeps crashing after some minutes.

like

typing this in the cli heroku ps:scale web=1

this is how i set the port

var app = express()
app.set('port', (process.env.PORT) || 5000)
// SPIN UP SERVER
app.listen(app.get('port'), function () {
  console.log('Running on port', app.get('port'))
})

the log

$ heroku logs
2017-03-07T08:56:53.964138+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=81819d8f-9fc2-4d72-b3a2-b7fde4930417 fwd="31.13.113.64" dyno= connect= service= status=503 bytes=
2017-03-07T08:58:07.116769+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=9df360fb-9b55-4ab2-a67b-8d666b1d6db7 fwd="31.13.102.107" dyno= connect= service= status=503 bytes=
2017-03-07T08:59:21.085472+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=0742553f-e506-491c-80e4-1539e1decf4c fwd="31.13.114.78" dyno= connect= service= status=503 bytes=
2017-03-07T09:00:40.538513+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=717d0506-c098-49fa-921e-125fe7286a04 fwd="31.13.113.176" dyno= connect= service= status=503 bytes=
2017-03-07T09:01:56.032586+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=93ba9709-a374-4532-8e73-b41b6216e406 fwd="31.13.113.84" dyno= connect= service= status=503 bytes=
2017-03-07T09:03:17.015196+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=d2afcdbb-e079-4e81-8a4f-6bba3f831fde fwd="31.13.110.97" dyno= connect= service= status=503 bytes=
2017-03-07T09:04:40.339415+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=a1d0f243-7afc-4f19-9378-e916d1651a09 fwd="31.13.102.125" dyno= connect= service= status=503 bytes=
2017-03-07T09:06:02.989125+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=224b6a85-6607-4cb1-b294-764b9f36252a fwd="31.13.113.90" dyno= connect= service= status=503 bytes=
2017-03-07T09:07:29.479672+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=350e5974-741a-476a-b59b-cfd7c455bdf7 fwd="31.13.102.102" dyno= connect= service= status=503 bytes=
2017-03-07T09:08:45.760868+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=4b8194fb-85a6-4595-a680-1c17f5af5bf7 fwd="31.13.110.126" dyno= connect= service= status=503 bytes=
2017-03-07T09:10:09.100216+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=9cad0806-1c4f-45c7-a617-15ecc80201e7 fwd="31.13.114.78" dyno= connect= service= status=503 bytes=
2017-03-07T09:11:28.519846+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=5df0438d-8bf5-4db2-bf88-2293e7e8fa81 fwd="31.13.102.110" dyno= connect= service= status=503 bytes=
2017-03-07T09:12:54.962281+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=b352a060-d6ae-4612-ad32-a1c88836ce79 fwd="31.13.102.127" dyno= connect= service= status=503 bytes=
2017-03-07T09:13:03.133808+00:00 heroku[web.1]: State changed from crashed to starting
2017-03-07T09:13:04.529654+00:00 heroku[web.1]: Starting process with command `node index.js`
2017-03-07T09:13:06.597891+00:00 app[web.1]: GRABBING WIT
2017-03-07T09:13:06.637063+00:00 app[web.1]: Running on port 35231
2017-03-07T09:13:08.215961+00:00 heroku[web.1]: State changed from starting to up
2017-03-07T09:14:15.236302+00:00 heroku[router]: at=info method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=9a7d82c7-abb5-44c8-9e94-7f98e32cff1b fwd="31.13.110.99" dyno=web.1 connect=1ms service=90ms status=200 bytes=201
2017-03-07T09:14:15.769291+00:00 app[web.1]: Executing merge action
2017-03-07T09:14:16.181301+00:00 app[web.1]: Executing say with message: 2017-03-07 13:00:00 lagos weather forecast 
2017-03-07T09:14:16.182548+00:00 app[web.1]: WIT WANTS TO TALK TO: 1781786975472826
2017-03-07T09:14:16.182593+00:00 app[web.1]: WIT HAS SOMETHING TO SAY: 2017-03-07 13:00:00 lagos weather forecast 
2017-03-07T09:14:16.209388+00:00 app[web.1]: WIT HAS A CONTEXT: { _fbid_: '1781786975472826',
2017-03-07T09:14:16.209390+00:00 app[web.1]:   locat: 'lagos',
2017-03-07T09:14:16.209391+00:00 app[web.1]:   dat: '2017-03-07 13:00:00' }
2017-03-07T09:14:16.846188+00:00 heroku[web.1]: Process exited with status 1
2017-03-07T09:14:16.588543+00:00 app[web.1]: Executing action: fetch-forecast
2017-03-07T09:14:16.717633+00:00 app[web.1]: /app/services/wit.js:149
2017-03-07T09:14:16.717635+00:00 app[web.1]:   if (date === jsonData.list[i].dt_txt) {
2017-03-07T09:14:16.717636+00:00 app[web.1]:                                ^
2017-03-07T09:14:16.717637+00:00 app[web.1]: 
2017-03-07T09:14:16.717638+00:00 app[web.1]: TypeError: Cannot read property 'dt_txt' of undefined
2017-03-07T09:14:16.717639+00:00 app[web.1]:     at Request._callback (/app/services/wit.js:149:32)
2017-03-07T09:14:16.717640+00:00 app[web.1]:     at Request.self.callback (/app/node_modules/request/request.js:187:22)
2017-03-07T09:14:16.717640+00:00 app[web.1]:     at emitTwo (events.js:87:13)
2017-03-07T09:14:16.717641+00:00 app[web.1]:     at Request.emit (events.js:172:7)
2017-03-07T09:14:16.717642+00:00 app[web.1]:     at Request.<anonymous> (/app/node_modules/request/request.js:1126:10)
2017-03-07T09:14:16.717642+00:00 app[web.1]:     at emitOne (events.js:77:13)
2017-03-07T09:14:16.717643+00:00 app[web.1]:     at Request.emit (events.js:169:7)
2017-03-07T09:14:16.717644+00:00 app[web.1]:     at IncomingMessage.<anonymous> (/app/node_modules/request/request.js:1046:12)
2017-03-07T09:14:16.717645+00:00 app[web.1]:     at IncomingMessage.g (events.js:260:16)
2017-03-07T09:14:16.717646+00:00 app[web.1]:     at emitNone (events.js:72:20)
2017-03-07T09:14:16.863152+00:00 heroku[web.1]: State changed from up to crashed
2017-03-07T09:23:59.284086+00:00 heroku[web.1]: State changed from crashed to starting
2017-03-07T09:24:01.580046+00:00 heroku[web.1]: Starting process with command `node index.js`
2017-03-07T09:24:05.809576+00:00 app[web.1]: GRABBING WIT
2017-03-07T09:24:05.924459+00:00 app[web.1]: Running on port 28392
2017-03-07T09:24:05.968782+00:00 heroku[web.1]: State changed from starting to up
2017-03-07T10:00:03.549825+00:00 heroku[web.1]: Idling
2017-03-07T10:00:03.550345+00:00 heroku[web.1]: State changed from up to down
2017-03-07T10:00:04.361633+00:00 heroku[web.1]: Stopping all processes with SIGTERM
2017-03-07T10:00:04.498563+00:00 heroku[web.1]: Process exited with status 143
2017-03-07T12:01:51.673073+00:00 heroku[web.1]: Unidling
2017-03-07T12:01:51.673414+00:00 heroku[web.1]: State changed from down to starting
2017-03-07T12:01:53.676870+00:00 heroku[web.1]: Starting process with command `node index.js`
2017-03-07T12:01:56.290230+00:00 app[web.1]: Running on port 43074
2017-03-07T12:01:56.249464+00:00 app[web.1]: GRABBING WIT
2017-03-07T12:01:57.315203+00:00 heroku[web.1]: State changed from starting to up
2017-03-07T12:01:57.765390+00:00 heroku[router]: at=info method=HEAD path="/" host=safe-temple-90677.herokuapp.com request_id=f2adc9b9-dd93-4305-8a86-f3c5be7e2cde fwd="54.198.194.21" dyno=web.1 connect=1ms service=20ms status=200 bytes=200
2017-03-07T12:37:37.068030+00:00 heroku[web.1]: Idling
2017-03-07T12:37:37.068503+00:00 heroku[web.1]: State changed from up to down
2017-03-07T12:37:37.887286+00:00 heroku[web.1]: Stopping all processes with SIGTERM
2017-03-07T12:37:38.030801+00:00 heroku[web.1]: Process exited with status 143
2017-03-07T15:17:29.700320+00:00 heroku[web.1]: Unidling
2017-03-07T15:17:29.700704+00:00 heroku[web.1]: State changed from down to starting
2017-03-07T15:17:31.201586+00:00 heroku[web.1]: Starting process with command `node index.js`
2017-03-07T15:17:33.502602+00:00 app[web.1]: GRABBING WIT
2017-03-07T15:17:33.544722+00:00 app[web.1]: Running on port 34866
2017-03-07T15:17:34.828307+00:00 heroku[web.1]: State changed from starting to up
2017-03-07T15:17:35.879110+00:00 heroku[router]: at=info method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=a9cd91d8-0c3f-49e2-8366-18b3f42faa0c fwd="31.13.114.69" dyno=web.1 connect=1ms service=42ms status=200 bytes=201
2017-03-07T15:17:36.515555+00:00 heroku[router]: at=info method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=ab1dee01-5289-49a7-94b2-0ed3f70b85ef fwd="31.13.113.67" dyno=web.1 connect=1ms service=18ms status=200 bytes=201
2017-03-07T15:17:37.620224+00:00 app[web.1]: Executing merge action
2017-03-07T15:17:38.050442+00:00 app[web.1]: Executing say with message: Getting you the weather for today at rome
2017-03-07T15:17:38.051244+00:00 app[web.1]: WIT WANTS TO TALK TO: 1781786975472826
2017-03-07T15:17:38.051288+00:00 app[web.1]: WIT HAS SOMETHING TO SAY: Getting you the weather for today at rome
2017-03-07T15:17:38.068401+00:00 app[web.1]: WIT HAS A CONTEXT: { _fbid_: '1781786975472826', locat: 'rome', missingDat: true }
2017-03-07T15:17:38.849856+00:00 app[web.1]: Executing action: fetch-weather
2017-03-07T15:17:39.655894+00:00 heroku[router]: at=info method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=7bbe3d86-da8c-4c53-b0c9-e45e0b80c889 fwd="31.13.114.80" dyno=web.1 connect=1ms service=4ms status=200 bytes=201
2017-03-07T15:17:39.704790+00:00 app[web.1]: Executing say with message: overcast clouds in rome
2017-03-07T15:17:39.705032+00:00 app[web.1]: WIT WANTS TO TALK TO: 1781786975472826
2017-03-07T15:17:39.705110+00:00 app[web.1]: WIT HAS SOMETHING TO SAY: overcast clouds in rome
2017-03-07T15:17:39.705684+00:00 app[web.1]: WIT HAS A CONTEXT: { _fbid_: '1781786975472826', forecast: 'overcast clouds' }
2017-03-07T15:17:40.113984+00:00 app[web.1]: Waiting for further messages
2017-03-07T15:17:46.513047+00:00 heroku[router]: at=info method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=2a9d56bc-0347-49b3-988b-0c9240cec5f9 fwd="31.13.113.94" dyno=web.1 connect=0ms service=1ms status=200 bytes=201
2017-03-07T15:18:40.398203+00:00 heroku[router]: at=info method=POST path="/webhooks" host=safe-temple-90677.herokuapp.com request_id=5f8cf61e-524c-46ec-acef-c2086bebe338 fwd="31.13.102.126" dyno=web.1 connect=0ms service=6ms status=200 bytes=201
2017-03-07T15:18:41.311907+00:00 app[web.1]: Executing merge action
2017-03-07T15:18:41.546198+00:00 app[web.1]: Executing action: fetch-weather
2017-03-07T15:18:51.556434+00:00 app[web.1]: [warn] I didn't get the callback after 10 seconds. Did you forget to call me back?
2017-03-07T15:54:28.273144+00:00 heroku[web.1]: Idling
2017-03-07T15:54:28.273744+00:00 heroku[web.1]: State changed from up to down
2017-03-07T15:54:28.903317+00:00 heroku[web.1]: Stopping all processes with SIGTERM
2017-03-07T15:54:29.068913+00:00 heroku[web.1]: Process exited with status 143
2017-03-07T16:05:09.174635+00:00 heroku[web.1]: Unidling
2017-03-07T16:05:09.176009+00:00 heroku[web.1]: State changed from down to starting
2017-03-07T16:05:10.949690+00:00 heroku[web.1]: Starting process with command `node index.js`
2017-03-07T16:05:13.145210+00:00 app[web.1]: GRABBING WIT
2017-03-07T16:05:13.185095+00:00 app[web.1]: Running on port 34415
2017-03-07T16:05:13.650386+00:00 heroku[web.1]: State changed from starting to up
2017-03-07T16:05:14.263374+00:00 heroku[router]: at=info method=GET path="/" host=safe-temple-90677.herokuapp.com request_id=3e560b4e-afb7-455f-aad5-c39f087cd643 fwd="197.211.63.112" dyno=web.1 connect=1ms service=18ms status=304 bytes=150
2017-03-07T16:05:16.130712+00:00 heroku[router]: at=info method=GET path="/favicon.ico" host=safe-temple-90677.herokuapp.com request_id=2f675cd7-07f8-4a7b-baf9-f40ffb68951a fwd="197.211.63.112" dyno=web.1 connect=1ms service=7ms status=404 bytes=386

We would need to see the rest of the logs – Varedis Mar 06 '17 at 13:39 — Varedis, Mar 06 '17 at 13:39

score 0 · Answer 1 · answered Mar 06 '17 at 13:56

It's impossible to tell for sure without seeing your complete logs and your complete source code, but sometimes services that work for a while and then crash may leak memory or some other resources. Just because V8 handles memory allocation/deallocation for you, don't assume that your app cannot leak memory.

If it crashes always handling the same request then it's another matter entirely, but if it handles requests and then crashes for no apparent reason, you should always assume that it may be cause by some leaking and investigate it in more details.

I'm afraid that no one will be able to tell you anything more considering how little info you included in your question.

score 0 · Accepted Answer · answered Mar 08 '17 at 10:40

Looking at the logs the only time you have an actual crash has a really obvious error after it:

2017-03-07T09:14:16.588543+00:00 app[web.1]: Executing action: fetch-forecast
2017-03-07T09:14:16.717633+00:00 app[web.1]: /app/services/wit.js:149
2017-03-07T09:14:16.717635+00:00 app[web.1]:   if (date === jsonData.list[i].dt_txt) {
2017-03-07T09:14:16.717636+00:00 app[web.1]:                                ^
2017-03-07T09:14:16.717637+00:00 app[web.1]: 
2017-03-07T09:14:16.717638+00:00 app[web.1]: TypeError: Cannot read property 'dt_txt' of undefined
2017-03-07T09:14:16.717639+00:00 app[web.1]:     at Request._callback (/app/services/wit.js:149:32)
2017-03-07T09:14:16.717640+00:00 app[web.1]:     at Request.self.callback (/app/node_modules/request/request.js:187:22)
2017-03-07T09:14:16.717640+00:00 app[web.1]:     at emitTwo (events.js:87:13)
2017-03-07T09:14:16.717641+00:00 app[web.1]:     at Request.emit (events.js:172:7)
2017-03-07T09:14:16.717642+00:00 app[web.1]:     at Request.<anonymous> (/app/node_modules/request/request.js:1126:10)
2017-03-07T09:14:16.717642+00:00 app[web.1]:     at emitOne (events.js:77:13)
2017-03-07T09:14:16.717643+00:00 app[web.1]:     at Request.emit (events.js:169:7)
2017-03-07T09:14:16.717644+00:00 app[web.1]:     at IncomingMessage.<anonymous> (/app/node_modules/request/request.js:1046:12)
2017-03-07T09:14:16.717645+00:00 app[web.1]:     at IncomingMessage.g (events.js:260:16)
2017-03-07T09:14:16.717646+00:00 app[web.1]:     at emitNone (events.js:72:20)
2017-03-07T09:14:16.863152+00:00 heroku[web.1]: State changed from up to crashed

The rest just looks like the dyno scaling. What dyno type are you running on Heroku? If it is the free version it will go to sleep after a period of inactivity.

thanks for clearing me up,the reason for the error is that user input a message wrongly and the bot couldn't handle it, didnt know that would cause a crash. I will work on the error. Thanks again — nipek, Mar 08 '17 at 11:13

bot hosted on heroku keeps crashing

2 Answers2