Timeout on /loadtracks when trying to load localfile for a second time

[lavalink-devs]

Timeout on /loadtracks when trying to load localfile for a second time

[freyacodes]

Can you provide a thread dump?

Run jstack <server-pid>

[AndyTempel]

https://gist.github.com/AndyTempel/8abb1bb5d3116a6ebe18f39b934e35cc

I should add. After the restart of lavalink the first request goes through fine, but second has the same problem.

[shikhir-arora]

Is it just for the second track or any second or further track? And is anything playing when you are doing the GET requests? Have you tried it with two non-local tracks?

[devoxin]

I used to get this issue with local tracks, not sure what fixed it but recent V2 builds have been OK for me.

[AndyTempel]

It's every request after the first one, nothing was playing and it happens only for local files. I've tried using the download link in the Readme, but no change.

[shikhir-arora]

You'd want the latest one, which is here at the moment:

https://ci.fredboat.com/viewLog.html?buildId=3089&tab=artifacts&buildTypeId=Lavalink_Build&guest=1

If you are using Linux/macOS and something like wget you can download it: wget https://ci.fredboat.com/repository/download/Lavalink_Build/3089:id/Lavalink.jar?guest=1

(The ?guest=1 is required to download like that, you can just rename it obviously).

See if that helps; it's using Lavaplayer 1.2.56.

[AndyTempel]

Same problem with the 3089 build that you provided.

[AndyTempel]

I even tried it running root and with the new newest build 3112, but it's the same problem.

uname -a: (Debian stretch 9.3)

Linux rickbot-img 4.9.0-6-amd64 #1 SMP Debian 4.9.82-1+deb9u2 (2018-02-21) x86_64 GNU/Linux

java -version:

openjdk version "1.8.0_151"
OpenJDK Runtime Environment (build 1.8.0_151-8u151-b12-1~deb9u1-b12)
OpenJDK 64-Bit Server VM (build 25.151-b12, mixed mode)

[shikhir-arora]

To @Frederikam perhaps updating to the just released version of Spring Boot could help. There's also some interesting things like this graceful terminator but I'm not sure if that's really necessary. Upgrading from 1.15.10 to the 2.0 release may fix issues, if anything it should offer some nice improvements.

@AndyTempel -- do you get this with all local tracks or just that one?

There's clearly a lock happening in your trace which you posted earlier:

This is the endpoint and it's locked on the second attempt because the /loadtracks REST handler here is frozen from the first event -- which is a direct result from
here -- and that is causing the /loadtracks endpoint to wait, as seen here in your stack trace.

[AndyTempel]

All of them. The first request is fine, but after the first, it's just stuck.

[shikhir-arora]

What I meant to say... 👀 (and not that embarrassing post I just made and deleted!)

https://repl.it/repls/LightDimDestination -- of course my info is removed, but you can replace it with yours.

It works fine for me and I'm using a local track too. Sorry, the last thing I said (and deleted) was obviously only returning two every time, been up way too long (=____=)

But, I still don't know why you're getting the lock that you do 🤷

[AndyTempel]

Further testing:

1. Step: Python for loop requests (Outputs only the first and then freezes)

