Error posting segment to overlord indexer (null value in column)
- Dominant language
- Java
- Stars
- 14.1k
- Forks
- 3.8k
- Avg merge
- 2d 58m
- Merged PRs (30d)
- 233
Description
### Affected Version
Druid 27.0.0 running K8 using Druid-Operator.
### Description
Trying load some very simple json data. I see the segments get added to deep storage (S3/minio), but after that a 500 error is thrown when posting the segment to the Overlord indexer:
ERROR: null value in column \"used_status_last_updated\" of relation \"druid_segments\" violates not-null constraint
Here's the full log:
```
2024-01-11T16:15:16,613 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.wire - http-outgoing-0 << "Server: MinIO[\r][\n]"
2024-01-11T16:15:16,613 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.wire - http-outgoing-0 << "Strict-Transport-Security: max-age=31536000; includeSubDomains[\r][\n]"
2024-01-11T16:15:16,613 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.wire - http-outgoing-0 << "Vary: Origin[\r][\n]"
2024-01-11T16:15:16,613 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.wire - http-outgoing-0 << "Vary: Accept-Encoding[\r][\n]"
2024-01-11T16:15:16,613 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.wire - http-outgoing-0 << "X-Amz-Bucket-Region: us-east-1[\r][\n]"
2024-01-11T16:15:16,613 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.wire - http-outgoing-0 << "X-Amz-Request-Id: 17A9571D23D08D46[\r][\n]"
2024-01-11T16:15:16,613 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.wire - http-outgoing-0 << "X-Content-Type-Options: nosniff[\r][\n]"
2024-01-11T16:15:16,613 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.wire - http-outgoing-0 << "X-Xss-Protection: 1; mode=block[\r][\n]"
2024-01-11T16:15:16,613 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.wire - http-outgoing-0 << "Date: Thu, 11 Jan 2024 16:15:16 GMT[\r][\n]"
2024-01-11T16:15:16,613 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.wire - http-outgoing-0 << "[\r][\n]"
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.headers - http-outgoing-0 << HTTP/1.1 200 OK
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.headers - http-outgoing-0 << Accept-Ranges: bytes
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.headers - http-outgoing-0 << Content-Length: 0
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.headers - http-outgoing-0 << Content-Security-Policy: block-all-mixed-content
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.headers - http-outgoing-0 << ETag: "bf2dba2b3e2d62524b8be307d0550cde"
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.headers - http-outgoing-0 << Server: MinIO
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.headers - http-outgoing-0 << Strict-Transport-Security: max-age=31536000; includeSubDomains
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.headers - http-outgoing-0 << Vary: Origin
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.headers - http-outgoing-0 << Vary: Accept-Encoding
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.headers - http-outgoing-0 << X-Amz-Bucket-Region: us-east-1
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.headers - http-outgoing-0 << X-Amz-Request-Id: 17A9571D23D08D46
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.headers - http-outgoing-0 << X-Content-Type-Options: nosniff
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.headers - http-outgoing-0 << X-Xss-Protection: 1; mode=block
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.headers - http-outgoing-0 << Date: Thu, 11 Jan 2024 16:15:16 GMT
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.impl.execchain.MainClientExec - Connection can be kept alive for 60000 MILLISECONDS
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection [id: 0][route: {}->http://minio.core-platform-services:39000] can be kept alive for 60.0 seconds
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.impl.conn.DefaultManagedHttpClientConnection - http-outgoing-0: set socket timeout to 0
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection released: [id: 0][route: {}->http://minio.core-platform-services:39000][total available: 1; route allocated: 1 of 50; total allocated: 1 of 50]
2024-01-11T16:15:16,614 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] com.amazonaws.retry.ClockSkewAdjuster - Reported server date (from 'Date' header): Thu, 11 Jan 2024 16:15:16 GMT
2024-01-11T16:15:16,615 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] com.amazonaws.request - Received successful response: 200, AWS Request ID: 17A9571D23D08D46
2024-01-11T16:15:16,615 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] com.amazonaws.requestId - x-amzn-RequestId: not available
2024-01-11T16:15:16,615 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] com.amazonaws.requestId - AWS Request ID: 17A9571D23D08D46
2024-01-11T16:15:16,618 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.druid.storage.s3.S3DataSegmentPusher - Deleting temporary cached index.zip
2024-01-11T16:15:16,650 INFO [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.druid.segment.realtime.appenderator.AppenderatorImpl - Segment[inline_data_2010-01-01T00:00:00.000Z_2010-01-02T00:00:00.000Z_2024-01-11T16:15:15.684Z] of 876 bytes built from 1 incremental persist(s) in 136ms; pushed to deep storage in 310ms. Load spec is: {"type":"s3_zip","bucket":"tradeinfluence","key":"druid/segments/inline_data/2010-01-01T00:00:00.000Z_2010-01-02T00:00:00.000Z/2024-01-11T16:15:15.684Z/0/index.zip","S3Schema":"s3n"}
2024-01-11T16:15:16,650 INFO [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-merge] org.apache.druid.segment.realtime.appenderator.AppenderatorImpl - Push complete...
2024-01-11T16:15:16,656 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-publish] org.apache.druid.segment.realtime.appenderator.BaseAppenderatorDriver - Dropping segments: [inline_data_2010-01-01T00:00:00.000Z_2010-01-02T00:00:00.000Z_2024-01-11T16:15:15.684Z]
2024-01-11T16:15:16,663 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-persist] org.apache.druid.segment.realtime.appenderator.AppenderatorImpl - Removing commit metadata for segment[inline_data_2010-01-01T00:00:00.000Z_2010-01-02T00:00:00.000Z_2024-01-11T16:15:15.684Z].
2024-01-11T16:15:16,680 INFO [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-appenderator-persist] org.apache.druid.segment.realtime.appenderator.AppenderatorImpl - Dropped segment[inline_data_2010-01-01T00:00:00.000Z_2010-01-02T00:00:00.000Z_2024-01-11T16:15:15.684Z].
2024-01-11T16:15:16,685 DEBUG [task-runner-0-priority-0] org.apache.druid.indexing.common.task.InputSourceProcessor - Pushed segments: [inline_data_2010-01-01T00:00:00.000Z_2010-01-02T00:00:00.000Z_2024-01-11T16:15:15.684Z]
2024-01-11T16:15:16,700 DEBUG [[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]-publish] org.apache.druid.indexing.common.actions.RemoteTaskActionClient - Performing action for task[index_parallel_inline_data_blblegcd_2024-01-11T16:15:08.010Z]: SegmentTransactionalInsertAction{segmentsToBeOverwritten=null, segments=[inline_data_2010-01-01T00:00:00.000Z_2010-01-02T00:00:00.000Z_2024-01-11T16:15:15.684Z], startMetadata=null, endMetadata=null, dataSource='null', segmentsToBeDropped=null}
2024-01-11T16:15:16,715 DEBUG [ServiceClientFactory-2] org.apache.druid.rpc.ServiceClientImpl - Service [OVERLORD] request [POST http://192.168.156.197:8088/druid/indexer/v1/action] starting.
2024-01-11T16:15:16,716 DEBUG [ServiceClientFactory-2] org.apache.druid.java.util.http.client.NettyHttpClient - [POST http://192.168.156.197:8088/druid/indexer/v1/action] starting
2024-01-11T16:15:16,716 TRACE [ServiceClientFactory-2] org.apache.druid.java.util.http.client.pool.ChannelResourceFactory - isGood = isSucess[true] && isConnected[true] && isOpen[true]
2024-01-11T16:15:16,763 DEBUG [HttpClient-Netty-Worker-2] org.apache.druid.java.util.http.client.NettyHttpClient - [POST http://192.168.156.197:8088/druid/indexer/v1/action] messageReceived: DefaultHttpResponse(chunked: true)
HTTP/1.1 500 Internal Server Error
Date: Thu, 11 Jan 2024 16:15:16 GMT
Content-Type: application/json
Transfer-Encoding: chunked
2024-01-11T16:15:16,764 DEBUG [HttpClient-Netty-Worker-2] org.apache.druid.java.util.http.client.NettyHttpClient - [POST http://192.168.156.197:8088/druid/indexer/v1/action] Got response: 500 Internal Server Error
2024-01-11T16:15:16,769 DEBUG [HttpClient-Netty-Worker-2] org.apache.druid.java.util.http.client.NettyHttpClient - [POST http://192.168.156.197:8088/druid/indexer/v1/action] messageReceived: org.jboss.netty.handler.codec.http.DefaultHttpChunk@6ec6ea2a
2024-01-11T16:15:16,769 DEBUG [HttpClient-Netty-Worker-2] org.apache.druid.java.util.http.client.NettyHttpClient - [POST http://192.168.156.197:8088/druid/indexer/v1/action] Got chunk: 4038B, last=false
2024-01-11T16:15:16,770 DEBUG [HttpClient-Netty-Worker-2] org.apache.druid.java.util.http.client.NettyHttpClient - [POST http://192.168.156.197:8088/druid/indexer/v1/action] messageReceived: org.jboss.netty.handler.codec.http.HttpChunk$1@76ded591
2024-01-11T16:15:16,770 DEBUG [HttpClient-Netty-Worker-2] org.apache.druid.java.util.http.client.NettyHttpClient - [POST http://192.168.156.197:8088/druid/indexer/v1/action] Got chunk: 0B, last=true
2024-01-11T16:15:16,774 INFO [ServiceClientFactory-0] org.apache.druid.rpc.ServiceClientImpl - Service [OVERLORD] request [POST http://192.168.156.197:8088/druid/indexer/v1/action] encountered server error [500 Internal Server Error] on attempt #1; retrying in 5,000 ms; first 1KB of body: {"error":"java.lang.RuntimeException: org.skife.jdbi.v2.exceptions.CallbackFailedException: org.skife.jdbi.v2.exceptions.UnableToExecuteStatementException: java.sql.BatchUpdateException: Batch entry 0 INSERT INTO druid_segments (id, dataSource, created_date, start, \"end\", partitioned, version, used, payload) VALUES ('inline_data_2010-01-01T00:00:00.000Z_2010-01-02T00:00:00.000Z_2024-01-11T16:15:15.684Z', 'inline_data', '2024-01-11T16:15:16.744Z', '2010-01-01T00:00:00.000Z', '2010-01-02T00:00:00.000Z', 'TRUE', '2024-01-11T16:15:15.684Z', 'TRUE', ?) was aborted: ERROR: null value in column \"used_status_last_updated\" of relation \"druid_segments\" violates not-null constraint\n Detail: Failing row contains (inline_data_2010-01-01T00:00:00.000Z_2010-01-02T00:00:00.000Z_20..., inline_data, 2024-01-11T16:15:16.744Z, 2010-01-01T00:00:00.000Z, 2010-01-02T00:00:00.000Z, t, 2024-01-11T16:15:15.684Z, t, \\x7b2264617461536f75726365223a22696e6c696e655f64617461222c22696e..., null). Call getNex
2024-01-11T16:15:21,778 DEBUG [ServiceClientFactory-0] org.apache.druid.rpc.ServiceClientImpl - Service [OVERLORD] request [POST http://192.168.156.197:8088/druid/indexer/v1/action] starting.
2024-01-11T16:15:21,778 DEBUG [ServiceClientFactory-0] org.apache.druid.java.util.http.client.NettyHttpClient - [POST http://192.168.156.197:8088/druid/indexer/v1/action] starting
2024-01-11T16:15:21,778 TRACE [ServiceClientFactory-0] org.apache.druid.java.util.http.client.pool.ChannelResourceFactory - isGood = isSucess[true] && isConnected[true] && isOpen[true]
2024-01-11T16:15:21,821 DEBUG [HttpClient-Netty-Worker-3] org.apache.druid.java.util.http.client.NettyHttpClient - [POST http://192.168.156.197:8088/druid/indexer/v1/action] messageReceived: DefaultHttpResponse(chunked: true)
HTTP/1.1 500 Internal Server Error
Date: Thu, 11 Jan 2024 16:15:21 GMT
Content-Type: application/json
Transfer-Encoding: chunked
2024-01-11T16:15:21,822 DEBUG [HttpClient-Netty-Worker-3] org.apache.druid.java.util.http.client.NettyHttpClient - [POST http://192.168.156.197:8088/druid/indexer/v1/action] Got response: 500 Internal Server Error
2024-01-11T16:15:21,822 DEBUG [HttpClient-Netty-Worker-3] org.apache.druid.java.util.http.client.NettyHttpClient - [POST http://192.168.156.197:8088/druid/indexer/v1/action] messageReceived: org.jboss.netty.handler.codec.http.DefaultHttpChunk@37d0644
2024-01-11T16:15:21,822 DEBUG [HttpClient-Netty-Worker-3] org.apache.druid.java.util.http.client.NettyHttpClient - [POST http://192.168.156.197:8088/druid/indexer/v1/action] Got chunk: 4038B, last=false
2024-01-11T16:15:21,823 DEBUG [HttpClient-Netty-Worker-3] org.apache.druid.java.util.http.client.NettyHttpClient - [POST http://192.168.156.197:8088/druid/indexer/v1/action] messageReceived: org.jboss.netty.handler.codec.http.HttpChunk$1@76ded591
2024-01-11T16:15:21,823 DEBUG [HttpClient-Netty-Worker-3] org.apache.druid.java.util.http.client.NettyHttpClient - [POST http://192.168.156.197:8088/druid/indexer/v1/action] Got chunk: 0B, last=true
2024-01-11T16:15:21,826 INFO [ServiceClientFactory-2] org.apache.druid.rpc.ServiceClientImpl - Service [OVERLORD] request [POST http://192.168.156.197:8088/druid/indexer/v1/action] encountered server error [500 Internal Server Error] on attempt #2; retrying in 10,000 ms; first 1KB of body: {"error":"java.lang.RuntimeException: org.skife.jdbi.v2.exceptions.CallbackFailedException: org.skife.jdbi.v2.exceptions.UnableToExecuteStatementException: java.sql.BatchUpdateException: Batch entry 0 INSERT INTO druid_segments (id, dataSource, created_date, start, \"end\", partitioned, version, used, payload) VALUES ('inline_data_2010-01-01T00:00:00.000Z_2010-01-02T00:00:00.000Z_2024-01-11T16:15:15.684Z', 'inline_data', '2024-01-11T16:15:21.804Z', '2010-01-01T00:00:00.000Z', '2010-01-02T00:00:00.000Z', 'TRUE', '2024-01-11T16:15:15.684Z', 'TRUE', ?) was aborted: ERROR: null value in column \"used_status_last_updated\" of relation \"druid_segments\" violates not-null constraint\n Detail: Failing row contains (inline_data_2010-01-01T00:00:00.000Z_2010-01-02T00:00:00.000Z_20..., inline_data, 2024-01-11T16:15:21.804Z, 2010-01-01T00:00:00.000Z, 2010-01-02T00:00:00.000Z, t, 2024-01-11T16:15:15.684Z, t, \\x7b2264617461536f75726365223a22696e6c696e655f64617461222c22696e..., null). Call getNex
2024-01-11T16:15:25,165 DEBUG [main-SendThread(tiny-cluster-zk-0.tiny-cluster-zk:2181)] org.apache.zookeeper.ClientCnxn - Got ping response for sessionid: 0x10001f85fff0014 after 3ms
```
Contributor guide
Research direction
Start with the Druid 27.0.0 Overlord request at POST /druid/indexer/v1/action and the segment publish log showing the INSERT into druid_segments. Investigate why used_status_last_updated is null when the segment is posted, then verify that publishing the sample segment no longer returns the 500 constraint error.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- java
- Domain
- backend, databases
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100