search

EngineHub / CommandHelper

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

Redis connection not reinstated on connection failure. #834

Open LadyCailinBot opened 10 years ago

LadyCailinBot commented 10 years ago

CMDHELPER-2829 - Reported by CyaNox

After having the test server idle for a while (no scripts calling any PSN calls that would store in the Redis PSN) the following error popped up once it tried to retrieve a value from the Redis PSN:

The line in question is nothing wrong with as it works perfectly fine after boot up and also after a /reloadalias but for completeness sake I'll add the line of code as well:

  ...
  @g = get_value('redis.permissions.' . @where . 's') # @@@ The line that initiated the error @@@
  ...

The error:

20:51:15 [INFO] IOException: com.laytonsmith.libs.redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketException: Broken pipe
        proc _permissions_permission_ex:/.../Permissions.inc.ms:159
        proc _permissions_add_permission_to_group:/.../Permissions.inc.ms:194
        <<main code>>:/.../Permissions.msa:16

20:51:15 [SEVERE] The previous MethodScript error had an attached cause:
20:51:15 [SEVERE] com.laytonsmith.persistance.DataSourceException: com.laytonsmith.libs.redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketException: Broken pipe
20:51:15 [SEVERE]       at com.laytonsmith.persistance.RedisDataSource.get0(RedisDataSource.java:112)
20:51:15 [SEVERE]       at com.laytonsmith.persistance.AbstractDataSource.get(AbstractDataSource.java:68)
20:51:15 [SEVERE]       at com.laytonsmith.persistance.PersistanceNetwork.get(PersistanceNetwork.java:110)
20:51:15 [SEVERE]       at com.laytonsmith.core.functions.Persistance$get_value.exec(Persistance.java:151)
20:51:15 [SEVERE]       at com.laytonsmith.core.Script.eval(Script.java:310)
20:51:15 [SEVERE]       at com.laytonsmith.core.Script.eval(Script.java:272)
20:51:15 [SEVERE]       at com.laytonsmith.core.Procedure.execute(Procedure.java:191)
20:51:15 [SEVERE]       at com.laytonsmith.core.Procedure.cexecute(Procedure.java:149)
20:51:15 [SEVERE]       at com.laytonsmith.core.Script.eval(Script.java:239)
20:51:15 [SEVERE]       at com.laytonsmith.core.Script.eval(Script.java:272)
20:51:15 [SEVERE]       at com.laytonsmith.core.Procedure.execute(Procedure.java:194)
20:51:15 [SEVERE]       at com.laytonsmith.core.Procedure.cexecute(Procedure.java:149)
20:51:15 [SEVERE]       at com.laytonsmith.core.Script.eval(Script.java:239)
20:51:15 [SEVERE]       at com.laytonsmith.core.Script.seval(Script.java:210)
20:51:15 [SEVERE]       at com.laytonsmith.core.Procedure.cexecute(Procedure.java:147)
20:51:15 [SEVERE]       at com.laytonsmith.core.Script.eval(Script.java:239)
20:51:15 [SEVERE]       at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1494)
20:51:15 [SEVERE]       at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1454)
20:51:15 [SEVERE]       at com.laytonsmith.core.Script.run(Script.java:164)
20:51:15 [SEVERE]       at com.laytonsmith.core.AliasCore.alias(AliasCore.java:150)
20:51:15 [SEVERE]       at com.laytonsmith.commandhelper.CommandHelperServerListener.onServerCommand(CommandHelperServerListener.java:41)
20:51:15 [SEVERE]       at sun.reflect.GeneratedMethodAccessor10.invoke(Unknown Source)
20:51:15 [SEVERE]       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
20:51:15 [SEVERE]       at java.lang.reflect.Method.invoke(Method.java:606)
20:51:15 [SEVERE]       at org.bukkit.plugin.java.JavaPluginLoader$1.execute(JavaPluginLoader.java:425)
20:51:15 [SEVERE]       at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:62)
20:51:15 [SEVERE]       at org.bukkit.plugin.TimedRegisteredListener.callEvent(TimedRegisteredListener.java:30)
20:51:15 [SEVERE]       at org.bukkit.plugin.SimplePluginManager.fireEvent(SimplePluginManager.java:478)
20:51:15 [SEVERE]       at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:463)
20:51:15 [SEVERE]       at net.minecraft.server.v1_6_R3.DedicatedServer.as(DedicatedServer.java:272)
20:51:15 [SEVERE]       at net.minecraft.server.v1_6_R3.DedicatedServer.t(DedicatedServer.java:241)
20:51:15 [SEVERE]       at net.minecraft.server.v1_6_R3.MinecraftServer.s(MinecraftServer.java:493)
20:51:15 [SEVERE]       at net.minecraft.server.v1_6_R3.MinecraftServer.run(MinecraftServer.java:425)
20:51:15 [SEVERE]       at net.minecraft.server.v1_6_R3.ThreadServerApplication.run(SourceFile:583)
20:51:15 [SEVERE] Caused by: com.laytonsmith.libs.redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketException: Broken pipe
20:51:15 [SEVERE]       at com.laytonsmith.libs.redis.clients.jedis.Connection.flush(Connection.java:66)
20:51:15 [SEVERE]       at com.laytonsmith.libs.redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:180)
20:51:15 [SEVERE]       at com.laytonsmith.libs.redis.clients.jedis.Connection.getBulkReply(Connection.java:171)
20:51:15 [SEVERE]       at com.laytonsmith.libs.redis.clients.jedis.Jedis.get(Jedis.java:67)
20:51:15 [SEVERE]       at com.laytonsmith.persistance.RedisDataSource.get0(RedisDataSource.java:109)
20:51:15 [SEVERE]       ... 33 more
20:51:15 [SEVERE] Caused by: java.net.SocketException: Broken pipe
20:51:15 [SEVERE]       at java.net.SocketOutputStream.socketWrite0(Native Method)
20:51:15 [SEVERE]       at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)
20:51:15 [SEVERE]       at java.net.SocketOutputStream.write(SocketOutputStream.java:153)
20:51:15 [SEVERE]       at com.laytonsmith.libs.redis.clients.util.RedisOutputStream.flushBuffer(RedisOutputStream.java:29)
20:51:15 [SEVERE]       at com.laytonsmith.libs.redis.clients.util.RedisOutputStream.flush(RedisOutputStream.java:227)
20:51:15 [SEVERE]       at com.laytonsmith.libs.redis.clients.jedis.Connection.flush(Connection.java:64)
20:51:15 [SEVERE]       ... 37 more

