Clean up logs for batch segment allocation #14727

kfaraz · 2023-08-01T13:57:53Z

Motivation

Batch segment allocation is often difficult to debug due to the actual error messages being hidden in the logs.

Changes

Update signature of method IndexerMetadataStorageCoordinator.allocatePendingSegments to return List<SegmentAllocateResult> instead of just the allocated SegmentIdWithShardSpec
Propagate the encountered error all the way back to the SegmentAllocationQueue where it is logged when abandoning a request.
Simplify the logs and error messages
Reduce log level and remove logs where information is not useful for debugging
Rename some methods for clarity
No functional change

Old logs in case of a conflicting segment

2023-08-01T14:09:15,209 INFO [main] org.apache.druid.indexing.overlord.TaskLockbox - Allocating [1] segments for datasource [wiki], interval [2022-01-01T00:00:00.000Z/2022-01-01T00:30:00.000Z]
2023-08-01T14:09:15,290 WARN [main] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[wiki], interval[2022-01-01T00:00:00.000Z/2022-01-01T00:30:00.000Z], existingVersion[2023-08-01T14:09:15.046Z]: conflicting segment[wiki_2022-01-01T00:00:00.000Z_2022-01-01T01:00:00.000Z_2023-08-01T14:09:15.046Z].
2023-08-01T14:09:15,290 INFO [main] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Created [0] new segments for [1] allocate requests.
2023-08-01T14:09:15,291 INFO [main] org.apache.druid.indexing.common.actions.SegmentAllocationQueue - Allocation failed on attempt [1] due to error [Storage coordinator could not allocate segment.]. Can still retry action [SegmentAllocateAction{dataSource='wiki', timestamp=2022-01-01T00:00:00.000Z, queryGranularity={type=period, period=PT1S, timeZone=UTC, origin=null}, preferredSegmentGranularity={type=period, period=PT30M, timeZone=UTC, origin=null}, sequenceName='noop_2023-08-01T14:09:15.017Z_7d445db1-640c-4943-af64-3ed055493eae', previousSegmentId='null', skipSegmentLineageCheck=false, partialShardSpec=org.apache.druid.timeline.partition.NumberedPartialShardSpec@557b6a37, lockGranularity=TIME_CHUNK}].
2023-08-01T14:09:15,291 INFO [main] org.apache.druid.indexing.overlord.TaskLockbox - Allocating [1] segments for datasource [wiki], interval [2022-01-01T00:00:00.000Z/2022-01-01T00:15:00.000Z]
2023-08-01T14:09:15,295 WARN [main] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[wiki], interval[2022-01-01T00:00:00.000Z/2022-01-01T00:15:00.000Z], existingVersion[2023-08-01T14:09:15.046Z]: conflicting segment[wiki_2022-01-01T00:00:00.000Z_2022-01-01T01:00:00.000Z_2023-08-01T14:09:15.046Z].
2023-08-01T14:09:15,295 INFO [main] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Created [0] new segments for [1] allocate requests.
2023-08-01T14:09:15,296 INFO [main] org.apache.druid.indexing.common.actions.SegmentAllocationQueue - Allocation failed on attempt [2] due to error [Storage coordinator could not allocate segment.]. Can still retry action [SegmentAllocateAction{dataSource='wiki', timestamp=2022-01-01T00:00:00.000Z, queryGranularity={type=period, period=PT1S, timeZone=UTC, origin=null}, preferredSegmentGranularity={type=period, period=PT30M, timeZone=UTC, origin=null}, sequenceName='noop_2023-08-01T14:09:15.017Z_7d445db1-640c-4943-af64-3ed055493eae', previousSegmentId='null', skipSegmentLineageCheck=false, partialShardSpec=org.apache.druid.timeline.partition.NumberedPartialShardSpec@557b6a37, lockGranularity=TIME_CHUNK}].
2023-08-01T14:09:15,296 INFO [main] org.apache.druid.indexing.overlord.TaskLockbox - Allocating [1] segments for datasource [wiki], interval [2022-01-01T00:00:00.000Z/2022-01-01T00:10:00.000Z]
2023-08-01T14:09:15,299 WARN [main] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[wiki], interval[2022-01-01T00:00:00.000Z/2022-01-01T00:10:00.000Z], existingVersion[2023-08-01T14:09:15.046Z]: conflicting segment[wiki_2022-01-01T00:00:00.000Z_2022-01-01T01:00:00.000Z_2023-08-01T14:09:15.046Z].
2023-08-01T14:09:15,299 INFO [main] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Created [0] new segments for [1] allocate requests.
2023-08-01T14:09:15,300 INFO [main] org.apache.druid.indexing.common.actions.SegmentAllocationQueue - Allocation failed on attempt [3] due to error [Storage coordinator could not allocate segment.]. Can still retry action [SegmentAllocateAction{dataSource='wiki', timestamp=2022-01-01T00:00:00.000Z, queryGranularity={type=period, period=PT1S, timeZone=UTC, origin=null}, preferredSegmentGranularity={type=period, period=PT30M, timeZone=UTC, origin=null}, sequenceName='noop_2023-08-01T14:09:15.017Z_7d445db1-640c-4943-af64-3ed055493eae', previousSegmentId='null', skipSegmentLineageCheck=false, partialShardSpec=org.apache.druid.timeline.partition.NumberedPartialShardSpec@557b6a37, lockGranularity=TIME_CHUNK}].
2023-08-01T14:09:15,300 INFO [main] org.apache.druid.indexing.overlord.TaskLockbox - Allocating [1] segments for datasource [wiki], interval [2022-01-01T00:00:00.000Z/2022-01-01T00:05:00.000Z]
2023-08-01T14:09:15,304 WARN [main] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[wiki], interval[2022-01-01T00:00:00.000Z/2022-01-01T00:05:00.000Z], existingVersion[2023-08-01T14:09:15.046Z]: conflicting segment[wiki_2022-01-01T00:00:00.000Z_2022-01-01T01:00:00.000Z_2023-08-01T14:09:15.046Z].
2023-08-01T14:09:15,305 INFO [main] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Created [0] new segments for [1] allocate requests.
2023-08-01T14:09:15,305 ERROR [main] org.apache.druid.indexing.common.actions.SegmentAllocationQueue - Exhausted max attempts [4] for allocation with latest error [Storage coordinator could not allocate segment.]. Completing action [SegmentAllocateAction{dataSource='wiki', timestamp=2022-01-01T00:00:00.000Z, queryGranularity={type=period, period=PT1S, timeZone=UTC, origin=null}, preferredSegmentGranularity={type=period, period=PT30M, timeZone=UTC, origin=null}, sequenceName='noop_2023-08-01T14:09:15.017Z_7d445db1-640c-4943-af64-3ed055493eae', previousSegmentId='null', skipSegmentLineageCheck=false, partialShardSpec=org.apache.druid.timeline.partition.NumberedPartialShardSpec@557b6a37, lockGranularity=TIME_CHUNK}] with a null value.
2023-08-01T14:09:15,305 INFO [main] org.apache.druid.indexing.common.actions.SegmentAllocationQueue - Successfully processed [0 / 1] requests in batch [{datasource='wiki', groupId='group_1', batchId=0, lock=TIME_CHUNK, allocInterval=2022-01-01T00:00:00.000Z/2022-01-01T00:30:00.000Z, skipLineageCheck=false}].

