discord-audio-pipe icon indicating copy to clipboard operation
discord-audio-pipe copied to clipboard

DAP eventually fails to reconnect

Open MaxLebled opened this issue 4 years ago • 8 comments

Hello! I have a minor issue I'd like to report: after several hours left unattended, DAP can fail to stay connected to a voice channel. When this happens, selecting a different voice channel & back didn't seem to work, or at least not fully: the bot account was in the channel, but audio didn't go through until a full program restart.

Errors log:

Disconnected from voice... Reconnecting in 1.18s.
Traceback (most recent call last):
  File "discord\voice_client.py", line 383, in poll_voice_ws
  File "discord\gateway.py", line 889, in poll_event
discord.errors.ConnectionClosed: Shard ID None WebSocket closed with 1006
Attempting a reconnect in 0.61s
Traceback (most recent call last):
  File "discord\client.py", line 551, in connect
  File "discord\gateway.py", line 578, in poll_event
discord.errors.ConnectionClosed: Shard ID None WebSocket closed with 1000
Attempting a reconnect in 1.14s
Traceback (most recent call last):
  File "discord\client.py", line 551, in connect
  File "discord\gateway.py", line 578, in poll_event
discord.errors.ConnectionClosed: Shard ID None WebSocket closed with 1000
Attempting a reconnect in 0.87s
Traceback (most recent call last):
  File "discord\client.py", line 551, in connect
  File "discord\gateway.py", line 578, in poll_event
discord.errors.ConnectionClosed: Shard ID None WebSocket closed with 1000
Disconnected from voice... Reconnecting in 0.41s.
Traceback (most recent call last):
  File "discord\voice_client.py", line 383, in poll_voice_ws
  File "discord\gateway.py", line 889, in poll_event
discord.errors.ConnectionClosed: Shard ID None WebSocket closed with 1001

I believe part of this failure to auto-reconnect may be witnessed by manually changing a server's voice region while connected; the "jump" in sessions can then result in these slightly different errors:

Disconnected from voice... Reconnecting in 1.27s.
Traceback (most recent call last):
  File "discord\voice_client.py", line 383, in poll_voice_ws
  File "discord\gateway.py", line 889, in poll_event
discord.errors.ConnectionClosed: Shard ID None WebSocket closed with 4000
Exception in voice thread Thread-20
Traceback (most recent call last):
  File "discord\player.py", line 598, in run
  File "discord\player.py", line 591, in _do_run
  File "discord\voice_client.py", line 598, in send_audio_packet
TypeError: str, bytes or bytearray expected, not NoneType
Disconnected from voice... Reconnecting in 1.77s.
Traceback (most recent call last):
  File "discord\voice_client.py", line 383, in poll_voice_ws
  File "discord\gateway.py", line 889, in poll_event
discord.errors.ConnectionClosed: Shard ID None WebSocket closed with 4000

In this specific case, selecting a different voice channel & back worked.

Again, this probably isn't a very important issue as I reckon this program is mainly aimed at active usage, but if you wanted to look into improving its long-term resiliency, I'd be happy to help try out fixes or improvements.

Cheers! (and by the way, the new UI looks great 😃)

MaxLebled avatar Oct 05 '20 13:10 MaxLebled

Thanks! Network issues can be difficult to reproduce so I appreciate the reports. It is strange that it fails to reconnect automatically, I'll have to investigate.

Also, did you try switching the channel to None and back? That performs a hard reconnect to voice while switching to another room will simply move the bot.

QiCuiHub avatar Oct 05 '20 21:10 QiCuiHub

Just had another session end in a stranger way, after much longer (roughly 2 whole days)... DAP.exe was nowhere to be found. Only one error, the same as before (line 383 & 889) was in the log file.

As for switching the channel to None and back, I can confirm it works to get voice "unstuck"! 🙂

MaxLebled avatar Oct 07 '20 17:10 MaxLebled

Coming in with another report (after roughly 20 hours of runtime, I think) that exhibited a slightly different behaviour: the bot would still show in the channel, but doing the "switch to none & back" trick didn't work to get voice through again, neither on Channel nor Server. No "green circle" around the avatar, no voice feed. A full app restart worked.

This one's pretty long:

