SlowQueryLog create ArrayIndexOutOfBoundsException and other problems

[evangoe]

• dble version：5.7.11-dble-3.20.10.0-b29c7c91ac638509dbc4f2c146aea41c3f9f0b83-20201203053354
  there is 2 issues in my project :

First :

when I use default bootstarp.cnf config value "-DenableSlowLog=1", dble can dead after it running sometimes ,maybe one day or several days.
the logs show like this :

INFO | jvm 1 | 2021/02/23 23:07:22 | Server startup successfully. dble version is [5.7.11-dble-3.20.10.0-b29c7c91ac638509dbc4f2c146aea41c3f9f0b83-20201203053354]. Please see logs in logs/dble.log INFO | jvm 1 | 2021/02/23 23:12:08 | Exception in thread "SlowQueryLogProcessor" java.lang.NullPointerException INFO | jvm 1 | 2021/02/23 23:12:08 | at com.actiontech.dble.server.trace.TraceResult.genLogResult(TraceResult.java:598) INFO | jvm 1 | 2021/02/23 23:12:08 | at com.actiontech.dble.log.slow.SlowQueryLogEntry.toString(SlowQueryLogEntry.java:55) INFO | jvm 1 | 2021/02/23 23:12:08 | at com.actiontech.dble.log.slow.SlowQueryLogProcessor.writeLog(SlowQueryLogProcessor.java:82) INFO | jvm 1 | 2021/02/23 23:12:08 | at com.actiontech.dble.log.slow.SlowQueryLogProcessor.run(SlowQueryLogProcessor.java:55) INFO | jvm 1 | 2021/02/23 23:19:14 | Debugger failed to attach: handshake failed - received >POST /ws/v1/cl< - expected >JDWP-Handshake< INFO | jvm 1 | 2021/02/23 23:24:35 | Debugger failed to attach: handshake failed - received >GET / HTTP/1.1< - expected >JDWP-Handshake< INFO | jvm 1 | 2021/02/24 01:39:47 | Debugger failed to attach: handshake failed - received >�< - expected >JDWP-Handshake< INFO | jvm 1 | 2021/02/24 02:04:42 | Exception in thread "BusinessExecutor28" java.lang.ArrayIndexOutOfBoundsException: 7 INFO | jvm 1 | 2021/02/24 02:04:42 | at com.actiontech.dble.backend.mysql.MySQLMessage.readUB4(MySQLMessage.java:84) INFO | jvm 1 | 2021/02/24 02:04:42 | at com.actiontech.dble.net.mysql.AuthPacket.read(AuthPacket.java:67) INFO | jvm 1 | 2021/02/24 02:04:42 | at com.actiontech.dble.services.mysqlauthenticate.MySQLFrontAuthService.handleAuthPacket(MySQLFrontAuthService.java:145) INFO | jvm 1 | 2021/02/24 02:04:42 | at com.actiontech.dble.services.mysqlauthenticate.MySQLFrontAuthService.handleInnerData(MySQLFrontAuthService.java:62) INFO | jvm 1 | 2021/02/24 02:04:42 | at com.actiontech.dble.net.service.AbstractService.handleData(AbstractService.java:284) INFO | jvm 1 | 2021/02/24 02:04:42 | at com.actiontech.dble.net.service.AbstractService.execute(AbstractService.java:105) INFO | jvm 1 | 2021/02/24 02:04:42 | at com.actiontech.dble.net.executor.FrontendBlockRunnable.run(FrontendBlockRunnable.java:54) INFO | jvm 1 | 2021/02/24 02:04:42 | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) INFO | jvm 1 | 2021/02/24 02:04:42 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) INFO | jvm 1 | 2021/02/24 02:04:42 | at java.lang.Thread.run(Thread.java:745) INFO | jvm 1 | 2021/02/24 02:11:25 | Debugger failed to attach: handshake failed - received >POST /ws/v1/cl< - expected >JDWP-Handshake< INFO | jvm 1 | 2021/02/24 03:07:19 | Debugger failed to attach: timeout during handshake INFO | jvm 1 | 2021/02/24 04:01:12 | Exception in thread "BusinessExecutor9" java.lang.ArrayIndexOutOfBoundsException INFO | jvm 1 | 2021/02/24 05:03:57 | Debugger failed to attach: recv failed during handshake: 资源暂时不可用 INFO | jvm 1 | 2021/02/24 05:04:29 | Debugger failed to attach: recv failed during handshake: 资源暂时不可用 INFO | jvm 1 | 2021/02/24 05:04:33 | Debugger failed to attach: handshake failed - received >GET http://pas< - expected >JDWP-Handshake< INFO | jvm 1 | 2021/02/24 05:56:00 | Debugger failed to attach: handshake failed - received >POST /ws/v1/cl< - expected >JDWP-Handshake< INFO | jvm 1 | 2021/02/24 06:49:56 | Debugger failed to attach: recv failed during handshake: Connection reset by peer INFO | jvm 1 | 2021/02/24 06:49:57 | Debugger failed to attach: handshake failed - received >GET / HTTP/1.1< - expected >JDWP-Handshake< INFO | jvm 1 | 2021/02/24 06:49:58 | Debugger failed to attach: recv failed during handshake: Connection reset by peer INFO | jvm 1 | 2021/02/24 06:49:58 | Debugger failed to attach: handshake failed - received >���< - expected >JDWP-Handshake< INFO | jvm 1 | 2021/02/24 10:16:54 | Debugger failed to attach: handshake failed - received >�< - expected >JDWP-Handshake< INFO | jvm 1 | 2021/02/24 11:24:52 | Exception in thread "BusinessExecutor16" java.lang.ArrayIndexOutOfBoundsException INFO | jvm 1 | 2021/02/24 12:14:34 | Exception in thread "BusinessExecutor13" java.lang.OutOfMemoryError: Java heap space INFO | jvm 1 | 2021/02/24 12:14:34 | at java.lang.AbstractStringBuilder.<init>(AbstractStringBuilder.java:68) INFO | jvm 1 | 2021/02/24 12:14:38 | at java.lang.StringBuilder.<init>(StringBuilder.java:101) INFO | jvm 1 | 2021/02/24 12:14:38 | at com.alibaba.druid.sql.visitor.ParameterizedOutputVisitorUtils.parameterize(ParameterizedOutputVisitorUtils.java:103) INFO | jvm 1 | 2021/02/24 12:14:38 | at com.alibaba.druid.sql.visitor.ParameterizedOutputVisitorUtils.parameterize(ParameterizedOutputVisitorUtils.java:66) INFO | jvm 1 | 2021/02/24 12:14:38 | at com.alibaba.druid.wall.WallProvider.getWhiteSql(WallProvider.java:465) INFO | jvm 1 | 2021/02/24 12:14:38 | at com.alibaba.druid.wall.WallProvider.checkWhiteAndBlackList(WallProvider.java:767) INFO | jvm 1 | 2021/02/24 12:14:38 | at com.alibaba.druid.wall.WallProvider.checkInternal(WallProvider.java:600) INFO | jvm 1 | 2021/02/24 12:14:38 | at com.alibaba.druid.wall.WallProvider.check(WallProvider.java:578) INFO | jvm 1 | 2021/02/24 12:14:38 | at com.actiontech.dble.services.mysqlsharding.ShardingService.query(ShardingService.java:175) INFO | jvm 1 | 2021/02/24 12:14:38 | at com.actiontech.dble.services.mysqlsharding.MySQLProtoLogicHandler.query(MySQLProtoLogicHandler.java:70) INFO | jvm 1 | 2021/02/24 12:14:38 | at com.actiontech.dble.services.mysqlsharding.ShardingService.handleInnerData(ShardingService.java:217) INFO | jvm 1 | 2021/02/24 12:14:38 | at com.actiontech.dble.net.service.AbstractService.handleData(AbstractService.java:284) INFO | jvm 1 | 2021/02/24 12:14:38 | at com.actiontech.dble.net.service.AbstractService.execute(AbstractService.java:105) INFO | jvm 1 | 2021/02/24 12:14:38 | at com.actiontech.dble.net.executor.FrontendBlockRunnable.run(FrontendBlockRunnable.java:54) INFO | jvm 1 | 2021/02/24 12:14:38 | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) INFO | jvm 1 | 2021/02/24 12:14:38 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) INFO | jvm 1 | 2021/02/24 12:14:38 | at java.lang.Thread.run(Thread.java:745) STATUS | wrapper | 2021/02/24 12:20:24 | JVM appears hung: Timed out waiting for signal from JVM. Restarting JVM. STATUS | wrapper | 2021/02/24 12:20:24 | JVM received a signal SIGKILL (9). STATUS | wrapper | 2021/02/24 12:20:24 | JVM process is gone. STATUS | wrapper | 2021/02/24 12:20:24 | JVM exited after being requested to terminate. STATUS | wrapper | 2021/02/24 12:20:30 | JVM process is gone.

second:

i can exec command "disable @@slow_query_log;" when i use mange account connect to dble.
it reports "SQL 错误 [1003] [HY000]: Unsupported statement"

[PanternBao]

NullPointExeception is known issues when keeping slow log on.

[dcy10000]

NullPointExeception causes slow query logs are not consumed anymore. So, OutOfMemoryError happens. It was fixed on #2397 and #2514.

ArrayIndexOutOfBoundsException is caused when has no enough memory. In this situation, the socket channel read less byte than usual. It was fixed on #2501.

Those features will be released in the next version of dble.

[jndxcaiwei]

verified on: 5.7.11-dble-9.9.9.9-917611feba5a3dc0ed58c863d9ceb14d02a048e8-20210318014809