Overlord Exception While Announcing Historical Segments

Hi,

I am facing an exception in overlord in a production environment while announcing the Historical Segment.

It looks to me some sort of multi-threading issue (if thats possible ) as the segment is already present in the MetaData and still the “segmentExists” method (IndexerSQLMetadataStorageCoordinator.java+581) is returning “FALSE” on some of the times .

We are using druid-0.9.1 in our production.

Following is the Logs :

2017-08-08 06:15:02.534+0000 INFO io.druid.metadata.IndexerSQLMetadataStorageCoordinator Found [prod_report_ds_2017-08-08T05:00:00.000Z_2017-08-08T06:00:00.000Z_2017-08-08T05:00:04.589Z_5] in DB, not updating DB

2017-08-08 06:15:01.692+0000 ERROR io.druid.metadata.IndexerSQLMetadataStorageCoordinator Exception inserting segment[prod_report_ds_2017-08-08T05:00:00.000Z_2017-08-08T06:00:00.000Z_2017-08-08T05:00:04.589Z_5] into DB

org.skife.jdbi.v2.exceptions.UnableToExecuteStatementException: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint “druid_segments_pkey”

Detail: Key (id)=(prod_report_ds_2017-08-08T05:00:00.000Z_2017-08-08T06:00:00.000Z_2017-08-08T05:00:04.589Z_5) already exists.

Show all 89 lines

**2017-08-08 06:15:01.690+**0000 INFO [qtp1997290658-83] io.druid.metadata.IndexerSQLMetadataStorageCoordinator Published segment [prod_report_ds_2017-08-08T05:00:00.000Z_2017-08-08T06:00:00.000Z_2017-08-08T05:00:04.589Z_5] to DB

In above logs it is clear the the segment [prod_report_ds_2017-08-08T05:00:00.000Z_2017-08-08T06:00:00.000Z_2017-08-08T05:00:04.589Z_5] has already been inserted in the postgres (metadata) but still overlord throws an exception. Also the very first line (after around 1 minute difference), “segmentExists” would have returned true.

Note the time between last two logger lines , hardly in milliseconds. Is it possible that two thread would have come at this method (announceHistoricalSegment) and executed segmentExists without knowing about each other (Race Condition)

Could anyone please confirm about the above behavior ?

Thanks,

Pravesh Gupta

Any help would be appreciated.

Let me know if any more information is required from our end.

Thanks,

Pravesh Gupta

Hi Pravesh,
I have seen similar case before, it is possible for two replica tasks to hit this as they both try to publish the segments around the same time.

however, IIRC, this case is handled by making the replica task rety one more time when seeing the segment on next retry and then completes with SUCCESS.

Do you see any other issues with this ?

or just the exception being logged and task being able to succeed in the next try.

Hey Nishant,

Thanks for the reply.

Well indeed we are having two replica task in our case which might be causing this.

We do not see any functional impact with this, but logging an exception does raise alerts & concerns. The task are indeed getting succeeded , but as I mentioned in my original question , time difference between two threads trying to update the metastore (possibly these two threads are replica thread) is very very less. So it boils down to multithreading handling in the Code. I do not see anything specific being done in the code to handle this scenario (please note that this is happening continuously in our production enviroments).

I am assuming this scenario would have been seen by someone already while implementing this or code review. So any reason why there are no thread safety in that piece of code. I am talking about segmentExists(handle, segment) method being called outside of any synchronization block at Line No 581 of IndexerSQLMetadataStorageCoordinator class (Branch - origin/0.9.1)

Also , Is there any way to suppress this Exception assuming the exception is harmless. Because our elastic search job is sending alerts continuously in production environment ??

Thanks,

Pravesh Gupta

Hi,

Any help or confirmation here ?

Thanks,

Pravesh Gupta

Could anyone please confirm whether this exception is harmful or not in our scenario?

I have also raised an issue regarding this for tracking : https://github.com/druid-io/druid/issues/5025

Thanks,

Pravesh Gupta

Hi Pravesh,
The above exception is not harmful as the task is supposed to retry and eventually succeed.

Would be glad to accept a patch to handle this race condition in a better way.

Hi Pravesh,

Can you please try upgrading and seeing if you still face this issue? I seem to recall a fix for this landing sometime after 0.9.1.

Thanks Nishant for the confirmation.

Gian,

We will try upgrading the Druid and see if I still see the issue. However I do not see any special handling for races in latest codeBase.

Thanks,

Pravesh Gupta

IIRC this was fixed by implementing retries on failed segment publish transactions. When the transaction retries, the race should be gone (the segment should be recognized as existing) and so it should succeed at that time. At least, that’s what I recall…