search

apache / druid

Apache Druid: a high performance real-time analytics database.
https://druid.apache.org/
Apache License 2.0
13.47k stars 3.7k forks source link

Error posting segment to overlord indexer (null value in column) #15667

Open CoinCoderBuffalo opened 9 months ago

CoinCoderBuffalo commented 9 months ago

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
wjjpt commented 5 months ago

Hi @buffaloDeveloper , check this link for this issue:

https://github.com/apache/druid/issues/15326#28.0.0-upgrade-notes-and-incompatible-changes-upgrade-notes-upgrade-druid-segments-table (Upgrade notes and incompatible changes section)

There is a new column used_status_last_updated in the druid_segments table that cannot be null if the table has been created first time by Druid 28.0.0, but if this table is from a previous version, then Druid modify this table without the constraint (accepting segments without used_status_last_updated defined)