Describe the bug/issue.
At a random time (didn't find any trigger yet) when my music bot is in a voicechannel I get the event Abnormal Closure of type WebSocketClosedEvent. Everytime this event happens I get a WebSocket Exception some time later (in the given log this is ~70min). This gets caught by Discord.NET and a reconnect is initialized. The bot never leaves the channel.
If a music request is asked after this, the bot will accept it but will never output the music stream. Logging shows that lavalink is playing, but still no output from the bot. This throws no new exceptions (DiscordSocketClient log level: Verbose).
I don't know what the triggers before and expected behavior is after I get the Abnormal Closure event. Nor do I know how to catch it and provide a solution/workaround for it.
Feel free to ask for more information. Any information regarding this Abnormale Closure event and how to work with it is much appreciated.
Versions
- Discord.NET 2.3.0
- Victoria 5.1.11
- Lavalink 3.3.2.3
OS: Debian GNU/Linux 10 (buster)
Reproducibility:
Didn't found a trigger yet. Can happens twice in 1 hour, can be 1 time in a week.
Stacktrace / Screenshots
Abnormal closure event log (included some more lines for conveinice)
05:31:03 [Debug] Victoria: {"playingPlayers":0,"op":"stats","memory":{"reservable":2063597568,"used":337347960,"free":18119304,"allocated":355467264},"players":2,"cpu":{"cores":4,"systemLoad":0.06788544593064699,"lavalinkLoad":0.00225},"uptime":434035540}
05:32:03 [Debug] Victoria: {"playingPlayers":0,"op":"stats","memory":{"reservable":2063597568,"used":338154624,"free":17312640,"allocated":355467264},"players":2,"cpu":{"cores":4,"systemLoad":0.059888814016172506,"lavalinkLoad":0.00225},"uptime":434095540}
**05:32:32 [Debug] Victoria: {"op":"event","reason":"Abnormal closure","code":1006,"byRemote":false,"type":"WebSocketClosedEvent","guildId":"307269176202887169"}**
05:33:03 [Debug] Victoria: {"playingPlayers":0,"op":"stats","memory":{"reservable":2063597568,"used":338815952,"free":16651312,"allocated":355467264},"players":2,"cpu":{"cores":4,"systemLoad":0.061317183951551855,"lavalinkLoad":0.00225},"uptime":434155540}
05:34:03 [Debug] Victoria: {"playingPlayers":0,"op":"stats","memory":{"reservable":2063597568,"used":339340296,"free":16126968,"allocated":355467264},"players":2,"cpu":{"cores":4,"systemLoad":0.06012884753042234,"lavalinkLoad":0.00225},"uptime":434215540}
WebSocket Exception + reconnect:
06:41:37 [Warning] Gateway: System.Exception: WebSocket connection was closed
---> System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake.
---> System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake.
at System.Net.WebSockets.ManagedWebSocket.ThrowIfEOFUnexpected(Boolean throwOnPrematureClosure)
at System.Net.WebSockets.ManagedWebSocket.EnsureBufferContainsAsync(Int32 minimumRequiredBytes, CancellationToken cancellationToken, Boolean throwOnPrematureClosure)
at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
at Discord.Net.WebSockets.DefaultWebSocketClient.RunAsync(CancellationToken cancelToken)
--- End of inner exception stack trace ---
at Discord.ConnectionManager.<>c__DisplayClass29_0.<<StartAsync>b__0>d.MoveNext()
06:41:37 [Info] Gateway: Disconnecting
06:41:37 [Verbose] Gateway: Disconnected from iXD Varia
06:41:37 [Verbose] Gateway: Disconnected from iXD
06:41:37 [Verbose] Gateway: Disconnected from iNTERMiXED
06:41:37 [Info] Gateway: Disconnected
06:41:38 [Info] Gateway: Connecting
06:41:38 [Verbose] Rest: GET gateway: 128.03 ms
06:41:39 [Verbose] Gateway: Connected to iXD Varia
06:41:39 [Info] Gateway: Connected
06:41:39 [Verbose] Gateway: Connected to iXD
06:41:39 [Verbose] Gateway: Connected to iNTERMiXED
06:41:39 [Info] Gateway: Resumed previous session
Lavalink/Victoria logging when a music command is used
07:30:42.035 DEBUG 17445 --- [ XNIO-1 task-24] o.s.web.servlet.DispatcherServlet : GET "/loadtracks?identifier=ytsearch%3Aspanish+flea", parameters={masked}
07:30:42.062 DEBUG 17445 --- [ XNIO-1 task-24] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public java.util.concurrent.CompletionStage<org.springframework.http.ResponseEntity<java.lang.String>> lavalink.server.player.AudioLoaderRestHandler.getLoadTracks(javax.servlet.http.HttpServletRequest,java.lang.String)
07:30:42.063 INFO 17445 --- [ XNIO-1 task-24] l.server.player.AudioLoaderRestHandler : Got request to load for identifier "ytsearch:spanish flea"
07:30:42.064 DEBUG 17445 --- [ XNIO-1 task-24] o.s.w.c.request.async.WebAsyncManager : Started async request
07:30:42.064 DEBUG 17445 --- [ XNIO-1 task-24] o.s.web.servlet.DispatcherServlet : Exiting but response remains open for further handling
07:30:42.792 INFO 17445 --- [ader-2-thread-1] lavalink.server.player.AudioLoader : Loaded playlist Search results for: spanish flea
07:30:42.793 DEBUG 17445 --- [ader-2-thread-1] o.s.w.c.request.async.WebAsyncManager : Async result set, dispatch to /loadtracks
07:30:42.793 DEBUG 17445 --- [ XNIO-1 task-25] o.s.web.servlet.DispatcherServlet : "ASYNC" dispatch for GET "/loadtracks?identifier=ytsearch%3Aspanish+flea", parameters={masked}
07:30:42.794 DEBUG 17445 --- [ XNIO-1 task-25] s.w.s.m.m.a.RequestMappingHandlerAdapter : Resume with async result [<200 OK OK,{"playlistInfo":{},"loadType":"SEARCH_RESULT","tracks":[{"track":"QAAAfQIAGlNwYW5pc2ggRmx (truncated)...]
07:30:42.794 DEBUG 17445 --- [ XNIO-1 task-25] o.s.w.s.m.m.a.HttpEntityMethodProcessor : Using 'application/json', given [*/*] and supported [application/json]
07:30:42.794 DEBUG 17445 --- [ XNIO-1 task-25] o.s.w.s.m.m.a.HttpEntityMethodProcessor : Writing ["{"playlistInfo":{},"loadType":"SEARCH_RESULT","tracks":[{"track":"QAAAfQIAGlNwYW5pc2ggRmxlYSAtIEhlc (truncated)...]
07:30:42.810 DEBUG 17445 --- [ XNIO-1 task-25] o.s.web.servlet.DispatcherServlet : Exiting from "ASYNC" dispatch, status 200
07:30:42.815 INFO 17445 --- [ XNIO-1 I/O-4] lavalink.server.io.SocketServer : {"endTime":0,"track":"QAAAfQIAGlNwYW5pc2ggRmxlYSAtIEhlcmIgQWxwZXJ0AAlLbGFyIE5hbWUAAAAAAAHsMAALbU1MMmZQZWM3eFUAAQAraHR0cHM6Ly93d3cueW91dHViZS5jb20vd2F0Y2g/dj1tTUwyZlBlYzd4VQAHeW91dHViZQAAAAAAAAAA","noReplace":false,"startTime":0,"guildId":"307269176202887169","op":"play"}
07:30:42 [Debug] Victoria: {"op":"event","type":"TrackStartEvent","track":"QAAAfQIAGlNwYW5pc2ggRmxlYSAtIEhlcmIgQWxwZXJ0AAlLbGFyIE5hbWUAAAAAAAHsMAALbU1MMmZQZWM3eFUAAQAraHR0cHM6Ly93d3cueW91dHViZS5jb20vd2F0Y2g/dj1tTUwyZlBlYzd4VQAHeW91dHViZQAAAAAAAAAA","guildId":"307269176202887169"}
07:30:42 [Debug] Victoria: {"op":"playerUpdate","state":{"position":0,"time":1616524242815},"guildId":"307269176202887169"}
07:30:42 [Debug] Victoria: {"op":"playerUpdate","state":{"position":0,"time":1616524242815},"guildId":"307269176202887169"}
07:30:43 [Verbose] Rest: POST channels/312940674133655552/messages: 455.64 ms
07:30:43 [Verbose] Command: Executed "Play" for USERNAME in iXD/music
07:30:47 [Debug] Victoria: {"op":"playerUpdate","state":{"position":4200,"time":1616524247815},"guildId":"307269176202887169"}
07:30:52 [Debug] Victoria: {"op":"playerUpdate","state":{"position":9200,"time":1616524252815},"guildId":"307269176202887169"}
07:30:57 [Debug] Victoria: {"op":"playerUpdate","state":{"position":14200,"time":1616524257815},"guildId":"307269176202887169"}