search

Skylar-Tech / node-red-contrib-matrix-chat

Matrix chat server support for Node-RED
GNU General Public License v3.0
31 stars 10 forks source link

Server Config: Wrong Access Token causes NodeRED to crash #40

Closed Angstroem closed 2 years ago

Angstroem commented 2 years ago

Problem

When setting up a new Matrix server config and using a access token that is invalid, the NodeRED container crashes. This furthermore forces a backup to be redeployed as the container will not start again with the wrongly configured token.

Expectation

If the server config is wrong, an error is thrown in the NodeRED console

Actual behavior

The NodeRED Docker container crashes

How to reproduce?

Create a new Matrix server config or edit any currently working config and change to the access token to an invalid one, then redeploy the flow.

Additional information

System

NodeRed: 2.1.6, latest today Docker: Version 20.10.9, build c2ea9bc node-red-contrib-matrix-chat: 0.3.0, latest today

Logs

When crashing, the container yields the following output:

node-red_1  | 26 Jan 21:18:34 - [info] Starting flows
node-red_1  | 26 Jan 21:18:34 - [info] [matrix-server-config:Matrix@MyServer] Initializing Matrix Server Config node
node-red_1  | 26 Jan 21:18:34 - [info] [matrix-server-config:Matrix@MyServer] Initializing crypto...
node-red_1  | Crypto: Starting up crypto store...
node-red_1  | 26 Jan 21:18:34 - [info] Started flows
node-red_1  | Crypto: initialising roomlist...
node-red_1  | Crypto: initialising crypto object...
node-red_1  | Crypto: initialising Olm...
node-red_1  | Crypto: initialising Olm device...
node-red_1  | Crypto: loading device list...
node-red_1  | Crypto: fetching own devices...
node-red_1  | Crypto: checking for key backup...
node-red_1  | Checking key backup status...
node-red_1  | 26 Jan 21:18:35 - [info] [matrix-server-config:Matrix@MyServer] Connecting to Matrix server...
node-red_1  | 26 Jan 21:18:35 - [error] [matrix-server-config:Matrix@MyServer] [Session.logged_out] M_UNKNOWN_TOKEN: Invalid macaroon passed.
node-red_1  | Error checking for active key backup M_UNKNOWN_TOKEN: Invalid macaroon passed.
node-red_1  |     at parseErrorResponse (/data/node_modules/matrix-js-sdk/lib/http-api.js:860:13)
node-red_1  |     at /data/node_modules/matrix-js-sdk/lib/http-api.js:810:17
node-red_1  |     at Request._callback (/data/node_modules/matrix-js-sdk/lib/http-api.js:734:9)
node-red_1  |     at Request.self.callback (/data/node_modules/request/request.js:185:22)
node-red_1  |     at Request.emit (events.js:400:28)
node-red_1  |     at Request.<anonymous> (/data/node_modules/request/request.js:1154:10)
node-red_1  |     at Request.emit (events.js:400:28)
node-red_1  |     at IncomingMessage.<anonymous> (/data/node_modules/request/request.js:1076:12)
node-red_1  |     at Object.onceWrapper (events.js:519:28)
node-red_1  |     at IncomingMessage.emit (events.js:412:35) {
node-red_1  |   errcode: 'M_UNKNOWN_TOKEN',
node-red_1  |   data: {
node-red_1  |     errcode: 'M_UNKNOWN_TOKEN',
node-red_1  |     error: 'Invalid macaroon passed.',
node-red_1  |     soft_logout: false
node-red_1  |   },
node-red_1  |   httpStatus: 401
node-red_1  | }
node-red_1  | 26 Jan 21:18:35 - [error] [matrix-server-config:Matrix@MyServer] [Session.logged_out] M_UNKNOWN_TOKEN: Invalid macaroon passed.
node-red_1  | M_UNKNOWN_TOKEN: Invalid macaroon passed.
node-red_1  |     at parseErrorResponse (/data/node_modules/matrix-js-sdk/lib/http-api.js:860:13)
node-red_1  |     at /data/node_modules/matrix-js-sdk/lib/http-api.js:810:17
node-red_1  |     at Request._callback (/data/node_modules/matrix-js-sdk/lib/http-api.js:734:9)
node-red_1  |     at Request.self.callback (/data/node_modules/request/request.js:185:22)
node-red_1  |     at Request.emit (events.js:400:28)
node-red_1  |     at Request.<anonymous> (/data/node_modules/request/request.js:1154:10)
node-red_1  |     at Request.emit (events.js:400:28)
node-red_1  |     at IncomingMessage.<anonymous> (/data/node_modules/request/request.js:1076:12)
node-red_1  |     at Object.onceWrapper (events.js:519:28)
node-red_1  |     at IncomingMessage.emit (events.js:412:35) {
node-red_1  |   errcode: 'M_UNKNOWN_TOKEN',
node-red_1  |   data: {
node-red_1  |     errcode: 'M_UNKNOWN_TOKEN',
node-red_1  |     error: 'Invalid macaroon passed.',
node-red_1  |     soft_logout: false
node-red_1  |   },
node-red_1  |   httpStatus: 401
node-red_1  | }
node-red_1  | Caching capabilities:  {}
node-red_1  | Getting saved sync token...
node-red_1  | Getting push rules...
node-red_1  | Got saved sync token
node-red_1  | Getting saved sync...
node-red_1  | Got reply from saved sync, exists? false
node-red_1  | 26 Jan 21:18:35 - [error] [matrix-server-config:Matrix@MyServer] [Session.logged_out] M_UNKNOWN_TOKEN: Invalid macaroon passed.
node-red_1  | M_UNKNOWN_TOKEN: Invalid macaroon passed.
node-red_1  |     at parseErrorResponse (/data/node_modules/matrix-js-sdk/lib/http-api.js:860:13)
node-red_1  |     at /data/node_modules/matrix-js-sdk/lib/http-api.js:810:17
node-red_1  |     at Request._callback (/data/node_modules/matrix-js-sdk/lib/http-api.js:734:9)
node-red_1  |     at Request.self.callback (/data/node_modules/request/request.js:185:22)
node-red_1  |     at Request.emit (events.js:400:28)
node-red_1  |     at Request.<anonymous> (/data/node_modules/request/request.js:1154:10)
node-red_1  |     at Request.emit (events.js:400:28)
node-red_1  |     at IncomingMessage.<anonymous> (/data/node_modules/request/request.js:1076:12)
node-red_1  |     at Object.onceWrapper (events.js:519:28)
node-red_1  |     at IncomingMessage.emit (events.js:412:35) {
node-red_1  |   errcode: 'M_UNKNOWN_TOKEN',
node-red_1  |   data: {
node-red_1  |     errcode: 'M_UNKNOWN_TOKEN',
node-red_1  |     error: 'Invalid macaroon passed.',
node-red_1  |     soft_logout: false
node-red_1  |   },
node-red_1  |   httpStatus: 401
node-red_1  | }
node-red_1  | M_UNKNOWN_TOKEN: Invalid macaroon passed.
node-red_1  |     at parseErrorResponse (/data/node_modules/matrix-js-sdk/lib/http-api.js:860:13)
node-red_1  |     at /data/node_modules/matrix-js-sdk/lib/http-api.js:810:17
node-red_1  |     at Request._callback (/data/node_modules/matrix-js-sdk/lib/http-api.js:734:9)
node-red_1  |     at Request.self.callback (/data/node_modules/request/request.js:185:22)
node-red_1  |     at Request.emit (events.js:400:28)
node-red_1  |     at Request.<anonymous> (/data/node_modules/request/request.js:1154:10)
node-red_1  |     at Request.emit (events.js:400:28)
node-red_1  |     at IncomingMessage.<anonymous> (/data/node_modules/request/request.js:1076:12)
node-red_1  |     at Object.onceWrapper (events.js:519:28)
node-red_1  |     at IncomingMessage.emit (events.js:412:35) {
node-red_1  |   errcode: 'M_UNKNOWN_TOKEN',
node-red_1  |   data: {
node-red_1  |     errcode: 'M_UNKNOWN_TOKEN',
node-red_1  |     error: 'Invalid macaroon passed.',
node-red_1  |     soft_logout: false
node-red_1  |   },
node-red_1  |   httpStatus: 401
node-red_1  | }
node-red_1  | 26 Jan 21:18:35 - [red] Uncaught Exception:
node-red_1  | 26 Jan 21:18:35 - [error] RuntimeError: abort(M_UNKNOWN_TOKEN: Invalid macaroon passed.). Build with -s ASSERTIONS=1 for more info.
node-red_1  |     at process.q (/data/node_modules/olm/olm.js:27:182)
node-red_1  |     at process.emit (events.js:400:28)
node-red_1  |     at processPromiseRejections (internal/process/promises.js:245:33)
node-red_1  |     at processTicksAndRejections (internal/process/task_queues.js:96:32)
node-red_1  | npm ERR! code ELIFECYCLE
node-red_1  | npm ERR! errno 1
node-red_1  | npm ERR! node-red-docker@2.1.6 start: `node $NODE_OPTIONS node_modules/node-red/red.js $FLOWS "--userDir" "/data"`
node-red_1  | npm ERR! Exit status 1
node-red_1  | npm ERR!
node-red_1  | npm ERR! Failed at the node-red-docker@2.1.6 start script.
node-red_1  | npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
node-red_1  |
node-red_1  | npm ERR! A complete log of this run can be found in:
node-red_1  | npm ERR!     /data/.npm/_logs/2022-01-26T20_18_35_168Z-debug.log
nodered_node-red_1 exited with code 1