(a bunch of line 383/889 tracebacks)
Traceback (most recent call last):
  File "discord\voice_client.py", line 383, in poll_voice_ws
  File "discord\gateway.py", line 889, in poll_event
discord.errors.ConnectionClosed: Shard ID None WebSocket closed with 1006
Attempting a reconnect in 1.63s
Traceback (most recent call last):
  File "discord\client.py", line 551, in connect
  File "discord\gateway.py", line 578, in poll_event
discord.errors.ConnectionClosed: Shard ID None WebSocket closed with 1000
Attempting a reconnect in 0.75s
Traceback (most recent call last):
  File "aiohttp\connector.py", line 967, in _create_direct_connection
  File "aiohttp\connector.py", line 830, in _resolve_host
  File "aiohttp\resolver.py", line 30, in resolve
  File "asyncio\base_events.py", line 792, in getaddrinfo
  File "concurrent\futures\thread.py", line 57, in run
  File "socket.py", line 752, in getaddrinfo
socket.gaierror: [Errno 11001] getaddrinfo failed

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "discord\client.py", line 548, in connect
  File "asyncio\tasks.py", line 442, in wait_for
  File "discord\gateway.py", line 296, in from_client
  File "discord\http.py", line 910, in get_gateway
  File "discord\http.py", line 185, in request
  File "aiohttp\client.py", line 1012, in __aenter__
  File "aiohttp\client.py", line 483, in _request
  File "aiohttp\connector.py", line 523, in connect
  File "aiohttp\connector.py", line 859, in _create_connection
  File "aiohttp\connector.py", line 971, in _create_direct_connection
aiohttp.client_exceptions.ClientConnectorError: Cannot connect to host discord.com:443 ssl:default [getaddrinfo failed]
Attempting a reconnect in 3.98s
Traceback (most recent call last):
  File "aiohttp\connector.py", line 967, in _create_direct_connection
  File "aiohttp\connector.py", line 830, in _resolve_host
  File "aiohttp\resolver.py", line 30, in resolve
  File "asyncio\base_events.py", line 792, in getaddrinfo
  File "concurrent\futures\thread.py", line 57, in run
  File "socket.py", line 752, in getaddrinfo
socket.gaierror: [Errno 11001] getaddrinfo failed

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "discord\client.py", line 548, in connect
  File "asyncio\tasks.py", line 442, in wait_for
  File "discord\gateway.py", line 296, in from_client
  File "discord\http.py", line 910, in get_gateway
  File "discord\http.py", line 185, in request
  File "aiohttp\client.py", line 1012, in __aenter__
  File "aiohttp\client.py", line 483, in _request
  File "aiohttp\connector.py", line 523, in connect
  File "aiohttp\connector.py", line 859, in _create_connection
  File "aiohttp\connector.py", line 971, in _create_direct_connection
aiohttp.client_exceptions.ClientConnectorError: Cannot connect to host discord.com:443 ssl:default [getaddrinfo failed]
Attempting a reconnect in 0.74s
Traceback (most recent call last):
  File "discord\client.py", line 551, in connect
  File "discord\gateway.py", line 578, in poll_event
discord.errors.ConnectionClosed: Shard ID None WebSocket closed with 1000
Attempting a reconnect in 1.22s
Traceback (most recent call last):
  File "discord\client.py", line 551, in connect
  File "discord\gateway.py", line 578, in poll_event
discord.errors.ConnectionClosed: Shard ID None WebSocket closed with 1000
Error on change_channel
Traceback (most recent call last):
  File "discord\voice_client.py", line 329, in connect
  File "discord\utils.py", line 352, in sane_wait_for
concurrent.futures._base.TimeoutError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "gui.py", line 277, in change_channel
  File "discord\abc.py", line 1122, in connect
  File "discord\voice_client.py", line 331, in connect
  File "discord\voice_client.py", line 423, in disconnect
AttributeError: 'VoiceClient' object has no attribute 'ws'
Error on change_channel
Traceback (most recent call last):
  File "discord\voice_client.py", line 329, in connect
  File "discord\utils.py", line 352, in sane_wait_for
