Startup fails with "Timeout waiting for ping event"

[gbonfiglio]

Describe the bug

Slack bridge throws this at startup:

MatrixHttpClient (REQ-2) { errcode: 'M_UNKNOWN', error: 'No known servers' }
Aug-6 11:04:41.561 ERROR Main Homeserver cannot reach the bridge. You probably need to adjust your configuration. Error: Failed to join room
    at Intent._ensureJoined (/opt/slack-bridge/node_modules/matrix-appservice-bridge/lib/components/intent.js:808:60)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async Intent.sendEvent (/opt/slack-bridge/node_modules/matrix-appservice-bridge/lib/components/intent.js:284:9)
    at async Bridge.pingAppserviceRoute (/opt/slack-bridge/node_modules/matrix-appservice-bridge/lib/bridge.js:1094:9)
    at async Main.pingBridge (/opt/slack-bridge/lib/Main.js:1421:26)
    at async Main.run (/opt/slack-bridge/lib/Main.js:922:9)

And shortly after times out and exits with:

/opt/slack-bridge/node_modules/matrix-appservice-bridge/lib/bridge.js:1091
                this.selfPingDeferred?.defer.reject(new Error("Timeout waiting for ping event"));
                                                    ^

Error: Timeout waiting for ping event
    at Timeout._onTimeout (/opt/slack-bridge/node_modules/matrix-appservice-bridge/lib/bridge.js:1091:53)
    at listOnTimeout (node:internal/timers:564:17)
    at process.processTimers (node:internal/timers:507:7)

All of this would point at a server issue (Synapse runs on localhost) except the bridge is actively logging successful calls from it:

Aug-6 11:04:41.699 INFO bridge 127.0.0.1 - - [06/Aug/2022:11:04:41 +0000] "PUT /transactions/905?access_token=<REDACTED> HTTP/1.1" 200 2 "-" "Synapse/1.64.0"
Aug-6 11:04:41.743 INFO bridge 127.0.0.1 - - [06/Aug/2022:11:04:41 +0000] "PUT /transactions/906?access_token=<REDACTED> HTTP/1.1" 200 2 "-" "Synapse/1.64.0"

I'm honestly at a loss for options. Debugging log mode doesn't log anything more. I'm conscious this is not good enough as a bug report but does anyone have any idea, or knows where I can pull more details? The error and subsequent behaviour don't really make sense to me.

Thanks!

To Reproduce
Steps to reproduce the behavior:

• this happens at startup

Expected behavior
Matrix Slack bridge should start no issues. If there is a server side issue, I should not be able to see successful calls to it.

Screenshots
If applicable, add screenshots to help explain your problem.

• N/A

Desktop (please complete the following information):

• N/A

Smartphone (please complete the following information):

• N/A

Additional context
Add any other context about the problem here.

[JohnStarich]

I'm seeing this now too. I'm not certain, but this seems to happen after startup for me – where it throws an error that triggers a full exit. i.e. an uncaught promise rejection?

Here's the similar error I'm seeing:

Nov-7 05:35:56.616 INFO Main Bridge initialised
Nov-7 05:35:56.616 INFO app Matrix-side listening on port 5858
/usr/src/app/node_modules/matrix-appservice-bridge/lib/bridge.js:1097
                this.selfPingDeferred?.defer.reject(new Error("Timeout waiting for ping event"));
                                                    ^

Error: Timeout waiting for ping event
    at Timeout._onTimeout (/usr/src/app/node_modules/matrix-appservice-bridge/lib/bridge.js:1097:53)
    at listOnTimeout (node:internal/timers:564:17)
    at process.processTimers (node:internal/timers:507:7)

Node.js v18.10.0

I'm not a Node.js expert so please take this with a grain of salt, but I think the Node.js version change may have had something to do with it. Uncaught promise rejections used to be warnings only, and changed to throws in Node.js 15:

As of Node.js 15, the default mode for unhandledRejection is changed to throw (from warn). In throw mode, if an unhandledRejection hook is not set, the unhandledRejection is raised as an uncaught exception. Users that have an unhandledRejection hook should see no change in behavior, and it’s still possible to switch modes using the --unhandled-rejections=mode process flag.
– https://nodejs.org/en/blog/release/v15.0.0/#throw-on-unhandled-rejections-33021

I haven't looked, but I wonder if we're missing the unhandledRejection hook it mentions.

[JohnStarich]

Aha, that was it!

I added --unhandled-rejections=warn to my container's entrypoint (between node and lib/app.js) and received this log instead of an exit:

(node:10) UnhandledPromiseRejectionWarning: Error: Timeout waiting for ping event
    at Timeout._onTimeout (/usr/src/app/node_modules/matrix-appservice-bridge/lib/bridge.js:1097:53)
    at listOnTimeout (node:internal/timers:564:17)
    at process.processTimers (node:internal/timers:507:7)
(node:10) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 2)

I imagine a more proper fix would involve resolving the uncaught rejection at the source, but maybe adding an unhandled rejection hook would be prudent as well.

[scottwallacesh]

I'm having the same issue and adding this extra argument stops the container from restarting but I'm wondering why it's happening in the first place.

[scottwallacesh]

I've noticed that after the warning happens, though, the bridge stops responding. I've reverted the change but the bridge crashes regularly, after the ping timeout. The container restarts, some messages flow and then it crashes again, etc.

This has been happening since December 1, for me.

[jkms]

I'm experiencing the same with matrixdotorg/matrix-appservice-slack:latest

[edukimod]

Same problem here with latest. Curious it was working until a node crash, after the restart there's no way to make it work again. Did you find any workaround?

[ayushin]

is there a stable version of this bridge?

[jkms]

I continue to experience this with docker. Container runs for 60 seconds then crashes.

d3c9abb38319   matrixdotorg/matrix-appservice-slack   "node lib/app.js -c …"   2 weeks ago   Up 50 seconds                    matrix-appservice-slack
john@matrix:~$ date && docker ps | grep slack
Mon Nov  6 15:57:07 UTC 2023
d3c9abb38319   matrixdotorg/matrix-appservice-slack   "node lib/app.js -c …"   2 weeks ago   Up 51 seconds                    matrix-appservice-slack
john@matrix:~$ date && docker ps | grep slack
Mon Nov  6 15:57:08 UTC 2023
d3c9abb38319   matrixdotorg/matrix-appservice-slack   "node lib/app.js -c …"   2 weeks ago   Up 53 seconds                    matrix-appservice-slack
john@matrix:~$ date && docker ps | grep slack
Mon Nov  6 15:57:09 UTC 2023
d3c9abb38319   matrixdotorg/matrix-appservice-slack   "node lib/app.js -c …"   2 weeks ago   Up 54 seconds                    matrix-appservice-slack
john@matrix:~$ date && docker ps | grep slack
Mon Nov  6 15:57:11 UTC 2023
d3c9abb38319   matrixdotorg/matrix-appservice-slack   "node lib/app.js -c …"   2 weeks ago   Up 55 seconds                    matrix-appservice-slack
john@matrix:~$ date && docker ps | grep slack
Mon Nov  6 15:57:12 UTC 2023
d3c9abb38319   matrixdotorg/matrix-appservice-slack   "node lib/app.js -c …"   2 weeks ago   Up 57 seconds                    matrix-appservice-slack
john@matrix:~$ date && docker ps | grep slack
Mon Nov  6 15:57:13 UTC 2023
d3c9abb38319   matrixdotorg/matrix-appservice-slack   "node lib/app.js -c …"   2 weeks ago   Up 58 seconds                    matrix-appservice-slack
john@matrix:~$ date && docker ps | grep slack
Mon Nov  6 15:57:15 UTC 2023
d3c9abb38319   matrixdotorg/matrix-appservice-slack   "node lib/app.js -c …"   2 weeks ago   Up 59 seconds                    matrix-appservice-slack
john@matrix:~$ date && docker ps | grep slack
Mon Nov  6 15:57:16 UTC 2023
d3c9abb38319   matrixdotorg/matrix-appservice-slack   "node lib/app.js -c …"   2 weeks ago   Up About a minute                matrix-appservice-slack
john@matrix:~$ date && docker ps | grep slack
Mon Nov  6 15:57:17 UTC 2023
d3c9abb38319   matrixdotorg/matrix-appservice-slack   "node lib/app.js -c …"   2 weeks ago   Up Less than a second              matrix-appservice-slack

