[BUGS] Transport failure java.lang.IndexOutOfBoundsException: readerIndex(1) + length(1)

[sss534534]

Hello, Everyone:

There is a bug in your library:

• ENV:
  DB: MySQL
  SQL:
  [iot_cloud]> SELECT iot_m_barrier.car_park_id FROM iot_m_barrier WHERE (iot_m_barrier.kid = 1576108104068099);

CREATE SQL:
car_park_id varchar(64) NOT NULL DEFAULT '' COMMENT ' park ID ';

EXPLAIN:
The type of field 'car_park_id' is varchar(64), use the default value '' will cause a IndexOutOfBoundsException, the stack trace like this:

14:03:37.527 [vert.x-eventloop-thread-0] ERROR com.github.mauricio.async.db.mysql.MySQLConnection - Transport failure
java.lang.IndexOutOfBoundsException: readerIndex(1) + length(1) exceeds writerIndex(1): UnpooledSlicedByteBuf(ridx: 1, widx: 1, cap: 1/1, unwrapped: UnpooledByteBufAllocator$InstrumentedUnpooledUnsafeNoCleanerDirectByteBuf(ridx: 111, widx: 120, cap: 256))
at io.netty.buffer.AbstractByteBuf.checkReadableBytes0(AbstractByteBuf.java:1405) ~[netty-buffer-4.1.25.Final.jar:4.1.25.Final]
at io.netty.buffer.AbstractByteBuf.readByte(AbstractByteBuf.java:707) ~[netty-buffer-4.1.25.Final.jar:4.1.25.Final]
at io.netty.buffer.AbstractByteBuf.readUnsignedByte(AbstractByteBuf.java:721) ~[netty-buffer-4.1.25.Final.jar:4.1.25.Final]
at io.netty.buffer.SwappedByteBuf.readUnsignedByte(SwappedByteBuf.java:536) ~[netty-buffer-4.1.25.Final.jar:4.1.25.Final]
at com.github.mauricio.async.db.util.ChannelWrapper$.readBinaryLength$extension(ChannelWrapper.scala:52) ~[db-async-common_2.12-0.2.21.jar:0.2.21]
at com.github.mauricio.async.db.mysql.decoder.OkDecoder.decode(OkDecoder.scala:29) ~[mysql-async_2.12-0.2.21.jar:0.2.21]
at com.github.mauricio.async.db.mysql.codec.MySQLFrameDecoder.doDecoding(MySQLFrameDecoder.scala:172) ~[mysql-async_2.12-0.2.21.jar:0.2.21]
at com.github.mauricio.async.db.mysql.codec.MySQLFrameDecoder.handleCommonFlow(MySQLFrameDecoder.scala:157) ~[mysql-async_2.12-0.2.21.jar:0.2.21]
at com.github.mauricio.async.db.mysql.codec.MySQLFrameDecoder.decode(MySQLFrameDecoder.scala:90) ~[mysql-async_2.12-0.2.21.jar:0.2.21]
at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:489) ~[netty-codec-4.1.25.Final.jar:4.1.25.Final]
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:428) ~[netty-codec-4.1.25.Final.jar:4.1.25.Final]
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:265) ~[netty-codec-4.1.25.Final.jar:4.1.25.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.25.Final.jar:4.1.25.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.25.Final.jar:4.1.25.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.25.Final.jar:4.1.25.Final]
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1434) [netty-transport-4.1.25.Final.jar:4.1.25.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.25.Final.jar:4.1.25.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.25.Final.jar:4.1.25.Final]
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:965) [netty-transport-4.1.25.Final.jar:4.1.25.Final]
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163) [netty-transport-4.1.25.Final.jar:4.1.25.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:647) [netty-transport-4.1.25.Final.jar:4.1.25.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:582) [netty-transport-4.1.25.Final.jar:4.1.25.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:499) [netty-transport-4.1.25.Final.jar:4.1.25.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:461) [netty-transport-4.1.25.Final.jar:4.1.25.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884) [netty-common-4.1.25.Final.jar:4.1.25.Final]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-common-4.1.25.Final.jar:4.1.25.Final]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]

[andy-yx-chen]

will you get the same error if you use https://github.com/andy-yx-chen/vertx-mysql-postgresql-client this instead?

[kashimotoxiang]

same error, how can I fix it?

[oshai]

Can you share the updated stacktrace?

[kashimotoxiang]

