leaking unencrypted messages during startup

[hacker-h]

I just installed and gave it a try in the recent node red container.

Apparently if you attempt to send messages while the "Send message" node is not connected yet, those messages will be queued and sent upon readiness without encryption.

All messages sent after connection readiness are however encrypted again as expected.

[skylord123]

This is interesting. I assume this is because the crypto hasn't fully initialized.

I'll have to change it so that it doesn't go to full "connected" state until crypto is finished starting up (unless crypto isn't enabled). That should fix this problem.

This is mainly just for my own curiosity but why are you sending messages right as node-red starts? I've never had anything that sends a message right away so I am just curious what your use-case is.

Thanks for the issue :)

[hacker-h]

My use case is that I use notifications for sensor messages (which can send at arbitrary times and also very frequently). Also it can take from few seconds to almost a minute to establish encryption sometimes, so it is easy to face this issue when quickly debugging e.g. with injector nodes :)

[skylord123]

I just looked through the source for matrix-js-sdk and it should not be sending unencypted messages to encrypted rooms.. They have a check before a message sends that checks if the room is encrypted and if so it throws an error.

There is an open issue on the sdk where people have found if they join a room then send a message before the client is fully in the room it will send unencrypted. Are you joining a room and sending a message or sending a message to a room the client is already in? For reference here is the issue: https://github.com/matrix-org/matrix-js-sdk/issues/906

If you are sending messages to a room the client is already in (and has been for a while) then this is probably not the problem. If this is the problem we will have to wait for it to be fixed upstream.

[skylord123]

Another question: what sort of device are you running on?

I usually run on PowerEdge servers so encryption enabled really quick. It's interesting that it takes a while for yours to start up. If you could get the logs from Node-RED it would help a ton in debugging this. If you are running on a raspberry-pi that could make sense on why it takes a while and I may need to order one to test this out.

[skylord123]

I was able to replicate this and found the issue. It is for sure a bug in this repo. I'll get a new release pushed out tonight and update this issue.

Thanks agaain!

Still curious why crypto takes sometimes up to a minute to init for you. That seems really odd (unless you are on lower end hardware).

[hacker-h]

I'm running on a pretty low level amd64 hardware with specs comparable to raspberry pi

here are some logs, I replaced keys etc. with #VARIABLES#

