SQLException Connection is read-only
366 views
Skip to first unread message
Tommaso Parisi
Nov 2, 2016, 5:48:10 AM11/2/16
to Druid User
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 moreRegards,
Tommaso
Gian Merlino
Nov 2, 2016, 10:58:22 AM11/2/16
to druid...@googlegroups.com
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"?
Gian
--
You received this message because you are subscribed to the Google Groups "Druid User" group.
To unsubscribe from this group and stop receiving emails from it, send an email to druid-user+unsubscribe@googlegroups.com.
To post to this group, send email to druid...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/druid-user/5a6cc606-812f-439b-9e29-df41cd7241fa%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
Tommaso Parisi
Nov 2, 2016, 11:41:11 AM11/2/16
to Druid User
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]
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
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.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.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) ~[?:?]
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.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]
Gian
To unsubscribe from this group and stop receiving emails from it, send an email to druid-user+...@googlegroups.com.
Tommaso Parisi
Nov 16, 2016, 5:04:47 AM11/16/16
to Druid User
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
(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
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
Nishant Bangarwa
Nov 16, 2016, 6:12:51 AM11/16/16
to Druid User
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 ?
To view this discussion on the web visit https://groups.google.com/d/msgid/druid-user/5fefa623-0a0f-451a-9dfd-6b4230bee339%40googlegroups.com.
Tommaso Parisi
Nov 16, 2016, 6:49:26 AM11/16/16
to Druid User
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).
Reply all
Reply to author
Forward
0 new messages