2. Step: cURL (no restarts in-between, right after the execution of python loop):
   First request:

 Trying 138.68.171.135...
 Connected to 138.68.171.135 (138.68.171.135) port 8822 (#0)
 GET /loadtracks?identifier=/var/www/rickbot/res/soundboard/vsauce.mp3 HTTP/1.1
 Host: 138.68.171.135:8822
 User-Agent: curl/7.47.0
 Accept: */*
 Authorization: ...
 HTTP/1.1 200 
 Content-Type: application/json;charset=UTF-8
 Content-Length: 410
 Date: Sun, 04 Mar 2018 07:09:16 GMT
 Connection #0 to host 138.68.171.135 left intact
[{"track":"QAAAhAIABlZTQVVDRQADSEVZAAAAAAAACJIAKi92YXIvd3d3L3JpY2tib3QvcmVzL3NvdW5kYm9hcmQvdnNhdWNlLm1wMwABACovdmFyL3d3dy9yaWNrYm90L3Jlcy9zb3VuZGJvYXJkL3ZzYXVjZS5tcDMABWxvY2FsAANtcDMAAAAAAAAAAA==","info":{"identifier":"/var/www/rickbot/res/soundboard/vsauce.mp3","isSeekable":true,"author":"HEY","length":2194,"isStream":false,"position":0,"title":"VSAUCE","uri":"/var/www/rickbot/res/soundboard/vsauce.mp3"}}]

Second request (no response):

   Trying 138.68.171.135...
 Connected to 138.68.171.135 (138.68.171.135) port 8822 (#0)
 GET /loadtracks?identifier=/var/www/rickbot/res/soundboard/vsauce.mp3 HTTP/1.1
 Host: 138.68.171.135:8822
 User-Agent: curl/7.47.0
 Accept: */*
 Authorization: ...
 

3. Step: Postman (after the cURL)
   

[AndyTempel]

@shikhir-arora If I don't restart after the first test comment I don't get any response.
Maybe I should add: I'm using DigitalOcean, 2GB droplet in LON1 region with Debian stretch 9.3. I've installed python from source and java from the default repo (default-jre, default-jdk)

If I restart and execute the code, wait a minute:

Python 3.6.1 (default, Dec 2015, 13:05:11)
[GCC 4.8.2] on linux
   
[{"track":"QAAAmgIAGEdhbWluZyBTb3VuZCBFZmZlY3QgKEhEKQAHRGVuaWVkIAAAAAAAADB4ACovdmFyL3d3dy9yaWNrYm90L3Jlcy9zb3VuZGJvYXJkL2RlbmllZC5tcDMAAQAqL3Zhci93d3cvcmlja2JvdC9yZXMvc291bmRib2FyZC9kZW5pZWQubXAzAAVsb2NhbAADbXAzAAAAAAAAAAA=","info":{"identifier":"/var/www/rickbot/res/soundboard/denied.mp3","isSeekable":true,"author":"Denied ","length":12408,"isStream":false,"position":0,"title":"Gaming Sound Effect (HD)","uri":"/var/www/rickbot/res/soundboard/denied.mp3"}}]

And the Lavalink log:

[07:28:42] [ INFO ] [[/]] Initializing Spring FrameworkServlet 'dispatcherServlet'
[07:28:42] [ INFO ] [DispatcherServlet] FrameworkServlet 'dispatcherServlet': initialization started
[07:28:42] [ INFO ] [DispatcherServlet] FrameworkServlet 'dispatcherServlet': initialization completed in 46 ms
[07:28:42] [ INFO ] [AudioLoaderRestHandler] GET /loadtracks
[07:28:42] [ INFO ] [GarbageCollectionMonitor] GC monitoring enabled, reporting results every 2 minutes.
[07:28:42] [ INFO ] [AudioLoader] Loaded track Gaming Sound Effect (HD)
[07:28:42] [ INFO ] [AudioLoaderRestHandler] GET /loadtracks
[07:28:43] [ INFO ] [AudioLoader] Loaded track Gaming Sound Effect (HD)

[shikhir-arora]

Yeah, I can't replicate that.

That's with 20 requests, and on the Lavalink log:

(yeah, there's more than 20 because I did it more than once so the log show them, but you see -- it works perfectly there).

The only difference is I'm running jdk-10 on this dev server and all my servers now:

root@lavalink-toronto1:~/lavalink# java --version
java 10 2018-03-20
Java(TM) SE Runtime Environment 18.3 (build 10+45)
Java HotSpot(TM) 64-Bit Server VM 18.3 (build 10+45, mixed mode)
root@lavalink-toronto1:~/lavalink# 

But I've been using Java 9 for ages until a few days ago but even Java 8 cannot be the issue. And you are using the same latest build #3089 that I linked earlier for Lavalink.

So to see if it's isolated, you may want to try it on another server/computer, as well as try different local tracks. Then you can go and see if it's some issue with firewalls or HTTP clients. 😕

Also, for what its worth, make sure the permissions for Lavalink and the track especially are correct.

sudo chmod 0755 /var/www/rickbot/res/soundboard/vsauce.mp3 if it's not already. Though, it shouldn't work at all if permissions are issues, usually...You can temporarily set it to 0777 but I'm just speaking at this point - I don't think that is the problem.

I went ahead and tried it on my production server and since I can't really replicate your lock on there (which also runs lavalink in a different region), or on my local computer (macOS 10.13.4 Beta -just for a quick test) -- it really points to something with your server.

Also, the fact you say it only happens for local tracks really does seem to be a server (or wherever Lavalink is running on) issue, be it limitations on disk IO/connections/network requests or some other thing. Again, see if you can replicate it on different conditions..

---

Kind of unrelated/besides that updating to 2.0 for Springboot is probably a good idea for the lib anyway, since it's out as of Mar 1. /cc Fred or whomever 👍

[AndyTempel]

I can confirm that is isolated to my VPS, on my desktop it works like you'd expect. On the same file.

[shikhir-arora]

Yeah, then you probably want to check with your VPS/settings. Run some stats, htop, see what's going on and know the limits or whatnot. Many VPS's have firewalls that could take that second connection to a local file like that and block it, so you'd have to check there. That's not something LL dev's can fix really then. I only suggest the 2.0 Springboot update in gradle because it has some nice features, but that's a side thing from this post.

[AndyTempel]

Closed as DigitalOcean thing. (Going to test that further.)

[devoxin]

Probably not worth closing this as I could replicate it on an OVH server, however since moving lavalink to another server the issue has since resolved itself

[shikhir-arora]

I have a few OVH servers but they're all dedicated servers and I wasn't able to replicate on any of them.

[schnapster]

#125 probably fixes this.