Cannot upgrade snap 5.4.5 to 6.x

tuxmartin commented 1 year ago

Description:

I tried to upgrade Rocket.Chat from 5.4.5 to 6.x using Snap on Debian 11, but it crashed.

Steps to reproduce:

snap switch rocketchat-server --channel=6.x/stable
snap refresh

Server Setup Information:

Version of Rocket.Chat Server: 5.4.5
Operating System: Debian 11
Deployment Method: snap
Number of Running Instances: 1
NodeJS Version: 14.19.3
MongoDB Version: 4.4.15

Relevant logs:

root@example.net / # snap list
Name               Version    Rev    Tracking       Publisher    Notes
core               16-2.58.3  14946  latest/stable  canonical✓   core
core18             20230320   2721   latest/stable  canonical✓   base
core20             20230308   1852   latest/stable  canonical✓   base
hello-world        6.4        29     latest/stable  canonical✓   -
rocketchat-server  5.4.5      1544   5.x/stable     rocketchat✓  -
root@example.net / # snap refresh 
All snaps up to date.
root@example.net / # snap switch rocketchat-server --channel=6.x/stable
"rocketchat-server" switched to the "6.x/stable" channel

root@example.net / # snap list
Name               Version    Rev    Tracking       Publisher    Notes
core               16-2.58.3  14946  latest/stable  canonical✓   core
core18             20230320   2721   latest/stable  canonical✓   base
core20             20230308   1852   latest/stable  canonical✓   base
hello-world        6.4        29     latest/stable  canonical✓   -
rocketchat-server  5.4.5      1544   6.x/stable     rocketchat✓  -
root@example.net / # 
root@example.net / # 
root@example.net / # snap refresh 
error: cannot perform the following tasks:
- Start snap "rocketchat-server" (1545) services (systemctl command [start snap.rocketchat-server.rocketchat-mongo.service] failed with exit status 1: Job for snap.rocketchat-server.rocketchat-mongo.service failed because the control process exited with error code.
See "systemctl status snap.rocketchat-server.rocketchat-mongo.service" and "journalctl -xe" for details.
)
root@example.net / # systemctl status snap.rocketchat-server.rocketchat-mongo.service
● snap.rocketchat-server.rocketchat-mongo.service - Service for snap application rocketchat-server.rocketchat-mongo
     Loaded: loaded (/etc/systemd/system/snap.rocketchat-server.rocketchat-mongo.service; enabled; vendor preset: enabled)
     Active: active (running) since Wed 2023-04-19 02:04:33 CEST; 13s ago
   Main PID: 2445768 (mongod)
      Tasks: 75 (limit: 9502)
     Memory: 266.5M
        CPU: 3.018s
     CGroup: /system.slice/snap.rocketchat-server.rocketchat-mongo.service
root@example.net / #

douglascarlos-dev commented 1 year ago

Estou com o mesmo problema

kupe-dono commented 1 year ago

Hello,

I have the same issue.

Host System : Ubuntu 22.04.2 LTS (GNU/Linux 5.15.0-70-generic x86_64)

@host > snap info rocketchat-server

name:      rocketchat-server
summary:   Rocket.Chat server
publisher: Rocket.Chat (rocketchat✓)
store-url: https://snapcraft.io/rocketchat-server
contact:   https://open.rocket.chat/channel/ubuntu-snap
license:   unset
description: |
  Have your own Slack like online chat, built with Meteor. https://rocket.chat/
commands:
  - rocketchat-server.backupdb
  - rocketchat-server.mongo
  - rocketchat-server.restoredb
services:
  rocketchat-server.rocketchat-caddy: simple, disabled, inactive
  rocketchat-server.rocketchat-mongo: forking, enabled, active
  rocketchat-server:                  simple, enabled, active
snap-id:      wdBUbiEuMNHmAHLBCXQXOcXaOCvbWS1e
tracking:     6.x/candidate
refresh-date: today at 10:32 CEST

Steps to reproduce : sudo snap switch rocketchat-server --channel=6.x/candidate or stable (same results) sudo snap refresh rocketchat-server

Relevant logs :

Apr 20 10:32:25 rocket.local systemd[1]: Reloading.
Apr 20 10:32:26 rocket.local systemd[1]: Mounting Mount unit for rocketchat-server, revision 1545...
Apr 20 10:32:26 rocket.local kernel: loop8: detected capacity change from 0 to 639088
Apr 20 10:32:26 rocket.local systemd[1]: Mounted Mount unit for rocketchat-server, revision 1545.
Apr 20 10:32:26 rocket.local systemd[1]: Started snap.rocketchat-server.hook.pre-refresh.7ad1be10-eed1-4a71-a160-a2acc243c66e.scope.
Apr 20 10:32:27 rocket.local kernel: audit: type=1400 audit(1681979547.041:87): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.hook.pre-refresh" name="/proc/1703/mountinfo" pid=1703 comm="mongo" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:27 rocket.local kernel: audit: type=1400 audit(1681979547.337:88): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.hook.pre-refresh" name="/proc/1711/mountinfo" pid=1711 comm="mongo" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:27 rocket.local kernel: audit: type=1400 audit(1681979547.417:89): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.hook.pre-refresh" name="/proc/1719/mountinfo" pid=1719 comm="mongo" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:27 rocket.local kernel: audit: type=1400 audit(1681979547.493:90): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.hook.pre-refresh" name="/proc/1727/mountinfo" pid=1727 comm="mongo" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:27 rocket.local kernel: audit: type=1400 audit(1681979547.709:91): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.hook.pre-refresh" name="/proc/1739/mountinfo" pid=1739 comm="mongod" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:27 rocket.local mongod[1120]: {"t":{"$date":"2023-04-20T10:32:27.720+02:00"},"s":"I",  "c":"REPL",     "id":40441,   "ctx":"SignalHandler","msg":"Stopping TopologyVersionObserver"}
Apr 20 10:32:27 rocket.local mongod[1120]: {"t":{"$date":"2023-04-20T10:32:27.726+02:00"},"s":"I",  "c":"REPL",     "id":40447,   "ctx":"TopologyVersionObserver","msg":"Stopped TopologyVersionObserver"}
Apr 20 10:32:28 rocket.local rocketchat-server.rocketchat-mongo[1769]: {"t":{"$date":"2023-04-20T10:32:28.372+02:00"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"main","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
Apr 20 10:32:28 rocket.local rocketchat-server.rocketchat-mongo[1769]: {"t":{"$date":"2023-04-20T10:32:28.374+02:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
Apr 20 10:32:28 rocket.local rocketchat-server.rocketchat-mongo[1769]: {"t":{"$date":"2023-04-20T10:32:28.374+02:00"},"s":"I",  "c":"NETWORK",  "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}
Apr 20 10:32:28 rocket.local rocketchat-server.rocketchat-mongo[1769]: There doesn't seem to be a server running with dbpath: /var/snap/rocketchat-server/common
Apr 20 10:32:28 rocket.local rocketchat-server.rocketchat-mongo[1740]: [ERROR] mongo server shutdown failed
Apr 20 10:32:28 rocket.local systemd[1]: snap.rocketchat-server.rocketchat-mongo.service: Control process exited, code=exited, status=1/FAILURE
Apr 20 10:32:28 rocket.local systemd[1]: snap.rocketchat-server.rocketchat-mongo.service: Failed with result 'exit-code'.
Apr 20 10:32:28 rocket.local systemd[1]: snap.rocketchat-server.rocketchat-mongo.service: Consumed 8.439s CPU time.
Apr 20 10:32:28 rocket.local systemd[1]: snap.rocketchat-server.rocketchat-mongo.service: Scheduled restart job, restart counter is at 1.
Apr 20 10:32:28 rocket.local systemd[1]: Stopped Service for snap application rocketchat-server.rocketchat-mongo.
Apr 20 10:32:28 rocket.local systemd[1]: snap.rocketchat-server.rocketchat-mongo.service: Consumed 8.439s CPU time.
Apr 20 10:32:28 rocket.local systemd[1]: Starting Service for snap application rocketchat-server.rocketchat-mongo...
Apr 20 10:32:28 rocket.local rocketchat-server.rocketchat-mongo[1801]: about to fork child process, waiting until server is ready for connections.
Apr 20 10:32:28 rocket.local rocketchat-server.rocketchat-mongo[1803]: forked process: 1803
Apr 20 10:32:28 rocket.local mongod[1803]: {"t":{"$date":"2023-04-20T10:32:28.621+02:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
Apr 20 10:32:28 rocket.local mongod[1803]: {"t":{"$date":"2023-04-20T10:32:28.621+02:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
Apr 20 10:32:28 rocket.local systemd[1]: snap.rocketchat-server.hook.pre-refresh.7ad1be10-eed1-4a71-a160-a2acc243c66e.scope: Deactivated successfully.
Apr 20 10:32:28 rocket.local systemd[1]: snap.rocketchat-server.hook.pre-refresh.7ad1be10-eed1-4a71-a160-a2acc243c66e.scope: Consumed 1.524s CPU time.
Apr 20 10:32:28 rocket.local systemd[1]: snap.rocketchat-server.rocketchat-mongo.service: Deactivated successfully.
Apr 20 10:32:28 rocket.local systemd[1]: Stopped Service for snap application rocketchat-server.rocketchat-mongo.
Apr 20 10:32:28 rocket.local systemd[1]: Stopping Service for snap application rocketchat-server.rocketchat-server...
Apr 20 10:32:29 rocket.local rocketchat-server.rocketchat-server[1183]: /snap/rocketchat-server/1544/helpers/rocketchat.sh: line 23:  1252 Killed                  node $SNAP/main.js
Apr 20 10:32:29 rocket.local systemd[1]: snap.rocketchat-server.rocketchat-server.service: Deactivated successfully.
Apr 20 10:32:29 rocket.local systemd[1]: Stopped Service for snap application rocketchat-server.rocketchat-server.
Apr 20 10:32:29 rocket.local systemd[1]: snap.rocketchat-server.rocketchat-server.service: Consumed 34.543s CPU time.
Apr 20 10:32:29 rocket.local snapd[835]: services.go:1103: RemoveSnapServices - disabling snap.rocketchat-server.rocketchat-caddy.service
Apr 20 10:32:29 rocket.local snapd[835]: services.go:1103: RemoveSnapServices - disabling snap.rocketchat-server.rocketchat-mongo.service
Apr 20 10:32:29 rocket.local snapd[835]: services.go:1103: RemoveSnapServices - disabling snap.rocketchat-server.rocketchat-server.service
Apr 20 10:32:29 rocket.local systemd[1]: Reloading.
Apr 20 10:32:30 rocket.local kernel: audit: type=1400 audit(1681979550.745:92): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="/snap/snapd/18933/usr/lib/snapd/snap-confine" pid=1890 comm="apparmor_parser"
Apr 20 10:32:30 rocket.local kernel: audit: type=1400 audit(1681979550.745:93): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="/snap/snapd/18933/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=1890 comm="apparmor_parser"
Apr 20 10:32:31 rocket.local kernel: audit: type=1400 audit(1681979551.001:94): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.rocketchat-server.hook.post-refresh" pid=1895 comm="apparmor_parser"
Apr 20 10:32:31 rocket.local kernel: audit: type=1400 audit(1681979551.005:95): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.rocketchat-server.hook.install" pid=1894 comm="apparmor_parser"
Apr 20 10:32:31 rocket.local kernel: audit: type=1400 audit(1681979551.037:96): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.rocketchat-server.hook.pre-refresh" pid=1896 comm="apparmor_parser"
Apr 20 10:32:31 rocket.local systemd[1]: Reloading.
Apr 20 10:32:32 rocket.local systemd[1]: Started snap.rocketchat-server.hook.post-refresh.18eba5bd-c9f5-4be7-b7ba-209105b2a246.scope.
Apr 20 10:32:32 rocket.local systemd[1]: snap.rocketchat-server.hook.post-refresh.18eba5bd-c9f5-4be7-b7ba-209105b2a246.scope: Deactivated successfully.
Apr 20 10:32:32 rocket.local systemd[1]: Reloading.
Apr 20 10:32:33 rocket.local systemd[1]: Starting Service for snap application rocketchat-server.rocketchat-mongo...
Apr 20 10:32:33 rocket.local kernel: show_signal: 8 callbacks suppressed
Apr 20 10:32:33 rocket.local kernel: traps: mongod[2024] trap invalid opcode ip:557876bd26da sp:7ffcfc3a8120 error:0 in mongod[557872b2f000+520e000]
Apr 20 10:32:33 rocket.local rocketchat-server.rocketchat-mongo[2000]: /snap/rocketchat-server/1545/helpers/mongo.sh: line 17:  2024 Illegal instruction     (core dumped) mongod --config=$SNAP_DATA/mongod.conf --fork --syslog
Apr 20 10:32:33 rocket.local rocketchat-server.rocketchat-mongo[2000]: [ERROR] mongo server start failed
Apr 20 10:32:33 rocket.local systemd[1]: snap.rocketchat-server.rocketchat-mongo.service: Control process exited, code=exited, status=1/FAILURE
Apr 20 10:32:33 rocket.local systemd[1]: snap.rocketchat-server.rocketchat-mongo.service: Failed with result 'exit-code'.
Apr 20 10:32:33 rocket.local systemd[1]: Failed to start Service for snap application rocketchat-server.rocketchat-mongo.
Apr 20 10:32:33 rocket.local systemd[1]: Cannot find unit for notify message of PID 1999, ignoring.
Apr 20 10:32:33 rocket.local systemd[1]: Stopped Service for snap application rocketchat-server.rocketchat-mongo.
Apr 20 10:32:33 rocket.local systemd[1]: Reloading.
Apr 20 10:32:34 rocket.local snapd[835]: taskrunner.go:289: [change 42 "Start snap \"rocketchat-server\" (1545) services" task] failed: systemctl command [start snap.rocketchat-server.rocketchat-mongo.service] failed with exit status 1: Job for snap.rocketchat-server.rocketchat-mongo.service failed because the control process exited with error code.
Apr 20 10:32:34 rocket.local snapd[835]: See "systemctl status snap.rocketchat-server.rocketchat-mongo.service" and "journalctl -xeu snap.rocketchat-server.rocketchat-mongo.service" for details.
Apr 20 10:32:34 rocket.local snapd[835]: services.go:1103: RemoveSnapServices - disabling snap.rocketchat-server.rocketchat-caddy.service
Apr 20 10:32:34 rocket.local snapd[835]: services.go:1103: RemoveSnapServices - disabling snap.rocketchat-server.rocketchat-mongo.service
Apr 20 10:32:34 rocket.local snapd[835]: services.go:1103: RemoveSnapServices - disabling snap.rocketchat-server.rocketchat-server.service
Apr 20 10:32:34 rocket.local systemd[1]: Reloading.
Apr 20 10:32:35 rocket.local kernel: audit: type=1400 audit(1681979555.182:105): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="/snap/snapd/18933/usr/lib/snapd/snap-confine" pid=2115 comm="apparmor_parser"
Apr 20 10:32:35 rocket.local kernel: audit: type=1400 audit(1681979555.182:106): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="/snap/snapd/18933/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=2115 comm="apparmor_parser"
Apr 20 10:32:35 rocket.local kernel: audit: type=1400 audit(1681979555.442:107): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.rocketchat-server.hook.post-refresh" pid=2120 comm="apparmor_parser"
Apr 20 10:32:35 rocket.local kernel: audit: type=1400 audit(1681979555.442:108): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.rocketchat-server.hook.pre-refresh" pid=2121 comm="apparmor_parser"
Apr 20 10:32:35 rocket.local kernel: audit: type=1400 audit(1681979555.446:109): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.rocketchat-server.hook.install" pid=2119 comm="apparmor_parser"
Apr 20 10:32:35 rocket.local kernel: audit: type=1400 audit(1681979555.474:110): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.rocketchat-server.mongo" pid=2122 comm="apparmor_parser"
Apr 20 10:32:35 rocket.local kernel: audit: type=1400 audit(1681979555.474:111): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.rocketchat-server.hook.configure" pid=2118 comm="apparmor_parser"
Apr 20 10:32:35 rocket.local kernel: audit: type=1400 audit(1681979555.474:112): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.rocketchat-server.backupdb" pid=2117 comm="apparmor_parser"
Apr 20 10:32:35 rocket.local kernel: audit: type=1400 audit(1681979555.726:113): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.rocketchat-server.restoredb" pid=2123 comm="apparmor_parser"
Apr 20 10:32:35 rocket.local systemd[1]: Reloading.
Apr 20 10:32:36 rocket.local systemd[1]: Reloading.
Apr 20 10:32:36 rocket.local systemd[1]: Starting Service for snap application rocketchat-server.rocketchat-mongo...
Apr 20 10:32:36 rocket.local rocketchat-server.rocketchat-mongo[2223]: about to fork child process, waiting until server is ready for connections.
Apr 20 10:32:36 rocket.local rocketchat-server.rocketchat-mongo[2225]: forked process: 2225
Apr 20 10:32:37 rocket.local mongod[2225]: {"t":{"$date":"2023-04-20T10:32:37.001+02:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
Apr 20 10:32:37 rocket.local mongod[2225]: {"t":{"$date":"2023-04-20T10:32:37.001+02:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
Apr 20 10:32:38 rocket.local mongod[2225]: {"t":{"$date":"2023-04-20T10:32:38.153+02:00"},"s":"W",  "c":"CONTROL",  "id":22120,   "ctx":"initandlisten","msg":"Access control is not enabled for the database. Read and write access to data and configuration is unrestricted","tags":["startupWarnings"]}
Apr 20 10:32:38 rocket.local mongod[2225]: {"t":{"$date":"2023-04-20T10:32:38.153+02:00"},"s":"W",  "c":"CONTROL",  "id":22138,   "ctx":"initandlisten","msg":"You are running this process as the root user, which is not recommended","tags":["startupWarnings"]}
Apr 20 10:32:38 rocket.local mongod[2225]: {"t":{"$date":"2023-04-20T10:32:38.153+02:00"},"s":"W",  "c":"CONTROL",  "id":22184,   "ctx":"initandlisten","msg":"Soft rlimits too low","attr":{"currentValue":1024,"recommendedMinimum":64000},"tags":["startupWarnings"]}
Apr 20 10:32:38 rocket.local mongod[2225]: {"t":{"$date":"2023-04-20T10:32:38.227+02:00"},"s":"W",  "c":"FTDC",     "id":23915,   "ctx":"initandlisten","msg":"Error getting directory iterator '{sysBlockPathStr}': {ec_message}","attr":{"sysBlockPathStr":"/sys/block","ec_message":"Permission denied"}}
Apr 20 10:32:38 rocket.local mongod[2225]: {"t":{"$date":"2023-04-20T10:32:38.240+02:00"},"s":"I",  "c":"REPL",     "id":40440,   "ctx":"initandlisten","msg":"Starting the TopologyVersionObserver"}
Apr 20 10:32:38 rocket.local mongod[2225]: {"t":{"$date":"2023-04-20T10:32:38.241+02:00"},"s":"I",  "c":"REPL",     "id":40445,   "ctx":"TopologyVersionObserver","msg":"Started TopologyVersionObserver"}
Apr 20 10:32:38 rocket.local rocketchat-server.rocketchat-mongo[2223]: child process started successfully, parent exiting
Apr 20 10:32:38 rocket.local systemd[1]: Started Service for snap application rocketchat-server.rocketchat-mongo.
Apr 20 10:32:38 rocket.local systemd[1]: Started Service for snap application rocketchat-server.rocketchat-server.
Apr 20 10:32:38 rocket.local systemd[1]: snap-rocketchat\x2dserver-1545.mount: Deactivated successfully.
Apr 20 10:32:38 rocket.local rocketchat-server.rocketchat-server[2294]: node $SNAP/main.js
Apr 20 10:32:38 rocket.local systemd[1]: Reloading.
Apr 20 10:32:39 rocket.local kernel: kauditd_printk_skb: 6 callbacks suppressed
Apr 20 10:32:39 rocket.local kernel: audit: type=1400 audit(1681979559.002:120): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/netstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:39 rocket.local kernel: audit: type=1400 audit(1681979559.002:121): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/snmp" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:39 rocket.local kernel: audit: type=1400 audit(1681979559.002:122): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/mountinfo" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:39 rocket.local kernel: audit: type=1400 audit(1681979559.002:123): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/vmstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:39 rocket.local systemd[1]: Starting Ubuntu Advantage Timer for running repeated jobs...
Apr 20 10:32:39 rocket.local snapd[835]: handlers.go:673: Reported install problem for "rocketchat-server" as already-reported
Apr 20 10:32:39 rocket.local systemd[1]: ua-timer.service: Deactivated successfully.
Apr 20 10:32:39 rocket.local systemd[1]: Finished Ubuntu Advantage Timer for running repeated jobs.
Apr 20 10:32:40 rocket.local kernel: audit: type=1400 audit(1681979559.998:124): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/netstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:40 rocket.local kernel: audit: type=1400 audit(1681979559.998:125): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/snmp" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:40 rocket.local kernel: audit: type=1400 audit(1681979559.998:126): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/mountinfo" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:40 rocket.local kernel: audit: type=1400 audit(1681979559.998:127): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/vmstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:41 rocket.local kernel: audit: type=1400 audit(1681979560.998:128): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/netstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:41 rocket.local kernel: audit: type=1400 audit(1681979560.998:129): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/snmp" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:44 rocket.local kernel: kauditd_printk_skb: 14 callbacks suppressed
Apr 20 10:32:44 rocket.local kernel: audit: type=1400 audit(1681979564.146:144): apparmor="ALLOWED" operation="open" profile="/usr/sbin/sssd" name="/proc/812/cmdline" pid=913 comm="sssd_nss" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:45 rocket.local kernel: audit: type=1400 audit(1681979564.998:145): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/netstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:45 rocket.local kernel: audit: type=1400 audit(1681979564.998:146): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/snmp" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:45 rocket.local kernel: audit: type=1400 audit(1681979564.998:147): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/mountinfo" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:45 rocket.local kernel: audit: type=1400 audit(1681979564.998:148): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/vmstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:46 rocket.local kernel: audit: type=1400 audit(1681979565.998:149): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/netstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:46 rocket.local kernel: audit: type=1400 audit(1681979565.998:150): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/snmp" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:46 rocket.local kernel: audit: type=1400 audit(1681979565.998:151): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/mountinfo" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:46 rocket.local kernel: audit: type=1400 audit(1681979565.998:152): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/vmstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:46 rocket.local rocketchat-server.rocketchat-server[2358]: strict mode: use allowUnionTypes to allow union type keyword at "#/properties/value" (strictTypes)
Apr 20 10:32:47 rocket.local kernel: audit: type=1400 audit(1681979566.998:153): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/netstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:47 rocket.local rocketchat-server.rocketchat-server[2358]: LocalStore: store created at
Apr 20 10:32:47 rocket.local rocketchat-server.rocketchat-server[2358]: LocalStore: store created at
Apr 20 10:32:47 rocket.local rocketchat-server.rocketchat-server[2358]: LocalStore: store created at
Apr 20 10:32:50 rocket.local kernel: kauditd_printk_skb: 11 callbacks suppressed
Apr 20 10:32:50 rocket.local kernel: audit: type=1400 audit(1681979569.999:165): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/netstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:50 rocket.local kernel: audit: type=1400 audit(1681979569.999:166): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/snmp" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:50 rocket.local kernel: audit: type=1400 audit(1681979569.999:167): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/mountinfo" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:50 rocket.local kernel: audit: type=1400 audit(1681979569.999:168): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/vmstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:51 rocket.local kernel: audit: type=1400 audit(1681979570.999:169): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/netstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:51 rocket.local kernel: audit: type=1400 audit(1681979570.999:170): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/snmp" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:51 rocket.local kernel: audit: type=1400 audit(1681979570.999:171): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/mountinfo" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:51 rocket.local kernel: audit: type=1400 audit(1681979570.999:172): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/vmstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:51 rocket.local rocketchat-server.rocketchat-server[2358]: MessageType.render is deprecated. Use MessageType.message instead. livechat_webrtc_video_call
Apr 20 10:32:51 rocket.local rocketchat-server.rocketchat-server[2358]: {"level":40,"time":"2023-04-20T08:32:51.820Z","pid":2358,"hostname":"rocket","name":"VoIPService","msg":"Voip is not enabled. Cant start the service"}
Apr 20 10:32:52 rocket.local kernel: audit: type=1400 audit(1681979572.015:173): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/netstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:52 rocket.local kernel: audit: type=1400 audit(1681979572.015:174): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/snmp" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:55 rocket.local rocketchat-server.rocketchat-server[2358]: Browserslist: caniuse-lite is outdated. Please run:
Apr 20 10:32:55 rocket.local rocketchat-server.rocketchat-server[2358]:   npx update-browserslist-db@latest
Apr 20 10:32:55 rocket.local rocketchat-server.rocketchat-server[2358]:   Why you should do it regularly: https://github.com/browserslist/update-db#readme
Apr 20 10:32:55 rocket.local rocketchat-server.rocketchat-server[2358]: {"level":40,"time":"2023-04-20T08:32:55.410Z","pid":2358,"hostname":"rocket","name":"VoIPService","msg":"VoIP service already stopped"}
Apr 20 10:32:55 rocket.local rocketchat-server.rocketchat-server[2358]: {"level":51,"time":"2023-04-20T08:32:55.804Z","pid":2358,"hostname":"rocket","name":"Migrations","msg":"Not migrating, already at version 281"}
Apr 20 10:32:55 rocket.local rocketchat-server.rocketchat-server[2358]: {"level":51,"time":"2023-04-20T08:32:55.853Z","pid":2358,"hostname":"rocket","name":"DatabaseWatcher","msg":"Using change streams"}
Apr 20 10:32:56 rocket.local kernel: kauditd_printk_skb: 14 callbacks suppressed
Apr 20 10:32:56 rocket.local kernel: audit: type=1400 audit(1681979575.999:189): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/netstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:56 rocket.local kernel: audit: type=1400 audit(1681979575.999:190): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/net/snmp" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:56 rocket.local kernel: audit: type=1400 audit(1681979575.999:191): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/2225/mountinfo" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:56 rocket.local kernel: audit: type=1400 audit(1681979575.999:192): apparmor="DENIED" operation="open" profile="snap.rocketchat-server.rocketchat-mongo" name="/proc/vmstat" pid=2225 comm="ftdc" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: Loaded the Apps Framework and loaded a total of 1 Apps!
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: +--------------------------------------------------------+
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: |                     SERVER RUNNING                     |
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: +--------------------------------------------------------+
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: |                                                        |
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: |  Rocket.Chat Version: 5.4.5                            |
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: |       NodeJS Version: 14.19.3 - x64                    |
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: |      MongoDB Version: 4.4.15                           |
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: |       MongoDB Engine: wiredTiger                       |
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: |             Platform: linux                            |
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: |         Process Port: 3000                             |
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: |             Site URL: https://rocket.local  |
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: |     ReplicaSet OpLog: Enabled                          |
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: |          Commit Hash: 45d3ca8961                       |
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: |        Commit Branch: HEAD                             |
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: |                                                        |
Apr 20 10:32:56 rocket.local rocketchat-server.rocketchat-server[2358]: +--------------------------------------------------------+

debdutdeb commented 1 year ago

this seems like the old apparmour issue

homberger commented 1 year ago

Copied from the logs above:

kernel: traps: mongod[2024] trap invalid opcode ip:557876bd26da sp:7ffcfc3a8120 error:0 in mongod[557872b2f000+520e000]
rocketchat-server.rocketchat-mongo[2000]: /snap/rocketchat-server/1545/helpers/mongo.sh: line 17:  2024 Illegal instruction     (core dumped) mongod --config=$SNAP_DATA/mongod.conf --fork --syslog
rocketchat-server.rocketchat-mongo[2000]: [ERROR] mongo server start failed

@kupe-dono Please check if your cpu is supporting avx or avx2 instructions. (not tested this: If it is running on a virtual machine using QEMU, you need QEMU 7.2 or newer to have support of avx/avx2 instructions. If QEMU is an older version, you could try to use the cpu of the host system)

Copied from MongoDB Platform Support Notes:

MongoDB 5.0 requires use of the AVX instruction set.
It requires the following minimum x86_64 microarchitectures:

For Intel x86_64, MongoDB requires one of:
- a Sandy Bridge or later Core processor, or
- a Tiger Lake or later Celeron or Pentium processor.

For AMD x86_64, MongoDB requires:
- a Bulldozer or later processor.

The available snap version of Rocket.Chat is not checking if the cpu is supporting avx/avx2, but there is a commit on branch develop that will fix this problem, I guess:

https://github.com/RocketChat/rocketchat-server-snap/blob/c66f1d08becef6878adc8009c89db22f4b2b3264/snap/hooks/install#L80-L84

tuxmartin commented 1 year ago

@homberger Hello, thanks for the information about MongoDB.

My Rocket.Chat is in the virtual machine on Proxmox (qemu) with a very old CPU Intel Xeon W3530 (launch date Q1'10) without AVX support. So I have to stay with Rocket.Chat 5.x :-( Because if I try to add avx feature, it crashes on error:

kvm: warning: host doesn't support requested feature: CPUID.01H:ECX.avx [bit 28]
kvm: Host doesn't support requested features
TASK ERROR: start failed: QEMU exited with code 1

For people with newer CPU, just add a file with this content:

# cat /etc/pve/virtual-guest/cpu-models.conf
cpu-model: avx
  flags +avx
  phys-bits host
  hidden 0
  hv-vendor-id proxmox
  reported-model kvm64

And set CPU to "avx" on your virtual machine, and it should work.

kupe-dono commented 1 year ago

Thanks a lot @homberger, my proxmox is in 7.3 version but the proc vm's type was configured on default(kvm64). I set it to "host" and it works :)

homberger commented 1 year ago

@tuxmartin

My Rocket.Chat is in the virtual machine on Proxmox (qemu) with a very old CPU Intel Xeon W3530 (launch date Q1'10) without AVX support. So I have to stay with Rocket.Chat 5.x :-(

I did not test this yet, but I am going to use this approach if it will be necessary for any installation: You could try to override the mongodb version the snap is using. Use MongoDB 4.4 instead of 5.0 with Rocket.Chat 6. Docs (easier than I thought): https://snapcraft.io/docs/overrides#heading--overriding-the-pull-step

This will be overridden by you: https://github.com/RocketChat/rocketchat-server-snap/blob/6.0.0/snap/snapcraft.yaml#L73-L83

tuxmartin commented 1 year ago

@homberger it looks good. How can I use it?

k-ahn commented 8 months ago

@tuxmartin I have the same question. @homberger Help!

k-ahn commented 5 months ago

@homberger Please share the details!

RocketChat / server-snap