search

vert-x3 / vertx-mysql-postgresql-client

This client is deprecated - use instead
https://github.com/eclipse-vertx/vertx-sql-client
Apache License 2.0
117 stars 59 forks source link

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

Open sss534534 opened 6 years ago

sss534534 commented 6 years ago

Hello, Everyone:

There is a bug in your library:

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 commented 5 years ago

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

kashimotoxiang commented 5 years ago

same error, how can I fix it?

oshai commented 5 years ago

Can you share the updated stacktrace?

kashimotoxiang commented 5 years ago 
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 commented 5 years ago

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: image

oshai commented 5 years ago

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

kashimotoxiang commented 5 years ago

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 image

oshai commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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

oshai commented 5 years ago

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

kashimotoxiang commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

@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

andy-yx-chen commented 5 years ago

@kashimotoxiang are you able to reproduce your issue towards an local MySQL server? or could you simplify your code to reproduce the issue and share with us