Scary 500 error while doing batch ingestion.

Hi,

Weird thing happening from yesterday.

I found out that ingestion stopped working. I bounced the overlord services and also other coordinator , historical and broker services twice but it is still the same.

Below error I am getting below error in ingestion logs.

2015-12-04T07:30:31,503 WARN [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Exception submitting action for task[index_spini_prod_v0_2015-12-04T07:30:04.980Z]
java.io.IOException: Scary HTTP status returned: 500 Server Error. Check your overlord[ip-172-31-24-214.ap-southeast-1.compute.internal:8090] logs for exceptions.
	at io.druid.indexing.common.actions.RemoteTaskActionClient.submit(RemoteTaskActionClient.java:121) [druid-indexing-service-0.8.1.jar:0.8.1]
	at io.druid.indexing.common.TaskToolbox.pushSegments(TaskToolbox.java:202) [druid-indexing-service-0.8.1.jar:0.8.1]
	at io.druid.indexing.common.task.IndexTask.run(IndexTask.java:215) [druid-indexing-service-0.8.1.jar:0.8.1]
	at io.druid.indexing.overlord.ThreadPoolTaskRunner$ThreadPoolTaskRunnerCallable.call(ThreadPoolTaskRunner.java:235) [druid-indexing-service-0.8.1.jar:0.8.1]
	at io.druid.indexing.overlord.ThreadPoolTaskRunner$ThreadPoolTaskRunnerCallable.call(ThreadPoolTaskRunner.java:214) [druid-indexing-service-0.8.1.jar:0.8.1]
	at java.util.concurrent.FutureTask.run(FutureTask.java:262) [?:1.7.0_91]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [?:1.7.0_91]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [?:1.7.0_91]
	at java.lang.Thread.run(Thread.java:745) [?:1.7.0_91]
2015-12-04T07:30:31,510 INFO [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Will try again in [PT56.420S].


So I looked into overlord logs and found errors as below.


0, 111, 110, 101, 34, 125, 44, 34, 98, 105, 110, 97, 114, 121, 86, 101, 114, 115, 105, 111, 110, 34, 58, 57, 44, 34, 115, 105, 122, 101, 34, 58, 56, 52, 52, 54, 52, 44, 34, 105, 100, 101, 110, 116, 105, 102, 105, 101, 114, 34, 58, 34, 115, 112, 105, 110, 105, 95, 112, 114, 111, 100, 95, 118, 48, 95, 50, 48, 49, 53, 45, 48, 55, 45, 51, 48, 84, 48, 48, 58, 48, 48, 58, 48, 48, 46, 48, 48, 48, 90, 95, 50, 48, 49, 53, 45, 48, 55, 45, 51, 49, 84, 48, 48, 58, 48, 48, 58, 48, 48, 46, 48, 48, 48, 90, 95, 50, 48, 49, 53, 45, 49, 50, 45, 48, 52, 84, 48, 55, 58, 51, 48, 58, 48, 52, 46, 57, 56, 53, 90, 34, 125],used:true,end:'2015-07-31T00:00:00.000Z',version:'2015-12-04T07:30:04.985Z'}, finder:[]}]

at org.skife.jdbi.v2.SQLStatement.internalExecute(SQLStatement.java:1306) ~[jdbi-2.32.jar:?]

at org.skife.jdbi.v2.Update.execute(Update.java:57) ~[jdbi-2.32.jar:?]

at io.druid.metadata.IndexerSQLMetadataStorageCoordinator.announceHistoricalSegment(IndexerSQLMetadataStorageCoordinator.java:183) ~[druid-server-0.8.1.jar:0.8.1]

at io.druid.metadata.IndexerSQLMetadataStorageCoordinator.access$200(IndexerSQLMetadataStorageCoordinator.java:55) ~[druid-server-0.8.1.jar:0.8.1]

at io.druid.metadata.IndexerSQLMetadataStorageCoordinator$3.inTransaction(IndexerSQLMetadataStorageCoordinator.java:156) ~[druid-server-0.8.1.jar:0.8.1]

at io.druid.metadata.IndexerSQLMetadataStorageCoordinator$3.inTransaction(IndexerSQLMetadataStorageCoordinator.java:149) ~[druid-server-0.8.1.jar:0.8.1]

at org.skife.jdbi.v2.BasicHandle.inTransaction(BasicHandle.java:319) ~[jdbi-2.32.jar:?]

at org.skife.jdbi.v2.DBI$4.withHandle(DBI.java:287) ~[jdbi-2.32.jar:?]

at org.skife.jdbi.v2.DBI.withHandle(DBI.java:259) ~[jdbi-2.32.jar:?]

... 60 more

Caused by: java.sql.SQLException: An SQL data change is not permitted for a read-only connection, user or database.

at org.apache.derby.client.am.SQLExceptionFactory.getSQLException(Unknown Source) ~[derbyclient-10.11.1.1.jar:?]

at org.apache.derby.client.am.SqlException.getSQLException(Unknown Source) ~[derbyclient-10.11.1.1.jar:?]

at org.apache.derby.client.am.ClientPreparedStatement.execute(Unknown Source) ~[derbyclient-10.11.1.1.jar:?]

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:1300) ~[jdbi-2.32.jar:?]