lambda$null$0:70, VertxMySQLHelper (cc.p1.q2)
handle:-1, 905826133 (cc.p1.q2.VertxMySQLHelper$$Lambda$79)
lambda$handleAsyncQueryResultToResultSet$12:321, AsyncSQLConnectionImpl (io.vertx.ext.asyncsql.impl)
handle:-1, 2106105598 (io.vertx.ext.asyncsql.impl.AsyncSQLConnectionImpl$$Lambda$82)
tryFail:170, FutureImpl (io.vertx.core.impl)
fail:100, FutureImpl (io.vertx.core.impl)
apply:55, ScalaUtils$1 (io.vertx.ext.asyncsql.impl)
apply:49, ScalaUtils$1 (io.vertx.ext.asyncsql.impl)
run$$$capture:60, CallbackRunnable (scala.concurrent.impl)
run:-1, CallbackRunnable (scala.concurrent.impl)
 - Async stack trace
<init>:54, CallbackRunnable (scala.concurrent.impl)
onComplete:303, Promise$DefaultPromise (scala.concurrent.impl)
scalaToVertx:49, ScalaUtils (io.vertx.ext.asyncsql.impl)
lambda$query$2:119, AsyncSQLConnectionImpl (io.vertx.ext.asyncsql.impl)
beginTransactionIfNeeded:305, AsyncSQLConnectionImpl (io.vertx.ext.asyncsql.impl)
query:118, AsyncSQLConnectionImpl (io.vertx.ext.asyncsql.impl)
lambda$getResult$1:64, VertxMySQLHelper (cc.p1.q2)
lambda$getConnection$0:68, BaseSQLClient (io.vertx.ext.asyncsql.impl)
handle:75, AsyncConnectionPool$1 (io.vertx.ext.asyncsql.impl.pool)
handle:70, AsyncConnectionPool$1 (io.vertx.ext.asyncsql.impl.pool)
apply:93, ScalaUtils$3 (io.vertx.ext.asyncsql.impl)
apply:89, ScalaUtils$3 (io.vertx.ext.asyncsql.impl)
run$$$capture:60, CallbackRunnable (scala.concurrent.impl)
run:-1, CallbackRunnable (scala.concurrent.impl)
 - Async stack trace
<init>:54, CallbackRunnable (scala.concurrent.impl)
onComplete:303, Promise$DefaultPromise (scala.concurrent.impl)
createAndConnect:96, AsyncConnectionPool (io.vertx.ext.asyncsql.impl.pool)
createConnection:70, AsyncConnectionPool (io.vertx.ext.asyncsql.impl.pool)
createOrWaitForAvailableConnection:109, AsyncConnectionPool (io.vertx.ext.asyncsql.impl.pool)
take:118, AsyncConnectionPool (io.vertx.ext.asyncsql.impl.pool)
getConnection:64, BaseSQLClient (io.vertx.ext.asyncsql.impl)
getConnection:54, AsyncSQLClientImpl (io.vertx.ext.asyncsql.impl)
getConnection:52, ClientWrapper (io.vertx.ext.asyncsql.impl)
getResult:61, VertxMySQLHelper (cc.p1.q2)
getHashtagScore:115, VertxMySQL (cc.p1.q2)
lambda$calculateScore$4:89, Query2 (cc.p1.q2)
tryComplete:125, FutureImpl (io.vertx.core.impl)
complete:86, FutureImpl (io.vertx.core.impl)
lambda$getKeywordsScore$4:207, VertxMySQL (cc.p1.q2)
tryComplete:125, FutureImpl (io.vertx.core.impl)
complete:86, FutureImpl (io.vertx.core.impl)
lambda$null$0:67, VertxMySQLHelper (cc.p1.q2)
lambda$handleAsyncQueryResultToResultSet$12:319, AsyncSQLConnectionImpl (io.vertx.ext.asyncsql.impl)
tryComplete:125, FutureImpl (io.vertx.core.impl)
complete:86, FutureImpl (io.vertx.core.impl)
apply:53, ScalaUtils$1 (io.vertx.ext.asyncsql.impl)
apply:49, ScalaUtils$1 (io.vertx.ext.asyncsql.impl)
run$$$capture:60, CallbackRunnable (scala.concurrent.impl)
run:-1, CallbackRunnable (scala.concurrent.impl)
 - Async stack trace
