[Audio] Lavalink jar download/redirect

[aikaterna]

Other bugs

What were you trying to do?

Helping people in support where they have installed Red 3.1 and are loading audio. This does not occur on every install.

What were you expecting to happen?

For the Lavalink.jar on our jar repo to be downloaded in the background on first load.

What actually happened?

[INFO] red.audio.manager: Downloading Lavalink.jar...

The bot stays "stuck" here until the user receives an SSL error: ssl.SSLError: [SSL: KRB5_S_INIT] application data after close notify (_ssl.c:2609) (Edit: This error is unrelated, see below)

How can we reproduce this issue?

Not quite sure of the cause on why some users can get the direct link and others get a redirect before they are served the jar. Yami and I tried curling the jar link we have in audio's manager.py and received a redirect. The bot installed on the machine I was doing the curl on was able to download the jar with no issues.

Note for users: If you're experiencing this issue, see this comment below on how to help us help you.

See: https://discordapp.com/channels/133049272517001216/387398816317440000/578251926303670303

The full SSL error: (Edit: This error is unrelated, see below)

SSL error in data received
protocol: <asyncio.sslproto.SSLProtocol object at 0x7f7095ecdda0>
transport: <_SelectorSocketTransport fd=8 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/lib/python3.7/asyncio/sslproto.py", line 526, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/usr/lib/python3.7/asyncio/sslproto.py", line 207, in feed_ssldata
    self._sslobj.unwrap()
  File "/usr/lib/python3.7/ssl.py", line 767, in unwrap
    return self._sslobj.shutdown()
ssl.SSLError: [SSL: KRB5_S_INIT] application data after close notify (_ssl.c:2609)

[TheWyn]

Redirected failing here but manually obtaining is fine with curl and wget.

[mikeshardmind]

Okay, so there's some weirdness here.

The redirect is normal:

curl "https://github.com/Cog-Creators/Lavalink-Jars/releases/download/3.2.0.3_772/Lavalink.jar" -o LavaLink.jar

(Not using curl's location flag intentionally to just quickly check if we are being redirected)

However, this shouldn't cause any issues (and in fact didn't seem to on the same machine where I got redirected with curl)

aiohttp (which we use for the download) follows redirects unless explicitly told not to.

Here's where the actual weirdness kicks in.

On the surface, this looks to be related to aio-libs/aiohttp#3535

However (And the reasons this may not be related)

1. We don't have a timeout
2. We are consuming the full response.

So unless the connection is terminated during download (at either end) I'm not sure we should be impacted by this issue specifically.

I'll try and look into this more later, but as I can't actually reproduce this locally, I am relying solely on what we have as an error and inspecting the conditions required to make this happen.

[SuperSandro2000]

[2019-06-08 17:17:18] [INFO] red.audio.manager: Downloading Lavalink.jar...
SSL error in data received
protocol: <asyncio.sslproto.SSLProtocol object at 0x7fdf6e7608d0>
transport: <_SelectorSocketTransport fd=8 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/lib/python3.7/asyncio/sslproto.py", line 526, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/usr/lib/python3.7/asyncio/sslproto.py", line 207, in feed_ssldata
    self._sslobj.unwrap()
  File "/usr/lib/python3.7/ssl.py", line 767, in unwrap
    return self._sslobj.shutdown()
ssl.SSLError: [SSL: KRB5_S_INIT] application data after close notify (_ssl.c:2609)
SSL error in data received
protocol: <asyncio.sslproto.SSLProtocol object at 0x7fdf6c304cc0>
transport: <_SelectorSocketTransport fd=8 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/lib/python3.7/asyncio/sslproto.py", line 526, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/usr/lib/python3.7/asyncio/sslproto.py", line 207, in feed_ssldata
    self._sslobj.unwrap()
  File "/usr/lib/python3.7/ssl.py", line 767, in unwrap
    return self._sslobj.shutdown()