New logs in case of a conflicting segment

2023-08-01T14:06:23,709 INFO [main] org.apache.druid.indexing.overlord.TaskLockbox - Allocating [1] segments for datasource[wiki], interval[2022-01-01T00:00:00.000Z/2022-01-01T00:30:00.000Z].
2023-08-01T14:06:23,774 INFO [main] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Created [0] new segments for [1] allocate requests.
2023-08-01T14:06:23,775 INFO [main] org.apache.druid.indexing.overlord.TaskLockbox - Allocating [1] segments for datasource[wiki], interval[2022-01-01T00:00:00.000Z/2022-01-01T00:15:00.000Z].
2023-08-01T14:06:23,781 INFO [main] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Created [0] new segments for [1] allocate requests.
2023-08-01T14:06:23,781 INFO [main] org.apache.druid.indexing.overlord.TaskLockbox - Allocating [1] segments for datasource[wiki], interval[2022-01-01T00:00:00.000Z/2022-01-01T00:10:00.000Z].
2023-08-01T14:06:23,787 INFO [main] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Created [0] new segments for [1] allocate requests.
2023-08-01T14:06:23,787 INFO [main] org.apache.druid.indexing.overlord.TaskLockbox - Allocating [1] segments for datasource[wiki], interval[2022-01-01T00:00:00.000Z/2022-01-01T00:05:00.000Z].
2023-08-01T14:06:23,793 INFO [main] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Created [0] new segments for [1] allocate requests.
2023-08-01T14:06:23,793 ERROR [main] org.apache.druid.indexing.common.actions.SegmentAllocationQueue - Failed allocation attempt[4/4] for task[noop_2023-08-01T14:06:23.541Z_647e2788-8667-43cc-b762-6a8aa3b74697], batch[{datasource='wiki', groupId='group_1', batchId=0, lock=TIME_CHUNK, allocInterval=2022-01-01T00:00:00.000Z/2022-01-01T00:30:00.000Z, skipLineageCheck=false}]: Segment[wiki_2022-01-01T00:00:00.000Z_2022-01-01T01:00:00.000Z_2023-08-01T14:06:23.577Z] in conflicting interval[2022-01-01T00:00:00.000Z/2022-01-01T01:00:00.000Z] has higher version[2023-08-01T14:06:23.577Z].
2023-08-01T14:06:23,794 INFO [main] org.apache.druid.indexing.common.actions.SegmentAllocationQueue - Successfully processed [0/1] requests in batch[{datasource='wiki', groupId='group_1', batchId=0, lock=TIME_CHUNK, allocInterval=2022-01-01T00:00:00.000Z/2022-01-01T00:30:00.000Z, skipLineageCheck=false}].

This PR has:

AmatyaAvadhanula · 2023-08-28T03:50:35Z