<init>:54, CallbackRunnable (scala.concurrent.impl)
onComplete:303, Promise$DefaultPromise (scala.concurrent.impl)
scalaToVertx:49, ScalaUtils (io.vertx.ext.asyncsql.impl)
lambda$query$2:119, AsyncSQLConnectionImpl (io.vertx.ext.asyncsql.impl)
beginTransactionIfNeeded:305, AsyncSQLConnectionImpl (io.vertx.ext.asyncsql.impl)
query:118, AsyncSQLConnectionImpl (io.vertx.ext.asyncsql.impl)
lambda$getResult$1:64, VertxMySQLHelper (cc.p1.q2)
lambda$getConnection$0:68, BaseSQLClient (io.vertx.ext.asyncsql.impl)
handle:75, AsyncConnectionPool$1 (io.vertx.ext.asyncsql.impl.pool)
handle:70, AsyncConnectionPool$1 (io.vertx.ext.asyncsql.impl.pool)
apply:93, ScalaUtils$3 (io.vertx.ext.asyncsql.impl)
apply:89, ScalaUtils$3 (io.vertx.ext.asyncsql.impl)
run$$$capture:60, CallbackRunnable (scala.concurrent.impl)
run:-1, CallbackRunnable (scala.concurrent.impl)
 - Async stack trace
<init>:54, CallbackRunnable (scala.concurrent.impl)
onComplete:303, Promise$DefaultPromise (scala.concurrent.impl)
createAndConnect:96, AsyncConnectionPool (io.vertx.ext.asyncsql.impl.pool)
createConnection:70, AsyncConnectionPool (io.vertx.ext.asyncsql.impl.pool)
createOrWaitForAvailableConnection:109, AsyncConnectionPool (io.vertx.ext.asyncsql.impl.pool)
take:118, AsyncConnectionPool (io.vertx.ext.asyncsql.impl.pool)
getConnection:64, BaseSQLClient (io.vertx.ext.asyncsql.impl)
getConnection:54, AsyncSQLClientImpl (io.vertx.ext.asyncsql.impl)
getConnection:52, ClientWrapper (io.vertx.ext.asyncsql.impl)
getResult:61, VertxMySQLHelper (cc.p1.q2)
getKeywordsScore:177, VertxMySQL (cc.p1.q2)
calculateScore:82, Query2 (cc.p1.q2)
lambda$process$2:41, Query2 (cc.p1.q2)
tryComplete:125, FutureImpl (io.vertx.core.impl)
complete:86, FutureImpl (io.vertx.core.impl)
lambda$getUserPool$0:30, VertxMySQL (cc.p1.q2)
tryComplete:125, FutureImpl (io.vertx.core.impl)
complete:86, FutureImpl (io.vertx.core.impl)
lambda$null$0:67, VertxMySQLHelper (cc.p1.q2)
lambda$handleAsyncQueryResultToResultSet$12:319, AsyncSQLConnectionImpl (io.vertx.ext.asyncsql.impl)
tryComplete:125, FutureImpl (io.vertx.core.impl)
complete:86, FutureImpl (io.vertx.core.impl)
apply:53, ScalaUtils$1 (io.vertx.ext.asyncsql.impl)
apply:49, ScalaUtils$1 (io.vertx.ext.asyncsql.impl)
run$$$capture:60, CallbackRunnable (scala.concurrent.impl)
run:-1, CallbackRunnable (scala.concurrent.impl)
 - Async stack trace
<init>:54, CallbackRunnable (scala.concurrent.impl)
onComplete:303, Promise$DefaultPromise (scala.concurrent.impl)
scalaToVertx:49, ScalaUtils (io.vertx.ext.asyncsql.impl)
lambda$query$2:119, AsyncSQLConnectionImpl (io.vertx.ext.asyncsql.impl)
beginTransactionIfNeeded:305, AsyncSQLConnectionImpl (io.vertx.ext.asyncsql.impl)
query:118, AsyncSQLConnectionImpl (io.vertx.ext.asyncsql.impl)
lambda$getResult$1:64, VertxMySQLHelper (cc.p1.q2)
lambda$getConnection$0:68, BaseSQLClient (io.vertx.ext.asyncsql.impl)
handle:75, AsyncConnectionPool$1 (io.vertx.ext.asyncsql.impl.pool)
handle:70, AsyncConnectionPool$1 (io.vertx.ext.asyncsql.impl.pool)
apply:93, ScalaUtils$3 (io.vertx.ext.asyncsql.impl)
apply:89, ScalaUtils$3 (io.vertx.ext.asyncsql.impl)
run$$$capture:60, CallbackRunnable (scala.concurrent.impl)
run:-1, CallbackRunnable (scala.concurrent.impl)
 - Async stack trace
