Heartbeat/Websocket connection error

[aplomBomb]

Describe the bug
Every so often during music playback it appears the websocket connection gets interrupted

Expected behavior
For the websocket connection to successfully reconnect on heartbeat

Error messages

DEBU[4717] [ws-v,s:703,shard:0]sent heartbeat
DEBU[4724] [ws-v,s:704,shard:0]closing receiver after read error
DEBU[4724] [ws-v,s:705,shard:0]is reconnecting
DEBU[4724] [ws-v,s:706,shard:0]closing operations handler
INFO[4724] [ws-v,s:707,shard:0]disconnected
DEBU[4724] [ws-v,s:709,shard:0]closing emitter
DEBU[4724] [ws-v,s:710,shard:0]reconnecting failed: failed to close WebSocket: failed to write control frame opClose: WebSocket closed: failed to read frame header: EOF
DEBU[4724] [ws-v,s:711,shard:0]trying to connect
DEBU[4724] [ws-v,s:708,shard:0]stopping pulse
DEBU[4724] [ws-v,s:712,shard:0]starting receiver
DEBU[4724] [ws-v,s:714,shard:0]Ready to receive operation codes...
DEBU[4724] [ws-v,s:713,shard:0]starting emitter
ERRO[4729] [ws-v,s:715,shard:0]establishing connection failed: did not receive desired event in time. opcode 2
INFO[4729] [ws-v,s:716,shard:0]next connection attempt in 3s
DEBU[4732] [ws-v,s:717,shard:0]trying to connect
DEBU[4732] [ws-v,s:718,shard:0]Ready to receive operation codes...
DEBU[4732] [ws-v,s:719,shard:0]tried to start an additional pulse
ERRO[4737] [ws-v,s:720,shard:0]establishing connection failed: did not receive desired event in time. opcode 2
INFO[4737] [ws-v,s:721,shard:0]next connection attempt in 7s
DEBU[4744] [ws-v,s:722,shard:0]trying to connect
DEBU[4744] [ws-v,s:724,shard:0]Ready to receive operation codes...
DEBU[4744] [ws-v,s:723,shard:0]tried to start an additional pulse
DEBU[4744] [ws-e,s:241,shard:0]heartbeat ACK ok
DEBU[4744] [ws-e,s:242,shard:0]sent heartbeat
ERRO[4749] [ws-v,s:725,shard:0]establishing connection failed: did not receive desired event in time. opcode 2
INFO[4749] [ws-v,s:726,shard:0]next connection attempt in 11s
DEBU[4760] [ws-v,s:727,shard:0]trying to connect
DEBU[4760] [ws-v,s:728,shard:0]Ready to receive operation codes...
DEBU[4760] [ws-v,s:729,shard:0]tried to start an additional pulse
ERRO[4765] [ws-v,s:730,shard:0]establishing connection failed: did not receive desired event in time. opcode 2
INFO[4765] [ws-v,s:731,shard:0]next connection attempt in 15s
DEBU[4779] [ws-v,s:732,shard:0]closing receiver after read error
DEBU[4780] [ws-v,s:733,shard:0]trying to connect
DEBU[4780] [ws-v,s:736,shard:0]starting receiver
DEBU[4780] [ws-v,s:735,shard:0]tried to start an additional pulse
DEBU[4780] [ws-v,s:734,shard:0]Ready to receive operation codes...
DEBU[4785] [ws-e,s:243,shard:0]heartbeat ACK ok
DEBU[4785] [ws-e,s:244,shard:0]sent heartbeat
ERRO[4785] [ws-v,s:737,shard:0]establishing connection failed: did not receive desired event in time. opcode 2
INFO[4785] [ws-v,s:738,shard:0]next connection attempt in 19s
DEBU[4804] [ws-v,s:739,shard:0]trying to connect
DEBU[4805] [ws-v,s:740,shard:0]Ready to receive operation codes...
DEBU[4805] [ws-v,s:741,shard:0]tried to start an additional pulse
ERRO[4810] [ws-v,s:742,shard:0]establishing connection failed: did not receive desired event in time. opcode 2
INFO[4810] [ws-v,s:743,shard:0]next connection attempt in 23s
DEBU[4827] [ws-e,s:245,shard:0]heartbeat ACK ok
DEBU[4827] [ws-e,s:246,shard:0]sent heartbeat
DEBU[4833] [ws-v,s:744,shard:0]trying to connect
DEBU[4833] [ws-v,s:745,shard:0]Ready to receive operation codes...
DEBU[4833] [ws-v,s:746,shard:0]tried to start an additional pulse
DEBU[4835] [ws-v,s:747,shard:0]closing receiver after read error
ERRO[4838] [ws-v,s:748,shard:0]establishing connection failed: did not receive desired event in time. opcode 2
INFO[4838] [ws-v,s:749,shard:0]next connection attempt in 27s
DEBU[4865] [ws-v,s:750,shard:0]trying to connect
DEBU[4865] [ws-v,s:752,shard:0]starting receiver
DEBU[4865] [ws-v,s:751,shard:0]Ready to receive operation codes...
DEBU[4865] [ws-v,s:753,shard:0]tried to start an additional pulse
DEBU[4868] [ws-e,s:247,shard:0]heartbeat ACK ok
DEBU[4868] [ws-e,s:248,shard:0]sent heartbeat
ERRO[4870] [ws-v,s:754,shard:0]establishing connection failed: did not receive desired event in time. opcode 2
INFO[4870] [ws-v,s:755,shard:0]next connection attempt in 31s
DEBU[4901] [ws-v,s:756,shard:0]trying to connect
DEBU[4901] [ws-v,s:757,shard:0]Ready to receive operation codes...
DEBU[4901] [ws-v,s:758,shard:0]tried to start an additional pulse
ERRO[4906] [ws-v,s:759,shard:0]establishing connection failed: did not receive desired event in time. opcode 2
INFO[4906] [ws-v,s:760,shard:0]next connection attempt in 35s```



**Desktop (please complete the following information):**
 - Golang version: v1.15
 - Using Go modules? yes
 - Disgord version? v0.21.1-0.20201118211648-e7e8dc53dcd6
 - Connected to the gateway before using REST methods? yes

**Additional context**
![image](https://user-images.githubusercontent.com/39172279/100157848-447e9900-2e79-11eb-8dcd-0f07bee43415.png)

[andersfylling]

Note: it's been running for hours. I figure it's a reconnect issue.

[andersfylling]

I noticed that once the voice client have connected it updates a variable haveConnectedOnce to true. This is never set to false, and causes disgord to always send a RESUME command, even if discord have invalidated the session.

I believe this is the issue, and that has now been patched here: 4a4d9ae

If the issue persists. Please comment so and I will open up the issue.
(Remember to use the commit hash above as the version, or v0.22 when that has been released. Otherwise your observations won't respect the latest patch)

[aplomBomb]

After about 16 hours or so.....I've been getting the opcode 2 error again, v0.22

[andersfylling]

Do you have more of the logs? What has been happening before?

…

On Tue, 8 Dec 2020, 02:28 Christian Baldwin, ***@***.***> wrote: After about 16 hours or so.....I've been getting the opcode 2 error again, v0.22 [image: image] <https://user-images.githubusercontent.com/39172279/101426328-c2f02780-38ca-11eb-8e58-bcecd1759f08.png> — You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub <#351 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AB346VHO4WLEVBFXAZOPRP3STV6MXANCNFSM4UBPKTNQ> .

[andersfylling]

It would be great to see more of the logs, before you get opcode 2 errors to verify that disgord detects the resume condition. There should be a message with "might try to resume. Increase timeout by". Can you please provide that section of the logs?

[aplomBomb]

I haven't been using the logger, i'll enable it and supply you with more robust logs when it occurs again, sorry I should have done that before commenting again, my apologies!

[andersfylling]

So the picture you linked is not from the v0.22 instance?

If you have to restart it, can you also upgrade to disgord v0.23.1 =)

[aplomBomb]

it is

[aplomBomb]

yes, i'll update, enable logger and report back as soon as it happens

[andersfylling]

If you're able to it would be great if you could store debug logs. Note that there's going to be a lot of stuff so it should be stored in a file.

[aplomBomb]

I closed this because I'm unable to reproduce it.

[andersfylling]

Lies