logs look like this:

/usr/src/app/node_modules/matrix-appservice-bridge/lib/bridge.js:1104
                this.selfPingDeferred?.defer.reject(new Error("Timeout waiting for ping event"));
                                                    ^

Error: Timeout waiting for ping event
    at Timeout._onTimeout (/usr/src/app/node_modules/matrix-appservice-bridge/lib/bridge.js:1104:53)
    at listOnTimeout (node:internal/timers:569:17)
    at process.processTimers (node:internal/timers:512:7)

Node.js v18.18.0
INFO 17:49:57:546 [Main] Enabled RTM
INFO 17:49:57:549 [Main] Enabled hook handler
INFO 17:49:57:595 [Main] Loading databases
INFO 17:49:57:752 [PgDatastore] Database schema is at version v16
INFO 17:49:57:767 [SlackHookHandler] Slack-side listening on port 9898 over http
ERROR 17:49:57:827 [MatrixHttpClient] (REQ-2) {
  errcode: 'M_UNKNOWN',
  error: "Can't join remote room because no servers that are in the room have been provided."
}
ERROR 17:49:57:836 [Main] Homeserver cannot reach the bridge. You probably need to adjust your configuration. Error: Failed to join room
    at Intent._ensureJoined (/usr/src/app/node_modules/matrix-appservice-bridge/lib/components/intent.js:806:60)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async Intent.sendEvent (/usr/src/app/node_modules/matrix-appservice-bridge/lib/components/intent.js:282:9)
    at async Bridge.pingAppserviceRoute (/usr/src/app/node_modules/matrix-appservice-bridge/lib/bridge.js:1107:9)
    at async Main.pingBridge (/usr/src/app/lib/Main.js:1498:26)
    at async Main.run (/usr/src/app/lib/Main.js:999:9)
INFO 17:49:57:850 [Main] Ensuring the bridge bot is registered
INFO 17:49:57:885 [Main] Fetching teams
INFO 17:49:57:899 [Main] Loaded 2 teams
INFO 17:49:57:901 [Main] [0/2] Getting team client for REDACTED
INFO 17:49:57:903 [Main] [1/2] Getting team client for Sistas
INFO 17:49:57:915 [SlackClientFactory] Creating new team client for REDACTED
INFO 17:49:58:067 [SlackClientFactory] Creating new team client for REDACTED
INFO 17:49:58:799 [Main] Starting RTM for REDACTED
INFO 17:49:58:852 [Main] Starting RTM for REDACTED
INFO 17:49:59:095 [SlackRTMHandler] Connected RTM client for  { id: 'REDACTED', name: 'REDACTED', domain: 'REDACTED' }
INFO 17:49:59:102 [Main] Started RTM for REDACTED
INFO 17:49:59:151 [SlackRTMHandler] Connected RTM client for  { id: 'REDACTED', name: 'REDACTED', domain: 'REDACTED' }
INFO 17:49:59:158 [Main] Started RTM for REDACTED
INFO 17:49:59:159 [Main] Finished loading all team clients
INFO 17:49:59:165 [Main] Found 2 room entries in store
INFO 17:49:59:171 [Main] [1/2] Loading room entry !REDACTED:domain.tld
INFO 17:49:59:172 [Main] [2/2] Loading room entry !REDACTED:domain.tld
INFO 17:49:59:287 [Provisioning] Provisioning API ready
INFO 17:49:59:297 [Main] Bridge initialised
INFO 17:49:59:297 [app] Matrix-side listening on port 5858
/usr/src/app/node_modules/matrix-appservice-bridge/lib/bridge.js:1104
                this.selfPingDeferred?.defer.reject(new Error("Timeout waiting for ping event"));
                                                    ^

