Scary 500 error while doing batch ingestion.

328 views

Skip to first unread message

Aman Gupta

unread,

Dec 4, 2015, 2:45:25 AM12/4/15

to Druid User

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

Himanshu Gupta

unread,

Dec 6, 2015, 1:11:39 AM12/6/15

to Druid User

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

Reply all

Reply to author

Forward

0 new messages