Relevant PSN config:

$shared=redis://localhost:6379?timeout=90&password=pass

# Shared
storage.redis.**=$shared
LadyCailinBot commented 10 years ago

Comment by CyaNox

Additional trace:

16:38:34 [INFO] IOException: com.laytonsmith.libs.redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketException: Broken pipe
        proc _permissions_permission_ex:/.../Permissions.inc.ms:168
        proc _permissions_add_permission_to_group:/.../Permissions.inc.ms:203
        <<main code>>:/.../Permissions.msa:16

16:38:34 [SEVERE] The previous MethodScript error had an attached cause:
16:38:34 [SEVERE] com.laytonsmith.persistance.DataSourceException: com.laytonsmith.libs.redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketException: Broken pipe
16:38:34 [SEVERE]       at com.laytonsmith.persistance.RedisDataSource.get0(RedisDataSource.java:112)
16:38:34 [SEVERE]       at com.laytonsmith.persistance.AbstractDataSource.get(AbstractDataSource.java:68)
16:38:34 [SEVERE]       at com.laytonsmith.persistance.PersistanceNetwork.get(PersistanceNetwork.java:110)
16:38:34 [SEVERE]       at com.laytonsmith.core.functions.Persistance$get_value.exec(Persistance.java:151)
16:38:34 [SEVERE]       at com.laytonsmith.core.Script.eval(Script.java:310)
16:38:34 [SEVERE]       at com.laytonsmith.core.Script.eval(Script.java:272)
16:38:34 [SEVERE]       at com.laytonsmith.core.Procedure.execute(Procedure.java:191)
16:38:34 [SEVERE]       at com.laytonsmith.core.Procedure.cexecute(Procedure.java:149)
16:38:34 [SEVERE]       at com.laytonsmith.core.Script.eval(Script.java:239)
16:38:34 [SEVERE]       at com.laytonsmith.core.Script.eval(Script.java:272)
16:38:34 [SEVERE]       at com.laytonsmith.core.Procedure.execute(Procedure.java:194)
16:38:34 [SEVERE]       at com.laytonsmith.core.Procedure.cexecute(Procedure.java:149)
16:38:34 [SEVERE]       at com.laytonsmith.core.Script.eval(Script.java:239)
16:38:34 [SEVERE]       at com.laytonsmith.core.Script.seval(Script.java:210)
16:38:34 [SEVERE]       at com.laytonsmith.core.Procedure.cexecute(Procedure.java:147)
16:38:34 [SEVERE]       at com.laytonsmith.core.Script.eval(Script.java:239)
16:38:34 [SEVERE]       at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1494)
16:38:34 [SEVERE]       at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1454)
16:38:34 [SEVERE]       at com.laytonsmith.core.Script.run(Script.java:164)
16:38:34 [SEVERE]       at com.laytonsmith.core.AliasCore.alias(AliasCore.java:150)
16:38:34 [SEVERE]       at com.laytonsmith.commandhelper.CommandHelperServerListener.onServerCommand(CommandHelperServerListener.java:41)
16:38:34 [SEVERE]       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
16:38:34 [SEVERE]       at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
16:38:34 [SEVERE]       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
16:38:34 [SEVERE]       at java.lang.reflect.Method.invoke(Method.java:606)
16:38:34 [SEVERE]       at org.bukkit.plugin.java.JavaPluginLoader$1.execute(JavaPluginLoader.java:425)
16:38:34 [SEVERE]       at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:62)
16:38:34 [SEVERE]       at org.bukkit.plugin.TimedRegisteredListener.callEvent(TimedRegisteredListener.java:30)
16:38:34 [SEVERE]       at org.bukkit.plugin.SimplePluginManager.fireEvent(SimplePluginManager.java:478)
16:38:34 [SEVERE]       at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:463)
16:38:34 [SEVERE]       at net.minecraft.server.v1_6_R3.DedicatedServer.as(DedicatedServer.java:272)
16:38:34 [SEVERE]       at net.minecraft.server.v1_6_R3.DedicatedServer.t(DedicatedServer.java:241)
16:38:34 [SEVERE]       at net.minecraft.server.v1_6_R3.MinecraftServer.s(MinecraftServer.java:493)
16:38:34 [SEVERE]       at net.minecraft.server.v1_6_R3.MinecraftServer.run(MinecraftServer.java:425)
16:38:34 [SEVERE]       at net.minecraft.server.v1_6_R3.ThreadServerApplication.run(SourceFile:583)
16:38:34 [SEVERE] Caused by: com.laytonsmith.libs.redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketException: Broken pipe
16:38:34 [SEVERE]       at com.laytonsmith.libs.redis.clients.jedis.Connection.flush(Connection.java:66)
16:38:34 [SEVERE]       at com.laytonsmith.libs.redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:180)
16:38:34 [SEVERE]       at com.laytonsmith.libs.redis.clients.jedis.Connection.getBulkReply(Connection.java:171)
16:38:34 [SEVERE]       at com.laytonsmith.libs.redis.clients.jedis.Jedis.get(Jedis.java:67)
16:38:34 [SEVERE]       at com.laytonsmith.persistance.RedisDataSource.get0(RedisDataSource.java:109)
16:38:34 [SEVERE]       ... 34 more
16:38:34 [SEVERE] Caused by: java.net.SocketException: Broken pipe
16:38:34 [SEVERE]       at java.net.SocketOutputStream.socketWrite0(Native Method)
16:38:34 [SEVERE]       at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)
16:38:34 [SEVERE]       at java.net.SocketOutputStream.write(SocketOutputStream.java:153)
16:38:34 [SEVERE]       at com.laytonsmith.libs.redis.clients.util.RedisOutputStream.flushBuffer(RedisOutputStream.java:29)
16:38:34 [SEVERE]       at com.laytonsmith.libs.redis.clients.util.RedisOutputStream.flush(RedisOutputStream.java:227)
16:38:34 [SEVERE]       at com.laytonsmith.libs.redis.clients.jedis.Connection.flush(Connection.java:64)
16:38:34 [SEVERE]       ... 38 more
LadyCailinBot commented 10 years ago

