mx-puppet-slack icon indicating copy to clipboard operation
mx-puppet-slack copied to clipboard

Constantly connecting to slack

Open zoglesby opened this issue 5 years ago • 2 comments

One of the slack I am bridging with is constantly showing a connected message every minute too two minutes. Any idea why, or how to troubleshoot this?

Screen Shot 2019-11-12 at 09 21 36

zoglesby avatar Nov 12 '19 14:11 zoglesby

I'm seeing this as well. I enabled debug level logging and seeing constantly these events on the console:

Jan-22 13:16:55.375 [SlackPuppet:client] verbose: Logged in as <slack-login> of team <slack-workspace>
Jan-22 13:16:55.798 [BotProvisioner] info: Sending status message for puppetId 1...
Jan-22 13:16:55.804 [bot-sdk-MatrixLiteClient] info: (REQ-56) PUT http://localhost:8008/_matrix/client/r0/rooms/!xxx%3Afoo.bar/send/m.room.message/<number>__REQ55
Jan-22 13:16:55.804 [bot-sdk-MatrixLiteClient] debug: (REQ-56) body = {"msgtype":"m.notice","body":"[Status] 1: Slack on `<slack-workspace>` as `<slack-login>`: connected","formatted_body":"<p>[Status] 1: Slack on <code><slack-workspace></code> as <code><slack-login></code>: connected</p>\n","format":"org.matrix.custom.html"}
Jan-22 13:16:55.850 [bot-sdk-MatrixLiteClient] debug: (REQ-56 RESP-H200) { event_id: '$xxx' }
Jan-22 13:16:55.850 [bot-sdk-Metrics] debug: matrix_client_function_call
Jan-22 13:16:55.850 [bot-sdk-Metrics] debug: matrix_client_function_call
Jan-22 13:16:55.850 [bot-sdk-Metrics] debug: matrix_client_function_call
Jan-22 13:16:56.210 [bot-sdk-Appservice] info: Processing transaction 353
Jan-22 13:16:56.210 [bot-sdk-Appservice] info: Processing event of type m.room.message
127.0.0.1 - - [22/Jan/2020:11:16:56 +0000] "PUT /transactions/353?access_token=<my-matrix-app-token> HTTP/1.1" 200 2 "-" "Synapse/1.7.2"
[INFO]  WebClient:2 API Call failed due to rate limiting. Will retry in 60 seconds.
[WARN]  WebClient:2 http request failed A rate limit was exceeded.
Jan-22 13:17:59.527 [SlackPuppet:client] verbose: Logged in as <slack-login> of team <slack-workspace>
Jan-22 13:17:59.912 [BotProvisioner] info: Sending status message for puppetId 1...
Jan-22 13:17:59.918 [bot-sdk-MatrixLiteClient] info: (REQ-57) PUT http://localhost:8008/_matrix/client/r0/rooms/!xxx%3Afoo.bar/send/m.room.message/<number>__REQ56
Jan-22 13:17:59.919 [bot-sdk-MatrixLiteClient] debug: (REQ-57) body = {"msgtype":"m.notice","body":"[Status] 1: Slack on `<slack-workspace>` as `<slack-login>`: connected","formatted_body":"<p>[Status] 1: Slack on <code><slack-workspace></code> as <code><slack-login></code>: connected</p>\n","format":"org.matrix.custom.html"}
Jan-22 13:17:59.975 [bot-sdk-MatrixLiteClient] debug: (REQ-57 RESP-H200) { event_id: '$xxx' }
Jan-22 13:17:59.976 [bot-sdk-Metrics] debug: matrix_client_function_call
Jan-22 13:17:59.976 [bot-sdk-Metrics] debug: matrix_client_function_call
Jan-22 13:17:59.976 [bot-sdk-Metrics] debug: matrix_client_function_call
Jan-22 13:18:00.347 [bot-sdk-Appservice] info: Processing transaction 354
Jan-22 13:18:00.347 [bot-sdk-Appservice] info: Processing event of type m.room.message
127.0.0.1 - - [22/Jan/2020:11:18:00 +0000] "PUT /transactions/354?access_token=<my-matrix-app-token> HTTP/1.1" 200 2 "-" "Synapse/1.7.2"
[INFO]  WebClient:2 API Call failed due to rate limiting. Will retry in 60 seconds.

Even there is nothing happening in Slack: I'm not sending any messages and other users haven't sent any new / pending messages either.

I don't know why mx-puppet-slack tries constantly to send something to Slack so often that I hit Slack's API rate limits?

I have tried to wait many minutes if the situation fixes by itself (if there's some initial sync or something similar going on) but it doesn't.

I also put one additional debug log event which logs what the client is sending to Slack and got this: will perform http request: URL: rtm.connect, body:{"token":"<my-slack-token-here>"}, headers: {} So it is empty message or is it trying to connect forever every minute? Or maybe it's disconnecting from the Slack and it reconnects and then again disconnects for some reason (so it's in some kind of connect/disconnect loop and it hits the rate limit)?

wapsi avatar Jan 22 '20 11:01 wapsi

The rate limit was always hit after Jan-22 13:18:00.347 [bot-sdk-Appservice] info: Processing event of type m.room.message, hmmmmm

Sorunome avatar Jan 23 '20 15:01 Sorunome