Skip to content

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

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

Description

@AppLetico
AppLetico
opened on Jan 11, 2024

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

Activity

  1. AppLetico
    added
    Uncategorized problem report
    on Jan 11, 2024
  2. asdf2014
    added
    Bug
    Kubernetes
    and removed
    Uncategorized problem report
    on Jan 16, 2024

  3. wjjpt commented on May 2, 2024

    @wjjpt
    wjjpt
    on May 2, 2024

    Hi @buffaloDeveloper , check this link for this issue:

    #15326 (comment) (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)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    BugKubernetes

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions