Bug report: BatchStatements above a certain size lead to ServerErrors

[Jonas Prellberg]

Hi,

I hope this is the correct place to file a bug report but I could not find any directions for reporting bugs on your github page. See the attached code for a minimal example producing the following exception:

Connecting...

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".

SLF4J: Defaulting to no-operation (NOP) logger implementation

SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

Connected.

Created keyspace.

Created table.

Exception in thread "main" com.datastax.driver.core.exceptions.ProtocolError: An unexpected protocol error occurred on host localhost/0:0:0:0:0:0:0:1:32774. This is a bug in this library, please report: Invalid query kind in BATCH messages. Must be 0 or 1 but got -111

at com.datastax.driver.core.exceptions.ProtocolError.copy(ProtocolError.java:65)

at com.datastax.driver.core.exceptions.ProtocolError.copy(ProtocolError.java:27)

at com.datastax.driver.core.DriverThrowables.propagateCause(DriverThrowables.java:37)

at com.datastax.driver.core.DefaultResultSetFuture.getUninterruptibly(DefaultResultSetFuture.java:245)

at com.datastax.driver.core.AbstractSession.execute(AbstractSession.java:64)

at dbp.BatchTest.main(BatchTest.java:30)

Caused by: com.datastax.driver.core.exceptions.ProtocolError: An unexpected protocol error occurred on host localhost/0:0:0:0:0:0:0:1:32774. This is a bug in this library, please report: Invalid query kind in BATCH messages. Must be 0 or 1 but got -111

at com.datastax.driver.core.Responses$Error.asException(Responses.java:110)

at com.datastax.driver.core.DefaultResultSetFuture.onSet(DefaultResultSetFuture.java:179)

at com.datastax.driver.core.RequestHandler.setFinalResult(RequestHandler.java:173)

at com.datastax.driver.core.RequestHandler.access$2500(RequestHandler.java:43)

at com.datastax.driver.core.RequestHandler$SpeculativeExecution.setFinalResult(RequestHandler.java:788)

at com.datastax.driver.core.RequestHandler$SpeculativeExecution.onSet(RequestHandler.java:607)

at com.datastax.driver.core.Connection$Dispatcher.channelRead0(Connection.java:1012)

at com.datastax.driver.core.Connection$Dispatcher.channelRead0(Connection.java:935)

at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)

at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:318)

at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:304)

at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:266)

at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:318)

at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:304)

at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)

at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:318)

at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:304)

at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:276)

at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:263)

at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:318)

at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:304)

at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)

at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)

at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)

at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)

at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)

at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)

at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)

at java.lang.Thread.run(Unknown Source)

The code was compiled with 'com.datastax.cassandra:cassandra-driver-core:3.0.3' and run against the cassandra:3.0.8 docker image. The culprit here seems to be the batch size as replacing 

batchStmt.size() >= 1000

with 

batchStmt.size() >= 50

solves the issue.

Best regards

Jonas

[Nate McCall]

The size at which to fail a batch is a configuration parameter on the server side:

https://github.com/apache/cassandra/blob/cassandra-3.0/conf/cassandra.yaml#L662-L663

If this is the cause, perhaps there is an issue in having a more informative error message. 

--
You received this message because you are subscribed to the Google Groups "DataStax Java Driver for Apache Cassandra User Mailing List" group.
To unsubscribe from this group and stop receiving emails from it, send an email to java-driver-us...@lists.datastax.com.

--

-----------------
Nate McCall
Wellington, NZ
@zznate

CTO
Apache Cassandra Consulting
http://www.thelastpickle.com

[Kevin Gallardo]

Hi, 

I don't manage to reproduce the issue...

Thank you for providing the example code, I have run it against a local Cassandra cluster with 1 node and another with 3 nodes, created with CCM, Cassandra version 3.0.8, and driver versions 3.0.3 and on the current 3.0 branch (3.1.x). I tried with different `batchStmt.size()` values and in a bigger `for` loop. I tried with `batchStmt.size() == 50 / 1000 / 5000 / 10000`, but no luck reproducing.

Are you able to reproduce it consistently? Have you done any specific configuration related to batches in your cassandra.yaml?

This error message comes from the C* node, so there should be a trace of that error in the C* log itself, which would contain a proper stacktrace of where exactly in the C* code the error occurs, would you be able to provide that log please?

Cheers.

Kévin Gallardo.

kgdo.me

Software Engineer in Drivers and Tools Team, at DataStax.

[Jonas Prellberg]

I tried increasing the setting you mentioned to 5000kb. My code still fails with the same error at batch sizes of 150. Since there is only a single int value being set (150*4b=600b) I don't think this is the issue.

