search

Atmosphere / atmosphere

Event Driven WebSockets Framework with Cross-Browser Fallbacks
http://async-io.org/
3.69k stars 750 forks source link

Websocket trying to reconnect every 30 seconds #2488

Closed ChadConning closed 9 months ago

ChadConning commented 1 year ago

After every 30 seconds the websocket is trying to reconnect and the UI running on the server refreshes. Then after maybe 35 minutes the cache is overloaded and the CPU usage goes from almost nothing up to 50% and the logs are flooded with "[org.atmosphere.cpr.AsynchronousProcessor] - Transport not matching webSocketEnabled." messages.

Atmosphere Info

Expected behavior The default WEBSOCKET_IDLETIME appears to 5 minutes. One would expect the connection to stay open for at least 5 minutes without any activity.

Screenshots

Every 30 seconds: 2023-02-09 14:24:24,310 INFO [New I/O worker #3] [org.atmosphere.wasync.transport.WebSocketTransport] - try reconnect : attempt [1/0] 2023-02-09 14:24:24,315 INFO [New I/O worker #3] [org.atmosphere.wasync.transport.WebSocketTransport] - reconnect successful ! in attempt [1/0] 2023-02-09 14:24:54,335 INFO [New I/O worker #4] [org.atmosphere.wasync.transport.WebSocketTransport] - try reconnect : attempt [1/0] 2023-02-09 14:24:54,345 INFO [New I/O worker #4] [org.atmosphere.wasync.transport.WebSocketTransport] - reconnect successful ! in attempt [1/0] 2023-02-09 14:25:24,367 INFO [New I/O worker #1] [org.atmosphere.wasync.transport.WebSocketTransport] - try reconnect : attempt [1/0] 2023-02-09 14:25:24,372 INFO [New I/O worker #1] [org.atmosphere.wasync.transport.WebSocketTransport] - reconnect successful ! in attempt [1/0] 2023-02-09 14:25:54,381 INFO [New I/O worker #2] [org.atmosphere.wasync.transport.WebSocketTransport] - try reconnect : attempt [1/0] 2023-02-09 14:25:54,390 INFO [New I/O worker #2] [org.atmosphere.wasync.transport.WebSocketTransport] - reconnect successful ! in attempt [1/0] 2023-02-09 14:26:24,401 INFO [New I/O worker #3] [org.atmosphere.wasync.transport.WebSocketTransport] - try reconnect : attempt [1/0] 2023-02-09 14:26:24,405 INFO [New I/O worker #3] [org.atmosphere.wasync.transport.WebSocketTransport] - reconnect successful ! in attempt [1/0] 2023-02-09 14:26:54,411 INFO [New I/O worker #4] [org.atmosphere.wasync.transport.WebSocketTransport] - try reconnect : attempt [1/0] 2023-02-09 14:26:54,414 INFO [New I/O worker #4] [org.atmosphere.wasync.transport.WebSocketTransport] - reconnect successful ! in attempt [1/0] 2023-02-09 14:27:24,432 INFO [New I/O worker #1] [org.atmosphere.wasync.transport.WebSocketTransport] - try reconnect : attempt [1/0] 2023-02-09 14:27:24,436 INFO [New I/O worker #1] [org.atmosphere.wasync.transport.WebSocketTransport] - reconnect successful ! in attempt [1/0]

After ~35 minutes: 2023-03-03 10:20:32,138 WARN [qtp327565109-111] [org.eclipse.jetty.http.HttpParser] - Header is too large 8194>8192 2023-03-03 10:20:32,218 INFO [New I/O worker #4] [org.atmosphere.wasync.impl.DefaultSocket] - Waiting 2000, allowing the http connection to get handled by the server. To reduce the delay, make sure some bytes get written when the connection is suspended on the server 2023-03-03 10:20:32,256 WARN [qtp327565109-110] [org.atmosphere.cpr.AsynchronousProcessor] - Transport not matching webSocketEnabled. Ending request for 29942959-d7e5-4750-bdbb-d1eab01d0f39 2023-03-03 10:20:32,259 WARN [New I/O worker #2] [org.atmosphere.wasync.transport.StreamTransport] - StreamTransport notified with exception Connection Error 500 : Invalid Content-Type[] for request 2023-03-03 10:20:32,211 WARN [New I/O worker #1] [com.ning.http.client.providers.netty.handler.WebSocketProtocol] - onError {} org.atmosphere.wasync.transport.TransportNotSupported: null

,which leads to the logs being filled with:

2023-03-02 09:48:30,923 WARN [qtp465378217-99] [org.atmosphere.cpr.AsynchronousProcessor] - Transport not matching webSocketEnabled. Ending request for 00336b23-2888-4b97-90f4-fd898536b4a8 2023-03-02 09:48:30,925 WARN [qtp465378217-102] [org.atmosphere.cpr.AsynchronousProcessor] - Transport not matching webSocketEnabled. Ending request for 00336b23-2888-4b97-90f4-fd898536b4a8 2023-03-02 09:48:30,927 WARN [qtp465378217-106] [org.atmosphere.cpr.AsynchronousProcessor] - Transport not matching webSocketEnabled. Ending request for 00336b23-2888-4b97-90f4-fd898536b4a8 2023-03-02 09:48:30,928 WARN [qtp465378217-99] [org.atmosphere.cpr.AsynchronousProcessor] - Transport not matching webSocketEnabled. Ending request for 00336b23-2888-4b97-90f4-fd898536b4a8 2023-03-02 09:48:30,932 WARN [qtp465378217-102] [org.atmosphere.cpr.AsynchronousProcessor] - Transport not matching webSocketEnabled. Ending request for 00336b23-2888-4b97-90f4-fd898536b4a8 2023-03-02 09:48:30,936 WARN [qtp465378217-106] [org.atmosphere.cpr.AsynchronousProcessor] - Transport not matching webSocketEnabled. Ending request for 00336b23-2888-4b97-90f4-fd898536b4a8 2023-03-02 09:48:30,938 WARN [qtp465378217-99] [org.atmosphere.cpr.AsynchronousProcessor] - Transport not matching webSocketEnabled. Ending request for 00336b23-2888-4b97-90f4-fd898536b4a8 2023-03-02 09:48:30,940 WARN [qtp465378217-100] [org.atmosphere.cpr.AsynchronousProcessor] - Transport not matching webSocketEnabled. Ending request for 00336b23-2888-4b97-90f4-fd898536b4a8 2023-03-02 09:48:30,942 WARN [qtp465378217-102] [org.atmosphere.cpr.AsynchronousProcessor] - Transport not matching webSocketEnabled. Ending request for 00336b23-2888-4b97-90f4-fd898536b4a8 2023-03-02 09:48:30,943 WARN [qtp465378217-99] [org.atmosphere.cpr.AsynchronousProcessor] - Transport not matching webSocketEnabled. Ending request for 00336b23-2888-4b97-90f4-fd898536b4a8

Systems:

Additional context I have set the property ApplicationConfig.WEBSOCKET_IDLETIME to 8 hours, but this is just a temporary fix. Is this solution okay? What is a better solution? Are there any side effects of setting the idle time to 8 hours?

jfarcand commented 1 year ago

@ChadConning I'm unable to reproduce. Can you share a test case on Github?