Connection failure to Redis results in all commands failing
LadyCailinBot opened this issue ยท 1 comments
CMDHELPER-2954 - Reported by TerrorBite
==Issue==
Initially a {{JedisConnectionException}} is thrown when the connection is lost (for whatever reason). There is apparently no attempt made to reestablish connection. Subsequently, any and all access to Redis attempted by CommandHelper (including automatic access to the {{user.**}} namespace) raises a {{ClassCastException}}.
Due to the above, this error prevents all commands from being run, not just aliases, and therefore is a serious issue (workaround would be to edit persistance.ini to direct requests for {{user.**}} to another database format such as sqlite or ser).
CMDHELPER-2829 has now been open for six months. However, the issue continues to occur even in recent builds. This is build 2705, and there have been no Redis-related commits since that build. I am opening this as a new bug since the codebase has changed since CMDHELPER-2829 was submitted.
==Details==
Server version: 1.7.9-R0.3-SNAPSHOT;
CommandHelper version: 3.3.1-SNAPSHOT:2705-136485b,master;
Loaded extensions and versions:
Core (version 3.3.1);
Redis server version: 2.4.10 (00000000:0)
yaml|title=persistance.ini contains**=redis://localhost:6379?timeout=90
==Observations==
- If the {{user.**}} namespace is configured for storage via Redis), then exceptions are thrown for all commands run, not just aliases. As a result, no commands can be run successfully by players.
- The Redis connection is not re-established automatically - manual intervention is required.
==Possible Workarounds==
- Run {{/reloadaliases}} whenever these errors occur to re-establish normal server operation.
- Attempt to use a higher timeout for Redis to reduce the probability of the Redis server closing the connection for idleness. This will not prevent the issue from occurring if the connection fails for a different reason.
- Map the {{user.**}} namespace to non-Redis storage in {{persistance.ini}}. This should prevent normal commands from generating exceptions when the Redis connection fails, however any aliases that use {{get_value()}} will still fail.
- Don't use Redis at all - this negates the advantages of using Redis, which is probably the most suitable storage backend for the CommandHelper Persistance Network when large volumes of data are being stored and accessed.
- A watchdog script could be written in MScript {color:SaddleBrown}[''Edit: this has now been implemented, see comments'']{color}, running code similar to {{try(get_value('test'), ...)}} on a timer in an attempt to detect a failed connection and run {{/reloadaliases}} automatically. The initial JedisConnectionException raises an MScript {{IOException}}, allowing it to be caught by {{try()}}. It should be possible for this code to also catch the subsequent {{CastException}}s, if these are also converted into their MScript equivalent.
==Case Study / Server Logs==
In this case study, a user's attempt to run a CommandHelper alias containing a {{get_value()}} call fails as the Redis connection has timed out. [http://puu.sh/9lu1C/ebfafe1615.jpg Screenshot from the user's point of view]. Subsequently, another user's attempt to run /back (a regular command) generates a {{ClassCastException}} from CommandHelper's {{onPlayerCommandPreprocess()}} handler, presumably while attempting to access {{user.Greekktofreakk2.aliases.back}} to look for a user alias.
{cut Server log}```
[16:29:00 INFO]: aequoris issued server command: /vanilla
[16:29:00 INFO]: CH: Running original command on player aequoris ----> /vanilla
[16:29:00 INFO]: IOException: com.laytonsmith.libs.redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketTimeoutException: Read timed out
proc _import_get:/data/minecraft/1.7-survival/plugins/CommandHelper/auto_include.ms:249
proc _changeserver:/data/minecraft/1.7-survival/plugins/CommandHelper/LocalPackages/bungee/auto_include.ms:20
<
[16:29:00 INFO]: [D]~Greekk: I'm actually crying
[16:29:02 INFO]: Greekktofreakk2 issued server command: /back
[16:29:02 WARN]:
java.lang.ClassCastException: [B cannot be cast to java.util.List
at com.laytonsmith.libs.redis.clients.jedis.Connection.getBinaryMultiBulkReply(Connection.java:202)
at com.laytonsmith.libs.redis.clients.jedis.Jedis.keys(Jedis.java:171)
at com.laytonsmith.persistence.RedisDataSource.keySet(RedisDataSource.java:161)
at com.laytonsmith.persistence.AbstractDataSource.stringKeySet(AbstractDataSource.java:156)
at com.laytonsmith.persistence.AbstractDataSource.getNamespace(AbstractDataSource.java:166)
at com.laytonsmith.persistence.AbstractDataSource.getValues0(AbstractDataSource.java:89)
at com.laytonsmith.persistence.AbstractDataSource.getValues(AbstractDataSource.java:79)
at com.laytonsmith.persistence.ThreadsafeDataSource.getValues(ThreadsafeDataSource.java:75)
at com.laytonsmith.persistence.PersistenceNetwork.getNamespace(PersistenceNetwork.java:169)
at com.laytonsmith.core.UserManager.getAllScripts(UserManager.java:131)
at com.laytonsmith.commandhelper.CommandHelperListener.runAlias(CommandHelperListener.java:90)
at com.laytonsmith.commandhelper.CommandHelperListener.onPlayerCommandPreprocess(CommandHelperListener.java:137)
at sun.reflect.GeneratedMethodAccessor292.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.bukkit.plugin.java.JavaPluginLoader$1.execute(JavaPluginLoader.java:292)
at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:62)
at org.bukkit.plugin.TimedRegisteredListener.callEvent(TimedRegisteredListener.java:47)
at org.bukkit.plugin.SimplePluginManager.fireEvent(SimplePluginManager.java:502)
at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:487)
at net.minecraft.server.v1_7_R3.PlayerConnection.handleCommand(PlayerConnection.java:991)
at net.minecraft.server.v1_7_R3.PlayerConnection.a(PlayerConnection.java:830)
at net.minecraft.server.v1_7_R3.PacketPlayInChat.a(PacketPlayInChat.java:28)
at net.minecraft.server.v1_7_R3.PacketPlayInChat.handle(PacketPlayInChat.java:65)
at net.minecraft.server.v1_7_R3.NetworkManager.a(NetworkManager.java:180)
at net.minecraft.server.v1_7_R3.ServerConnection.c(ServerConnection.java:81)
at net.minecraft.server.v1_7_R3.MinecraftServer.v(MinecraftServer.java:720)
at net.minecraft.server.v1_7_R3.DedicatedServer.v(DedicatedServer.java:283)
at net.minecraft.server.v1_7_R3.MinecraftServer.u(MinecraftServer.java:583)
at net.minecraft.server.v1_7_R3.MinecraftServer.run(MinecraftServer.java:489)
at net.minecraft.server.v1_7_R3.ThreadServerApplication.run(SourceFile:628)
From here on, many commands throw similar exceptions and fail to execute when run.
The original user again attempts to run the alias, generating a more detailed error:
{cut Server log}```
[16:29:50 INFO]: aequoris issued server command: /vanilla
[16:29:50 INFO]: CH: Running original command on player aequoris ----> /vanilla
[16:29:50 ERROR]: Uh oh! You've found an error in Core.
This is an error caused while running your code, so you may be able to find a workaround, but is ultimately an error in Core itself.
The line of code that caused the error was this:
@key = 'vanilla.whitelist.aequoris'
get_value(@key)
on or around /data/minecraft/1.7-survival/plugins/CommandHelper/auto_include.ms:249.
Please report this error to the developers, and be sure to include the version numbers:
Server version: 1.7.9-R0.3-SNAPSHOT;
CommandHelper version: 3.3.1-SNAPSHOT:2705-136485b,master;
Loaded extensions and versions:
Core (version 3.3.1);
Here's the stacktrace:
java.lang.ClassCastException: java.util.ArrayList cannot be cast to [B
at com.laytonsmith.libs.redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:185)
at com.laytonsmith.libs.redis.clients.jedis.Connection.getBulkReply(Connection.java:174)
at com.laytonsmith.libs.redis.clients.jedis.Jedis.get(Jedis.java:77)
at com.laytonsmith.persistence.RedisDataSource.get0(RedisDataSource.java:143)
at com.laytonsmith.persistence.AbstractDataSource.get(AbstractDataSource.java:73)
at com.laytonsmith.persistence.ThreadsafeDataSource.get(ThreadsafeDataSource.java:70)
at com.laytonsmith.persistence.PersistenceNetwork.get(PersistenceNetwork.java:104)
at com.laytonsmith.core.functions.Persistence$get_value.exec(Persistence.java:176)
at com.laytonsmith.core.Script.eval(Script.java:352)
at com.laytonsmith.core.Script.eval(Script.java:321)
at com.laytonsmith.core.Script.eval(Script.java:321)
at com.laytonsmith.core.functions.BasicLogic$ifelse.execs(BasicLogic.java:690)
at com.laytonsmith.core.Script.eval(Script.java:311)
at com.laytonsmith.core.Procedure.execute(Procedure.java:201)
at com.laytonsmith.core.Procedure.cexecute(Procedure.java:158)
at com.laytonsmith.core.Script.eval(Script.java:280)
at com.laytonsmith.core.Script.eval(Script.java:321)
at com.laytonsmith.core.Script.eval(Script.java:321)
at com.laytonsmith.core.functions.BasicLogic$ifelse.execs(BasicLogic.java:690)
at com.laytonsmith.core.Script.eval(Script.java:311)
at com.laytonsmith.core.Procedure.execute(Procedure.java:201)
at com.laytonsmith.core.Procedure.cexecute(Procedure.java:158)
at com.laytonsmith.core.Script.eval(Script.java:280)
at com.laytonsmith.core.Script.eval(Script.java:321)
at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1857)
at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1814)
at com.laytonsmith.core.Script.run(Script.java:193)
at com.laytonsmith.core.AliasCore.alias(AliasCore.java:167)
at com.laytonsmith.commandhelper.CommandHelperListener.runAlias(CommandHelperListener.java:92)
at com.laytonsmith.commandhelper.CommandHelperListener.onPlayerCommandPreprocess(CommandHelperListener.java:137)
at sun.reflect.GeneratedMethodAccessor292.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.bukkit.plugin.java.JavaPluginLoader$1.execute(JavaPluginLoader.java:292)
at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:62)
at org.bukkit.plugin.TimedRegisteredListener.callEvent(TimedRegisteredListener.java:47)
at org.bukkit.plugin.SimplePluginManager.fireEvent(SimplePluginManager.java:502)
at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:487)
at net.minecraft.server.v1_7_R3.PlayerConnection.handleCommand(PlayerConnection.java:991)
at net.minecraft.server.v1_7_R3.PlayerConnection.a(PlayerConnection.java:830)
at net.minecraft.server.v1_7_R3.PacketPlayInChat.a(PacketPlayInChat.java:28)
at net.minecraft.server.v1_7_R3.PacketPlayInChat.handle(PacketPlayInChat.java:65)
at net.minecraft.server.v1_7_R3.NetworkManager.a(NetworkManager.java:180)
at net.minecraft.server.v1_7_R3.ServerConnection.c(ServerConnection.java:81)
at net.minecraft.server.v1_7_R3.MinecraftServer.v(MinecraftServer.java:720)
at net.minecraft.server.v1_7_R3.DedicatedServer.v(DedicatedServer.java:283)
at net.minecraft.server.v1_7_R3.MinecraftServer.u(MinecraftServer.java:583)
at net.minecraft.server.v1_7_R3.MinecraftServer.run(MinecraftServer.java:489)
at net.minecraft.server.v1_7_R3.ThreadServerApplication.run(SourceFile:628)
```{cut}
An exception is thrown for a typo'd command that does not exist, demonstrating that the issue affects all commands.
{cut Server log}```
[16:46:15 INFO]: redworm668 issued server command: /waep rhelp
[16:46:15 WARN]:
java.lang.ClassCastException: java.lang.Long cannot be cast to java.util.List
at com.laytonsmith.libs.redis.clients.jedis.Connection.getBinaryMultiBulkReply(Connection.java:202)
at com.laytonsmith.libs.redis.clients.jedis.Jedis.keys(Jedis.java:171)
at com.laytonsmith.persistence.RedisDataSource.keySet(RedisDataSource.java:161)
at com.laytonsmith.persistence.AbstractDataSource.stringKeySet(AbstractDataSource.java:156)
at com.laytonsmith.persistence.AbstractDataSource.getNamespace(AbstractDataSource.java:166)
at com.laytonsmith.persistence.AbstractDataSource.getValues0(AbstractDataSource.java:89)
at com.laytonsmith.persistence.AbstractDataSource.getValues(AbstractDataSource.java:79)
at com.laytonsmith.persistence.ThreadsafeDataSource.getValues(ThreadsafeDataSource.java:75)
at com.laytonsmith.persistence.PersistenceNetwork.getNamespace(PersistenceNetwork.java:169)
at com.laytonsmith.core.UserManager.getAllScripts(UserManager.java:131)
at com.laytonsmith.commandhelper.CommandHelperListener.runAlias(CommandHelperListener.java:90)
at com.laytonsmith.commandhelper.CommandHelperListener.onPlayerCommandPreprocess(CommandHelperListener.java:137)
at sun.reflect.GeneratedMethodAccessor292.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.bukkit.plugin.java.JavaPluginLoader$1.execute(JavaPluginLoader.java:292)
at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:62)
at org.bukkit.plugin.TimedRegisteredListener.callEvent(TimedRegisteredListener.java:47)
at org.bukkit.plugin.SimplePluginManager.fireEvent(SimplePluginManager.java:502)
at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:487)
at net.minecraft.server.v1_7_R3.PlayerConnection.handleCommand(PlayerConnection.java:991)
at net.minecraft.server.v1_7_R3.PlayerConnection.a(PlayerConnection.java:830)
at net.minecraft.server.v1_7_R3.PacketPlayInChat.a(PacketPlayInChat.java:28)
at net.minecraft.server.v1_7_R3.PacketPlayInChat.handle(PacketPlayInChat.java:65)
at net.minecraft.server.v1_7_R3.NetworkManager.a(NetworkManager.java:180)
at net.minecraft.server.v1_7_R3.ServerConnection.c(ServerConnection.java:81)
at net.minecraft.server.v1_7_R3.MinecraftServer.v(MinecraftServer.java:720)
at net.minecraft.server.v1_7_R3.DedicatedServer.v(DedicatedServer.java:283)
at net.minecraft.server.v1_7_R3.MinecraftServer.u(MinecraftServer.java:583)
at net.minecraft.server.v1_7_R3.MinecraftServer.run(MinecraftServer.java:489)
at net.minecraft.server.v1_7_R3.ThreadServerApplication.run(SourceFile:628)
```{cut}
Exceptions continue to be thrown until {{/reloadaliases}} is run, whereupon CommandHelper reloads itself and in the process, the Redis connection is reestablished.
Comment by TerrorBite
For anyone interested, I have implemented the watchdog script.
=={{plugins/CommandHelper/LocalPackages/watchdog/watchdog.ms}}==
# Watchdog system for CommandHelper Redis backend
set_interval(5000, closure(){
#console('Watchdog testing Redis connection')
try(get_value('watchdog.test'), @exc,
console(color(RED).'Watchdog: REDIS FAILURE DETECTED!')
console(color(RED).'Failure of type '.@exc[0])
console(color(RED).'RELOADING ALIASES!')
runas('~console', /reloadaliases -r --whitelist)
, array(IOException,CastException))
})
Initial testing using a manufactured connection failure (generated by restarting the Redis server) indicates that this script successfully detects the JedisConnectionException and reloads the Persistance Network only (as indicated by the {{-r --whitelist}} arguments), thus reconnecting the backend without interfering with other CommandHelper activity. I will be waiting to see how it reacts when the connection fails by itself however.