Error: Timeout waiting for ping event
    at Timeout._onTimeout (/usr/src/app/node_modules/matrix-appservice-bridge/lib/bridge.js:1104:53)
    at listOnTimeout (node:internal/timers:569:17)
    at process.processTimers (node:internal/timers:512:7)

Node.js v18.18.0
INFO 17:50:59:716 [Main] Enabled RTM
INFO 17:50:59:720 [Main] Enabled hook handler
INFO 17:50:59:764 [Main] Loading databases
INFO 17:50:59:920 [PgDatastore] Database schema is at version v16
INFO 17:50:59:945 [SlackHookHandler] Slack-side listening on port 9898 over http
ERROR 17:51:00:008 [MatrixHttpClient] (REQ-2) {
  errcode: 'M_LIMIT_EXCEEDED',
  error: 'Too Many Requests',
  retry_after_ms: 15822
}
ERROR 17:51:00:015 [Main] Homeserver cannot reach the bridge. You probably need to adjust your configuration. Error: Failed to join room
    at Intent._ensureJoined (/usr/src/app/node_modules/matrix-appservice-bridge/lib/components/intent.js:806:60)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async Intent.sendEvent (/usr/src/app/node_modules/matrix-appservice-bridge/lib/components/intent.js:282:9)
    at async Bridge.pingAppserviceRoute (/usr/src/app/node_modules/matrix-appservice-bridge/lib/bridge.js:1107:9)
    at async Main.pingBridge (/usr/src/app/lib/Main.js:1498:26)
    at async Main.run (/usr/src/app/lib/Main.js:999:9)
INFO 17:51:00:032 [Main] Ensuring the bridge bot is registered
INFO 17:51:00:070 [Main] Fetching teams
INFO 17:51:00:081 [Main] Loaded 2 teams
INFO 17:51:00:083 [Main] [0/2] Getting team client for REDACTED
INFO 17:51:00:091 [Main] [1/2] Getting team client for Sistas
INFO 17:51:00:099 [SlackClientFactory] Creating new team client for REDACTED
INFO 17:51:00:257 [SlackClientFactory] Creating new team client for REDACTED
INFO 17:51:01:061 [Main] Starting RTM for REDACTED
INFO 17:51:01:416 [SlackRTMHandler] Connected RTM client for  { id: 'REDACTED', name: 'REDACTED', domain: 'REDACTED' }
INFO 17:51:01:422 [Main] Started RTM for REDACTED
INFO 17:51:01:472 [Main] Starting RTM for REDACTED
INFO 17:51:01:789 [SlackRTMHandler] Connected RTM client for  { id: 'REDACTED', name: 'REDACTED', domain: 'REDACTED' }
INFO 17:51:01:794 [Main] Started RTM for REDACTED
INFO 17:51:01:795 [Main] Finished loading all team clients
INFO 17:51:01:807 [Main] Found 2 room entries in store
INFO 17:51:01:808 [Main] [1/2] Loading room entry !REDACTED:domain.tld
INFO 17:51:01:808 [Main] [2/2] Loading room entry REDACTED:domain.tld
INFO 17:51:01:936 [Provisioning] Provisioning API ready
INFO 17:51:01:945 [Main] Bridge initialised
INFO 17:51:01:951 [app] Matrix-side listening on port 5858
/usr/src/app/node_modules/matrix-appservice-bridge/lib/bridge.js:1104
                this.selfPingDeferred?.defer.reject(new Error("Timeout waiting for ping event"));
                                                    ^

Error: Timeout waiting for ping event
    at Timeout._onTimeout (/usr/src/app/node_modules/matrix-appservice-bridge/lib/bridge.js:1104:53)
    at listOnTimeout (node:internal/timers:569:17)
    at process.processTimers (node:internal/timers:512:7)

Node.js v18.18.0