Red-discordbot: [Audio] Internal Lavalink.jar looping on startup

Created on 17 Feb 2019 · 5Comments · Source: Cog-Creators/Red-DiscordBot

When starting the audio module with internal lavalink.jar the lavalink server never fully starts continuously restarting. This behavior will continue even after unloading the audio cog, only stopping after the bot is closed.

Setting the lavalink server as external on localhost and starting it manually allows it to fully start and work. This behavior wasn't present on 3.0.0

lavalink.log when started by audio cog:

[13:10:25] [ INFO ] [Launcher] 

[32m       .  [31m _                  _ _       _    [32m__ _ _
[32m      /\\ [31m| | __ ___   ____ _| (_)_ __ | | __[32m\ \ \ \
[32m     ( ( )[31m| |/ _` \ \ / / _` | | | '_ \| |/ /[32m \ \ \ \
[32m      \\/ [31m| | (_| |\ V / (_| | | | | | |   < [32m  ) ) ) )
[32m       '  [31m|_|\__,_| \_/ \__,_|_|_|_| |_|_|\_\[32m / / / /
[0m    =========================================[32m/_/_/_/[0m

    Version:        2.2
    Build:          584
    Build time:     23.07.2018 17:18:37 CEST
    Branch          dev
    Commit:         a138a7b
    Commit time:    23.07.2018 17:14:31 CEST
    JVM:            11.0.2
    Lavaplayer      1.3.7

[13:10:27] [ INFO ] [Launcher] Starting Launcher on pebble with PID 8409 (/home/daf/butler/cogs/Audio/Lavalink.jar started by daf in /home/daf/butler/cogs/Audio)
[13:10:27] [ INFO ] [Launcher] No active profile set, falling back to default profiles: default
[13:10:28] [ INFO ] [AnnotationConfigServletWebServerApplicationContext] Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@455848: startup date [Sun Feb 17 13:10:28 WET 2019]; root of context hierarchy
[13:10:57] [ INFO ] [Launcher] 

[32m       .  [31m _                  _ _       _    [32m__ _ _
[32m      /\\ [31m| | __ ___   ____ _| (_)_ __ | | __[32m\ \ \ \
[32m     ( ( )[31m| |/ _` \ \ / / _` | | | '_ \| |/ /[32m \ \ \ \
[32m      \\/ [31m| | (_| |\ V / (_| | | | | | |   < [32m  ) ) ) )
[32m       '  [31m|_|\__,_| \_/ \__,_|_|_|_| |_|_|\_\[32m / / / /
[0m    =========================================[32m/_/_/_/[0m

    Version:        2.2
    Build:          584
    Build time:     23.07.2018 17:18:37 CEST
    Branch          dev
    Commit:         a138a7b
    Commit time:    23.07.2018 17:14:31 CEST
    JVM:            11.0.2
    Lavaplayer      1.3.7

[13:10:59] [ INFO ] [Launcher] Starting Launcher on pebble with PID 8442 (/home/daf/butler/cogs/Audio/Lavalink.jar started by daf in /home/daf/butler/cogs/Audio)
[13:10:59] [ INFO ] [Launcher] No active profile set, falling back to default profiles: default
[13:11:00] [ INFO ] [AnnotationConfigServletWebServerApplicationContext] Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@455848: startup date [Sun Feb 17 13:11:00 WET 2019]; root of context hierarchy
[13:11:28] [ INFO ] [Launcher] 

[32m       .  [31m _                  _ _       _    [32m__ _ _
[32m      /\\ [31m| | __ ___   ____ _| (_)_ __ | | __[32m\ \ \ \
[32m     ( ( )[31m| |/ _` \ \ / / _` | | | '_ \| |/ /[32m \ \ \ \
[32m      \\/ [31m| | (_| |\ V / (_| | | | | | |   < [32m  ) ) ) )
[32m       '  [31m|_|\__,_| \_/ \__,_|_|_|_| |_|_|\_\[32m / / / /
[0m    =========================================[32m/_/_/_/[0m

    Version:        2.2
    Build:          584
    Build time:     23.07.2018 17:18:37 CEST
    Branch          dev
    Commit:         a138a7b
    Commit time:    23.07.2018 17:14:31 CEST
    JVM:            11.0.2
    Lavaplayer      1.3.7

[13:11:30] [ INFO ] [Launcher] Starting Launcher on pebble with PID 8474 (/home/daf/butler/cogs/Audio/Lavalink.jar started by daf in /home/daf/butler/cogs/Audio)
[13:11:30] [ INFO ] [Launcher] No active profile set, falling back to default profiles: default
[13:11:31] [ INFO ] [AnnotationConfigServletWebServerApplicationContext] Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@455848: startup date [Sun Feb 17 13:11:31 WET 2019]; root of context hierarchy
[13:12:00] [ INFO ] [Launcher] 

[32m       .  [31m _                  _ _       _    [32m__ _ _
[32m      /\\ [31m| | __ ___   ____ _| (_)_ __ | | __[32m\ \ \ \
[32m     ( ( )[31m| |/ _` \ \ / / _` | | | '_ \| |/ /[32m \ \ \ \
[32m      \\/ [31m| | (_| |\ V / (_| | | | | | |   < [32m  ) ) ) )
[32m       '  [31m|_|\__,_| \_/ \__,_|_|_|_| |_|_|\_\[32m / / / /
[0m    =========================================[32m/_/_/_/[0m

    Version:        2.2
    Build:          584
    Build time:     23.07.2018 17:18:37 CEST
    Branch          dev
    Commit:         a138a7b
    Commit time:    23.07.2018 17:14:31 CEST
    JVM:            11.0.2
    Lavaplayer      1.3.7

[13:12:02] [ INFO ] [Launcher] Starting Launcher on pebble with PID 8508 (/home/daf/butler/cogs/Audio/Lavalink.jar started by daf in /home/daf/butler/cogs/Audio)
[13:12:02] [ INFO ] [Launcher] No active profile set, falling back to default profiles: default
[13:12:03] [ INFO ] [AnnotationConfigServletWebServerApplicationContext] Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@455848: startup date [Sun Feb 17 13:12:03 WET 2019]; root of context hierarchy
[13:12:32] [ INFO ] [Launcher] 

[32m       .  [31m _                  _ _       _    [32m__ _ _
[32m      /\\ [31m| | __ ___   ____ _| (_)_ __ | | __[32m\ \ \ \
[32m     ( ( )[31m| |/ _` \ \ / / _` | | | '_ \| |/ /[32m \ \ \ \
[32m      \\/ [31m| | (_| |\ V / (_| | | | | | |   < [32m  ) ) ) )
[32m       '  [31m|_|\__,_| \_/ \__,_|_|_|_| |_|_|\_\[32m / / / /
[0m    =========================================[32m/_/_/_/[0m

    Version:        2.2
    Build:          584
    Build time:     23.07.2018 17:18:37 CEST
    Branch          dev
    Commit:         a138a7b
    Commit time:    23.07.2018 17:14:31 CEST
    JVM:            11.0.2
    Lavaplayer      1.3.7

[13:12:33] [ INFO ] [Launcher] Starting Launcher on pebble with PID 8537 (/home/daf/butler/cogs/Audio/Lavalink.jar started by daf in /home/daf/butler/cogs/Audio)
[13:12:34] [ INFO ] [Launcher] No active profile set, falling back to default profiles: default
[13:12:34] [ INFO ] [AnnotationConfigServletWebServerApplicationContext] Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@455848: startup date [Sun Feb 17 13:12:34 WET 2019]; root of context hierarchy
[13:13:04] [ INFO ] [Launcher] 

[32m       .  [31m _                  _ _       _    [32m__ _ _
[32m      /\\ [31m| | __ ___   ____ _| (_)_ __ | | __[32m\ \ \ \
[32m     ( ( )[31m| |/ _` \ \ / / _` | | | '_ \| |/ /[32m \ \ \ \
[32m      \\/ [31m| | (_| |\ V / (_| | | | | | |   < [32m  ) ) ) )
[32m       '  [31m|_|\__,_| \_/ \__,_|_|_|_| |_|_|\_\[32m / / / /
[0m    =========================================[32m/_/_/_/[0m

    Version:        2.2
    Build:          584
    Build time:     23.07.2018 17:18:37 CEST
    Branch          dev
    Commit:         a138a7b
    Commit time:    23.07.2018 17:14:31 CEST
    JVM:            11.0.2
    Lavaplayer      1.3.7

[13:13:06] [ INFO ] [Launcher] Starting Launcher on pebble with PID 8573 (/home/daf/butler/cogs/Audio/Lavalink.jar started by daf in /home/daf/butler/cogs/Audio)
[13:13:06] [ INFO ] [Launcher] No active profile set, falling back to default profiles: default
[13:13:06] [ INFO ] [AnnotationConfigServletWebServerApplicationContext] Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@455848: startup date [Sun Feb 17 13:13:06 WET 2019]; root of context hierarchy
[13:13:35] [ INFO ] [Launcher] 

[32m       .  [31m _                  _ _       _    [32m__ _ _
[32m      /\\ [31m| | __ ___   ____ _| (_)_ __ | | __[32m\ \ \ \
[32m     ( ( )[31m| |/ _` \ \ / / _` | | | '_ \| |/ /[32m \ \ \ \
[32m      \\/ [31m| | (_| |\ V / (_| | | | | | |   < [32m  ) ) ) )
[32m       '  [31m|_|\__,_| \_/ \__,_|_|_|_| |_|_|\_\[32m / / / /
[0m    =========================================[32m/_/_/_/[0m

    Version:        2.2
    Build:          584
    Build time:     23.07.2018 17:18:37 CEST
    Branch          dev
    Commit:         a138a7b
    Commit time:    23.07.2018 17:14:31 CEST
    JVM:            11.0.2
    Lavaplayer      1.3.7

[13:13:37] [ INFO ] [Launcher] Starting Launcher on pebble with PID 8606 (/home/daf/butler/cogs/Audio/Lavalink.jar started by daf in /home/daf/butler/cogs/Audio)
[13:13:37] [ INFO ] [Launcher] No active profile set, falling back to default profiles: default
[13:13:38] [ INFO ] [AnnotationConfigServletWebServerApplicationContext] Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@7edb54: startup date [Sun Feb 17 13:13:38 WET 2019]; root of context hierarchy
[13:14:07] [ INFO ] [Launcher] 

[32m       .  [31m _                  _ _       _    [32m__ _ _
[32m      /\\ [31m| | __ ___   ____ _| (_)_ __ | | __[32m\ \ \ \
[32m     ( ( )[31m| |/ _` \ \ / / _` | | | '_ \| |/ /[32m \ \ \ \
[32m      \\/ [31m| | (_| |\ V / (_| | | | | | |   < [32m  ) ) ) )
[32m       '  [31m|_|\__,_| \_/ \__,_|_|_|_| |_|_|\_\[32m / / / /
[0m    =========================================[32m/_/_/_/[0m

    Version:        2.2
    Build:          584
    Build time:     23.07.2018 17:18:37 CEST
    Branch          dev
    Commit:         a138a7b
    Commit time:    23.07.2018 17:14:31 CEST
    JVM:            11.0.2
    Lavaplayer      1.3.7

[13:14:09] [ INFO ] [Launcher] Starting Launcher on pebble with PID 8643 (/home/daf/butler/cogs/Audio/Lavalink.jar started by daf in /home/daf/butler/cogs/Audio)
[13:14:09] [ INFO ] [Launcher] No active profile set, falling back to default profiles: default
[13:14:10] [ INFO ] [AnnotationConfigServletWebServerApplicationContext] Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@455848: startup date [Sun Feb 17 13:14:10 WET 2019]; root of context hierarchy
[13:14:39] [ INFO ] [Launcher] 

[32m       .  [31m _                  _ _       _    [32m__ _ _
[32m      /\\ [31m| | __ ___   ____ _| (_)_ __ | | __[32m\ \ \ \
[32m     ( ( )[31m| |/ _` \ \ / / _` | | | '_ \| |/ /[32m \ \ \ \
[32m      \\/ [31m| | (_| |\ V / (_| | | | | | |   < [32m  ) ) ) )
[32m       '  [31m|_|\__,_| \_/ \__,_|_|_|_| |_|_|\_\[32m / / / /
[0m    =========================================[32m/_/_/_/[0m

    Version:        2.2
    Build:          584
    Build time:     23.07.2018 17:18:37 CEST
    Branch          dev
    Commit:         a138a7b
    Commit time:    23.07.2018 17:14:31 CEST
    JVM:            11.0.2
    Lavaplayer      1.3.7

[13:14:40] [ INFO ] [Launcher] Starting Launcher on pebble with PID 8675 (/home/daf/butler/cogs/Audio/Lavalink.jar started by daf in /home/daf/butler/cogs/Audio)
[13:14:40] [ INFO ] [Launcher] No active profile set, falling back to default profiles: default
[13:15:10] [ INFO ] [Launcher] 

[32m       .  [31m _                  _ _       _    [32m__ _ _
[32m      /\\ [31m| | __ ___   ____ _| (_)_ __ | | __[32m\ \ \ \
[32m     ( ( )[31m| |/ _` \ \ / / _` | | | '_ \| |/ /[32m \ \ \ \
[32m      \\/ [31m| | (_| |\ V / (_| | | | | | |   < [32m  ) ) ) )
[32m       '  [31m|_|\__,_| \_/ \__,_|_|_|_| |_|_|\_\[32m / / / /
[0m    =========================================[32m/_/_/_/[0m

    Version:        2.2
    Build:          584
    Build time:     23.07.2018 17:18:37 CEST
    Branch          dev
    Commit:         a138a7b
    Commit time:    23.07.2018 17:14:31 CEST
    JVM:            11.0.2
    Lavaplayer      1.3.7

[13:15:12] [ INFO ] [Launcher] Starting Launcher on pebble with PID 8704 (/home/daf/butler/cogs/Audio/Lavalink.jar started by daf in /home/daf/butler/cogs/Audio)
[13:15:12] [ INFO ] [Launcher] No active profile set, falling back to default profiles: default
[13:15:13] [ INFO ] [AnnotationConfigServletWebServerApplicationContext] Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@7edb54: startup date [Sun Feb 17 13:15:13 WET 2019]; root of context hierarchy

lavalink.log started as external on localhost

[13:52:03] [ INFO ] [Launcher] 

[32m       .  [31m _                  _ _       _    [32m__ _ _
[32m      /\\ [31m| | __ ___   ____ _| (_)_ __ | | __[32m\ \ \ \
[32m     ( ( )[31m| |/ _` \ \ / / _` | | | '_ \| |/ /[32m \ \ \ \
[32m      \\/ [31m| | (_| |\ V / (_| | | | | | |   < [32m  ) ) ) )
[32m       '  [31m|_|\__,_| \_/ \__,_|_|_|_| |_|_|\_\[32m / / / /
[0m    =========================================[32m/_/_/_/[0m

    Version:        2.2
    Build:          584
    Build time:     23.07.2018 17:18:37 CEST
    Branch          dev
    Commit:         a138a7b
    Commit time:    23.07.2018 17:14:31 CEST
    JVM:            11.0.2
    Lavaplayer      1.3.7

[13:52:05] [ INFO ] [Launcher] Starting Launcher on pebble with PID 10031 (/home/daf/butler/cogs/Audio/Lavalink.jar.fixed-offical started by daf in /home/daf/butler/cogs/Audio)
[13:52:05] [ INFO ] [Launcher] No active profile set, falling back to default profiles: default
[13:52:06] [ INFO ] [AnnotationConfigServletWebServerApplicationContext] Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@138449f: startup date [Sun Feb 17 13:52:06 WET 2019]; root of context hierarchy
[13:52:22] [ INFO ] [TomcatWebServer] Tomcat initialized with port(s): 2333 (http)
[13:52:23] [ INFO ] [Http11NioProtocol] Initializing ProtocolHandler ["http-nio-2333"]
[13:52:23] [ INFO ] [StandardService] Starting service [Tomcat]
[13:52:23] [ INFO ] [StandardEngine] Starting Servlet Engine: Apache Tomcat/8.5.31
[13:52:23] [ INFO ] [AprLifecycleListener] The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: [/usr/java/packages/lib:/lib:/usr/lib]
[13:52:24] [ INFO ] [[/]] Initializing Spring embedded WebApplicationContext
[13:52:24] [ INFO ] [ContextLoader] Root WebApplicationContext: initialization completed in 18121 ms
[13:52:26] [ INFO ] [ServletRegistrationBean] Servlet dispatcherServlet mapped to [/]
[13:52:26] [ INFO ] [FilterRegistrationBean] Mapping filter: 'characterEncodingFilter' to: [/*]
[13:52:26] [ INFO ] [FilterRegistrationBean] Mapping filter: 'hiddenHttpMethodFilter' to: [/*]
[13:52:26] [ INFO ] [FilterRegistrationBean] Mapping filter: 'httpPutFormContentFilter' to: [/*]
[13:52:26] [ INFO ] [FilterRegistrationBean] Mapping filter: 'requestContextFilter' to: [/*]
[13:52:27] [ INFO ] [AudioSendFactoryConfiguration] OS: Linux, Arch: arm
[13:52:27] [ WARN ] [AudioSendFactoryConfiguration] This system and architecture appears to not support native audio sending! GC pauses may cause your bot to stutter during playback.
[13:52:27] [ WARN ] [Dsn] *** Couldn't find a suitable DSN, Sentry operations will do nothing! See documentation: https://docs.sentry.io/clients/java/ ***
[13:52:27] [ WARN ] [DefaultSentryClientFactory] No 'stacktrace.app.packages' was configured, this option is highly recommended as it affects stacktrace grouping and display on Sentry. See documentation: https://docs.sentry.io/clients/java/config/#in-application-stack-frames
[13:52:27] [ INFO ] [Launcher] No sentry dsn found, turning off sentry.
[13:52:28] [ INFO ] [SocketServer] Started WS server with port 2332
[13:52:34] [ INFO ] [GarbageCollectionMonitor] GC monitoring enabled, reporting results every 2 minutes.
[13:52:35] [ INFO ] [SimpleUrlHandlerMapping] Mapped URL path [/**/favicon.ico] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
[13:52:36] [ INFO ] [SocketServer] Connection opened from /127.0.0.1:41380 with protocol Draft_6455 extension: DefaultExtension protocol: 
[13:52:36] [ INFO ] [GarbageCollectionMonitor] GC monitoring enabled, reporting results every 2 minutes.
[13:52:36] [ ERROR] [LinuxCentralProcessor] Couldn't find physical processor count. Assuming 1.
[13:52:36] [ ERROR] [LinuxCentralProcessor] Couldn't find physical package count. Assuming 1.
[13:52:39] [ INFO ] [RequestMappingHandlerAdapter] Looking for @ControllerAdvice: org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@138449f: startup date [Sun Feb 17 13:52:06 WET 2019]; root of context hierarchy
[13:52:40] [ INFO ] [RequestMappingHandlerMapping] Mapped "{[/debug/nashorn],methods=[POST]}" onto public java.lang.String lavalink.server.util.DebugRestHandler.getLoadTracks(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse,java.lang.String,java.lang.String)
[13:52:40] [ INFO ] [RequestMappingHandlerMapping] Mapped "{[/decodetrack],methods=[GET],produces=[application/json]}" onto public org.springframework.http.ResponseEntity<java.lang.String> lavalink.server.player.AudioLoaderRestHandler.getDecodeTrack(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse,java.lang.String) throws java.io.IOException
[13:52:40] [ INFO ] [RequestMappingHandlerMapping] Mapped "{[/decodetracks],methods=[POST],consumes=[application/json],produces=[application/json]}" onto public org.springframework.http.ResponseEntity<java.lang.String> lavalink.server.player.AudioLoaderRestHandler.postDecodeTracks(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse,java.lang.String) throws java.io.IOException
[13:52:40] [ INFO ] [RequestMappingHandlerMapping] Mapped "{[/loadtracks],methods=[GET],produces=[application/json]}" onto public java.util.concurrent.CompletionStage<org.springframework.http.ResponseEntity<java.lang.String>> lavalink.server.player.AudioLoaderRestHandler.getLoadTracks(javax.servlet.http.HttpServletRequest,java.lang.String)
[13:52:40] [ INFO ] [RequestMappingHandlerMapping] Mapped "{[/error],produces=[text/html]}" onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
[13:52:40] [ INFO ] [RequestMappingHandlerMapping] Mapped "{[/error]}" onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
[13:52:41] [ INFO ] [SimpleUrlHandlerMapping] Mapped URL path [/webjars/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
[13:52:41] [ INFO ] [SimpleUrlHandlerMapping] Mapped URL path [/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
[13:52:44] [ INFO ] [AnnotationMBeanExporter] Registering beans for JMX exposure on startup
[13:52:44] [ INFO ] [Http11NioProtocol] Starting ProtocolHandler ["http-nio-2333"]
[13:52:44] [ INFO ] [NioSelectorPool] Using a shared selector for servlet write/read
[13:52:45] [ INFO ] [TomcatWebServer] Tomcat started on port(s): 2333 (http) with context path ''
[13:52:45] [ INFO ] [Launcher] Started Launcher in 46.157 seconds (JVM running for 54.941)
[13:52:47] [ INFO ] [SocketServer] {"op": "voiceUpdate", "guildId": "183723585536393216", "sessionId": "a26769f9f7bc78f4de07a5fd9260e042", "event": {"token": "6fa5ac5bf60f5029", "guild_id": "183723585536393216", "endpoint": "eu-west438.discord.gg:80"}}
[13:52:47] [ INFO ] [JDAA] Audio System successfully setup!
[13:52:47] [ INFO ] [[/]] Initializing Spring FrameworkServlet 'dispatcherServlet'
[13:52:47] [ INFO ] [DispatcherServlet] FrameworkServlet 'dispatcherServlet': initialization started
[13:52:48] [ INFO ] [DispatcherServlet] FrameworkServlet 'dispatcherServlet': initialization completed in 231 ms
[13:52:48] [ INFO ] [SocketServer] {"op": "voiceUpdate", "guildId": "183723585536393216", "sessionId": "a26769f9f7bc78f4de07a5fd9260e042", "event": {"token": "6fa5ac5bf60f5029", "guild_id": "183723585536393216", "endpoint": "eu-west438.discord.gg:80"}}
[13:52:48] [ INFO ] [SocketServer] {"op": "voiceUpdate", "guildId": "183723585536393216", "sessionId": "a26769f9f7bc78f4de07a5fd9260e042", "event": {"token": "6fa5ac5bf60f5029", "guild_id": "183723585536393216", "endpoint": "eu-west438.discord.gg:80"}}
[13:52:48] [ INFO ] [SocketServer] {"op": "voiceUpdate", "guildId": "183723585536393216", "sessionId": "a26769f9f7bc78f4de07a5fd9260e042", "event": {"token": "6fa5ac5bf60f5029", "guild_id": "183723585536393216", "endpoint": "eu-west438.discord.gg:80"}}
[13:52:48] [ INFO ] [AudioLoaderRestHandler] GET /loadtracks
[13:52:54] [ INFO ] [AudioLoader] Loaded playlist Search results for: zomboy lone wolf
[13:52:54] [ INFO ] [SocketServer] {"op": "play", "guildId": "183723585536393216", "track": "QAAAewIAElpvbWJveSAtIExvbmUgV29sZgAPWm9tYm95IE9mZmljaWFsAAAAAAAD6+gAC3RkeldVRWpmZlE0AAEAK2h0dHBzOi8vd3d3LnlvdXR1YmUuY29tL3dhdGNoP3Y9dGR6V1VFamZmUTQAB3lvdXR1YmUAAAAAAAAAAA=="}
[13:53:00] [ INFO ] [SocketServer] {"op": "volume", "guildId": "183723585536393216", "volume": 50}
[13:53:36] [ INFO ] [SocketServer] {"op": "volume", "guildId": "183723585536393216", "volume": 100}
[13:56:56] [ ERROR] [LocalAudioTrackExecutor] Error in playback of tdzWUEjffQ4
com.sedmelluq.discord.lavaplayer.tools.FriendlyException: Something went wrong when decoding the track.
    at com.sedmelluq.discord.lavaplayer.tools.ExceptionTools.wrapUnfriendlyExceptions(ExceptionTools.java:43)
    at com.sedmelluq.discord.lavaplayer.track.playback.LocalAudioTrackExecutor.executeProcessingLoop(LocalAudioTrackExecutor.java:269)
    at com.sedmelluq.discord.lavaplayer.container.matroska.MatroskaAudioTrack.process(MatroskaAudioTrack.java:38)
    at com.sedmelluq.discord.lavaplayer.track.DelegatedAudioTrack.processDelegate(DelegatedAudioTrack.java:27)
    at com.sedmelluq.discord.lavaplayer.source.youtube.YoutubeAudioTrack.processStatic(YoutubeAudioTrack.java:75)
    at com.sedmelluq.discord.lavaplayer.source.youtube.YoutubeAudioTrack.process(YoutubeAudioTrack.java:67)
    at com.sedmelluq.discord.lavaplayer.track.playback.LocalAudioTrackExecutor.execute(LocalAudioTrackExecutor.java:90)
    at com.sedmelluq.discord.lavaplayer.player.DefaultAudioPlayerManager.lambda$executeTrack$1(DefaultAudioPlayerManager.java:348)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: java.lang.RuntimeException: javax.net.ssl.SSLProtocolException: Connection reset
    at com.sedmelluq.discord.lavaplayer.container.matroska.MatroskaStreamingFile.provideFrames(MatroskaStreamingFile.java:309)
    at com.sedmelluq.discord.lavaplayer.container.matroska.MatroskaAudioTrack.lambda$process$0(MatroskaAudioTrack.java:39)
    at com.sedmelluq.discord.lavaplayer.track.playback.LocalAudioTrackExecutor.executeProcessingLoop(LocalAudioTrackExecutor.java:257)
    ... 9 common frames omitted
Caused by: javax.net.ssl.SSLProtocolException: Connection reset
    at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:126)
    at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:321)
    at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:264)
    at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:259)
    at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:137)
    at java.base/sun.security.ssl.SSLSocketImpl.decode(SSLSocketImpl.java:1155)
    at java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1125)
    at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:823)
    at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
    at org.apache.http.impl.io.SessionInputBufferImpl.read(SessionInputBufferImpl.java:198)
    at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:176)
    at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:135)
    at java.base/java.io.BufferedInputStream.fill(BufferedInputStream.java:252)
    at java.base/java.io.BufferedInputStream.read1(BufferedInputStream.java:292)
    at java.base/java.io.BufferedInputStream.read(BufferedInputStream.java:351)
    at com.sedmelluq.discord.lavaplayer.tools.io.PersistentHttpStream.internalRead(PersistentHttpStream.java:172)
    at com.sedmelluq.discord.lavaplayer.tools.io.PersistentHttpStream.read(PersistentHttpStream.java:185)
    at java.base/java.io.DataInputStream.readFully(DataInputStream.java:200)
    at com.sedmelluq.discord.lavaplayer.container.matroska.format.MutableMatroskaBlock.getNextFrameBuffer(MutableMatroskaBlock.java:54)
    at com.sedmelluq.discord.lavaplayer.container.matroska.MatroskaStreamingFile.processFrameInBlock(MatroskaStreamingFile.java:372)
    at com.sedmelluq.discord.lavaplayer.container.matroska.MatroskaStreamingFile.parseClusterSimpleBlock(MatroskaStreamingFile.java:336)
    at com.sedmelluq.discord.lavaplayer.container.matroska.MatroskaStreamingFile.parseNextCluster(MatroskaStreamingFile.java:321)
    at com.sedmelluq.discord.lavaplayer.container.matroska.MatroskaStreamingFile.provideFrames(MatroskaStreamingFile.java:297)
    ... 11 common frames omitted
Caused by: java.net.SocketException: Connection reset
    at java.base/java.net.SocketInputStream.read(SocketInputStream.java:186)
    at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
    at java.base/sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:448)
    at java.base/sun.security.ssl.SSLSocketInputRecord.decodeInputRecord(SSLSocketInputRecord.java:237)
    at java.base/sun.security.ssl.SSLSocketInputRecord.decode(SSLSocketInputRecord.java:190)
    at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:108)
    ... 29 common frames omitted
[13:56:56] [ INFO ] [SocketServer] {"op": "stop", "guildId": "183723585536393216"}
[13:57:31] [ INFO ] [AudioLoaderRestHandler] GET /loadtracks
[13:57:32] [ INFO ] [AudioLoader] Loaded playlist Search results for: zomboy lone wolf
[13:57:32] [ INFO ] [SocketServer] {"op": "play", "guildId": "183723585536393216", "track": "QAAAewIAElpvbWJveSAtIExvbmUgV29sZgAPWm9tYm95IE9mZmljaWFsAAAAAAAD6+gAC3RkeldVRWpmZlE0AAEAK2h0dHBzOi8vd3d3LnlvdXR1YmUuY29tL3dhdGNoP3Y9dGR6V1VFamZmUTQAB3lvdXR1YmUAAAAAAAAAAA=="}
[14:01:39] [ ERROR] [LocalAudioTrackExecutor] Error in playback of tdzWUEjffQ4
com.sedmelluq.discord.lavaplayer.tools.FriendlyException: Something went wrong when decoding the track.
    at com.sedmelluq.discord.lavaplayer.tools.ExceptionTools.wrapUnfriendlyExceptions(ExceptionTools.java:43)
    at com.sedmelluq.discord.lavaplayer.track.playback.LocalAudioTrackExecutor.executeProcessingLoop(LocalAudioTrackExecutor.java:269)
    at com.sedmelluq.discord.lavaplayer.container.matroska.MatroskaAudioTrack.process(MatroskaAudioTrack.java:38)
    at com.sedmelluq.discord.lavaplayer.track.DelegatedAudioTrack.processDelegate(DelegatedAudioTrack.java:27)
    at com.sedmelluq.discord.lavaplayer.source.youtube.YoutubeAudioTrack.processStatic(YoutubeAudioTrack.java:75)
    at com.sedmelluq.discord.lavaplayer.source.youtube.YoutubeAudioTrack.process(YoutubeAudioTrack.java:67)
    at com.sedmelluq.discord.lavaplayer.track.playback.LocalAudioTrackExecutor.execute(LocalAudioTrackExecutor.java:90)
    at com.sedmelluq.discord.lavaplayer.player.DefaultAudioPlayerManager.lambda$executeTrack$1(DefaultAudioPlayerManager.java:348)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: java.lang.RuntimeException: javax.net.ssl.SSLProtocolException: Connection reset
    at com.sedmelluq.discord.lavaplayer.container.matroska.MatroskaStreamingFile.provideFrames(MatroskaStreamingFile.java:309)
    at com.sedmelluq.discord.lavaplayer.container.matroska.MatroskaAudioTrack.lambda$process$0(MatroskaAudioTrack.java:39)
    at com.sedmelluq.discord.lavaplayer.track.playback.LocalAudioTrackExecutor.executeProcessingLoop(LocalAudioTrackExecutor.java:257)
    ... 9 common frames omitted
Caused by: javax.net.ssl.SSLProtocolException: Connection reset
    at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:126)
    at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:321)
    at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:264)
    at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:259)
    at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:137)
    at java.base/sun.security.ssl.SSLSocketImpl.decode(SSLSocketImpl.java:1155)
    at java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1125)
    at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:823)
    at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
    at org.apache.http.impl.io.SessionInputBufferImpl.read(SessionInputBufferImpl.java:198)
    at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:176)
    at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:135)
    at java.base/java.io.BufferedInputStream.fill(BufferedInputStream.java:252)
    at java.base/java.io.BufferedInputStream.read1(BufferedInputStream.java:292)
    at java.base/java.io.BufferedInputStream.read(BufferedInputStream.java:351)
    at com.sedmelluq.discord.lavaplayer.tools.io.PersistentHttpStream.internalRead(PersistentHttpStream.java:172)
    at com.sedmelluq.discord.lavaplayer.tools.io.PersistentHttpStream.read(PersistentHttpStream.java:185)
    at java.base/java.io.DataInputStream.readFully(DataInputStream.java:200)
    at com.sedmelluq.discord.lavaplayer.container.matroska.format.MutableMatroskaBlock.getNextFrameBuffer(MutableMatroskaBlock.java:54)
    at com.sedmelluq.discord.lavaplayer.container.matroska.MatroskaStreamingFile.processFrameInBlock(MatroskaStreamingFile.java:372)
    at com.sedmelluq.discord.lavaplayer.container.matroska.MatroskaStreamingFile.parseClusterSimpleBlock(MatroskaStreamingFile.java:336)
    at com.sedmelluq.discord.lavaplayer.container.matroska.MatroskaStreamingFile.parseNextCluster(MatroskaStreamingFile.java:321)
    at com.sedmelluq.discord.lavaplayer.container.matroska.MatroskaStreamingFile.provideFrames(MatroskaStreamingFile.java:297)
    ... 11 common frames omitted
Caused by: java.net.SocketException: Connection reset
    at java.base/java.net.SocketInputStream.read(SocketInputStream.java:186)
    at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
    at java.base/sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:448)
    at java.base/sun.security.ssl.SSLSocketInputRecord.decodeInputRecord(SSLSocketInputRecord.java:237)
    at java.base/sun.security.ssl.SSLSocketInputRecord.decode(SSLSocketInputRecord.java:190)
    at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:108)
    ... 29 common frames omitted
[14:01:40] [ INFO ] [SocketServer] {"op": "stop", "guildId": "183723585536393216"}
[14:02:55] [ INFO ] [AudioLoaderRestHandler] GET /loadtracks
[14:02:56] [ INFO ] [AudioLoader] Loaded playlist Search results for: hype music
[14:02:56] [ INFO ] [SocketServer] {"op": "play", "guildId": "183723585536393216", "track": "QAAAqwIAQkh5cGUgVHJhcCBNdXNpYyBNaXggfCBCZXN0IG9mIFN1bW1lciAyMDE1IHwgWyAxIEhvdXIgXSBvZiBJbnNhbml0eQAPT2ZmaWNpYWxTaGVsbFp6AAAAAABBTsAAC0F0SlFLQ01BT1k4AAEAK2h0dHBzOi8vd3d3LnlvdXR1YmUuY29tL3dhdGNoP3Y9QXRKUUtDTUFPWTgAB3lvdXR1YmUAAAAAAAAAAA=="}

System information:
Linux pebble 4.20.6-1-ARCH #1 SMP PREEMPT Fri Feb 8 02:30:15 UTC 2019 armv7l GNU/Linux
packages fully updated as the time of this report
running Orange PI PC Plus

In progress Bug

Source

dafzor

👍1

All 5 comments

Hi @dafzor, it looks like your architecture is fairly unique which probably means you require a modified Lavalink.jar for the server to run properly. @aikaterna tells me you've made modifications to the Lavalink.jar yourself - please note that if you're using internal Lavalink and replace the internal Lavalink.jar, then after updating Red, the Lavalink.jar will be re-downloaded and will replace the internal jar you modified.

Tobotimus on 18 Feb 2019

While that is the case the stock lavalink.jar still runs and function as
long as volume is left at 100% (the modification adds the native arm lib
required for it to work).

So the issue reported here is not due to that. Has I said I'm using the
same lavalink.jar when starting it as an external server and it starts
normally.

On Mon, 18 Feb 2019, 00:27 Toby Harradine <[email protected] wrote:

Hi @dafzor https://github.com/dafzor, it looks like your architecture
is fairly unique which probably means you require a modified Lavalink.jar
for the server to run properly. @aikaterna https://github.com/aikaterna
tells me you've made modifications to the Lavalink.jar yourself - please
note that if you're using internal Lavalink and replace the internal
Lavalink.jar, then after updating Red, the Lavalink.jar will be
re-downloaded and will replace the internal jar you modified.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/Cog-Creators/Red-DiscordBot/issues/2463#issuecomment-464534070,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ABiZrlgWlCVBFejVi3-JB8icPVidMDNdks5vOfNhgaJpZM4a_k9P
.

dafzor on 18 Feb 2019

@dafzor Looking at your logfile for the internal Lavalink, it seems as though the server is restarting at almost exactly 30 second intervals. To me this indicates some kind of timeout error. Are you able to provide any accompanying logs from Red? It might also be helpful if you start the bot with the --debug flag.

Tobotimus on 18 Feb 2019

👍1

Did as requested and bellow is the redbot log, all seems to indicate that it tries to connect before it's fully started and when it fails it just restarts the lavalink server thinking it's "unresponsive"?

Feb 18 19:52:22 pebble systemd[1]: Started Red-DiscordBot.
Feb 18 19:52:29 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/core/settings.json
Feb 18 19:52:29 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 572: Basic config:
Feb 18 19:52:29 pebble redbot[17762]: {'COG_PATH_APPEND': 'cogs', 'CORE_PATH_APPEND': 'core', 'DATA_PATH': '/home/daf/butler', 'STORAGE_DETAILS': {}, 'STORAGE_TYPE': 'JSON'}
Feb 18 19:52:29 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 577: Using driver: 'JSON'
Feb 18 19:52:29 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/cogs/CogManager/settings.json
Feb 18 19:52:30 pebble redbot[17762]: Connected to Discord. Getting ready...
Feb 18 19:52:32 pebble redbot[17762]: Loading packages...
Feb 18 19:52:32 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 572: Basic config:
Feb 18 19:52:32 pebble redbot[17762]: {'COG_PATH_APPEND': 'cogs', 'CORE_PATH_APPEND': 'core', 'DATA_PATH': '/home/daf/butler', 'STORAGE_DETAILS': {}, 'STORAGE_TYPE': 'JSON'}
Feb 18 19:52:32 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 577: Using driver: 'JSON'
Feb 18 19:52:32 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/cogs/Permissions/settings.json
Feb 18 19:52:32 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 572: Basic config:
Feb 18 19:52:32 pebble redbot[17762]: {'COG_PATH_APPEND': 'cogs', 'CORE_PATH_APPEND': 'core', 'DATA_PATH': '/home/daf/butler', 'STORAGE_DETAILS': {}, 'STORAGE_TYPE': 'JSON'}
Feb 18 19:52:32 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 577: Using driver: 'JSON'
Feb 18 19:52:32 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/cogs/CustomCommands/settings.json
Feb 18 19:52:32 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 572: Basic config:
Feb 18 19:52:32 pebble redbot[17762]: {'COG_PATH_APPEND': 'cogs', 'CORE_PATH_APPEND': 'core', 'DATA_PATH': '/home/daf/butler', 'STORAGE_DETAILS': {}, 'STORAGE_TYPE': 'JSON'}
Feb 18 19:52:32 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 577: Using driver: 'JSON'
Feb 18 19:52:32 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/cogs/Downloader/settings.json
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 572: Basic config:
Feb 18 19:52:34 pebble redbot[17762]: {'COG_PATH_APPEND': 'cogs', 'CORE_PATH_APPEND': 'core', 'DATA_PATH': '/home/daf/butler', 'STORAGE_DETAILS': {}, 'STORAGE_TYPE': 'JSON'}
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 577: Using driver: 'JSON'
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/cogs/Image/settings.json
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 572: Basic config:
Feb 18 19:52:34 pebble redbot[17762]: {'COG_PATH_APPEND': 'cogs', 'CORE_PATH_APPEND': 'core', 'DATA_PATH': '/home/daf/butler', 'STORAGE_DETAILS': {}, 'STORAGE_TYPE': 'JSON'}
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 577: Using driver: 'JSON'
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/cogs/Alias/settings.json
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 572: Basic config:
Feb 18 19:52:34 pebble redbot[17762]: {'COG_PATH_APPEND': 'cogs', 'CORE_PATH_APPEND': 'core', 'DATA_PATH': '/home/daf/butler', 'STORAGE_DETAILS': {}, 'STORAGE_TYPE': 'JSON'}
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 577: Using driver: 'JSON'
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/cogs/Bank/settings.json
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 572: Basic config:
Feb 18 19:52:34 pebble redbot[17762]: {'COG_PATH_APPEND': 'cogs', 'CORE_PATH_APPEND': 'core', 'DATA_PATH': '/home/daf/butler', 'STORAGE_DETAILS': {}, 'STORAGE_TYPE': 'JSON'}
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 577: Using driver: 'JSON'
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/cogs/Trivia/settings.json
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 572: Basic config:
Feb 18 19:52:34 pebble redbot[17762]: {'COG_PATH_APPEND': 'cogs', 'CORE_PATH_APPEND': 'core', 'DATA_PATH': '/home/daf/butler', 'STORAGE_DETAILS': {}, 'STORAGE_TYPE': 'JSON'}
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 577: Using driver: 'JSON'
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/cogs/Admin/settings.json
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 572: Basic config:
Feb 18 19:52:34 pebble redbot[17762]: {'COG_PATH_APPEND': 'cogs', 'CORE_PATH_APPEND': 'core', 'DATA_PATH': '/home/daf/butler', 'STORAGE_DETAILS': {}, 'STORAGE_TYPE': 'JSON'}
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 577: Using driver: 'JSON'
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/cogs/Streams/settings.json
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 572: Basic config:
Feb 18 19:52:34 pebble redbot[17762]: {'COG_PATH_APPEND': 'cogs', 'CORE_PATH_APPEND': 'core', 'DATA_PATH': '/home/daf/butler', 'STORAGE_DETAILS': {}, 'STORAGE_TYPE': 'JSON'}
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 577: Using driver: 'JSON'
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/cogs/Currency/settings.json
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 572: Basic config:
Feb 18 19:52:34 pebble redbot[17762]: {'COG_PATH_APPEND': 'cogs', 'CORE_PATH_APPEND': 'core', 'DATA_PATH': '/home/daf/butler', 'STORAGE_DETAILS': {}, 'STORAGE_TYPE': 'JSON'}
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 577: Using driver: 'JSON'
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/cogs/ReactPoll/settings.json
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 572: Basic config:
Feb 18 19:52:34 pebble redbot[17762]: {'COG_PATH_APPEND': 'cogs', 'CORE_PATH_APPEND': 'core', 'DATA_PATH': '/home/daf/butler', 'STORAGE_DETAILS': {}, 'STORAGE_TYPE': 'JSON'}
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 577: Using driver: 'JSON'
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/cogs/Tweets/settings.json
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 572: Basic config:
Feb 18 19:52:34 pebble redbot[17762]: {'COG_PATH_APPEND': 'cogs', 'CORE_PATH_APPEND': 'core', 'DATA_PATH': '/home/daf/butler', 'STORAGE_DETAILS': {}, 'STORAGE_TYPE': 'JSON'}
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 577: Using driver: 'JSON'
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/cogs/OboobsC/settings.json
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 572: Basic config:
Feb 18 19:52:34 pebble redbot[17762]: {'COG_PATH_APPEND': 'cogs', 'CORE_PATH_APPEND': 'core', 'DATA_PATH': '/home/daf/butler', 'STORAGE_DETAILS': {}, 'STORAGE_TYPE': 'JSON'}
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 577: Using driver: 'JSON'
Feb 18 19:52:34 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/cogs/EventMaker/settings.json
Feb 18 19:52:35 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 572: Basic config:
Feb 18 19:52:35 pebble redbot[17762]: {'COG_PATH_APPEND': 'cogs', 'CORE_PATH_APPEND': 'core', 'DATA_PATH': '/home/daf/butler', 'STORAGE_DETAILS': {}, 'STORAGE_TYPE': 'JSON'}
Feb 18 19:52:35 pebble redbot[17762]: [18/02/2019 19:52] DEBUG config get_conf 577: Using driver: 'JSON'
Feb 18 19:52:35 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _load_json 83: Reading file /home/daf/butler/cogs/Audio/settings.json
Feb 18 19:52:35 pebble redbot[17762]: [18/02/2019 19:52] DEBUG json_io _save_json 50: Saving file /home/daf/butler/cogs/ReactPoll/settings.json
Feb 18 19:52:35 pebble redbot[17762]: [18/02/2019 19:52] INFO manager start_lavalink_server 126: Lavalink jar started. PID: 17830
Feb 18 19:52:35 pebble redbot[17762]: Loaded packages: permissions, customcom, downloader, image, alias, trivia, general, admin, streams, rolemembers, droll, currency, reactpoll, tweets, oboobs, eventmaker, audio
Feb 18 19:52:35 pebble redbot[17762]: [18/02/2019 19:52] INFO manager shutdown_lavalink_server 136: Shutting down lavalink server.
Feb 18 19:52:36 pebble redbot[17762]: Task exception was never retrieved
Feb 18 19:52:36 pebble redbot[17762]: future: <Task finished coro=<monitor_lavalink_server() done, defined at /home/daf/.local/lib/python3.7/site-packages/redbot/cogs/audio/manager.py:30> exception=AttributeError("'NoneType' object has no attribute 'poll'")>
Feb 18 19:52:36 pebble redbot[17762]: Traceback (most recent call last):
Feb 18 19:52:36 pebble redbot[17762]:   File "/home/daf/.local/lib/python3.7/site-packages/redbot/cogs/audio/manager.py", line 32, in monitor_lavalink_server
Feb 18 19:52:36 pebble redbot[17762]:     if proc.poll() is not None:
Feb 18 19:52:36 pebble redbot[17762]: AttributeError: 'NoneType' object has no attribute 'poll'
Feb 18 19:52:36 pebble redbot[17762]: [18/02/2019 19:52] INFO manager start_lavalink_server 126: Lavalink jar started. PID: 17843
Feb 18 19:52:36 pebble redbot[17762]: [18/02/2019 19:52] DEBUG node connect 192: Lavalink WS connecting to ws://localhost:2333 or ws://localhost:2332 with headers {'Authorization': 'youshallnotpass', 'User-Id': 429449238280405013, 'Num-Shards': 1}
Feb 18 19:52:36 pebble redbot[17762]: [18/02/2019 19:52] DEBUG node _multi_try_connect 236: Failed connect attempt 1, retrying in 1.704282818653991
Feb 18 19:52:36 pebble redbot[17762]: [18/02/2019 19:52] DEBUG node _multi_try_connect 236: Failed connect attempt 1, retrying in 0.5403186779391012
Feb 18 19:52:37 pebble redbot[17762]: [18/02/2019 19:52] DEBUG node _multi_try_connect 236: Failed connect attempt 2, retrying in 2.237040242766253
Feb 18 19:52:37 pebble redbot[17762]: ______         _           ______ _                       _  ______       _
Feb 18 19:52:37 pebble redbot[17762]: | ___ \       | |          |  _  (_)                     | | | ___ \     | |
Feb 18 19:52:37 pebble redbot[17762]: | |_/ /___  __| |  ______  | | | |_ ___  ___ ___  _ __ __| | | |_/ / ___ | |_
Feb 18 19:52:37 pebble redbot[17762]: |    // _ \/ _` | |______| | | | | / __|/ __/ _ \| '__/ _` | | ___ \/ _ \| __|
Feb 18 19:52:37 pebble redbot[17762]: | |\ \  __/ (_| |          | |/ /| \__ \ (_| (_) | | | (_| | | |_/ / (_) | |_
Feb 18 19:52:37 pebble redbot[17762]: \_| \_\___|\__,_|          |___/ |_|___/\___\___/|_|  \__,_| \____/ \___/ \__|
Feb 18 19:52:37 pebble redbot[17762]: ┌───────────────────────────────────┐    ┌──────────────────────────┐
Feb 18 19:52:37 pebble redbot[17762]: │butler#9025                        │    │X Error Reporting         │
Feb 18 19:52:37 pebble redbot[17762]: │Prefixes: .                        │    │X MongoDB                 │
Feb 18 19:52:37 pebble redbot[17762]: │Language: en                       │    │√ Voice                   │
Feb 18 19:52:37 pebble redbot[17762]: │Red Bot Version: 3.0.1             │    │X Docs                    │
Feb 18 19:52:37 pebble redbot[17762]: │Discord.py Version: 1.0.0a         │    │X Tests                   │
Feb 18 19:52:37 pebble redbot[17762]: │Shards: 1                          │    └──────────────────────────┘
Feb 18 19:52:37 pebble redbot[17762]: │Servers: 1                         │
Feb 18 19:52:37 pebble redbot[17762]: │Users: 12                          │
Feb 18 19:52:37 pebble redbot[17762]: │19 cogs with 103 commands          │
Feb 18 19:52:37 pebble redbot[17762]: └───────────────────────────────────┘
Feb 18 19:52:37 pebble redbot[17762]: Invite URL: https://discordapp.com/oauth2/authorize?client_id=<redacted>&scope=bot
Feb 18 19:52:38 pebble redbot[17762]: [18/02/2019 19:52] DEBUG node _multi_try_connect 236: Failed connect attempt 2, retrying in 3.830107501966753
Feb 18 19:52:39 pebble redbot[17762]: [18/02/2019 19:52] DEBUG node _multi_try_connect 236: Failed connect attempt 3, retrying in 7.870037410162463
Feb 18 19:52:42 pebble redbot[17762]: [18/02/2019 19:52] DEBUG node _multi_try_connect 236: Failed connect attempt 3, retrying in 2.5612946955698126
Feb 18 19:52:44 pebble redbot[17762]: [18/02/2019 19:52] DEBUG node _multi_try_connect 236: Failed connect attempt 4, retrying in 10.116771176486495
Feb 18 19:52:47 pebble redbot[17762]: [18/02/2019 19:52] DEBUG node _multi_try_connect 236: Failed connect attempt 4, retrying in 9.626989285486214
Feb 18 19:52:54 pebble redbot[17762]: [18/02/2019 19:52] DEBUG node _multi_try_connect 236: Failed connect attempt 5, retrying in 16.67042220499931
Feb 18 19:52:56 pebble redbot[17762]: [18/02/2019 19:52] DEBUG node _multi_try_connect 236: Failed connect attempt 5, retrying in 12.104663348412213
Feb 18 19:53:06 pebble redbot[17762]: [18/02/2019 19:53] INFO manager shutdown_lavalink_server 136: Shutting down lavalink server.
Feb 18 19:53:06 pebble redbot[17762]: Task exception was never retrieved
Feb 18 19:53:06 pebble redbot[17762]: future: <Task finished coro=<monitor_lavalink_server() done, defined at /home/daf/.local/lib/python3.7/site-packages/redbot/cogs/audio/manager.py:30> exception=AttributeError("'NoneType' object has no attribute 'poll'")>
Feb 18 19:53:06 pebble redbot[17762]: Traceback (most recent call last):
Feb 18 19:53:06 pebble redbot[17762]:   File "/home/daf/.local/lib/python3.7/site-packages/redbot/cogs/audio/manager.py", line 32, in monitor_lavalink_server
Feb 18 19:53:06 pebble redbot[17762]:     if proc.poll() is not None:
Feb 18 19:53:06 pebble redbot[17762]: AttributeError: 'NoneType' object has no attribute 'poll'
Feb 18 19:53:08 pebble redbot[17762]: [18/02/2019 19:53] INFO manager start_lavalink_server 126: Lavalink jar started. PID: 17886
Feb 18 19:53:08 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node connect 192: Lavalink WS connecting to ws://localhost:2333 or ws://localhost:2332 with headers {'Authorization': 'youshallnotpass', 'User-Id': 429449238280405013, 'Num-Shards': 1}
Feb 18 19:53:08 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 1, retrying in 1.029424664739015
Feb 18 19:53:08 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 1, retrying in 1.3531865409899526
Feb 18 19:53:09 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 6, retrying in 13.007768553948175
Feb 18 19:53:09 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 2, retrying in 3.119662806628245
Feb 18 19:53:09 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 2, retrying in 0.9943716017190543
Feb 18 19:53:10 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 3, retrying in 1.109355507213233
Feb 18 19:53:11 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 6, retrying in 40.68895225053265
Feb 18 19:53:11 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 4, retrying in 12.030944249545211
Feb 18 19:53:12 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 3, retrying in 0.3607774828031287
Feb 18 19:53:12 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 4, retrying in 3.17321123420866
Feb 18 19:53:15 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 5, retrying in 5.337617922959847
Feb 18 19:53:21 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 6, retrying in 50.14370838804984
Feb 18 19:53:22 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 7, retrying in 51.68293651711248
Feb 18 19:53:23 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 5, retrying in 25.04974598014297
Feb 18 19:53:38 pebble redbot[17762]: [18/02/2019 19:53] INFO manager shutdown_lavalink_server 136: Shutting down lavalink server.
Feb 18 19:53:38 pebble redbot[17762]: Task exception was never retrieved
Feb 18 19:53:38 pebble redbot[17762]: future: <Task finished coro=<monitor_lavalink_server() done, defined at /home/daf/.local/lib/python3.7/site-packages/redbot/cogs/audio/manager.py:30> exception=AttributeError("'NoneType' object has no attribute 'poll'")>
Feb 18 19:53:38 pebble redbot[17762]: Traceback (most recent call last):
Feb 18 19:53:38 pebble redbot[17762]:   File "/home/daf/.local/lib/python3.7/site-packages/redbot/cogs/audio/manager.py", line 32, in monitor_lavalink_server
Feb 18 19:53:38 pebble redbot[17762]:     if proc.poll() is not None:
Feb 18 19:53:38 pebble redbot[17762]: AttributeError: 'NoneType' object has no attribute 'poll'
Feb 18 19:53:39 pebble redbot[17762]: [18/02/2019 19:53] INFO manager start_lavalink_server 126: Lavalink jar started. PID: 17923
Feb 18 19:53:39 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node connect 192: Lavalink WS connecting to ws://localhost:2333 or ws://localhost:2332 with headers {'Authorization': 'youshallnotpass', 'User-Id': 429449238280405013, 'Num-Shards': 1}
Feb 18 19:53:39 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 1, retrying in 0.01087135645787951
Feb 18 19:53:39 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 1, retrying in 0.4997286759531765
Feb 18 19:53:39 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 2, retrying in 2.9407129501177414
Feb 18 19:53:40 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 2, retrying in 2.6967577630397286
Feb 18 19:53:42 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 3, retrying in 0.13527025940002524
Feb 18 19:53:43 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 4, retrying in 3.0842300795657973
Feb 18 19:53:43 pebble redbot[17762]: [18/02/2019 19:53] DEBUG node _multi_try_connect 236: Failed connect attempt 3, retrying in 5.344690419801022
Feb 18 19:53:45 pebble systemd[1]: Stopping Red-DiscordBot...
Feb 18 19:53:45 pebble systemd[1]: red.service: Main process exited, code=killed, status=15/TERM
Feb 18 19:53:45 pebble systemd[1]: red.service: Succeeded.
Feb 18 19:53:45 pebble systemd[1]: Stopped Red-DiscordBot.

dafzor on 18 Feb 2019

👍1

@dafzor Thanks for the extra info. Indeed, it's likely due to limited resource availability (whether from your hardware, or other processes) that the server takes longer than 30 seconds to start up, causing the connect task to timeout and raise an exception. I'll note that the timeout error ought to be logged in the console.

We're thinking of making the server subprocess manager wait for the lavalink server to be ready by piping and parsing stdout, rather than just retrying the connection until it either succeeds or times out.

Thanks for bringing this to the attention of the devs.

Tobotimus on 18 Feb 2019

🎉1

Was this page helpful?

0 / 5 - 0 ratings