SQLException Connection is read-only

Hello,
I have been running a druid 0.9.1 cluster for some months with no problems.

Yesterday night I started receiving a lot of errors like the one reported below. I have double checked the mysql configuration to see if the grants on the druid_segments table were changed or there was a problem on the database, but everything seems ok on that side.

I restarted the coordinator node and the errors stopped (actually after half an hour they restarted but they ceased after 5 minutes without any intervention)

It seems that druid was trying to set used=false on some old segments. I noticed that these segments in the database had already used=0. I updated them manually some weeks ago because they were corrupted due to this issue https://github.com/druid-io/druid/issues/3493

I was wondering if there is some action that I should take in order to avoid to leave the system in some unclean state.

If the problem was due to the manual update that I made on the database, can you tell me if there is a safer way to mark a segment as unused?

Here is the error:

2016-11-02T08:02:20,380 ERROR [Coordinator-Exec--0] io.druid.metadata.SQLMetadataSegmentManager - org.skife.jdbi.v2.exceptions.CallbackFailedException: org.skife.jdbi.v2.exceptions.UnableToExecuteStatementException: java.sql.SQLException: Connection is read-only. Queries leading to data modification are not allowed [statement:"UPDATE druid_segments SET used=false WHERE id = :segmentID", located:"UPDATE druid_segments SET used=false WHERE id = :segmentID", rewritten:"UPDATE druid_segments SET used=false WHERE id = ?", arguments:{ positional:{}, named:{segmentID:'content20stats_2016-08-30T00:00:00.000Z_2016-08-31T00:00:00.000Z_2016-08-30T00:00:00.100Z_8'}, finder:[]}]
org.skife.jdbi.v2.exceptions.CallbackFailedException: org.skife.jdbi.v2.exceptions.UnableToExecuteStatementException: java.sql.SQLException: Connection is read-only. Queries leading to data modification are not allowed [statement:"UPDATE druid_segments SET used=false WHERE id = :segmentID", located:"UPDATE druid_segments SET used=false WHERE id = :segmentID", rewritten:"UPDATE druid_segments SET used=false WHERE id = ?", arguments:{ positional:{}, named:{segmentID:'content20stats_2016-08-30T00:00:00.000Z_2016-08-31T00:00:00.000Z_2016-08-30T00:00:00.100Z_8'}, finder:[]}]
        at org.skife.jdbi.v2.DBI.withHandle(DBI.java:284) ~[jdbi-2.63.1.jar:2.63.1]
        at io.druid.metadata.SQLMetadataSegmentManager.removeSegment(SQLMetadataSegmentManager.java:365) [druid-server-0.9.1.1.jar:0.9.1.1]
        at io.druid.server.coordinator.DruidCoordinator.removeSegment(DruidCoordinator.java:317) [druid-server-0.9.1.1.jar:0.9.1.1]
        at io.druid.server.coordinator.helper.DruidCoordinatorCleanupOvershadowed.run(DruidCoordinatorCleanupOvershadowed.java:82) [druid-server-0.9.1.1.jar:0.9.1.1]
        at io.druid.server.coordinator.DruidCoordinator$CoordinatorRunnable.run(DruidCoordinator.java:703) [druid-server-0.9.1.1.jar:0.9.1.1]
        at io.druid.server.coordinator.DruidCoordinator$5.call(DruidCoordinator.java:585) [druid-server-0.9.1.1.jar:0.9.1.1]
        at io.druid.server.coordinator.DruidCoordinator$5.call(DruidCoordinator.java:578) [druid-server-0.9.1.1.jar:0.9.1.1]
        at com.metamx.common.concurrent.ScheduledExecutors$2.run(ScheduledExecutors.java:99) [java-util-0.27.9.jar:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_101]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_101]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_101]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_101]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_101]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_101]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_101]
Caused by: org.skife.jdbi.v2.exceptions.UnableToExecuteStatementException: java.sql.SQLException: Connection is read-only. Queries leading to data modification are not allowed [statement:"UPDATE druid_segments SET used=false WHERE id = :segmentID", located:"UPDATE druid_segments SET used=false WHERE id = :segmentID", rewritten:"UPDATE druid_segments SET used=false WHERE id = ?", arguments:{ positional:{}, named:{segmentID:'content20stats_2016-08-30T00:00:00.000Z_2016-08-31T00:00:00.000Z_2016-08-30T00:00:00.100Z_8'}, finder:[]}]
        at org.skife.jdbi.v2.SQLStatement.internalExecute(SQLStatement.java:1334) ~[jdbi-2.63.1.jar:2.63.1]
        at org.skife.jdbi.v2.Update.execute(Update.java:56) ~[jdbi-2.63.1.jar:2.63.1]
        at io.druid.metadata.SQLMetadataSegmentManager$7.withHandle(SQLMetadataSegmentManager.java:374) ~[druid-server-0.9.1.1.jar:0.9.1.1]
        at io.druid.metadata.SQLMetadataSegmentManager$7.withHandle(SQLMetadataSegmentManager.java:367) ~[druid-server-0.9.1.1.jar:0.9.1.1]
        at org.skife.jdbi.v2.DBI.withHandle(DBI.java:281) ~[jdbi-2.63.1.jar:2.63.1]
        ... 14 more
Caused by: java.sql.SQLException: Connection is read-only. Queries leading to data modification are not allowed
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:957) ~[?:?]
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:896) ~[?:?]
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:885) ~[?:?]
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:860) ~[?:?]
        at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1138) ~[?:?]
        at org.apache.commons.dbcp2.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:198) ~[commons-dbcp2-2.0.1.jar:2.0.1]
        at org.apache.commons.dbcp2.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:198) ~[commons-dbcp2-2.0.1.jar:2.0.1]
        at org.skife.jdbi.v2.SQLStatement.internalExecute(SQLStatement.java:1328) ~[jdbi-2.63.1.jar:2.63.1]
        at org.skife.jdbi.v2.Update.execute(Update.java:56) ~[jdbi-2.63.1.jar:2.63.1]
        at io.druid.metadata.SQLMetadataSegmentManager$7.withHandle(SQLMetadataSegmentManager.java:374) ~[druid-server-0.9.1.1.jar:0.9.1.1]
        at io.druid.metadata.SQLMetadataSegmentManager$7.withHandle(SQLMetadataSegmentManager.java:367) ~[druid-server-0.9.1.1.jar:0.9.1.1]
        at org.skife.jdbi.v2.DBI.withHandle(DBI.java:281) ~[jdbi-2.63.1.jar:2.63.1]
        ... 14 more

Regards,
Tommaso

This seems like a connection got stuck in a read-only state that was supposed to be temporary. Do you see any log messages earlier in the logs like “Unable to reset connection read-only state”?

I have found that the error “Unable to reset connection read-only state” has occurred in the coordinator log each day at the same time (13:09 UTC)

This morning I have restarted the coordinator and I have received it immediately after the restart

Today at 13:09 there I have not received any error ( everything seems to be working fine)

I see this line in the stack trace “Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Can’t call rollback when autocommit=true”

Maybe I should set autocommit=false in the mysql configuration?