nodered_1  | 24 Nov 21:44:33 - [info] [matrix-server-config:@#BOT_USER#] Initializing Matrix Server Config node
nodered_1  | 24 Nov 21:44:33 - [info] [matrix-server-config:@#BOT_USER#] Initializing crypto...
nodered_1  | Crypto: Starting up crypto store...
nodered_1  | 24 Nov 21:44:33 - [info] Started flows
nodered_1  | Crypto: initialising roomlist...
nodered_1  | Crypto: initialising crypto object...
nodered_1  | Crypto: initialising Olm...
nodered_1  | Crypto: initialising Olm device...
nodered_1  | Crypto: loading device list...
nodered_1  | Crypto: fetching own devices...
nodered_1  | Crypto: checking for key backup...
nodered_1  | Checking key backup status...
nodered_1  | 24 Nov 21:44:33 - [info] [matrix-server-config:@#BOT_USER#] Connecting to Matrix server...
nodered_1  | Getting saved sync token...
nodered_1  | Getting push rules...
nodered_1  | Got saved sync token
nodered_1  | Getting saved sync...
nodered_1  | Got reply from saved sync, exists? false
nodered_1  | 24 Nov 21:44:33 - [info] [mqtt-broker:hivemq] Connected to broker: mqtt://hivemq:1883
nodered_1  | Got push rules
nodered_1  | Checking lazy load status...
nodered_1  | Checking whether lazy loading has changed in store...
nodered_1  | Storing client options...
nodered_1  | Stored client options
nodered_1  | Getting filter...
nodered_1  | Ignoring signature from unknown key ed25519:#KEY01#
nodered_1  | No usable key backup: not enabling key backup
nodered_1  | Sending first sync request...
nodered_1  | Waiting for saved sync before starting sync processing...
nodered_1  | Initial sync performed - resetting device tracking state
nodered_1  | Now tracking device list for @#BOT_USER#
nodered_1  | Enabling encryption in !#ROOM_ID#; starting to track device lists for all users therein
nodered_1  | Starting to track devices for room !#ROOM_ID# ...
nodered_1  | Now tracking device list for @#BOT_USER_ID#
nodered_1  | Error decrypting event (id=$#DATA#): DecryptionError[msg: The sender's device has not sent us the keys for this message., session: #DATA#|#KEY_REQUEST#]
nodered_1  | enqueueing key request for !#ROOM_ID# / #KEY_REQUEST#
nodered_1  | Enabling encryption in #ROOM_ID2#; starting to track device lists for all users therein
nodered_1  | Starting to track devices for room #ROOM_ID2# ...
nodered_1  | Now tracking device list for #USER_ID2#
nodered_1  | 24 Nov 21:44:37 - [info] [matrix-server-config:@#BOT_USER#] Matrix client connected
nodered_1  | 24 Nov 21:44:37 - [info] [matrix-server-config:@#BOT_USER#] Matrix server connection ready.
nodered_1  | Starting key download for [
nodered_1  |   '@#BOT_USER#',
nodered_1  |   '@#BOT_USER_ID#',
nodered_1  |   '#USER_ID2#'
nodered_1  | ]
nodered_1  | Marking device list outdated for @#BOT_USER#
nodered_1  | Queued key download for [ '@#BOT_USER#' ]
nodered_1  | Saving device tracking data #DATA#
nodered_1  | Requesting keys for !#ROOM_ID# / #KEY_REQUEST# from [@#BOT_USER#:*](id #KEY_REQUEST_ID#)
nodered_1  | PUT /sendToDevice/m.room_key_request/#KEY_REQUEST_ID# { '@#BOT_USER#': [ '*' ] }
nodered_1  | received to_device m.room_key_request from: @#BOT_USER# id: undefined
nodered_1  | m.room_key_request from @#BOT_USER#:#DEVICE_NAME# for !#ROOM_ID# / #KEY_REQUEST# (id #KEY_REQUEST_ID#)
nodered_1  | Ignoring room key request from ourselves
nodered_1  | received to_device m.room_key_request from: @#BOT_USER# id: undefined
nodered_1  | m.room_key_request from @#BOT_USER#:#DEVICE_NAME# for !#ROOM_ID# / #KEY_REQUEST# (id #KEY_REQUEST_ID#)
nodered_1  | Ignoring room key request from ourselves
nodered_1  | received to_device m.room_key_request from: @#BOT_USER# id: undefined
nodered_1  | m.room_key_request from @#BOT_USER#:#DEVICE_NAME# for !#ROOM_ID# / #KEY_REQUEST# (id #KEY_REQUEST_ID#)
nodered_1  | Ignoring room key request from ourselves
nodered_1  | received to_device m.room_key_request from: @#BOT_USER# id: undefined
nodered_1  | m.room_key_request from @#BOT_USER#:#DEVICE_NAME# for !#ROOM_ID# / #KEY_REQUEST# (id #KEY_REQUEST_ID#)
nodered_1  | Ignoring room key request from ourselves
nodered_1  | received to_device m.room_key_request from: @#BOT_USER# id: undefined
nodered_1  | m.room_key_request from @#BOT_USER#:#DEVICE_NAME# for !#ROOM_ID# / #KEY_REQUEST# (id #KEY_REQUEST_ID#)
nodered_1  | Ignoring room key request from ourselves
nodered_1  | received to_device m.room_key_request from: @#BOT_USER# id: undefined
nodered_1  | m.room_key_request from @#BOT_USER#:#DEVICE_NAME# for !#ROOM_ID# / #KEY_REQUEST# (id #KEY_REQUEST_ID#)
nodered_1  | Ignoring room key request from ourselves
nodered_1  | received to_device m.room_key_request from: @#BOT_USER# id: undefined
nodered_1  | m.room_key_request from @#BOT_USER#:#DEVICE_NAME# for !#ROOM_ID# / #KEY_REQUEST# (id #KEY_REQUEST_ID#)
nodered_1  | Ignoring room key request from ourselves
nodered_1  | received to_device m.room_key_request from: @#BOT_USER# id: undefined
nodered_1  | m.room_key_request from @#BOT_USER#:#DEVICE_NAME# for !#ROOM_ID# / #KEY_REQUEST# (id #KEY_REQUEST_ID#)
nodered_1  | Ignoring room key request from ourselves
nodered_1  | received to_device m.room_key_request from: @#BOT_USER# id: undefined
nodered_1  | m.room_key_request from @#BOT_USER#:#DEVICE_NAME# for !#ROOM_ID# / #KEY_REQUEST# (id #KEY_REQUEST_ID#)
nodered_1  | Ignoring room key request from ourselves
nodered_1  | received to_device m.room_key_request from: @#BOT_USER# id: undefined
nodered_1  | m.room_key_request from @#BOT_USER#:#DEVICE_NAME# for !#ROOM_ID# / #KEY_REQUEST# (id #KEY_REQUEST_ID#)
nodered_1  | Ignoring room key request from ourselves
nodered_1  | received to_device m.room_key_request from: @#BOT_USER# id: undefined
nodered_1  | m.room_key_request from @#BOT_USER#:#DEVICE_NAME# for !#ROOM_ID# / #KEY_REQUEST# (id #KEY_REQUEST_ID#)
nodered_1  | Ignoring room key request from ourselves
nodered_1  | got device keys for @#BOT_USER#: {
nodered_1  |   #DEVICE_KEY_NAME#: {
nodered_1  |     algorithms: [ 'm.olm.v1.curve25519-aes-sha2', 'm.megolm.v1.aes-sha2' ],
nodered_1  |     device_id: '#DEVICE_NAME#',
nodered_1  |     keys: {
nodered_1  |       'curve25519:#DEVICE_NAME#': '#KEY#',
nodered_1  |       'ed25519:#DEVICE_NAME#': '#KEY#'
nodered_1  |     },
nodered_1  |     signatures: { '@#BOT_USER#': [Object] },
nodered_1  |     user_id: '@#BOT_USER#',
nodered_1  |     unsigned: { device_display_name: 'app.element.io (Firefox, Ubuntu)' }
nodered_1  |   }
nodered_1  | }
nodered_1  | Local device #DEVICE_NAME# missing from sync, skipping removal
nodered_1  | Mismatched device_id #DEVICE_NAME# in keys from @#BOT_USER#:#DEVICE_KEY_NAME#
nodered_1  | got cross-signing keys for @#BOT_USER#: {
nodered_1  |   master: {
nodered_1  |     user_id: '@#BOT_USER#',
nodered_1  |     usage: [ 'master' ],
nodered_1  |     keys: {
nodered_1  |       'ed25519:#KEY01#': '#KEY01#'
nodered_1  |     },
nodered_1  |     signatures: { '@#BOT_USER#': [Object] }
nodered_1  |   },
nodered_1  |   self_signing: {
nodered_1  |     user_id: '@#BOT_USER#',
nodered_1  |     usage: [ 'self_signing' ],
nodered_1  |     keys: {
nodered_1  |       'ed25519:#KEY1#': '#KEY1#'
nodered_1  |     },
nodered_1  |     signatures: { '@#BOT_USER#': [Object] }
nodered_1  |   },
nodered_1  |   user_signing: {
nodered_1  |     user_id: '@#BOT_USER#',
nodered_1  |     usage: [ 'user_signing' ],
nodered_1  |     keys: {
nodered_1  |       'ed25519:#KEY2#': '#KEY2#'
nodered_1  |     },
nodered_1  |     signatures: { '@#BOT_USER#': [Object] }
nodered_1  |   }
nodered_1  | }
nodered_1  | got device keys for @#BOT_USER_ID#: {
nodered_1  |   #DATA#: {
nodered_1  |     algorithms: [ 'm.olm.v1.curve25519-aes-sha2', 'm.megolm.v1.aes-sha2' ],
nodered_1  |     device_id: '#DATA#',
nodered_1  |     keys: {
nodered_1  |       'curve25519:#DATA#': '#DATA#',
nodered_1  |       'ed25519:#DATA#': '#DATA#'
nodered_1  |     },
nodered_1  |     signatures: { '@#BOT_USER_ID#': [Object] },
nodered_1  |     user_id: '@#BOT_USER_ID#',
nodered_1  |     unsigned: { device_display_name: 'Element Desktop (Linux)' }
nodered_1  |   },
nodered_1  |   #DATA#: {
nodered_1  |     algorithms: [ 'm.megolm.v1.aes-sha2', 'm.olm.v1.curve25519-aes-sha2' ],
nodered_1  |     device_id: '#DATA#',
nodered_1  |     keys: {
nodered_1  |       'curve25519:#DATA#': '#DATA#',
nodered_1  |       'ed25519:#DATA#': '#DATA#'
nodered_1  |     },
nodered_1  |     signatures: { '@#BOT_USER_ID#': [Object] },
nodered_1  |     user_id: '@#BOT_USER_ID#',
nodered_1  |     unsigned: { device_display_name: 'Element Android' }
nodered_1  |   }
nodered_1  | }
nodered_1  | got cross-signing keys for @#BOT_USER_ID#: {
nodered_1  |   master: {
nodered_1  |     user_id: '@#BOT_USER_ID#',
nodered_1  |     usage: [ 'master' ],
nodered_1  |     keys: {
nodered_1  |       'ed25519:#DATA#': '#DATA#'
nodered_1  |     },
nodered_1  |     signatures: { '@#BOT_USER_ID#': [Object] }
nodered_1  |   },
nodered_1  |   self_signing: {
nodered_1  |     user_id: '@#BOT_USER_ID#',
nodered_1  |     usage: [ 'self_signing' ],
nodered_1  |     keys: {
nodered_1  |       'ed25519:#DATA#': '#DATA#'
nodered_1  |     },
nodered_1  |     signatures: { '@#BOT_USER_ID#': [Object] }
nodered_1  |   },
nodered_1  |   user_signing: undefined
nodered_1  | }
nodered_1  | got device keys for #USER_ID2#: {
nodered_1  |   #DEVICE_KEY_NAME2#: {
nodered_1  |     algorithms: [ 'm.olm.v1.curve25519-aes-sha2', 'm.megolm.v1.aes-sha2' ],
nodered_1  |     device_id: '#DEVICE_KEY_NAME2#',
nodered_1  |     keys: {
nodered_1  |       'curve25519:#DEVICE_KEY_NAME2#': '#DATA#',
nodered_1  |       'ed25519:#DEVICE_KEY_NAME2#': '#DATA#'
nodered_1  |     },
nodered_1  |     signatures: { '#USER_ID2#': [Object] },
nodered_1  |     unsigned: { device_display_name: 'Mobilgerät' },
nodered_1  |     user_id: '#USER_ID2#'
nodered_1  |   }
nodered_1  | }
nodered_1  | got cross-signing keys for #USER_ID2#: {
nodered_1  |   master: {
nodered_1  |     signatures: { '#USER_ID2#': [Object] },
nodered_1  |     user_id: '#USER_ID2#',
nodered_1  |     usage: [ 'master' ],
nodered_1  |     keys: {
nodered_1  |       'ed25519:+#DATA#': '+#DATA#'
nodered_1  |     }
nodered_1  |   },
nodered_1  |   self_signing: {
nodered_1  |     signatures: { '#USER_ID2#': [Object] },
nodered_1  |     user_id: '#USER_ID2#',
nodered_1  |     usage: [ 'self_signing' ],
nodered_1  |     keys: {
nodered_1  |       'ed25519:#DATA#': '#DATA#'
nodered_1  |     }
nodered_1  |   },
nodered_1  |   user_signing: undefined
nodered_1  | }
nodered_1  | Completed key download for @#BOT_USER#,@#BOT_USER_ID#,#USER_ID2#
nodered_1  | Starting key download for [ '@#BOT_USER#' ]
nodered_1  | Another update in the queue for @#BOT_USER# - not marking up-to-date
nodered_1  | Device list for @#BOT_USER_ID# now up to date
nodered_1  | Device list for #USER_ID2# now up to date
nodered_1  | Saving device tracking data #DATA#
nodered_1  | got device keys for @#BOT_USER#: {
nodered_1  |   #DEVICE_KEY_NAME#: {
nodered_1  |     algorithms: [ 'm.olm.v1.curve25519-aes-sha2', 'm.megolm.v1.aes-sha2' ],
nodered_1  |     device_id: '#DEVICE_NAME#',
nodered_1  |     keys: {
nodered_1  |       'curve25519:#DEVICE_NAME#': '#DATA#',
nodered_1  |       'ed25519:#DEVICE_NAME#': '#DATA#'
nodered_1  |     },
nodered_1  |     signatures: { '@#BOT_USER#': [Object] },
nodered_1  |     user_id: '@#BOT_USER#',
nodered_1  |     unsigned: { device_display_name: 'app.element.io (Firefox, Ubuntu)' }
nodered_1  |   }
nodered_1  | }
nodered_1  | got cross-signing keys for @#BOT_USER#: {
nodered_1  |   master: {
nodered_1  |     user_id: '@#BOT_USER#',
nodered_1  |     usage: [ 'master' ],
nodered_1  |     keys: {
nodered_1  |       'ed25519:#KEY01#': '#KEY01#'
nodered_1  |     },
nodered_1  |     signatures: { '@#BOT_USER#': [Object] }
nodered_1  |   },
nodered_1  |   self_signing: {
nodered_1  |     user_id: '@#BOT_USER#',
nodered_1  |     usage: [ 'self_signing' ],
nodered_1  |     keys: {
nodered_1  |       'ed25519:#KEY1#': '#KEY1#'
nodered_1  |     },
nodered_1  |     signatures: { '@#BOT_USER#': [Object] }
nodered_1  |   },
nodered_1  |   user_signing: {
nodered_1  |     user_id: '@#BOT_USER#',
nodered_1  |     usage: [ 'user_signing' ],
nodered_1  |     keys: {
nodered_1  |       'ed25519:#KEY2#': '#KEY2#'
nodered_1  |     },
nodered_1  |     signatures: { '@#BOT_USER#': [Object] }
nodered_1  |   }
nodered_1  | }
nodered_1  | Local device #DEVICE_NAME# missing from sync, skipping removal
nodered_1  | Mismatched device_id #DEVICE_NAME# in keys from @#BOT_USER#:#DEVICE_KEY_NAME#
nodered_1  | Completed key download for @#BOT_USER#
nodered_1  | Device list for @#BOT_USER# now up to date
nodered_1  | Saving device tracking data #DATA#

