Closed filmaj closed 8 months ago
Seems might be caused by https://github.com/slackapi/java-slack-sdk/issues/1206
too_many_websockets
gets raised by our backend if the backend has more than 10 concurrent connections active with a single app.
Because this is a single instance of an app, this leads me to believe maybe this library is establishing more than these ten connections at a time, possibly due to reconnection logic? Looking at the socket-mode code, it seems to me no connection pool is used in this library. The only location I see where possibly multiple connections are held at the same time is here, but presumably the 'old' session is only active for a very short, overlapping time between the 'new' session is connected, so I'm not sure this is possible.
@dbudim are you able to provide more logs? If possible including verbose logging and from the very first occurrence of any disconnect or warning received from the Slack backend.
Another possibility is perhaps the backend's state-tracking for how many concurrent connections per app ID are active is stale?
too_many_websockets
gets raised by our backend if the backend has more than 10 concurrent connections active with a single app.Because this is a single instance of an app, this leads me to believe maybe this library is establishing more than these ten connections at a time, possibly due to reconnection logic? Looking at the socket-mode code, it seems to me no connection pool is used in this library. The only location I see where possibly multiple connections are held at the same time is here, but presumably the 'old' session is only active for a very short, overlapping time between the 'new' session is connected, so I'm not sure this is possible.
@dbudim are you able to provide more logs? If possible including verbose logging and from the very first occurrence of any disconnect or warning received from the Slack backend.
Another possibility is perhaps the backend's state-tracking for how many concurrent connections per app ID are active is stale?
I'll do on another fail, old logs wasn't saved from beginning.
DEBUG log level is ok? Or need more verbose (trace) ?
Could we don't check sessions count before waiting next failure?
Yes, DEBUG level is fine, thank you!
Could we don't check sessions count before waiting next failure?
Possible. Once we have logs, I think it will be easier to cross-reference behaviour with code to get a better idea of why this is happening.
@dbudim not sure if you saw, but in #1206 the original poster of that issue mentioned that switching to the Tyrus WebSocket implementation addressed the issue for them. Maybe worth a shot to see if that helps you, as well?
@dbudim not sure if you saw, but in #1206 the original poster of that issue mentioned that switching to the Tyrus WebSocket implementation addressed the issue for them. Maybe worth a shot to see if that helps you, as well?
Nice idea, I'll try and back with result within a week)
👋 It looks like this issue has been open for 30 days with no activity. We'll mark this as stale for now, and wait 10 days for an update or for further comment before closing this issue out. If you think this issue needs to be prioritized, please comment to get the thread going again! Maintainers also review issues marked as stale on a regular basis and comment or adjust status if the issue needs to be reprioritized.
As this issue has been inactive for more than one month, we will be closing it. Thank you to all the participants! If you would like to raise a related issue, please create a new issue which includes your specific details and references this issue number.
@filmaj Hi, sorry for a delay, I have a full portion of logs from a beginning and it starts from
Failed to send a ping message
and then makes retries. After that it exceed a limit of sessions. By the way I moved to recommended ws library and nothing helps(
Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:232] - New session is open (session id: 2217e8d7-6eff-4488-8259-e125c4041301)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 2217e8d7-6eff-4488-8259-e125c4041301, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:06 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 2217e8d7-6eff-4488-8259-e125c4041301, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@58b2f406[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@4933579e[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@2a8b7534]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@72e510c3[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 16])
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: fac195f4-a738-4bbf-9462-320f6796c25b, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:232] - New session is open (session id: 09916a41-b340-4f45-8799-54a24b39c9e6)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 09916a41-b340-4f45-8799-54a24b39c9e6, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 965d73cf-f075-431e-9e6e-61aea16123e5, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:232] - New session is open (session id: caf24176-39f9-44e4-a08b-741d179bf12f)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: caf24176-39f9-44e4-a08b-741d179bf12f, reason: Closed abnormally.)
[socket-mode-session-cleaner-worker-95] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: c1ed11a6-1dfe-4d01-ab22-b34f92df0b2d, reason: com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl did it)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: dbb2bb28-c5ea-4713-8827-17e05464719e, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:232] - New session is open (session id: 90be2317-2bae-46d7-a749-b7c12ae9e45b)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:232] - New session is open (session id: c3b41e09-1085-42be-989a-a4329ec78f9d)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 90be2317-2bae-46d7-a749-b7c12ae9e45b, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@2304bf7d[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@59fef065[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@3bb99d78]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@736366eb[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 9])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: d95fcf25-96bb-488e-82d0-c58f34f971fd)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 05b787e7-eac4-46fe-be77-9224c3afe8d4, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: d95fcf25-96bb-488e-82d0-c58f34f971fd, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: fc1f4a6d-dca2-4b2e-a460-ef6e36b85bf7)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 1399de65-d596-4c50-8eb9-0642a739da3a)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: fc1f4a6d-dca2-4b2e-a460-ef6e36b85bf7, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 794fa0c3-be2c-49dd-b1c4-139e48655f62)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 794fa0c3-be2c-49dd-b1c4-139e48655f62, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@473c7589[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@1206fbbd[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@5d6631b2]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@bd69ced[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 11])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 79bc4280-dbda-4538-aad1-5d68033edcb0, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 794fa0c3-be2c-49dd-b1c4-139e48655f62, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 5b4f8944-eb06-40d7-aba0-add54fa8e00c)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 5b4f8944-eb06-40d7-aba0-add54fa8e00c, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 14a9dcff-fac7-4474-be19-76b0603d6f73)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 14a9dcff-fac7-4474-be19-76b0603d6f73, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: f5b2229b-47c3-4d32-b38e-b10682988a11)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: f5b2229b-47c3-4d32-b38e-b10682988a11, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: e7183eb7-66d6-4d78-b12b-858734bf5462)
[socket-mode-session-cleaner-worker-144] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 4a66a00a-4ee4-493b-9727-cbf2bd19564a, reason: com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl did it)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 4a7c4440-5025-49b9-9540-c8b2b2fbcc8c)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: e6abc674-dc7f-4034-ac90-e3b5da6d2e53)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 8e6205c2-3632-4bbd-a941-f4caf35c9119)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 2f7a5e41-2276-48fd-adfa-d09289dd9145)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 2d043bdb-cc4e-49cc-a5fa-c620d713a7c7)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 791a9efa-d232-4c44-b3c2-d5ce653025bc)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: e6abc674-dc7f-4034-ac90-e3b5da6d2e53, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 65b336bc-f233-452f-a504-e0a6362da1d6, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: d3218d3a-28d3-4af0-b710-81266999c052)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: d3218d3a-28d3-4af0-b710-81266999c052, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: d3218d3a-28d3-4af0-b710-81266999c052, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@68aab4fd[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@733001c1[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@68ec4a4c]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@68b304cb[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 17])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 10f4f6f3-7ba6-414c-8484-be717f253b3f, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 8a4b7f2c-a3c4-4be8-865d-f785658b9d2e, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: b8424916-a257-4621-9f41-c96da7cd38c5)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 576e0f2a-5a31-4438-8691-b11e92488210)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: b8424916-a257-4621-9f41-c96da7cd38c5, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 3f88f8a6-d3b7-4cf9-9bae-aea29cf66800)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 3f88f8a6-d3b7-4cf9-9bae-aea29cf66800, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@3eb2a393[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@46814ab9[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@22826d90]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@73742555[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 4])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 791a9efa-d232-4c44-b3c2-d5ce653025bc, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 3f88f8a6-d3b7-4cf9-9bae-aea29cf66800, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 791a9efa-d232-4c44-b3c2-d5ce653025bc, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@7e63b99d[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@2f98fbc2[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@2e505c5]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@5b2e1863[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 32])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 84dcd1e6-9b50-4b00-914c-2b5e5deda05e, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 84dcd1e6-9b50-4b00-914c-2b5e5deda05e, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@24e4cc9c[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@7545533a[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@392c25c1]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@5b2e1863[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 32])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 2959c247-b34c-421a-947a-1a76bc3a1c85, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: a538df59-61a7-4604-af00-58eaaa4d625c)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: a538df59-61a7-4604-af00-58eaaa4d625c, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: f7eaa661-f240-435c-8e4c-54a293bd58b0)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: f7eaa661-f240-435c-8e4c-54a293bd58b0, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 0a4bb8bd-89fd-40d1-b5dd-d3dc39a8d3fc)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 0a4bb8bd-89fd-40d1-b5dd-d3dc39a8d3fc, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 7a02ae57-3271-423c-b343-16659d776df7)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 7a02ae57-3271-423c-b343-16659d776df7, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 9e9b7b70-dafa-4035-8ce0-0aa4bd0d898d)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 9e9b7b70-dafa-4035-8ce0-0aa4bd0d898d, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 84104aab-1b7c-4d3e-a279-d860c86fc30b)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 84104aab-1b7c-4d3e-a279-d860c86fc30b, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 49eb7157-4530-447c-afab-00de8444c204)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 49eb7157-4530-447c-afab-00de8444c204, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@19a1633a[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@540bb83a[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@10c3fd61]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@76af3c45[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 12])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 49eb7157-4530-447c-afab-00de8444c204, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 2f7a5e41-2276-48fd-adfa-d09289dd9145, reason: Closed abnormally.)
[socket-mode-session-cleaner-worker-95] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 2f7a5e41-2276-48fd-adfa-d09289dd9145, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@4e75a0aa[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@5b303df2[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@5bce7996]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@268bbaad[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 11])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 6830e028-f620-4e45-85cb-557fea1a9484)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 6830e028-f620-4e45-85cb-557fea1a9484, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 3832638b-6a8c-43fa-84e4-16efe5a0eb9a)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 3832638b-6a8c-43fa-84e4-16efe5a0eb9a, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@2be7b175[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@51c897eb[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@4b7d5065]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@10ce62b2[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 19])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 013fc9e9-719f-41d7-931a-358ca821e152, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 3832638b-6a8c-43fa-84e4-16efe5a0eb9a, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 0f49f222-c3c8-4f88-b07a-8876ab9f17e0)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 0f49f222-c3c8-4f88-b07a-8876ab9f17e0, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 0f49f222-c3c8-4f88-b07a-8876ab9f17e0, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@1652ada[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@1b2299db[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@11080e23]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@501e87a6[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 13])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 1399de65-d596-4c50-8eb9-0642a739da3a, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 0ba86d61-e074-4d53-b3fa-ebc4aaea9190)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 0ba86d61-e074-4d53-b3fa-ebc4aaea9190, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: f6c805c6-21df-4f49-b1de-f7e29f351515)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: f6c805c6-21df-4f49-b1de-f7e29f351515, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 76fd4f7a-4ec1-47c8-81bc-95a50f12c231)
[Grizzly(1)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 76fd4f7a-4ec1-47c8-81bc-95a50f12c231, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: a57e51fb-4255-46bc-9671-cef169764d63)
[Grizzly(1)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: a57e51fb-4255-46bc-9671-cef169764d63, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 2d043bdb-cc4e-49cc-a5fa-c620d713a7c7, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 03fb50a3-b0d9-4b77-96e5-b6294eb48ee8)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 03fb50a3-b0d9-4b77-96e5-b6294eb48ee8, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: f16c5a1c-5082-4057-b0ba-8cd477c41b01)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: f16c5a1c-5082-4057-b0ba-8cd477c41b01, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: c0eb641c-9c9f-4681-af44-37e405e75cbc)
[socket-mode-session-cleaner-worker-95] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 1c290446-2c5c-49a8-a909-266cc2e48e6d, reason: com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl did it)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 11f5014a-097f-4f9a-9aaf-8a0ce5ce9db4)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 11f5014a-097f-4f9a-9aaf-8a0ce5ce9db4, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 991f9316-1a41-43cd-bffd-7e56d9748ca9)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: d3ab0814-2ea9-4b78-b0e8-ea0a39756fb4)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 991f9316-1a41-43cd-bffd-7e56d9748ca9, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: bbe50fa2-d7fb-4255-9265-229ea2de31f6)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: bbe50fa2-d7fb-4255-9265-229ea2de31f6, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 8ee1d8ee-d023-431b-9625-20387d95748d)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 8ee1d8ee-d023-431b-9625-20387d95748d, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: e4dc7a9d-2b22-4751-a489-23228c977445)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: e842a265-17c7-49c9-a30c-9163a70c0a28)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: e4dc7a9d-2b22-4751-a489-23228c977445, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 592f3a8d-fadb-461f-95c9-e3a250b72af8)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 5e73ec8f-4803-40f3-a8ca-0ed66e3dfd0c)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 8e06ff07-15b0-4524-968b-a3e504627fce)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: fa3f2fe9-ec40-468b-a5cb-2ca7f25a4deb)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 90dba958-8dc5-4fcf-a457-9afabcefb423)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: bd00f506-cac0-402d-882d-690dc5d491bd)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 66652362-b9fc-442f-bd59-56fbd2c419a4)
[Grizzly(2)] 2023-12-24 01:47:08 [ERROR] [SocketModeClient:263] - Failed to reconnect to the Socket Mode server: Failed to connect to the Socket Mode API endpoint. (status: 429, error: ratelimited)
java.io.IOException: Failed to connect to the Socket Mode API endpoint. (status: 429, error: ratelimited)
at com.slack.api.Slack.issueSocketModeUrl(Slack.java:196)
at com.slack.api.socket_mode.SocketModeClient.connectToNewEndpoint(SocketModeClient.java:65)
at com.slack.api.socket_mode.SocketModeClient.runCloseListenersAndAutoReconnectAsNecessary(SocketModeClient.java:261)
at com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl.onClose(SocketModeClientTyrusImpl.java:242)
at jdk.internal.reflect.GeneratedMethodAccessor72.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at org.glassfish.tyrus.core.AnnotatedEndpoint.callMethod(AnnotatedEndpoint.java:551)
at org.glassfish.tyrus.core.AnnotatedEndpoint.onClose(AnnotatedEndpoint.java:566)
at org.glassfish.tyrus.core.AnnotatedEndpoint.onClose(AnnotatedEndpoint.java:575)
at org.glassfish.tyrus.core.TyrusEndpointWrapper.onClose(TyrusEndpointWrapper.java:1235)
at org.glassfish.tyrus.core.TyrusWebSocket.onClose(TyrusWebSocket.java:110)
at org.glassfish.tyrus.core.ProtocolHandler.close(ProtocolHandler.java:488)
at org.glassfish.tyrus.core.TyrusWebSocket.close(TyrusWebSocket.java:244)
at org.glassfish.tyrus.client.TyrusClientEngine$2$1.close(TyrusClientEngine.java:613)
at org.glassfish.tyrus.container.grizzly.client.GrizzlyClientFilter$CloseTask.execute(GrizzlyClientFilter.java:484)
at org.glassfish.tyrus.container.grizzly.client.TaskProcessor.processTask(TaskProcessor.java:91)
at org.glassfish.tyrus.container.grizzly.client.TaskProcessor.processTask(TaskProcessor.java:68)
at org.glassfish.tyrus.container.grizzly.client.GrizzlyClientFilter.handleClose(GrizzlyClientFilter.java:198)
at org.glassfish.grizzly.filterchain.ExecutorResolver$4.execute(ExecutorResolver.java:52)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:260)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:177)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:109)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:88)
at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:53)
at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:515)
at org.glassfish.grizzly.nio.NIOConnection.preClose(NIOConnection.java:881)
at org.glassfish.grizzly.nio.transport.TCPNIOConnection.preClose(TCPNIOConnection.java:73)
at org.glassfish.grizzly.nio.NIOConnection.terminate0(NIOConnection.java:599)
at org.glassfish.grizzly.nio.transport.TCPNIOConnection.terminate0(TCPNIOConnection.java:267)
at org.glassfish.grizzly.nio.transport.TCPNIOTransport.read(TCPNIOTransport.java:608)
at org.glassfish.grizzly.nio.transport.TCPNIOTransportFilter.handleRead(TCPNIOTransportFilter.java:51)
at org.glassfish.grizzly.filterchain.TransportFilter.handleRead(TransportFilter.java:149)
at org.glassfish.grizzly.ssl.SSLBaseFilter$SSLTransportFilterWrapper.handleRead(SSLBaseFilter.java:1120)
at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:95)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:260)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:177)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:109)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:88)
at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:53)
at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:515)
at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:89)
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:94)
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:33)
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:114)
at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:569)
at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:549)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: SlackApiException(response=Response{protocol=h2, code=429, message=, url=https://slack.com/api/apps.connections.open}, responseBody={"ok":false,"error":"ratelimited"}, error=SlackApiErrorResponse(ok=false, warning=null, error=ratelimited, needed=null, provided=null, httpResponseHeaders=null))
at com.slack.api.methods.impl.MethodsClientImpl.parseJsonResponseAndRunListeners(MethodsClientImpl.java:3553)
at com.slack.api.methods.impl.MethodsClientImpl.parseJsonResponseAndRunListeners(MethodsClientImpl.java:3526)
at com.slack.api.methods.impl.MethodsClientImpl.postFormWithTokenAndParseResponse(MethodsClientImpl.java:3433)
at com.slack.api.methods.impl.MethodsClientImpl.appsConnectionsOpen(MethodsClientImpl.java:1297)
at com.slack.api.methods.impl.MethodsClientImpl.appsConnectionsOpen(MethodsClientImpl.java:1302)
at com.slack.api.Slack.issueSocketModeUrl(Slack.java:184)
... 47 more
Updated bolt sdk and jdk (saw advices that solves some issues with ssl) but didn't help.
First we hav and hadhsake error and then retries and exceeding a limit
12-26T18:22:47.375Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : New session is open (session id: fd362d39-f74f-4a84-8954-9acf138768f9)
2023-12-26T18:22:47.390Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : onClose listener is called (session id: fd362d39-f74f-4a84-8954-9acf138768f9, reason: Closed abnormally.)
2023-12-26T18:22:47.485Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : New session is open (session id: e0021593-e6f6-41c2-9549-c051c8e876e5)
2023-12-26T18:22:47.504Z INFO 130 --- [ Grizzly(1)] c.s.api.socket_mode.SocketModeClient : onClose listener is called (session id: e0021593-e6f6-41c2-9549-c051c8e876e5, reason: Closed abnormally.)
2023-12-26T18:22:47.520Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : New session is open (session id: c045827f-7121-489f-b33c-3362b803a994)
2023-12-26T18:22:47.523Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : onClose listener is called (session id: c045827f-7121-489f-b33c-3362b803a994, reason: Closed abnormally.)
2023-12-26T18:22:47.594Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : New session is open (session id: 03df01fd-d3a5-4069-bac7-3bc87aa69641)
2023-12-26T18:22:47.614Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : New session is open (session id: d04a1c12-145f-43f8-9431-b6e49ed7cc03)
2023-12-26T18:22:47.615Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : onClose listener is called (session id: 03df01fd-d3a5-4069-bac7-3bc87aa69641, reason: Closed abnormally.)
2023-12-26T18:22:47.712Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : New session is open (session id: f08109c4-ebeb-4152-8de4-a0656248e9a1)
2023-12-26T18:22:47.717Z WARN 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : Failed to send a ping message (session id: f08109c4-ebeb-4152-8de4-a0656248e9a1, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@61278af5[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@281e57f7[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@541e60a]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@5982a0d1[Shutting down, pool size = 4, active threads = 0, queued tasks = 0, completed tasks = 4])
2023-12-26T18:22:47.757Z INFO 130 --- [aner-worker-198] c.s.api.socket_mode.SocketModeClient : onClose listener is called (session id: f08109c4-ebeb-4152-8de4-a0656248e9a1, reason: com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl did it)
2023-12-26T18:22:47.788Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : New session is open (session id: 9c486e21-b2e0-42b7-a94f-d2049508e21f)
2023-12-26T18:22:47.892Z INFO 130 --- [aner-worker-192] c.s.api.socket_mode.SocketModeClient : onClose listener is called (session id: d04a1c12-145f-43f8-9431-b6e49ed7cc03, reason: com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl did it)
2023-12-26T18:22:47.898Z ERROR 130 --- [aner-worker-181] c.s.api.socket_mode.SocketModeClient : Failed to reconnect to Socket Mode server: javax.websocket.DeploymentException: Handshake error.
java.io.IOException: javax.websocket.DeploymentException: Handshake error.
at com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl.connect(SocketModeClientTyrusImpl.java:173) ~[slack-api-client-1.36.1.jar:1.36.1]
at com.slack.api.socket_mode.SocketModeClient.connectToNewEndpoint(SocketModeClient.java:66) ~[slack-api-client-1.36.1.jar:1.36.1]
at com.slack.api.socket_mode.SocketModeClient.runCloseListenersAndAutoReconnectAsNecessary(SocketModeClient.java:261) ~[slack-api-client-1.36.1.jar:1.36.1]
at com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl.onClose(SocketModeClientTyrusImpl.java:242) ~[slack-api-client-1.36.1.jar:1.36.1]
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) ~[na:na]
at java.base/java.lang.reflect.Method.invoke(Method.java:580) ~[na:na]
at org.glassfish.tyrus.core.AnnotatedEndpoint.callMethod(AnnotatedEndpoint.java:551) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.core.AnnotatedEndpoint.onClose(AnnotatedEndpoint.java:566) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.core.AnnotatedEndpoint.onClose(AnnotatedEndpoint.java:575) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.core.TyrusEndpointWrapper.onClose(TyrusEndpointWrapper.java:1235) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.core.TyrusWebSocket.onClose(TyrusWebSocket.java:110) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.core.ProtocolHandler.close(ProtocolHandler.java:488) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.core.TyrusWebSocket.close(TyrusWebSocket.java:244) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.core.TyrusWebSocket.close(TyrusWebSocket.java:254) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.core.TyrusRemoteEndpoint.close(TyrusRemoteEndpoint.java:480) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.core.TyrusSession.close(TyrusSession.java:211) ~[tyrus-standalone-client-1.21.jar:na]
at com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl.closeSession(SocketModeClientTyrusImpl.java:296) ~[slack-api-client-1.36.1.jar:1.36.1]
at com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl.lambda$setCurrentSession$1(SocketModeClientTyrusImpl.java:278) ~[slack-api-client-1.36.1.jar:1.36.1]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:1583) ~[na:na]
Caused by: javax.websocket.DeploymentException: Handshake error.
at org.glassfish.tyrus.client.ClientManager$3$1.run(ClientManager.java:658) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.client.ClientManager$3.run(ClientManager.java:696) ~[tyrus-standalone-client-1.21.jar:na]
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572) ~[na:na]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317) ~[na:na]
at org.glassfish.tyrus.client.ClientManager$SameThreadExecutorService.execute(ClientManager.java:849) ~[tyrus-standalone-client-1.21.jar:na]
at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:123) ~[na:na]
at org.glassfish.tyrus.client.ClientManager.connectToServer(ClientManager.java:493) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.client.ClientManager.connectToServer(ClientManager.java:355) ~[tyrus-standalone-client-1.21.jar:na]
at com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl.connect(SocketModeClientTyrusImpl.java:170) ~[slack-api-client-1.36.1.jar:1.36.1]
... 20 common frames omitted
Caused by: org.glassfish.tyrus.core.HandshakeException: Response code was not 101: 408.
at org.glassfish.tyrus.client.TyrusClientEngine.processResponse(TyrusClientEngine.java:300) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.container.grizzly.client.GrizzlyClientFilter.handleHandshake(GrizzlyClientFilter.java:323) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.container.grizzly.client.GrizzlyClientFilter.handleRead(GrizzlyClientFilter.java:292) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:95) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:260) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:177) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:109) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:88) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:53) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:515) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:89) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:94) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:33) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:114) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:569) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:549) ~[tyrus-standalone-client-1.21.jar:na]
... 1 common frames omitted
ion id: 92c7e0f2-1dba-472a-ab37-f053a8b283fc, reason: Closed abnormally.)
2023-12-26T23:24:16.881Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : New session is open (session id: a1b4f1cb-0b95-42b9-a5da-c070b8b2947c)
2023-12-26T23:24:16.897Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : New session is open (session id: 7a4a3c63-4fd6-4abe-80cc-2ef6031a361c)
2023-12-26T23:24:16.900Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : onClose listener is called (session id: a1b4f1cb-0b95-42b9-a5da-c070b8b2947c, reason: Closed abnormally.)
2023-12-26T23:24:16.928Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : onClose listener is called (session id: a1326811-8a08-448c-b1a3-2645d4b82e0f, reason: Closed abnormally.)
2023-12-26T23:24:16.941Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : New session is open (session id: 8b8d532e-d981-43eb-976a-83493ac4f0fe)
2023-12-26T23:24:16.951Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : onClose listener is called (session id: 8b8d532e-d981-43eb-976a-83493ac4f0fe, reason: Closed abnormally.)
2023-12-26T23:24:16.998Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : New session is open (session id: 4c32957b-bddf-40f8-8084-b6c5c2e68ecb)
2023-12-26T23:24:17.007Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : New session is open (session id: 355d9b0d-d4b5-4f0b-850c-63645061e1ad)
2023-12-26T23:24:17.011Z INFO 130 --- [ Grizzly(1)] c.s.api.socket_mode.SocketModeClient : onClose listener is called (session id: 4c32957b-bddf-40f8-8084-b6c5c2e68ecb, reason: Closed abnormally.)
2023-12-26T23:24:17.065Z WARN 130 --- [aner-worker-198] c.s.api.socket_mode.SocketModeClient : Failed to send a ping message (session id: 4c32957b-bddf-40f8-8084-b6c5c2e68ecb, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@5fec3609[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@2cec5a3c[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@6a54033c]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@2bd3abfd[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 7])
2023-12-26T23:24:17.072Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : New session is open (session id: 7e7e39af-d1fd-456f-a2e2-c68d378c336c)
2023-12-26T23:24:17.083Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : onClose listener is called (session id: 7e7e39af-d1fd-456f-a2e2-c68d378c336c, reason: Closed abnormally.)
2023-12-26T23:24:17.089Z ERROR 130 --- [ Grizzly(2)] com.slack.api.methods.impl.TeamIdCache : Failed to call auth.test API (error: status: 429, error: ratelimited, needed: null, provided: null, warning: null)
com.slack.api.methods.SlackApiException: status: 429, error: ratelimited, needed: null, provided: null, warning: null
at com.slack.api.methods.impl.MethodsClientImpl.parseJsonResponseAndRunListeners(MethodsClientImpl.java:3617) ~[slack-api-client-1.36.1.jar:1.36.1]
at com.slack.api.methods.impl.MethodsClientImpl.parseJsonResponseAndRunListeners(MethodsClientImpl.java:3590) ~[slack-api-client-1.36.1.jar:1.36.1]
at com.slack.api.methods.impl.TeamIdCache.lambda$lookupOrResolve$0(TeamIdCache.java:44) ~[slack-api-client-1.36.1.jar:1.36.1]
at java.base/java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1708) ~[na:na]
at com.slack.api.methods.impl.TeamIdCache.lookupOrResolve(TeamIdCache.java:67) ~[slack-api-client-1.36.1.jar:1.36.1]
at com.slack.api.methods.impl.TeamIdCache.lookupOrResolve(TeamIdCache.java:40) ~[slack-api-client-1.36.1.jar:1.36.1]
at com.slack.api.methods.impl.MethodsClientImpl.postFormWithTokenAndParseResponse(MethodsClientImpl.java:3488) ~[slack-api-client-1.36.1.jar:1.36.1]
at com.slack.api.methods.impl.MethodsClientImpl.appsConnectionsOpen(MethodsClientImpl.java:1301) ~[slack-api-client-1.36.1.jar:1.36.1]
at com.slack.api.methods.impl.MethodsClientImpl.appsConnectionsOpen(MethodsClientImpl.java:1306) ~[slack-api-client-1.36.1.jar:1.36.1]
at com.slack.api.Slack.issueSocketModeUrl(Slack.java:184) ~[slack-api-client-1.36.1.jar:1.36.1]
at com.slack.api.socket_mode.SocketModeClient.connectToNewEndpoint(SocketModeClient.java:65) ~[slack-api-client-1.36.1.jar:1.36.1]
at com.slack.api.socket_mode.SocketModeClient.runCloseListenersAndAutoReconnectAsNecessary(SocketModeClient.java:261) ~[slack-api-client-1.36.1.jar:1.36.1]
at com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl.onClose(SocketModeClientTyrusImpl.java:242) ~[slack-api-client-1.36.1.jar:1.36.1]
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) ~[na:na]
at java.base/java.lang.reflect.Method.invoke(Method.java:580) ~[na:na]
at org.glassfish.tyrus.core.AnnotatedEndpoint.callMethod(AnnotatedEndpoint.java:551) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.core.AnnotatedEndpoint.onClose(AnnotatedEndpoint.java:566) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.core.AnnotatedEndpoint.onClose(AnnotatedEndpoint.java:575) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.core.TyrusEndpointWrapper.onClose(TyrusEndpointWrapper.java:1235) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.core.TyrusWebSocket.onClose(TyrusWebSocket.java:110) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.core.ProtocolHandler.close(ProtocolHandler.java:488) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.core.TyrusWebSocket.close(TyrusWebSocket.java:244) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.client.TyrusClientEngine$2$1.close(TyrusClientEngine.java:613) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.container.grizzly.client.GrizzlyClientFilter$CloseTask.execute(GrizzlyClientFilter.java:484) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.container.grizzly.client.TaskProcessor.processTask(TaskProcessor.java:91) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.container.grizzly.client.TaskProcessor.processTask(TaskProcessor.java:68) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.tyrus.container.grizzly.client.GrizzlyClientFilter.handleClose(GrizzlyClientFilter.java:198) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.filterchain.ExecutorResolver$4.execute(ExecutorResolver.java:52) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:260) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:177) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:109) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:88) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:53) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:515) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.nio.NIOConnection.preClose(NIOConnection.java:881) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.nio.transport.TCPNIOConnection.preClose(TCPNIOConnection.java:73) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.nio.NIOConnection.terminate0(NIOConnection.java:599) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.nio.transport.TCPNIOConnection.terminate0(TCPNIOConnection.java:267) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.nio.transport.TCPNIOTransport.read(TCPNIOTransport.java:608) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.nio.transport.TCPNIOTransportFilter.handleRead(TCPNIOTransportFilter.java:51) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.filterchain.TransportFilter.handleRead(TransportFilter.java:149) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.ssl.SSLBaseFilter$SSLTransportFilterWrapper.handleRead(SSLBaseFilter.java:1120) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:95) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:260) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:177) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:109) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:88) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:53) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:515) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:89) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:94) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:33) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:114) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:569) ~[tyrus-standalone-client-1.21.jar:na]
at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:549) ~[tyrus-standalone-client-1.21.jar:na]
at java.base/java.lang.Thread.run(Thread.java:1583) ~[na:na]
Hey @dbudim, happy new year!
Regarding your last logs provided in your last comment: it seems the websocket connection gets closed 'abnormally' first:
2023-12-26T18:22:47.375Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : New session is open (session id: fd362d39-f74f-4a84-8954-9acf138768f9)
2023-12-26T18:22:47.390Z INFO 130 --- [ Grizzly(2)] c.s.api.socket_mode.SocketModeClient : onClose listener is called (session id: fd362d39-f74f-4a84-8954-9acf138768f9, reason: Closed abnormally.)
This is assuming that session id: fd362d39-f74f-4a84-8954-9acf138768f9
is the 'first' session on app boot up?
According to the WebSocket spec, an abnormal closure is one where the connection was severed without an endpoint sending a Close frame (see close code 1006). This indicates to me that the underlying network connection had an issue.
Regardless, I would expect this SDK to be able to handle this, try to reconnect, and not get itself all confused and cause a rate limit exception 😓
Looking through the logs, it seems to me that possibly the SDK is not accounting for the retries in a correct manner. Some of the session IDs are not 'paired' properly with a open and close message. For example, session ID 7a4a3c63-4fd6-4abe-80cc-2ef6031a361c
I only see an 'open' message for, but not a closed one. Additionally, it seems like the socket connection thread pool (of size 4) also experienced issues.
This will probably be difficult to debug / reproduce, but I will try...
Actually, #1256 has very similar logging as here... looking into it.
Going to close this issue as it is a duplicate of #1256 and there is more activity there. If you have more discussion to contribute to this issue, please comment over in #1256.
Operating context:
Relevant logs:
java SDK:
Originally posted by @dbudim in https://github.com/slackapi/node-slack-sdk/issues/1654#issuecomment-1779584504