The logfile at /data/.npm/_logs/2022-01-26T20_18_35_168Z-debug.log says:

0 info it worked if it ends with ok
1 verbose cli [
1 verbose cli   '/usr/local/bin/node',
1 verbose cli   '/usr/local/bin/npm',
1 verbose cli   '--no-update-notifier',
1 verbose cli   '--no-fund',
1 verbose cli   'start',
1 verbose cli   '--cache',
1 verbose cli   '/data/.npm',
1 verbose cli   '--',
1 verbose cli   '--userDir',
1 verbose cli   '/data'
1 verbose cli ]
2 info using npm@6.14.15
3 info using node@v14.18.2
4 verbose config Skipping project config: /usr/src/node-red/.npmrc. (matches userconfig)
5 verbose run-script [ 'prestart', 'start', 'poststart' ]
6 info lifecycle node-red-docker@2.1.6~prestart: node-red-docker@2.1.6
7 info lifecycle node-red-docker@2.1.6~start: node-red-docker@2.1.6
8 verbose lifecycle node-red-docker@2.1.6~start: unsafe-perm in lifecycle true
9 verbose lifecycle node-red-docker@2.1.6~start: PATH: /usr/local/lib/node_modules/npm/node_modules/npm-lifecycle/node-gyp-bin:/usr/src/node-red/node_modules/.bin:/usr/src/node-red/node_modules/.bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
10 verbose lifecycle node-red-docker@2.1.6~start: CWD: /usr/src/node-red
11 silly lifecycle node-red-docker@2.1.6~start: Args: [
11 silly lifecycle   '-c',
11 silly lifecycle   'node $NODE_OPTIONS node_modules/node-red/red.js $FLOWS "--userDir" "/data"'
11 silly lifecycle ]
12 silly lifecycle node-red-docker@2.1.6~start: Returned: code: 1  signal: null
13 info lifecycle node-red-docker@2.1.6~start: Failed to exec start script
14 verbose stack Error: node-red-docker@2.1.6 start: `node $NODE_OPTIONS node_modules/node-red/red.js $FLOWS "--userDir" "/data"`
14 verbose stack Exit status 1
14 verbose stack     at EventEmitter.<anonymous> (/usr/local/lib/node_modules/npm/node_modules/npm-lifecycle/index.js:332:16)
14 verbose stack     at EventEmitter.emit (events.js:400:28)
14 verbose stack     at ChildProcess.<anonymous> (/usr/local/lib/node_modules/npm/node_modules/npm-lifecycle/lib/spawn.js:55:14)
14 verbose stack     at ChildProcess.emit (events.js:400:28)
14 verbose stack     at maybeClose (internal/child_process.js:1058:16)
14 verbose stack     at Process.ChildProcess._handle.onexit (internal/child_process.js:293:5)
15 verbose pkgid node-red-docker@2.1.6
16 verbose cwd /usr/src/node-red
17 verbose Linux 4.19.0-17-amd64
18 verbose argv "/usr/local/bin/node" "/usr/local/bin/npm" "--no-update-notifier" "--no-fund" "start" "--cache" "/data/.npm" "--" "--userDir" "/data"
19 verbose node v14.18.2
20 verbose npm  v6.14.15
21 error code ELIFECYCLE
22 error errno 1
23 error node-red-docker@2.1.6 start: `node $NODE_OPTIONS node_modules/node-red/red.js $FLOWS "--userDir" "/data"`
23 error Exit status 1
24 error Failed at the node-red-docker@2.1.6 start script.
24 error This is probably not a problem with npm. There is likely additional logging output above.
25 verbose exit [ 1, true ]
skylord123 commented 2 years ago

Yeah I ran into this bug myself and have not found a solution yet. olm.js is throwing a RuntimeException so I need to dig in and see if there is any way to prevent this.

The file is obfuscated (because it is compiled) so it has made progress on this slow.

skylord123 commented 2 years ago

One way to fix this is to check the access token with loginWithToken() before we pass it to the client. I would assume the error would still happen if the auth token got invalidated (or even if the server loses connection) so I will have to out those cases.

skylord123 commented 2 years ago

@Angstroem Give the latest version a try. If an invalid token is passed it wont start the client anymore. This should be resolved.

Angstroem commented 2 years ago

Updated to version 0.4.1 today and i can confirm that a wrong access token does not crash NodeRED anymore. Thanks for the fast fix @skylord123 !

skylord123 commented 2 years ago

@Angstroem awesome, glad it worked out :)