I also noticed that after a while a get repetetive timeouts which can also be noticed in the matrix node showing disconnected state.

nodered_1  | /sync error ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
nodered_1  |     at /usr/src/node-red/node_modules/matrix-js-sdk/lib/http-api.js:683:24
nodered_1  |     at Timeout._runCallbacks (/usr/src/node-red/node_modules/matrix-js-sdk/lib/realtime-callbacks.js:186:15)
nodered_1  |     at listOnTimeout (internal/timers.js:554:17)
nodered_1  |     at processTimers (internal/timers.js:497:7) {
nodered_1  |   errcode: 'ORG.MATRIX.JSSDK_TIMEOUT',
nodered_1  |   data: [Object]
nodered_1  | }
nodered_1  | ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
nodered_1  |     at /usr/src/node-red/node_modules/matrix-js-sdk/lib/http-api.js:683:24
nodered_1  |     at Timeout._runCallbacks (/usr/src/node-red/node_modules/matrix-js-sdk/lib/realtime-callbacks.js:186:15)
nodered_1  |     at listOnTimeout (internal/timers.js:554:17)
nodered_1  |     at processTimers (internal/timers.js:497:7) {
nodered_1  |   errcode: 'ORG.MATRIX.JSSDK_TIMEOUT',
nodered_1  |   data: {
nodered_1  |     error: 'Locally timed out waiting for a response',
nodered_1  |     errcode: 'ORG.MATRIX.JSSDK_TIMEOUT',
nodered_1  |     timeout: 110000
nodered_1  |   }
nodered_1  | }
nodered_1  | Number of consecutive failed sync requests: 1
nodered_1  | Starting keep-alive
nodered_1  | 24 Nov 21:54:33 - [info] [matrix-server-config:@#BOT_USER#] Trying to reconnect to matrix server
nodered_1  | 24 Nov 21:54:41 - [info] [matrix-server-config:@#BOT_USER#] Matrix client connected
nodered_1  | 24 Nov 21:54:41 - [info] [matrix-server-config:@#BOT_USER#] Matrix server connection ready.
nodered_1  | /sync error ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
nodered_1  |     at /usr/src/node-red/node_modules/matrix-js-sdk/lib/http-api.js:683:24
nodered_1  |     at Timeout._runCallbacks (/usr/src/node-red/node_modules/matrix-js-sdk/lib/realtime-callbacks.js:186:15)
nodered_1  |     at listOnTimeout (internal/timers.js:554:17)
nodered_1  |     at processTimers (internal/timers.js:497:7) {
nodered_1  |   errcode: 'ORG.MATRIX.JSSDK_TIMEOUT',
nodered_1  |   data: [Object]
nodered_1  | }
nodered_1  | ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
nodered_1  |     at /usr/src/node-red/node_modules/matrix-js-sdk/lib/http-api.js:683:24
nodered_1  |     at Timeout._runCallbacks (/usr/src/node-red/node_modules/matrix-js-sdk/lib/realtime-callbacks.js:186:15)
nodered_1  |     at listOnTimeout (internal/timers.js:554:17)
nodered_1  |     at processTimers (internal/timers.js:497:7) {
nodered_1  |   errcode: 'ORG.MATRIX.JSSDK_TIMEOUT',
nodered_1  | Number of consecutive failed sync requests: 1
nodered_1  | Starting keep-alive
nodered_1  | 24 Nov 22:00:36 - [info] [matrix-server-config:@#BOT_USER#] Trying to reconnect to matrix server
nodered_1  |   data: {
nodered_1  |     error: 'Locally timed out waiting for a response',
nodered_1  |     errcode: 'ORG.MATRIX.JSSDK_TIMEOUT',
nodered_1  |     timeout: 110000
nodered_1  |   }
nodered_1  | }
nodered_1  | 24 Nov 22:00:41 - [info] [matrix-server-config:@#BOT_USER#] Matrix client connected
nodered_1  | 24 Nov 22:00:41 - [info] [matrix-server-config:@#BOT_USER#] Matrix server connection ready.
nodered_1  | /sync error ConnectionError: request failed: socket hang up
nodered_1  |     at /usr/src/node-red/node_modules/matrix-js-sdk/lib/http-api.js:777:15
nodered_1  |     at Request._callback (/usr/src/node-red/node_modules/matrix-js-sdk/lib/http-api.js:718:9)
nodered_1  |     at self.callback (/usr/src/node-red/node_modules/request/request.js:185:22)
nodered_1  |     at Request.emit (events.js:314:20)
nodered_1  |     at Request.onRequestError (/usr/src/node-red/node_modules/request/request.js:877:8)
nodered_1  |     at ClientRequest.emit (events.js:326:22)
nodered_1  |     at TLSSocket.socketOnEnd (_http_client.js:458:9)
nodered_1  |     at TLSSocket.emit (events.js:326:22)
nodered_1  |     at endReadableNT (_stream_readable.js:1241:12)
nodered_1  |     at processTicksAndRejections (internal/process/task_queues.js:84:21) {
nodered_1  |   _cause: [Error]
nodered_1  | }
nodered_1  | Number of consecutive failed sync requests: 1
nodered_1  | Starting keep-alive
nodered_1  | ConnectionError: request failed: socket hang up
nodered_1  |     at /usr/src/node-red/node_modules/matrix-js-sdk/lib/http-api.js:777:15
nodered_1  |     at Request._callback (/usr/src/node-red/node_modules/matrix-js-sdk/lib/http-api.js:718:9)
nodered_1  |     at self.callback (/usr/src/node-red/node_modules/request/request.js:185:22)
nodered_1  |     at Request.emit (events.js:314:20)
nodered_1  |     at Request.onRequestError (/usr/src/node-red/node_modules/request/request.js:877:8)
nodered_1  |     at ClientRequest.emit (events.js:326:22)
nodered_1  |     at TLSSocket.socketOnEnd (_http_client.js:458:9)
nodered_1  |     at TLSSocket.emit (events.js:326:22)
nodered_1  |     at endReadableNT (_stream_readable.js:1241:12)
nodered_1  |     at processTicksAndRejections (internal/process/task_queues.js:84:21) {
nodered_1  |   _cause: Error: socket hang up
nodered_1  |       at connResetException (internal/errors.js:609:14)
nodered_1  |       at TLSSocket.socketOnEnd (_http_client.js:458:23)
nodered_1  | 24 Nov 22:02:05 - [info] [matrix-server-config:@#BOT_USER#] Trying to reconnect to matrix server
nodered_1  |       at TLSSocket.emit (events.js:326:22)
nodered_1  |       at endReadableNT (_stream_readable.js:1241:12)
nodered_1  |       at processTicksAndRejections (internal/process/task_queues.js:84:21) {
nodered_1  |     code: 'ECONNRESET'
nodered_1  |   }
nodered_1  | }
nodered_1  | 24 Nov 22:02:17 - [info] [matrix-server-config:@#BOT_USER#] Matrix client connected
nodered_1  | 24 Nov 22:02:17 - [info] [matrix-server-config:@#BOT_USER#] Matrix server connection ready.
nodered_1  | /sync error ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
nodered_1  |     at /usr/src/node-red/node_modules/matrix-js-sdk/lib/http-api.js:683:24
nodered_1  |     at Timeout._runCallbacks (/usr/src/node-red/node_modules/matrix-js-sdk/lib/realtime-callbacks.js:186:15)
nodered_1  |     at listOnTimeout (internal/timers.js:554:17)
nodered_1  |     at processTimers (internal/timers.js:497:7) {
nodered_1  |   errcode: 'ORG.MATRIX.JSSDK_TIMEOUT',
nodered_1  |   data: [Object]
nodered_1  | }
nodered_1  | ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
nodered_1  |     at /usr/src/node-red/node_modules/matrix-js-sdk/lib/http-api.js:683:24
nodered_1  |     at Timeout._runCallbacks (/usr/src/node-red/node_modules/matrix-js-sdk/lib/realtime-callbacks.js:186:15)
nodered_1  |     at listOnTimeout (internal/timers.js:554:17)
nodered_1  |     at processTimers (internal/timers.js:497:7) {
nodered_1  |   errcode: 'ORG.MATRIX.JSSDK_TIMEOUT',
nodered_1  |   data: {
nodered_1  | Number of consecutive failed sync requests: 1
nodered_1  | Starting keep-alive
nodered_1  | 24 Nov 22:04:38 - [info] [matrix-server-config:@#BOT_USER#] Trying to reconnect to matrix server
nodered_1  |     error: 'Locally timed out waiting for a response',
nodered_1  |     errcode: 'ORG.MATRIX.JSSDK_TIMEOUT',
nodered_1  |     timeout: 110000
nodered_1  |   }
nodered_1  | }
nodered_1  | 24 Nov 22:04:47 - [info] [matrix-server-config:@#BOT_USER#] Matrix client connected
nodered_1  | 24 Nov 22:04:47 - [info] [matrix-server-config:@#BOT_USER#] Matrix server connection ready.
nodered_1  | /sync error ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
nodered_1  |     at /usr/src/node-red/node_modules/matrix-js-sdk/lib/http-api.js:683:24
nodered_1  |     at Timeout._runCallbacks (/usr/src/node-red/node_modules/matrix-js-sdk/lib/realtime-callbacks.js:186:15)
nodered_1  |     at listOnTimeout (internal/timers.js:554:17)
nodered_1  |     at processTimers (internal/timers.js:497:7) {
nodered_1  |   errcode: 'ORG.MATRIX.JSSDK_TIMEOUT',
nodered_1  |   data: [Object]
nodered_1  | }
nodered_1  | ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
nodered_1  |     at /usr/src/node-red/node_modules/matrix-js-sdk/lib/http-api.js:683:24
nodered_1  |     at Timeout._runCallbacks (/usr/src/node-red/node_modules/matrix-js-sdk/lib/realtime-callbacks.js:186:15)
nodered_1  |     at listOnTimeout (internal/timers.js:554:17)
nodered_1  |     at processTimers (internal/timers.js:497:7) {
nodered_1  |   errcode: 'ORG.MATRIX.JSSDK_TIMEOUT',
nodered_1  |   data: {
nodered_1  |     error: 'Locally timed out waiting for a response',
nodered_1  |     errcode: 'ORG.MATRIX.JSSDK_TIMEOUT',
nodered_1  |     timeout: 110000
nodered_1  |   }
nodered_1  | }
nodered_1  | Number of consecutive failed sync requests: 1
nodered_1  | Starting keep-alive
nodered_1  | 24 Nov 22:05:39 - [info] [matrix-server-config:@#BOT_USER#] Trying to reconnect to matrix server
nodered_1  | 24 Nov 22:05:45 - [info] [matrix-server-config:@#BOT_USER#] Matrix client connected
nodered_1  | 24 Nov 22:05:45 - [info] [matrix-server-config:@#BOT_USER#] Matrix server connection ready.

These timeouts are also visible for other devices in the same encrypted room (disconnection warning). However I couldn't identify any pattern for those timeouts yet. The only thing I excluded are network issues on the machine.

[hacker-h]

I was able to replicate this and found the issue. It is for sure a bug in this repo. I'll get a new release pushed out tonight and update this issue.

Thanks agaain!

Still curious why crypto takes sometimes up to a minute to init for you. That seems really odd (unless you are on lower end hardware).

Cool, good job!

[skylord123]

Just pushed out a new release 0.2.6 that fixes this. Give it a try and let me know how it goes.

I also noticed that after a while a get repetitive timeouts which can also be noticed in the matrix node showing disconnected state.

I have a bot running on my home server and I noticed that after a while of running it will constantly say "Disconnected" below the nodes despite it being able to still send messages. The logic for checking the connection state wasn't very good (despite being pulled straight from the matrix-js-sdk docs) so I just updated it in this release as well. This wont fix the timing out problem but should at least display the correct client state for you (or pretty close, it will only detect when it does a sync so it's possible a message will fail even if it says connected or vice-versa before the next sync occurs).

I added a new debug message for the sync state on this new release. It may be helpful in debugging the timeout.

These timeouts are also visible for other devices in the same encrypted room (disconnection warning). However I couldn't identify any pattern for those timeouts yet. The only thing I excluded are network issues on the machine.

If the problem is happening for multiple clients I would assume it's the server. If you end up figuring it out let me know, pretty curious.

Thanks!