2016-11-01T13:09:22,405 ERROR [Coordinator-Exec–0] io.druid.metadata.SQLMetadataSegmentManager - Unable to reset connection read-only state
java.sql.SQLException: Streaming result set com.mysql.jdbc.RowDataDynamic@4362e1d7 is still active. No statements may be issued when any streaming result sets are open and in use on a given connection. Ensure that you have called .close(
) on any active streaming result sets before attempting more queries.
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:868) ~[?:?]
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:864) ~[?:?]
at com.mysql.jdbc.MysqlIO.checkForOutstandingStreamingData(MysqlIO.java:3142) ~[?:?]
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2397) ~[?:?]
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2625) ~[?:?]
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2547) ~[?:?]
at com.mysql.jdbc.ConnectionImpl.setReadOnlyInternal(ConnectionImpl.java:5017) ~[?:?]
at com.mysql.jdbc.ConnectionImpl.setReadOnly(ConnectionImpl.java:5010) ~[?:?]
at org.apache.commons.dbcp2.DelegatingConnection.setReadOnly(DelegatingConnection.java:558) ~[commons-dbcp2-2.0.1.jar:2.0.1]
at org.apache.commons.dbcp2.DelegatingConnection.setReadOnly(DelegatingConnection.java:558) ~[commons-dbcp2-2.0.1.jar:2.0.1]
at io.druid.metadata.SQLMetadataSegmentManager$2.withHandle(SQLMetadataSegmentManager.java:179) [druid-server-0.9.1.1.jar:0.9.1.1]
at org.skife.jdbi.v2.DBI.withHandle(DBI.java:281) [jdbi-2.63.1.jar:2.63.1]
at io.druid.metadata.SQLMetadataSegmentManager.inReadOnlyTransaction(SQLMetadataSegmentManager.java:166) [druid-server-0.9.1.1.jar:0.9.1.1]
at io.druid.metadata.SQLMetadataSegmentManager.getUnusedSegmentIntervals(SQLMetadataSegmentManager.java:570) [druid-server-0.9.1.1.jar:0.9.1.1]
at io.druid.server.coordinator.helper.DruidCoordinatorSegmentKiller.findIntervalForKillTask(DruidCoordinatorSegmentKiller.java:111) [druid-server-0.9.1.1.jar:0.9.1.1]
at io.druid.server.coordinator.helper.DruidCoordinatorSegmentKiller.run(DruidCoordinatorSegmentKiller.java:90) [druid-server-0.9.1.1.jar:0.9.1.1]
at io.druid.server.coordinator.DruidCoordinator$CoordinatorRunnable.run(DruidCoordinator.java:703) [druid-server-0.9.1.1.jar:0.9.1.1]
at io.druid.server.coordinator.DruidCoordinator$5.call(DruidCoordinator.java:585) [druid-server-0.9.1.1.jar:0.9.1.1]
at io.druid.server.coordinator.DruidCoordinator$5.call(DruidCoordinator.java:578) [druid-server-0.9.1.1.jar:0.9.1.1]
at com.metamx.common.concurrent.ScheduledExecutors$2.run(ScheduledExecutors.java:99) [java-util-0.27.9.jar:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_101]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_101]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_101]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_101]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_101]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_101]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_101]
2016-11-01T13:09:22,413 ERROR [Coordinator-Exec–0] io.druid.server.coordinator.DruidCoordinator - Caught exception, ignoring so that schedule keeps going.: {class=io.druid.server.coordinator.DruidCoordinator, exceptionType=class org.skife.jdbi.v2.exceptions.CallbackFailedException, exceptionMessage=org.skife.jdbi.v2.exceptions.TransactionException: Failed to rollback transaction}
org.skife.jdbi.v2.exceptions.CallbackFailedException: org.skife.jdbi.v2.exceptions.TransactionException: Failed to rollback transaction
at org.skife.jdbi.v2.DBI.withHandle(DBI.java:284) ~[jdbi-2.63.1.jar:2.63.1]
at io.druid.metadata.SQLMetadataSegmentManager.inReadOnlyTransaction(SQLMetadataSegmentManager.java:166) ~[druid-server-0.9.1.1.jar:0.9.1.1]
at io.druid.metadata.SQLMetadataSegmentManager.getUnusedSegmentIntervals(SQLMetadataSegmentManager.java:570) ~[druid-server-0.9.1.1.jar:0.9.1.1]
at io.druid.server.coordinator.helper.DruidCoordinatorSegmentKiller.findIntervalForKillTask(DruidCoordinatorSegmentKiller.java:111) ~[druid-server-0.9.1.1.jar:0.9.1.1]
at io.druid.server.coordinator.helper.DruidCoordinatorSegmentKiller.run(DruidCoordinatorSegmentKiller.java:90) ~[druid-server-0.9.1.1.jar:0.9.1.1]
at io.druid.server.coordinator.DruidCoordinator$CoordinatorRunnable.run(DruidCoordinator.java:703) [druid-server-0.9.1.1.jar:0.9.1.1]
at io.druid.server.coordinator.DruidCoordinator$5.call(DruidCoordinator.java:585) [druid-server-0.9.1.1.jar:0.9.1.1]
at io.druid.server.coordinator.DruidCoordinator$5.call(DruidCoordinator.java:578) [druid-server-0.9.1.1.jar:0.9.1.1]
at com.metamx.common.concurrent.ScheduledExecutors$2.run(ScheduledExecutors.java:99) [java-util-0.27.9.jar:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_101]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_101]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_101]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_101]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_101]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_101]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_101]
Caused by: org.skife.jdbi.v2.exceptions.TransactionException: Failed to rollback transaction
at org.skife.jdbi.v2.tweak.transactions.LocalTransactionHandler.rollback(LocalTransactionHandler.java:89) ~[jdbi-2.63.1.jar:2.63.1]
at org.skife.jdbi.v2.BasicHandle.rollback(BasicHandle.java:172) ~[jdbi-2.63.1.jar:2.63.1]
at org.skife.jdbi.v2.tweak.transactions.LocalTransactionHandler.inTransaction(LocalTransactionHandler.java:190) ~[jdbi-2.63.1.jar:2.63.1]
at org.skife.jdbi.v2.BasicHandle.inTransaction(BasicHandle.java:327) ~[jdbi-2.63.1.jar:2.63.1]
at io.druid.metadata.SQLMetadataSegmentManager$2.withHandle(SQLMetadataSegmentManager.java:176) ~[druid-server-0.9.1.1.jar:0.9.1.1]
at org.skife.jdbi.v2.DBI.withHandle(DBI.java:281) ~[jdbi-2.63.1.jar:2.63.1]
… 15 more
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Can’t call rollback when autocommit=true
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:1.8.0_101]
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[?:1.8.0_101]
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:1.8.0_101]
at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[?:1.8.0_101]
at com.mysql.jdbc.Util.handleNewInstance(Util.java:404) ~[?:?]
at com.mysql.jdbc.Util.getInstance(Util.java:387) ~[?:?]
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:917) ~[?:?]
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:896) ~[?:?]
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:885) ~[?:?]
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:860) ~[?:?]
at com.mysql.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:4618) ~[?:?]
at org.apache.commons.dbcp2.DelegatingConnection.rollback(DelegatingConnection.java:488) ~[commons-dbcp2-2.0.1.jar:2.0.1]
at org.apache.commons.dbcp2.DelegatingConnection.rollback(DelegatingConnection.java:488) ~[commons-dbcp2-2.0.1.jar:2.0.1]
at org.skife.jdbi.v2.tweak.transactions.LocalTransactionHandler.rollback(LocalTransactionHandler.java:86) ~[jdbi-2.63.1.jar:2.63.1]
at org.skife.jdbi.v2.BasicHandle.rollback(BasicHandle.java:172) ~[jdbi-2.63.1.jar:2.63.1]
at org.skife.jdbi.v2.tweak.transactions.LocalTransactionHandler.inTransaction(LocalTransactionHandler.java:190) ~[jdbi-2.63.1.jar:2.63.1]
at org.skife.jdbi.v2.BasicHandle.inTransaction(BasicHandle.java:327) ~[jdbi-2.63.1.jar:2.63.1]
at io.druid.metadata.SQLMetadataSegmentManager$2.withHandle(SQLMetadataSegmentManager.java:176) ~[druid-server-0.9.1.1.jar:0.9.1.1]
at org.skife.jdbi.v2.DBI.withHandle(DBI.java:281) ~[jdbi-2.63.1.jar:2.63.1]

