search

RocketChat / Rocket.Chat

The communications platform that puts data protection first.
https://rocket.chat/
Other
40.56k stars 10.58k forks source link

Auto-restart after every message sent #13196

Closed slyk closed 5 years ago

slyk commented 5 years ago

Description:

I got RocketChat server snap version 0.73.2 on Ubuntu 16.04.5 LTS (GNU/Linux 4.4.0-141-generic x86_64) at DigitalOcean. Almost every time I send direct message I see that client had lost connection... rocketchat-server is restarting.

The message is send ok, so when server is restarted I see that message.

Steps to reproduce:

  1. Rocketchat Server from Snap with data
  2. Send DM to some user

Actual behavior:

Rocketchat server is restarted almost every time I send a message. Switching between channels/users and reading messages is ok.

Server Setup Information:

Additional context

TypeError: err.stack.split is not a function at return originalRun.call(this, val); packages/rocketchat_monitoring.js:3549

Relevant logs:

contents of the syslog:

Jan 18 21:25:33 nfchat rocketchat-server.rocketchat-server[7545]:  ^ ^  +--------------------------------------------------+
Jan 18 21:25:33 nfchat rocketchat-server.rocketchat-server[7545]:  ^ ^  |                  SERVER RUNNING                  |
Jan 18 21:25:33 nfchat rocketchat-server.rocketchat-server[7545]:  ^ ^  +--------------------------------------------------+
Jan 18 21:25:33 nfchat rocketchat-server.rocketchat-server[7545]:  ^ ^  |                                                  |
Jan 18 21:25:33 nfchat rocketchat-server.rocketchat-server[7545]:  ^ ^  |  Rocket.Chat Version: 0.73.2                     |
Jan 18 21:25:33 nfchat rocketchat-server.rocketchat-server[7545]:  ^ ^  |       NodeJS Version: 8.11.3 - x64               |
Jan 18 21:25:33 nfchat rocketchat-server.rocketchat-server[7545]:  ^ ^  |             Platform: linux                      |
Jan 18 21:25:33 nfchat rocketchat-server.rocketchat-server[7545]:  ^ ^  |         Process Port: 3000                       |
Jan 18 21:25:33 nfchat rocketchat-server.rocketchat-server[7545]:  ^ ^  |             Site URL: https://nfchat.*****.***  |
Jan 18 21:25:33 nfchat rocketchat-server.rocketchat-server[7545]:  ^ ^  |     ReplicaSet OpLog: Enabled                    |
Jan 18 21:25:33 nfchat rocketchat-server.rocketchat-server[7545]:  ^ ^  |          Commit Hash: 8ff0e3da16                 |
Jan 18 21:25:33 nfchat rocketchat-server.rocketchat-server[7545]:  ^ ^  |        Commit Branch: HEAD                       |
Jan 18 21:25:33 nfchat rocketchat-server.rocketchat-server[7545]:  ^ ^  |                                                  |
Jan 18 21:25:33 nfchat rocketchat-server.rocketchat-server[7545]:  ^ ^  +--------------------------------------------------+
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-server[7545]: packages/rocketchat_monitoring.js:3549
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-server[7545]:   return originalRun.call(this, val);
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-server[7545]:                      ^
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-server[7545]: TypeError: err.stack.split is not a function
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-server[7545]:     at Object.exports.parse (/snap/rocketchat-server/1362/programs/server/npm/node_modules/stack-trace/lib/stack-trace.js$
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-server[7545]:     at new Error (/snap/rocketchat-server/1362/programs/server/npm/node_modules/bugsnag/lib/error.js:69:28)
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-server[7545]:     at Function.Error.buildErrors (/snap/rocketchat-server/1362/programs/server/npm/node_modules/bugsnag/lib/error.js:82:$
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-server[7545]:     at notify (/snap/rocketchat-server/1362/programs/server/npm/node_modules/bugsnag/lib/bugsnag.js:37:34)
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-server[7545]:     at Object.Bugsnag.notify (/snap/rocketchat-server/1362/programs/server/npm/node_modules/bugsnag/lib/bugsnag.js:174:10)
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-server[7545]:     at notify (packages/rocketchat:lib/server/lib/bugsnag.js:22:21)
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-server[7545]:     at Object.Meteor._debug (packages/rocketchat:lib/server/lib/bugsnag.js:32:2)
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-server[7545]:     at Object.Meteor._debug (packages/rocketchat:error-handler/server/lib/RocketChat.ErrorHandler.js:41:32)
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-server[7545]:     at onException (packages/meteor.js:1338:14)
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-server[7545]:     at runWithEnvironment (packages/meteor.js:1361:9)
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-mongo[1551]: 2019-01-18T21:30:45.771+0200 I NETWORK  [conn155] end connection 127.0.0.1:56978 (4 connections now open)
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-mongo[1551]: 2019-01-18T21:30:45.772+0200 I NETWORK  [conn154] end connection 127.0.0.1:56970 (3 connections now open)
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-mongo[1551]: 2019-01-18T21:30:45.773+0200 I NETWORK  [conn153] end connection 127.0.0.1:56966 (2 connections now open)
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-mongo[1551]: 2019-01-18T21:30:45.774+0200 I NETWORK  [conn152] end connection 127.0.0.1:56962 (1 connection now open)
Jan 18 21:30:45 nfchat rocketchat-server.rocketchat-mongo[1551]: 2019-01-18T21:30:45.774+0200 I NETWORK  [conn151] end connection 127.0.0.1:56958 (0 connections now open)
Jan 18 21:30:45 nfchat systemd[1]: snap.rocketchat-server.rocketchat-server.service: Main process exited, code=exited, status=7/NOTRUNNING
Jan 18 21:30:45 nfchat systemd[1]: snap.rocketchat-server.rocketchat-server.service: Unit entered failed state.
Jan 18 21:30:45 nfchat systemd[1]: snap.rocketchat-server.rocketchat-server.service: Failed with result 'exit-code'.
Jan 18 21:30:46 nfchat systemd[1]: snap.rocketchat-server.rocketchat-server.service: Service hold-off time over, scheduling restart.
Jan 18 21:30:46 nfchat systemd[1]: Stopped Service for snap application rocketchat-server.rocketchat-server.
Jan 18 21:30:46 nfchat systemd[1]: Started Service for snap application rocketchat-server.rocketchat-server.
Jan 18 21:30:46 nfchat kernel: [227238.453375] audit_printk_skb: 300 callbacks suppressed
Jan 18 21:30:46 nfchat kernel: [227238.453379] audit: type=1400 audit(1547839846.548:2396): apparmor="DENIED" operation="ptrace" profile="snap.rocketchat-server.rocketchat-server" pid=761$
Jan 18 21:30:46 nfchat kernel: [227238.453573] audit: type=1400 audit(1547839846.548:2397): apparmor="DENIED" operation="ptrace" profile="snap.rocketchat-server.rocketchat-server" pid=761$
Jan 18 21:30:46 nfchat kernel: [227238.453678] audit: type=1400 audit(1547839846.548:2398): apparmor="DENIED" operation="ptrace" profile="snap.rocketchat-server.rocketchat-server" pid=761$
Jan 18 21:30:46 nfchat kernel: [227238.453763] audit: type=1400 audit(1547839846.548:2399): apparmor="DENIED" operation="ptrace" profile="snap.rocketchat-server.rocketchat-server" pid=761$
Jan 18 21:30:46 nfchat kernel: [227238.453845] audit: type=1400 audit(1547839846.548:2400): apparmor="DENIED" operation="ptrace" profile="snap.rocketchat-server.rocketchat-server" pid=761$
Jan 18 21:30:46 nfchat kernel: [227238.453926] audit: type=1400 audit(1547839846.548:2401): apparmor="DENIED" operation="ptrace" profile="snap.rocketchat-server.rocketchat-server" pid=761$
Jan 18 21:30:46 nfchat kernel: [227238.454009] audit: type=1400 audit(1547839846.548:2402): apparmor="DENIED" operation="ptrace" profile="snap.rocketchat-server.rocketchat-server" pid=761$
Jan 18 21:30:46 nfchat kernel: [227238.454091] audit: type=1400 audit(1547839846.548:2403): apparmor="DENIED" operation="ptrace" profile="snap.rocketchat-server.rocketchat-server" pid=761$
Jan 18 21:30:46 nfchat kernel: [227238.454173] audit: type=1400 audit(1547839846.548:2404): apparmor="DENIED" operation="ptrace" profile="snap.rocketchat-server.rocketchat-server" pid=761$
Jan 18 21:30:46 nfchat kernel: [227238.454253] audit: type=1400 audit(1547839846.548:2405): apparmor="DENIED" operation="ptrace" profile="snap.rocketchat-server.rocketchat-server" pid=761$
Jan 18 21:30:46 nfchat rocketchat-server.rocketchat-server[7599]: Checking if oplog has been enabled, and enabling if not
Jan 18 21:30:46 nfchat rocketchat-server.rocketchat-server[7599]: MongoDB shell version: 3.2.7
Jan 18 21:30:46 nfchat rocketchat-server.rocketchat-server[7599]: connecting to: test
Jan 18 21:30:46 nfchat rocketchat-server.rocketchat-mongo[1551]: 2019-01-18T21:30:46.642+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:57018 #156 (1 connection now op$
Jan 18 21:30:46 nfchat rocketchat-server.rocketchat-mongo[1551]: 2019-01-18T21:30:46.644+0200 I NETWORK  [conn156] end connection 127.0.0.1:57018 (0 connections now open)
Jan 18 21:30:47 nfchat rocketchat-server.rocketchat-mongo[1551]: 2019-01-18T21:30:47.879+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:57022 #157 (1 connection now op$
Jan 18 21:30:47 nfchat rocketchat-server.rocketchat-mongo[1551]: 2019-01-18T21:30:47.899+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:57026 #158 (2 connections now o$
Jan 18 21:30:47 nfchat rocketchat-server.rocketchat-mongo[1551]: 2019-01-18T21:30:47.903+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:57030 #159 (3 connections now o$

PS:

slyk commented 5 years ago

Seems like there can be problems with SMTP mail config. Another one config that I'm trying to turn off or revert to defaults... right now, after clearing SMTP config fields messages sent ok, without restarting... We'll try using it actively in next monday, to understand is it really the case. If so, the good idea would be to catch this error and tell people where is the problem. I'll keep you informed.

geekgonecrazy commented 5 years ago

Please let us know if you narrow down what field being incorrect is causing this to fail.

slyk commented 5 years ago

@geekgonecrazy I can confirm after a day of active usage, when I reset all fields in SMTP settings I got no restarts.

Then, I just added one setting - "host" for SMTP, and got restart with error on the third message I send to myself in chat.

The host I set in settings does not have any SMTP server installed (it was previously, but then it was disabled). So giving the wrong SMTP host to RocketChat leads to error for me. I don't get any special error and don't found any traces to SMTP error, just turning off each function one by one can help find this.

It would be great for others that lost their SMTP server connection to tell them about that problem instead of just restarting.

P.S. sometimes after reseting SMTP settings, I should to relogin before problem disappear.

abyrne55 commented 5 years ago

I think I'm experiencing the same issue on my snap installation, but I tried clearing the SMTP as described above and the issue doesn't seem to go away. Here's my server's info:

Version of Rocket.Chat Server: 0.73.2 Operating System: Ubuntu 18.04 Deployment Method: snap Number of Running Instances: 1 NodeJS Version: 8.11.3 - x64 MongoDB Version: v3.2.7

And here's what keeps getting printed to the log every time rocket.chat restarts (which is every 30 seconds - 5 minutes, seemingly random)

Jan 28 15:53:51 trout systemd[1]: Started Service for snap application rocketchat-server.rocketchat-server.
Jan 28 15:53:51 trout rocketchat-server.rocketchat-server[30584]: Checking if oplog has been enabled, and enabling if not
Jan 28 15:53:51 trout rocketchat-server.rocketchat-server[30584]: MongoDB shell version: 3.2.7
Jan 28 15:53:51 trout rocketchat-server.rocketchat-server[30584]: connecting to: test
Jan 28 15:53:51 trout rocketchat-server.rocketchat-server[30584]: /snap/rocketchat-server/1362/bin/startRocketChat: line 28: /var/snap/rocketchat-server/common/*.env: No such file or directory
Jan 28 15:53:54 trout rocketchat-server.rocketchat-server[30584]: Updating process.env.MAIL_URL
Jan 28 15:53:55 trout rocketchat-server.rocketchat-server[30584]: Starting Email Intercepter...
Jan 28 15:53:56 trout rocketchat-server.rocketchat-server[30584]: Warning: connect.session() MemoryStore is not
Jan 28 15:53:56 trout rocketchat-server.rocketchat-server[30584]: designed for a production environment, as it will leak
Jan 28 15:53:56 trout rocketchat-server.rocketchat-server[30584]: memory, and will not scale past a single process.
Jan 28 15:53:56 trout rocketchat-server.rocketchat-server[30584]: Setting default file store to FileSystem
Jan 28 15:53:59 trout rocketchat-server.rocketchat-server[30584]: {"line":"121","file":"migrations.js","message":"Migrations: Not migrating, already at version 137","time":{"$date":1548708839781},"level":"info"}
Jan 28 15:54:00 trout rocketchat-server.rocketchat-server[30584]: Using GridFS for custom sounds storage
Jan 28 15:54:00 trout rocketchat-server.rocketchat-server[30584]: Using GridFS for custom emoji storage
Jan 28 15:54:00 trout rocketchat-server.rocketchat-server[30584]: Updating process.env.MAIL_URL
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: The App 22236eb7-1786-42bc-846c-a086dd072c2e is checking if "math" command exists.
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: The App 22236eb7-1786-42bc-846c-a086dd072c2e is registering the command: "math"
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: Loaded the Apps Framework and loaded a total of 1 Apps!
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: ➔ System ➔ startup
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: ➔ +-------------------------------------------------+
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: ➔ |                  SERVER RUNNING                 |
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: ➔ +-------------------------------------------------+
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: ➔ |                                                 |
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: ➔ |  Rocket.Chat Version: 0.73.2                    |
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: ➔ |       NodeJS Version: 8.11.3 - x64              |
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: ➔ |             Platform: linux                     |
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: ➔ |         Process Port: 3000                      |
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: ➔ |             Site URL: https://chat.burpg.space  |
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: ➔ |     ReplicaSet OpLog: Enabled                   |
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: ➔ |          Commit Hash: 8ff0e3da16                |
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: ➔ |        Commit Branch: HEAD                      |
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: ➔ |                                                 |
Jan 28 15:54:02 trout rocketchat-server.rocketchat-server[30584]: ➔ +-------------------------------------------------+
Jan 28 15:54:06 trout rocketchat-server.rocketchat-server[30584]: Bugsnag:  Encountered an uncaught error, terminating…
Jan 28 15:54:06 trout rocketchat-server.rocketchat-server[30584]: TypeError: err.stack.split is not a function
Jan 28 15:54:06 trout rocketchat-server.rocketchat-server[30584]:     at Object.exports.parse (/snap/rocketchat-server/1362/programs/server/npm/node_modules/stack-trace/lib/stack-trace.js:26:25)
Jan 28 15:54:06 trout rocketchat-server.rocketchat-server[30584]:     at new Error (/snap/rocketchat-server/1362/programs/server/npm/node_modules/bugsnag/lib/error.js:69:28)
Jan 28 15:54:06 trout rocketchat-server.rocketchat-server[30584]:     at Function.Error.buildErrors (/snap/rocketchat-server/1362/programs/server/npm/node_modules/bugsnag/lib/error.js:82:20)
Jan 28 15:54:06 trout rocketchat-server.rocketchat-server[30584]:     at notify (/snap/rocketchat-server/1362/programs/server/npm/node_modules/bugsnag/lib/bugsnag.js:37:34)
Jan 28 15:54:06 trout rocketchat-server.rocketchat-server[30584]:     at Object.Bugsnag.notify (/snap/rocketchat-server/1362/programs/server/npm/node_modules/bugsnag/lib/bugsnag.js:174:10)
Jan 28 15:54:06 trout rocketchat-server.rocketchat-server[30584]:     at notify (packages/rocketchat:lib/server/lib/bugsnag.js:22:21)
Jan 28 15:54:06 trout rocketchat-server.rocketchat-server[30584]:     at Object.Meteor._debug (packages/rocketchat:lib/server/lib/bugsnag.js:32:2)
Jan 28 15:54:06 trout rocketchat-server.rocketchat-server[30584]:     at Object.Meteor._debug (packages/rocketchat:error-handler/server/lib/RocketChat.ErrorHandler.js:41:32)
Jan 28 15:54:06 trout rocketchat-server.rocketchat-server[30584]:     at wrapInternalException (packages/ddp-server/livedata_server.js:1737:12)
Jan 28 15:54:06 trout rocketchat-server.rocketchat-server[30584]:     at promise.then.exception (packages/ddp-server/livedata_server.js:745:25)
Jan 28 15:54:06 trout rocketchat-server.rocketchat-server[30584]:     at /snap/rocketchat-server/1362/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/fiber_pool.js:43:40
Jan 28 15:54:06 trout systemd[1]: snap.rocketchat-server.rocketchat-server.service: Main process exited, code=exited, status=1/FAILURE
Jan 28 15:54:06 trout systemd[1]: snap.rocketchat-server.rocketchat-server.service: Failed with result 'exit-code'.

Needless to say, this bug is seriously degrading server usability, so any suggestions for fixes?

slyk commented 5 years ago

When I was searching for some bug description, I found that there were problem in Node fibers module. But after 11.2 the problem seems like solved...

abyrne55 commented 5 years ago

Can you provide a link to that bug? And if this is the issue, is it possible to upgrade that node module inside the snap?

On Jan 29, 2019, at 3:09 PM, slyk notifications@github.com wrote:

When I was searching for some bug description, I found that there were problem in Node fibers module. But after 11.2 the problem seems like solved...

— You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.

slyk commented 5 years ago

Can you provide a link to that bug? And if this is the issue, is it possible to upgrade that node module inside the snap? … On Jan 29, 2019, at 3:09 PM, slyk @.***> wrote: When I was searching for some bug description, I found that there were problem in Node fibers module. But after 11.2 the problem seems like solved... — You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.

That bug report was solved in Node 8.11.2 as far as I remember, so when I've updated to 811.3 my server and continue to get my error, I closed tab with that bugtracker.

reetp commented 5 years ago

You can't update node inside a snap, or docker come to that. You can only do it on a manual type of install.

Regarding modules, I'm not sure but does a snap import and build modules when it is installing, and if so, is this yet another fibers module issue where they've moved the goalposts (again)?

I also note that snap appears to run on node 8.11.3 but say docker is on 8.11.4 Will that make a difference (not that it can be changed inside a snap as per my first comment - a rebuild would be required)

geekgonecrazy commented 5 years ago

Regarding modules, I'm not sure but does a snap import and build modules when it is installing, and if so, is this yet another fibers module issue where they've moved the goalposts (again)?

Snap ships node modules frozen in stone. Npm shouldn’t even come shipped in it :)

0.74 is in candidate channel if you’d like to give it a go

engelgabriel commented 5 years ago

@geekgonecrazy can we close this?

geekgonecrazy commented 5 years ago

I think so. Please comment here if this should be re-opened @slyk