[Jonas Prellberg]

I can consistently reproduce it and have done no changes to the docker container I mentioned. Can you please tell me how I can retrieve the logs you mentioned?

[Kevin Gallardo]

Seems like you could get the logs of the Cassandra container with the following command : 

docker logs your-cassandra-container-name

Taken from the Docker docs page : https://hub.docker.com/_/cassandra/.

The logs that are needed are the system logs, so you could also check in your container the /var/log/cassandra/system.log

Would you have the possibility to test against a local Cassandra node not launched in a Docker container to see if you can reproduce it there as well?

Cheers.

[Jonas Prellberg]

Here is the log: http://pastebin.com/dVGiAkbx

Weirdly enough there is no exception, the log in the pastebin is not truncated. It just ends there. Also I didn't mention so far that I am running Windows 10 64-bit.

I don't really want to install a local cassandra node on my machine right now, maybe later.

[Jonas Prellberg]

After a few more tests I could also produce another type of exception which does generate a stacktrace on the server side. The difference between the attached file and the one in my original post is the inclusion of more attributes in the PreparedStatement. The exception is then:

Connecting...

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".

SLF4J: Defaulting to no-operation (NOP) logger implementation

SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

Connected.

Created keyspace.

Created table.

Exception in thread "main" com.datastax.driver.core.exceptions.NoHostAvailableException: All host(s) tried for query failed (tried: localhost/127.0.0.1:32789 (com.datastax.driver.core.exceptions.ServerError: An unexpected error occurred server side on localhost/127.0.0.1:32789: java.lang.IndexOutOfBoundsException: index: 4096, length: 1664221440 (expected: range(0, 6764))))

at com.datastax.driver.core.exceptions.NoHostAvailableException.copy(NoHostAvailableException.java:84)

at com.datastax.driver.core.exceptions.NoHostAvailableException.copy(NoHostAvailableException.java:37)

at com.datastax.driver.core.DriverThrowables.propagateCause(DriverThrowables.java:37)

at com.datastax.driver.core.DefaultResultSetFuture.getUninterruptibly(DefaultResultSetFuture.java:245)

at com.datastax.driver.core.AbstractSession.execute(AbstractSession.java:64)

at dbp.BatchTest4.main(BatchTest4.java:32)

Caused by: com.datastax.driver.core.exceptions.NoHostAvailableException: All host(s) tried for query failed (tried: localhost/127.0.0.1:32789 (com.datastax.driver.core.exceptions.ServerError: An unexpected error occurred server side on localhost/127.0.0.1:32789: java.lang.IndexOutOfBoundsException: index: 4096, length: 1664221440 (expected: range(0, 6764))))

at com.datastax.driver.core.RequestHandler.reportNoMoreHosts(RequestHandler.java:207)

at com.datastax.driver.core.RequestHandler.access$1000(RequestHandler.java:43)

at com.datastax.driver.core.RequestHandler$SpeculativeExecution.sendRequest(RequestHandler.java:273)

at com.datastax.driver.core.RequestHandler$SpeculativeExecution$1.run(RequestHandler.java:396)

at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

The server log looks as follows: http://pastebin.com/vYQrbLzd

I am not sure if the errors are related but I figured it might help.

[Olivier Michallat]

Hi,

It looks like your network frames are getting corrupted between the client and Cassandra.

I ran your example successfully on my macbook (launching the container with docker run --name v308 -p 127.0.0.1:9042:9042 -p 127.0.0.1:9160:9160 -d cassandra:3.0.8), it works with batchStmt.size() >= 1000.

Maybe something is wrong with Docker on windows. Any chance you could try on another platform?

--

Olivier Michallat

Driver & tools engineer, DataStax

--

[Jonas Prellberg]

Hi,

I was able to test my code on a Mac as well and indeed it works there. I will try to run the code against a local cassandra node on my windows machine to check if your suspicion about Docker is correct (if that works... Windows is only listed as supported up until Windows 8). Thanks for looking into the issue.

[Jonas Prellberg]

I installed Cassandra 3.7 locally on my Win 10 64-bit machine and can confirm the code works. This seems to be an issue related to Docker. Just to be sure I also tested against the cassandra:3.7 docker image and the error occurs there as well.

[Olivier Michallat]

I could not find any directions for reporting bugs on your github page

Btw JIRA is the place to report bugs: https://datastax-oss.atlassian.net/browse/JAVA

It was listed in our README but it didn't say that it was the bug tracker, I fixed that. 

--

Olivier Michallat

Driver & tools engineer, DataStax