EngineHub / CommandHelper

Rapid scripting and command aliases for Minecraft owners
https://methodscript.com
Other
118 stars 71 forks source link

Connection failure to Redis results in all commands failing #953

Open LadyCailinBot opened 10 years ago

LadyCailinBot commented 10 years ago

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==

==Possible Workarounds==

==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 <

>:/data/minecraft/1.7-survival/plugins/CommandHelper/LocalPackages/bungee/bungee.msa:36 [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.
LadyCailinBot commented 10 years ago

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.