Comment by LadyCailin

I've updated the Jedis dependency, which may have addressed the issue. Can you try again and see if it has been fixed? The actual error looks like a bug in Jedis. I am checking to see if the connection is open before I use it, but that's apparently not working.

LadyCailinBot commented 10 years ago

Comment by CyaNox

Thus far it is working like a charm. Will most likely run into it again if this issue resurfaces.

LadyCailinBot commented 10 years ago

Comment by CyaNox

I am uncertain if there are other conditions that may influence my results as it seemed to work flawlessly not too long ago. Since I have a lot of scripts going it is kinda hard to see if there is PSN activity. Though if nobody is online for 300 seconds (the timeout setting in the redis configuration) most my scripts will not query the PSN during that time and potentially get the connection disconnected. I'm currently using a small workaround like this:

# Redis config says timeout is at 300 seconds so we just create activity
# every 120 seconds so redis will not terminate the connection.
set_interval(120 * 1000, closure(
  @i = get_value('redis.workaround.timetick')
  store_value('redis.workaround.timetick', time())
))

Which works quite well and keeps the connection alive but when I disable this workaround and have nobody online for a bit (i.e. no PSN activity) I still get the broken pipe error once I initiate PSN activity again.

Looks like this issue is still not fixed:

[04:12:51 INFO]: IOException: com.laytonsmith.libs.redis.clients.jedis.exceptions.JedisConnectionException: It seems like server has closed the connection.
        <<main code>>:/.../FishBans.ms:6