at org.skife.jdbi.v2.Update.execute(Update.java:57) ~[jdbi-2.32.jar:?]

at io.druid.metadata.IndexerSQLMetadataStorageCoordinator.announceHistoricalSegment(IndexerSQLMetadataStorageCoordinator.java:183) ~[druid-server-0.8.1.jar:0.8.1]

at io.druid.metadata.IndexerSQLMetadataStorageCoordinator.access$200(IndexerSQLMetadataStorageCoordinator.java:55) ~[druid-server-0.8.1.jar:0.8.1]

at io.druid.metadata.IndexerSQLMetadataStorageCoordinator$3.inTransaction(IndexerSQLMetadataStorageCoordinator.java:156) ~[druid-server-0.8.1.jar:0.8.1]

at io.druid.metadata.IndexerSQLMetadataStorageCoordinator$3.inTransaction(IndexerSQLMetadataStorageCoordinator.java:149) ~[druid-server-0.8.1.jar:0.8.1]

at org.skife.jdbi.v2.BasicHandle.inTransaction(BasicHandle.java:319) ~[jdbi-2.32.jar:?]

at org.skife.jdbi.v2.DBI$4.withHandle(DBI.java:287) ~[jdbi-2.32.jar:?]

at org.skife.jdbi.v2.DBI.withHandle(DBI.java:259) ~[jdbi-2.32.jar:?]

... 60 more

Caused by: org.apache.derby.client.am.SqlException: An SQL data change is not permitted for a read-only connection, user or database.

at org.apache.derby.client.am.ClientStatement.completeExecute(Unknown Source) ~[derbyclient-10.11.1.1.jar:?]

at org.apache.derby.client.net.NetStatementReply.parseEXCSQLSTTreply(Unknown Source) ~[derbyclient-10.11.1.1.jar:?]

at org.apache.derby.client.net.NetStatementReply.readExecute(Unknown Source) ~[derbyclient-10.11.1.1.jar:?]

at org.apache.derby.client.net.StatementReply.readExecute(Unknown Source) ~[derbyclient-10.11.1.1.jar:?]

at org.apache.derby.client.net.NetPreparedStatement.readExecute_(Unknown Source) ~[derbyclient-10.11.1.1.jar:?]

at org.apache.derby.client.am.ClientPreparedStatement.readExecute(Unknown Source) ~[derbyclient-10.11.1.1.jar:?]

at org.apache.derby.client.am.ClientPreparedStatement.flowExecute(Unknown Source) ~[derbyclient-10.11.1.1.jar:?]

at org.apache.derby.client.am.ClientPreparedStatement.executeX(Unknown Source) ~[derbyclient-10.11.1.1.jar:?]

at org.apache.derby.client.am.ClientPreparedStatement.execute(Unknown Source) ~[derbyclient-10.11.1.1.jar:?]

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:1300) ~[jdbi-2.32.jar:?]

at org.skife.jdbi.v2.Update.execute(Update.java:57) ~[jdbi-2.32.jar:?]

at io.druid.metadata.IndexerSQLMetadataStorageCoordinator.announceHistoricalSegment(IndexerSQLMetadataStorageCoordinator.java:183) ~[druid-server-0.8.1.jar:0.8.1]

at io.druid.metadata.IndexerSQLMetadataStorageCoordinator.access$200(IndexerSQLMetadataStorageCoordinator.java:55) ~[druid-server-0.8.1.jar:0.8.1]

at io.druid.metadata.IndexerSQLMetadataStorageCoordinator$3.inTransaction(IndexerSQLMetadataStorageCoordinator.java:156) ~[druid-server-0.8.1.jar:0.8.1]

at io.druid.metadata.IndexerSQLMetadataStorageCoordinator$3.inTransaction(IndexerSQLMetadataStorageCoordinator.java:149) ~[druid-server-0.8.1.jar:0.8.1]

at org.skife.jdbi.v2.BasicHandle.inTransaction(BasicHandle.java:319) ~[jdbi-2.32.jar:?]

at org.skife.jdbi.v2.DBI$4.withHandle(DBI.java:287) ~[jdbi-2.32.jar:?]

at org.skife.jdbi.v2.DBI.withHandle(DBI.java:259) ~[jdbi-2.32.jar:?]

... 60 more

2015-12-04T07:38:19,836 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 6 tasks from storage (0 tasks added, 0 tasks removed).

2015-12-04T07:39:19,837 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 6 tasks from storage (0 tasks added, 0 tasks removed).

2015-12-04T07:40:19,837 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 6 tasks from storage (0 tasks added, 0 tasks removed).

2015-12-04T07:41:19,837 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 6 tasks from storage (0 tasks added, 0 tasks removed).

2015-12-04T07:42:19,837 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 6 tasks from storage (0 tasks added, 0 tasks removed).

2015-12-04T07:43:19,838 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 6 tasks from storage (0 tasks added, 0 tasks removed).

Looking into this, I think derby connections still open of previous java process. So I bounced all the services back again.

Please help out urgently we will be going live this weekend.

Thanks,
Aman

Hi,

Found https://issues.apache.org/jira/browse/DERBY-5686 .

BTW, Derby is intended to be used for experimental setup only, I would strongly recommend to use mysql etc for the production.

– Himanshu