concurrent.futures._base.TimeoutError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "gui.py", line 277, in change_channel
  File "discord\abc.py", line 1122, in connect
  File "discord\voice_client.py", line 331, in connect
  File "discord\voice_client.py", line 423, in disconnect
AttributeError: 'VoiceClient' object has no attribute 'ws'
Error on change_channel
Traceback (most recent call last):
  File "discord\voice_client.py", line 329, in connect
  File "discord\utils.py", line 352, in sane_wait_for
concurrent.futures._base.TimeoutError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "gui.py", line 277, in change_channel
  File "discord\abc.py", line 1122, in connect
  File "discord\voice_client.py", line 331, in connect
  File "discord\voice_client.py", line 423, in disconnect
AttributeError: 'VoiceClient' object has no attribute 'ws'
Task was destroyed but it is pending!
task: <Task pending coro=<Event.wait() done, defined at asyncio\locks.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x00000249FD24A258>()]>>
Task was destroyed but it is pending!
task: <Task pending coro=<Event.wait() done, defined at asyncio\locks.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x00000249FD24A3A8>()]>>
Task was destroyed but it is pending!
task: <Task pending coro=<Event.wait() done, defined at asyncio\locks.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x00000249FCE0C3D8>()]>>

While I hope these logs may prove useful in helping improve the software, I can't help but think they could help even more if they had timestamps on each line—right now we don't know what is directly linked to what because of this...

MaxLebled avatar Oct 08 '20 21:10 MaxLebled

I was able to reproduce some of the behavior by sleeping my computer for a few hours while leaving the program running, however the None toggle trick still worked for me. You are right about the the timestamps, I'll add that to the program along with some options to get more detailed logs.

QiCuiHub avatar Oct 08 '20 22:10 QiCuiHub

The 2.0 exe should have timestamps for errors now. For verbose logging, you'll have to launch the program from CMD or PowerShell with .\dap.exe --verbose, and it will create a discord.log in the same dir.

QiCuiHub avatar Oct 08 '20 23:10 QiCuiHub

So, the bot eventually got itself stuck in a "reconnected, but not actually transmitting voice" state, here's the log. I trimmed the first 1000 lines or so, since they seemed like they contained potentially sensitive information (server/user IDs? shrug)

1009_discord.log

The most intriguing thing here is that there is nothing more is being logged after 22:19:52, including dis/connections to the channel, which did show up previously... except for ONE error that is not in discord.log, but dap_errors.log still... and close to 45 minutes later:

2020-10-09 23:05:06 Exception in voice thread Thread-3
Traceback (most recent call last):
  File "discord\player.py", line 598, in run
  File "discord\player.py", line 591, in _do_run
  File "discord\voice_client.py", line 598, in send_audio_packet
TypeError: str, bytes or bytearray expected, not NoneType

Hope that helps!

MaxLebled avatar Oct 09 '20 21:10 MaxLebled

Looking through the logs it looks like everything is fine before it stopped recording logs. I do see a bunch of packet loss but the program managed to survive through those events.

The fact that the program did not crash but stopped producing logs is extremely confusing. In my own testing, I did get the bot to fail to reconnect to voice api.

Disconnected from voice... Reconnecting in 1016.26s.

But I think your bot is somehow getting disconnected from a different part of discord.

Anyways thanks for the reports, I think we are getting closer to the issue. I'm looking to collect enough information so that I can create a decent bug report to discord.py and hopefully get these issues solved.

QiCuiHub avatar Oct 10 '20 01:10 QiCuiHub

I had the same problem this past weekend when running a game, you can see attached all the exceptions that happened. It kept disconnecting quite often, but my internet service provider really sucks so they drop packets now and again. So if this is a persistent connection type thing, might need to write a catch around this and just reconnect automatically because people with bad internet (or using this during peak times on their cable modems when the rest of the neighborhood is using up all the bandwidth) will have the same issues.

https://pastebin.com/HqVhSbhd

Might be only way to test this out, is to disconnect your development machine from the internet while being connected, then connect it up again a few seconds later.. since that's what happens to me, my ISP drops the internet every now and then for just like 3 pings. I keep a dos window open with ping -t google.com and I will drop at least 3 packets every 5 minutes or 10 minutes.

Amerisun avatar Feb 16 '21 00:02 Amerisun