[04:12:51 WARN]: The previous MethodScript error had an attached cause:
[04:12:51 WARN]: com.laytonsmith.persistance.DataSourceException: com.laytonsmith.libs.redis.clients.jedis.exceptions.JedisConnectionException: It seems like server has closed the connection.
[04:12:51 WARN]:        at com.laytonsmith.persistance.RedisDataSource.get0(RedisDataSource.java:112)
[04:12:51 WARN]:        at com.laytonsmith.persistance.AbstractDataSource.get(AbstractDataSource.java:68)
[04:12:51 WARN]:        at com.laytonsmith.persistance.PersistanceNetwork.get(PersistanceNetwork.java:110)
[04:12:51 WARN]:        at com.laytonsmith.core.functions.Persistance$get_value.exec(Persistance.java:151)
[04:12:51 WARN]:        at com.laytonsmith.core.Script.eval(Script.java:310)
[04:12:51 WARN]:        at com.laytonsmith.core.Script.eval(Script.java:272)
[04:12:51 WARN]:        at com.laytonsmith.core.Script.eval(Script.java:272)
[04:12:51 WARN]:        at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1494)
[04:12:51 WARN]:        at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1454)
[04:12:51 WARN]:        at com.laytonsmith.core.Script.run(Script.java:164)
[04:12:51 WARN]:        at com.laytonsmith.core.events.AbstractEvent.execute(AbstractEvent.java:73)
[04:12:51 WARN]:        at com.laytonsmith.core.events.BoundEvent.execute(BoundEvent.java:305)
[04:12:51 WARN]:        at com.laytonsmith.core.events.BoundEvent.trigger(BoundEvent.java:262)
[04:12:51 WARN]:        at com.laytonsmith.core.events.EventUtils.FireListeners(EventUtils.java:205)
[04:12:51 WARN]:        at com.laytonsmith.core.events.EventUtils.TriggerListener(EventUtils.java:193)
[04:12:51 WARN]:        at com.laytonsmith.abstraction.bukkit.events.drivers.BukkitPlayerListener.onPlayerLogin(BukkitPlayerListener.java:52)
[04:12:51 WARN]:        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[04:12:51 WARN]:        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[04:12:51 WARN]:        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[04:12:51 WARN]:        at java.lang.reflect.Method.invoke(Method.java:606)
[04:12:51 WARN]:        at org.bukkit.plugin.java.JavaPluginLoader$1.execute(JavaPluginLoader.java:425)
[04:12:51 WARN]:        at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:62)
[04:12:51 WARN]:        at org.bukkit.plugin.TimedRegisteredListener.callEvent(TimedRegisteredListener.java:30)
[04:12:51 WARN]:        at org.bukkit.plugin.SimplePluginManager.fireEvent(SimplePluginManager.java:478)
[04:12:51 WARN]:        at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:463)
[04:12:51 WARN]:        at net.minecraft.server.v1_7_R1.PlayerList.attemptLogin(PlayerList.java:362)
[04:12:51 WARN]:        at net.minecraft.server.v1_7_R1.LoginListener.c(LoginListener.java:70)
[04:12:51 WARN]:        at net.minecraft.server.v1_7_R1.LoginListener.a(LoginListener.java:42)
[04:12:51 WARN]:        at net.minecraft.server.v1_7_R1.NetworkManager.a(NetworkManager.java:149)
[04:12:51 WARN]:        at net.minecraft.server.v1_7_R1.ServerConnection.c(SourceFile:134)
[04:12:51 WARN]:        at net.minecraft.server.v1_7_R1.MinecraftServer.u(MinecraftServer.java:641)
[04:12:51 WARN]:        at net.minecraft.server.v1_7_R1.DedicatedServer.u(DedicatedServer.java:259)
[04:12:51 WARN]:        at net.minecraft.server.v1_7_R1.MinecraftServer.t(MinecraftServer.java:524)
[04:12:51 WARN]:        at net.minecraft.server.v1_7_R1.MinecraftServer.run(MinecraftServer.java:436)
[04:12:51 WARN]:        at net.minecraft.server.v1_7_R1.ThreadServerApplication.run(SourceFile:617)
[04:12:51 WARN]: Caused by: com.laytonsmith.libs.redis.clients.jedis.exceptions.JedisConnectionException: It seems like server has closed the connection.
[04:12:51 WARN]:        at com.laytonsmith.libs.redis.clients.util.RedisInputStream.readLine(RedisInputStream.java:90)
[04:12:51 WARN]:        at com.laytonsmith.libs.redis.clients.jedis.Protocol.processBulkReply(Protocol.java:96)
[04:12:51 WARN]:        at com.laytonsmith.libs.redis.clients.jedis.Protocol.process(Protocol.java:79)
[04:12:51 WARN]:        at com.laytonsmith.libs.redis.clients.jedis.Protocol.read(Protocol.java:138)
[04:12:51 WARN]:        at com.laytonsmith.libs.redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:185)
[04:12:51 WARN]:        at com.laytonsmith.libs.redis.clients.jedis.Connection.getBulkReply(Connection.java:174)
[04:12:51 WARN]:        at com.laytonsmith.libs.redis.clients.jedis.Jedis.get(Jedis.java:77)
[04:12:51 WARN]:        at com.laytonsmith.persistance.RedisDataSource.get0(RedisDataSource.java:109)
[04:12:51 WARN]:        ... 34 more
LadyCailinBot commented 10 years ago