Hello,
I am still experiencing this odd behavior from druid. Does anybody have some advice about where to look for a solution?

To recap: each day at the same hour (8:41 UTC) I see on the coordinator log the error posted below

2016-11-16T08:41:00,741 ERROR [Coordinator-Exec–0] io.druid.server.coordinator.DruidCoordinator - Caught exception, ignoring so that schedule keeps going.: {class=io.druid.server.coordinator.DruidCoordinator, exceptionType=class
org.skife.jdbi.v2.exceptions.CallbackFailedException, exceptionMessage=org.skife.jdbi.v2.exceptions.TransactionException: Failed to rollback transaction}
org.skife.jdbi.v2.exceptions.CallbackFailedException: org.skife.jdbi.v2.exceptions.TransactionException: Failed to rollback transaction
( I copied the entire stack trace in the previous post , you can find in the quoted text)

With a much higher frequency (hundreds per minute) I am receiving errors about a failing update on mysql regardings old segments

2016-11-16T09:49:08,466 ERROR [Coordinator-Exec--0] io.druid.metadata.SQLMetadataSegmentManager - org.skife.jdbi.v2.exceptions.CallbackFailedException: org.skife.jdbi.v2.exceptions.UnableToExecuteStatementException: java.sql.SQLException: Connection is read-only. Queries leading to data modification are not allowed [statement:"UPDATE druid_segments SET used=false WHERE id = :segmentID", located:"UPDATE druid_segments SET used=false WHERE id = :segmentID", rewritten:"UPDATE druid_segments SET used=false WHERE id = ?", arguments:{ positional:{}, named:{segmentID:'content20stats_2016-09-12T00:00:00.000Z_2016-09-13T00:00:00.000Z_2016-09-12T00:00:00.136Z_10'}, finder:[]}]
org.skife.jdbi.v2.exceptions.CallbackFailedException: org.skife.jdbi.v2.exceptions.UnableToExecuteStatementException: java.sql.SQLException: Connection is read-only. Queries leading to data modification are not allowed [statement:"UPDATE druid_segments SET used=false WHERE id = :segmentID", located:"UPDATE druid_segments SET used=false WHERE id = :segmentID", rewritten:"UPDATE druid_segments SET used=false WHERE id = ?", arguments:{ positional:{}, named:{segmentID:'content20stats_2016-09-12T00:00:00.000Z_2016-09-13T00:00:00.000Z_2016-09-12T00:00:00.136Z_10'}, finder:[]}]

(even in this case I reported the complete stack trace in the previous post)

I am ingesting data from kafka using kafka supervisor. Druid version is 0.9.1 It does not seem to be loss of data.
In the previous post I said that the segments appearing in the error had already the value used=0 on the database because I did some manual operation in the past, but I have realized that this is not true for all the errors. Many of them report segments which have used=1 and that I did not touch in the past

Thanks,
Tommaso

Hi,
I am not a database expert, but on a quick look it seems the connection being set to read only may be related to the fact that transaction rollback failed.

Do you see the same exception when you set autocommit=false ?

I assume that autocommit=false should be set by the client on a connection basis. The only way to test it is to change it globally via a mysql server system variable, but unfortunately I can’t do it in a production environment. (and I am not able to reproduce in stage).