Websocket trying to reconnect every 30 seconds
ChadConning opened this issue · 1 comments
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
- version 2.7.6
- atmosphere.js version 2.3.6
- using wasync 2.1.7
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:
- OS: Windows 10 and 11
- Microsoft Edge Version 110.0.1587.57
- Java 11 jdk-11.0.17+8
- Embedded Jetty 10
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?
@ChadConning I'm unable to reproduce. Can you share a test case on Github?