ssl.SSLError: [SSL: KRB5_S_INIT] application data after close notify (_ssl.c:2609)
[2019-06-08 17:18:49] [INFO] red.audio.manager: Downloading Lavalink.jar...
SSL error in data received
protocol: <asyncio.sslproto.SSLProtocol object at 0x7fdf6c214a90>
transport: <_SelectorSocketTransport fd=8 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/lib/python3.7/asyncio/sslproto.py", line 526, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/usr/lib/python3.7/asyncio/sslproto.py", line 207, in feed_ssldata
    self._sslobj.unwrap()
  File "/usr/lib/python3.7/ssl.py", line 767, in unwrap
    return self._sslobj.shutdown()
ssl.SSLError: [SSL: KRB5_S_INIT] application data after close notify (_ssl.c:2609)

[aikaterna]

For now until this is resolved, users can manually download the Lavalink.jar from https://github.com/Cog-Creators/Lavalink-Jars/releases/tag/3.2.0.3_796 and place it in their Audio data directory while the bot is off.

[SuperSandro2000]

I did this and the bot tries to download the jar anyway.

[Tobotimus]

The SSL error is a complete red herring (i.e. it's unrelated to this issue) and actually a bug in Python Asyncio and will be fixed in the next minor release of 3.7. It's simply a messy error message which shouldn't be logged (the 3.7 fix literally involves just not logging the error when it's received).

My guess is that this issue doesn't exist - the users are waiting for the jar to download, it's taking a little while, they check their console, see the SSL error, and assume it failed even though it's still downloading normally.

[aikaterna]

Some users waited over 10 minutes for the jar to download with no file at the end of it.

[Tobotimus]

For users experiencing problems when Red downloads the Lavalink jar, please install #2764 and try again. This will log whatever exception occurred in the console. If nothing is logged it means the connection is just damn slow, and it's probably still trying to download.

To install it, if you have the updatered cog, use this command in Discord:

[p]urlupdate https://github.com/Cog-Creators/Red-DiscordBot/tarball/refs/pull/2764/head#egg=Red-DiscordBot

Or update manually from the console using the install command but replace Red-DiscordBot with https://github.com/Cog-Creators/Red-DiscordBot/tarball/refs/pull/2764/head#egg=Red-DiscordBot

[TheWyn]

Here's the error with @Tobotimus patch:

[2019-06-09 01:07:53] [INFO] red.audio.manager: Downloading Lavalink.jar...
[2019-06-09 01:07:54] [INFO] red.audio.manager: Successfully downloaded Lavalink.jar (61,081,030 bytes written)
[2019-06-09 01:07:54] [ERROR] red.audio: Unhandled exception whilst starting internal Lavalink server, aborting...
Traceback (most recent call last):
  File "/home/wyn/.local/lib/python3.7/site-packages/redbot/cogs/audio/audio.py", line 141, in attempt_connect
    await self._manager.start()
  File "/home/wyn/.local/lib/python3.7/site-packages/redbot/cogs/audio/manager.py", line 63, in start
    await self.maybe_download_jar()
  File "/home/wyn/.local/lib/python3.7/site-packages/redbot/cogs/audio/manager.py", line 256, in maybe_download_jar
    await cls._download_jar()
  File "/home/wyn/.local/lib/python3.7/site-packages/redbot/cogs/audio/manager.py", line 229, in _download_jar
    pathlib.Path(path).replace(LAVALINK_JAR_FILE)
  File "/usr/lib/python3.7/pathlib.py", line 1321, in replace
    self._accessor.replace(self, target)
OSError: [Errno 18] Invalid cross-device link: '/tmp/tmp70u8_bmf' -> '/home/wyn/.local/share/Red-DiscordBot/cogs/Audio/Lavalink.jar'

[Tobotimus]

Aha! Thank you very much. Just note that this is just a single instance of an error, this is unlikely to the only error which was previously being silenced, other users are likely to have other exceptions.

As for this error you're receiving, some context... Red downloads the Lavalink.jar to a temporary directory (created automatically with the tempfile module) before moving it to its destination. This is to prevent corrupted or partially-downloaded files remaining in the cogs/Audio folder after the download fails.

It looks as though in your filesystem, /tmp is mounted on a different partition and using a different file-system to /home. Of course, this is pretty common and I'm sure you did this intentionally. So I think the solution is to use shutil.move instead of pathlib.Path.replace (i.e. os.rename) since shutil.move actually handles moving between different file-systems.

[Tobotimus]

Closing this now the logging PR has been merged and the most common underlying issue has been fixed.