<init>:54, CallbackRunnable (scala.concurrent.impl)
onComplete:303, Promise$DefaultPromise (scala.concurrent.impl)
createAndConnect:96, AsyncConnectionPool (io.vertx.ext.asyncsql.impl.pool)
createConnection:70, AsyncConnectionPool (io.vertx.ext.asyncsql.impl.pool)
createOrWaitForAvailableConnection:109, AsyncConnectionPool (io.vertx.ext.asyncsql.impl.pool)
take:118, AsyncConnectionPool (io.vertx.ext.asyncsql.impl.pool)
getConnection:64, BaseSQLClient (io.vertx.ext.asyncsql.impl)
getConnection:54, AsyncSQLClientImpl (io.vertx.ext.asyncsql.impl)
getConnection:52, ClientWrapper (io.vertx.ext.asyncsql.impl)
getResult:61, VertxMySQLHelper (cc.p1.q2)
getUserPool:25, VertxMySQL (cc.p1.q2)
process:29, Query2 (cc.p1.q2)
handleProcessQuery2:53, SimpleREST (cc.p1)
handleContext:227, RouteImpl (io.vertx.ext.web.impl)
iterateNext:121, RoutingContextImplBase (io.vertx.ext.web.impl)
next:134, RoutingContextImpl (io.vertx.ext.web.impl)
doEnd:296, BodyHandlerImpl$BHandler (io.vertx.ext.web.handler.impl)
end:276, BodyHandlerImpl$BHandler (io.vertx.ext.web.handler.impl)
lambda$handle$0:87, BodyHandlerImpl (io.vertx.ext.web.handler.impl)
doEnd:526, HttpServerRequestImpl (io.vertx.core.http.impl)
handleEnd:515, HttpServerRequestImpl (io.vertx.core.http.impl)
handleEnd:168, Http1xServerConnection (io.vertx.core.http.impl)
handleMessage:137, Http1xServerConnection (io.vertx.core.http.impl)
handleRead:397, ConnectionBase (io.vertx.core.net.impl)
executeTask:320, ContextImpl (io.vertx.core.impl)
execute:43, EventLoopContext (io.vertx.core.impl)
executeFromIO:188, ContextImpl (io.vertx.core.impl)
channelRead:174, VertxHandler (io.vertx.core.net.impl)
invokeChannelRead:362, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:348, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:340, AbstractChannelHandlerContext (io.netty.channel)
channelRead:86, ChannelInboundHandlerAdapter (io.netty.channel)
channelRead:102, WebSocketServerExtensionHandler (io.netty.handler.codec.http.websocketx.extensions)
invokeChannelRead:362, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:348, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:340, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:323, ByteToMessageDecoder (io.netty.handler.codec)
channelRead:297, ByteToMessageDecoder (io.netty.handler.codec)
invokeChannelRead:362, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:348, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:340, AbstractChannelHandlerContext (io.netty.channel)
end:61, Http1xOrH2CHandler (io.vertx.core.http.impl)
channelRead:38, Http1xOrH2CHandler (io.vertx.core.http.impl)
invokeChannelRead:362, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:348, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:340, AbstractChannelHandlerContext (io.netty.channel)
channelRead:1434, DefaultChannelPipeline$HeadContext (io.netty.channel)
invokeChannelRead:362, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:348, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:965, DefaultChannelPipeline (io.netty.channel)
read:163, AbstractNioByteChannel$NioByteUnsafe (io.netty.channel.nio)
processSelectedKey:644, NioEventLoop (io.netty.channel.nio)
processSelectedKeysOptimized:579, NioEventLoop (io.netty.channel.nio)
processSelectedKeys:496, NioEventLoop (io.netty.channel.nio)
run:458, NioEventLoop (io.netty.channel.nio)
run:897, SingleThreadEventExecutor$5 (io.netty.util.concurrent)
run:30, FastThreadLocalRunnable (io.netty.util.concurrent)
run:748, Thread (java.lang)