server/src/main/java/org/apache/druid/metadata/IndexerSQLMetadataStorageCoordinator.java

-          existingVersion,
-          overallMaxId
+      return SegmentAllocateResult.failure(
+          "Segment[%s] in conflicting interval[%s] has higher version[%s].",


This error message is inaccurate. It's also possible that the interval corresponding to overallMaxId isn't the same as the request's interval.

Thanks for catching this, I will break it up.

AmatyaAvadhanula · 2023-08-28T03:52:04Z

server/src/main/java/org/apache/druid/indexing/overlord/SegmentCreateRequest.java

+ * <p>
+ * This class does not implement equals() or hashCode() so that each request is
+ * treated as unique even if all the parameters are the same.
+ * TODO: why??


Is this pending or a leftover comment?

AmatyaAvadhanula · 2023-08-28T03:56:53Z

server/src/main/java/org/apache/druid/metadata/IndexerSQLMetadataStorageCoordinator.java

      );
-      return null;
    } else if (committedMaxId != null
               && committedMaxId.getShardSpec().getNumCorePartitions()
                  == SingleDimensionShardSpec.UNKNOWN_NUM_CORE_PARTITIONS) {
      log.warn(


Is this log needed if the SegmentAllocationResult's failure logs the message as well?

…essage

github-actions · 2024-02-16T00:16:34Z

This pull request has been marked as stale due to 60 days of inactivity.
It will be closed in 4 weeks if no further activity occurs. If you think
that's incorrect or this pull request should instead be reviewed, please simply
write any comment. Even if closed, you can still revive the PR at any time or
discuss it on the [email protected] list.
Thank you for your contributions.

github-actions · 2024-04-24T00:16:31Z

This pull request has been marked as stale due to 60 days of inactivity.
It will be closed in 4 weeks if no further activity occurs. If you think
that's incorrect or this pull request should instead be reviewed, please simply
write any comment. Even if closed, you can still revive the PR at any time or
discuss it on the [email protected] list.
Thank you for your contributions.

github-actions · 2024-06-26T00:17:09Z

This pull request has been marked as stale due to 60 days of inactivity.
It will be closed in 4 weeks if no further activity occurs. If you think
that's incorrect or this pull request should instead be reviewed, please simply
write any comment. Even if closed, you can still revive the PR at any time or
discuss it on the [email protected] list.
Thank you for your contributions.

kfaraz · 2024-06-27T05:14:24Z

Closed this PR as there are several merge conflicts now.

Clean up logs for batch segment allocation

69e7afd

kfaraz added Error handling Area - Ingestion labels Aug 1, 2023

kfaraz requested a review from abhishekagarwal87 August 1, 2023 13:58

kfaraz added 2 commits August 1, 2023 19:38

Minor fixes

d34736e

temp changes

09f4403

AmatyaAvadhanula reviewed Aug 28, 2023

View reviewed changes

kfaraz added 2 commits August 28, 2023 10:07

Merge branch 'master' of github.com:apache/druid into fix_seg_alloc_m…

45711fc

…essage

Update message

ea92550

github-actions bot added the stale label Feb 16, 2024

kfaraz removed the stale label Feb 23, 2024

github-actions bot added the stale label Apr 24, 2024

kfaraz removed the stale label Apr 26, 2024

kfaraz marked this pull request as draft April 26, 2024 15:02

github-actions bot added the stale label Jun 26, 2024

kfaraz closed this Jun 27, 2024

kfaraz reopened this Jun 27, 2024

kfaraz removed the stale label Jun 27, 2024

kfaraz closed this Jun 27, 2024

kfaraz deleted the fix_seg_alloc_message branch June 27, 2024 05:14

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Clean up logs for batch segment allocation #14727

Clean up logs for batch segment allocation #14727

kfaraz commented Aug 1, 2023 •

edited

Loading

AmatyaAvadhanula Aug 28, 2023

kfaraz Aug 28, 2023

AmatyaAvadhanula Aug 28, 2023

AmatyaAvadhanula Aug 28, 2023

kfaraz Aug 28, 2023

github-actions bot commented Feb 16, 2024

github-actions bot commented Apr 24, 2024

github-actions bot commented Jun 26, 2024

kfaraz commented Jun 27, 2024

Clean up logs for batch segment allocation #14727

Clean up logs for batch segment allocation #14727

Conversation

kfaraz commented Aug 1, 2023 • edited Loading

Motivation

Changes

Old logs in case of a conflicting segment

New logs in case of a conflicting segment

AmatyaAvadhanula Aug 28, 2023

Choose a reason for hiding this comment

kfaraz Aug 28, 2023

Choose a reason for hiding this comment

AmatyaAvadhanula Aug 28, 2023

Choose a reason for hiding this comment

AmatyaAvadhanula Aug 28, 2023

Choose a reason for hiding this comment

kfaraz Aug 28, 2023

Choose a reason for hiding this comment

github-actions bot commented Feb 16, 2024

github-actions bot commented Apr 24, 2024

github-actions bot commented Jun 26, 2024

kfaraz commented Jun 27, 2024

kfaraz commented Aug 1, 2023 •

edited

Loading