Comment by LadyCailin

I am definitely checking to see if the connection is up before I process a command, but for whatever reason, I guess that's returning true when it shouldn't. This is still on my todo list, but it may require fixing a bug in Jedis or something.

LadyCailinBot commented 10 years ago

Comment by LadyCailin

So, many database connections will close automatically if they aren't used for a while, and the "isConnected" method of these databases doesn't work properly, unless the connection is explicitly closed. http://stackoverflow.com/questions/3668506/efficient-sql-test-query-or-validation-query-that-will-work-across-all-or-most According to that, MySQL, SQLite, etc all have no-side-effect "test queries" that can be run to see if the connection is up or not.

My assumption is that the same principal applies to Redis. In light of that, (and to make things generally more efficient) I have started doing connection pooling for all DB based PN data sources. (MySQL, SQLite, and Redis). Redis was already internally doing connection caching, which would explain why this was only a problem with Redis, and not SQLite (and also might explain part of why SQLite is much slower than Redis). Because I'm adding this caching in SQLite and MySQL, I have to do "test queries" every so often, instead of using "isConnected". I'm putting a 10 second delay on this, if the connection hasn't been used in 10 seconds, I try a test query on it (and if that fails, creating an all new connection). I'm taking the same approach for Redis as well, so I suspect that this will be fixed correctly now.

LadyCailinBot commented 10 years ago

Comment by TerrorBite

Rather than manually running a test query of your own devising (i.e. SELECT 1 ) on the connection, you can call [http://docs.oracle.com/javase/7/docs/api/java/sql/Connection.html#isValid%28int%29 isValid(timeout)] on a ``` java.sql.Connection



This saves you from having to work out your own test queries for different DB engines, and has the added benefit of letting you provide a timeout value.
LadyCailinBot commented 10 years ago

Comment by LadyCailin

The version of SQLite that is linked doesn't have isValid (it's a newer method). https://bukkit.atlassian.net/browse/BUKKIT-2576 So I've added it, but I have to catch an AbstractMethodError, and fall back to the same method I was doing. But I have made a change to attempt isValid first. Thanks!

LadyCailinBot commented 10 years ago

Comment by TerrorBite

We're still getting errors like these. Why doesn't CommandHelper catch and handle a jedis.exceptions.JedisConnectionException?

LadyCailin commented 4 years ago

https://github.com/EngineHub/CommandHelper/issues/953 seem linked/duplicates