the res.cause() of fail is readerIndex(1) + length(1) exceeds writerIndex(1): UnpooledSlicedByteBuf(ridx: 1, widx: 1, cap: 1/1, unwrapped: UnpooledByteBufAllocator$InstrumentedUnpooledUnsafeNoCleanerDirectByteBuf(ridx: 74, widx: 83, cap: 512))

the mysql field type is mediumtext

[kashimotoxiang]

Maybe I need to specify the length of each field? In this case, I just set the field type as mediumtext and left the field length as 0:

[oshai]

From the stacktrace it looks like you're still not using jasync-sql. Can you try to use that?

[kashimotoxiang]

I just replace the vertx-mysql-postgresql-client with vertx-mysql-postgresql-client-jasync in pom.xml, but it doesn't' work. Here are the FailedFuture and its stacktrace

[oshai]

can you please turn on trace logging on com.github.jasync.sql.db.mysql.codec.MySQLFrameDecoder? It looks like an OK message returned from the server without expected data.
I will also try to reproduce it locally tomorrow.

[andy-yx-chen]

Looks like an impossible error, the okay message should never be one byte only, what’s the context for getting this error, what is the previous action you have done on the connection

[kashimotoxiang]

I have switched into vertx-jdbc-client and everything goes well. Because my database is under transforming now, later I will give you the trace logging on com.github.jasync.sql.db.mysql.codec.MySQLFrameDecoder.

The charset of my database is utf8mb4. Some values in my database are Null with mediumtext type, and I noticed that mediumtext is not allowed to set the default type. Because there are no inserted value as well as the default value, maybe no data could be returned in this case?

[andy-yx-chen]

My sense is the returned data was incorrectly parsed by the current driver and led to ok decoder is called

[oshai]

Can you also please share the version of the mysql server?

[kashimotoxiang]

I use google cloud platform, the database version is MySQL 5.7. Sorry I didn't found the log on com.github.jasync.sql.db.mysql.codec.MySQLFrameDecoder cuz I new here.

Here is my code:

    public Future<ResultSet> getResult(final String query) {
        // Now do stuff with it:
        // System.out.println("MYSQL:\t" + query);
        Future<ResultSet> future = Future.future();

        mySQLClient.getConnection(pool -> {
            if (pool.succeeded()) {
                SQLConnection connection = pool.result();
                connection.query(query, res -> {
                    if (res.succeeded()) {
                        // Get the result set
                        future.complete(res.result());
                    } else {
                        // Failed!
                        future.fail(res.cause());
                        System.out.println(query);
                        System.out.println("get query result fail!");
                    }
                    connection.close();
                });
            } else {
                System.out.println(pool.cause());
            }
        });
        return future;

    }

For each query, I simply return a Future and use this code to handle their result

        Future<ResultSet> tag1Future = getResult(cmd1);
        Future<ResultSet> tag2Future = getResult(cmd2);

        // return future
        Future<Double> tagScoreFuture = Future.future();

        CompositeFuture.all(tag1Future, tag2Future).setHandler(resp -> {
            if (resp.succeeded()) {

                List<ResultSet> futureResult = resp.result().list();
                String tag1 = futureResult.get(0).getResults().get(0).getString(0);
                String tag2 = futureResult.get(1).getResults().get(0).getString(0);

At the same time, there are hundreds of similar queries and Futures are created. I am worried that it is a concurrency problem.

Now I think it is not a problem about NULL value, because I found some SQL statements will also fail even SELECT COUNT(tweetid) FROM tweet WHERE type='retweet'( this should return a valid num). But the most time it success, such as SELECT relateduser FROM user WHERE userid='985775778'. Looks like this problem only appear on certain SQL statement.

[oshai]

I don't think it is a concurrency-related issue. What I do suspect is that google cloud mysql send different ok messages on some cases. it looks like jdbc connector is more permissive in that manner: https://github.com/mysql/mysql-connector-j/blob/36534fa273b4d7824a8668ca685465cf8eaeadd9/src/main/protocol-impl/java/com/mysql/cj/protocol/x/StatementExecuteOkBuilder.java and allows not to send all required data.

I think we can check the length of the message when creating OK message. @andy-yx-chen is there any specific reason you think this is a wrong message parsing?

[andy-yx-chen]

@oshai it looks like this message is attached to the other message, so I was suspecting if that is because the last frame was not correctly parsed and it mistakenly take the rest of buffer as an okay message. furthermore, if we can turn on the trace, then we will see what data we sent and receive to understand this issue a bit more