Summary

This article deals with a misleading NPE that could confuse users.

A java.lang.NullPointerException (NPE) can be seen as a consequence of a number of simple CQL statements, like for example CREATE TYPE, or ALTER TABLE, however the CQL statement will complete.

The problem is not the actual CQL statement but rather the slowLog facility that throws the NPE.

Symptoms

This stack is thrown after a CQL statement is run:

ERROR [SharedPool-Worker-1] 2016-12-07 16:19:57,071  QueryMessage.java:135 - Unexpected error during query
java.lang.NullPointerException: null
        at org.apache.cassandra.cql3.statements.CFStatement.columnFamily(CFStatement.java:62) ~[cassandra-all-2.1.13.1131.jar:2.1.13.1131]
        at com.datastax.bdp.cassandra.cql3.StatementUtils.getColumnFamily(StatementUtils.java:114) ~[dse-core-4.8.5.jar:4.8.5]
        at com.datastax.bdp.cassandra.cql3.CqlSlowLogPlugin.maybeRecord(CqlSlowLogPlugin.java:157) ~[dse-core-4.8.5.jar:4.8.5]
        at com.datastax.bdp.cassandra.cql3.DseQueryHandler$Operation.executeWithTiming(DseQueryHandler.java:216) ~[dse-core-4.8.5.jar:4.8.5]
        at com.datastax.bdp.cassandra.cql3.DseQueryHandler$Operation.executeWithAuditLogging(DseQueryHandler.java:259) ~[dse-core-4.8.5.jar:4.8.5]
        at com.datastax.bdp.cassandra.cql3.DseQueryHandler.process(DseQueryHandler.java:94) ~[dse-core-4.8.5.jar:4.8.5]
        at org.apache.cassandra.transport.messages.QueryMessage.execute(QueryMessage.java:122) ~[cassandra-all-2.1.13.1131.jar:2.1.13.1131]
        at org.apache.cassandra.transport.Message$Dispatcher.channelRead0(Message.java:439) [cassandra-all-2.1.13.1131.jar:2.1.13.1131]
        at org.apache.cassandra.transport.Message$Dispatcher.channelRead0(Message.java:335) [cassandra-all-2.1.13.1131.jar:2.1.13.1131]
        at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105) [netty-all-4.0.34.Final.jar:4.0.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:307) [netty-all-4.0.34.Final.jar:4.0.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext.access$600(AbstractChannelHandlerContext.java:32) [netty-all-4.0.34.Final.jar:4.0.34.Final]
        at io.netty.channel.AbstractChannelHandlerContext$7.run(AbstractChannelHandlerContext.java:298) [netty-all-4.0.34.Final.jar:4.0.34.Final]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_101]
        at org.apache.cassandra.concurrent.AbstractTracingAwareExecutorService$FutureTask.run(AbstractTracingAwareExecutorService.java:164) [cassandra-all-2.1.13.1131.jar:2.1.13.1131]
        at org.apache.cassandra.concurrent.SEPWorker.run(SEPWorker.java:105) [cassandra-all-2.1.13.1131.jar:2.1.13.1131]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_101]

Cause

This issue is tracked in the internal jira:

DSP-10930 - “Slow query log NPEs instead of logging slow statement”.

Affected versions: DSE 4.7.9, 4.8.9, 5.0.2

Solution

The jira is fixed in 4.8.11 and 5.0.3