Uploaded image for project: 'Couchbase Server'
  1. Couchbase Server
  2. MB-62825

[System Test] [Intermittent] External source error. org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body

    XMLWordPrintable

Details

    • Untriaged
    • 0
    • Unknown
    • Analytics Sprint 47, Analytics Sprint 48

    Description

      A couple of times during the run, the copy from S3 query has run into errors. The logs say these - 

       

       

      Occurrence number 1

       

      2024-07-20T17:01:41.519+00:00 WARN CBAS.apache.asterix [Executor-404:ClusterController] ASX1108: External source error. org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 181,133,562; received: 21,168,044)
      		 
      org.apache.hyracks.api.exceptions.HyracksDataException: ASX1108: External source error. org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 181,133,562; received: 21,168,044)
      		 
          at org.apache.hyracks.api.exceptions.HyracksDataException.create(HyracksDataException.java:70) ~[hyracks-api.jar:1.0.0-2230]
      		 
          at org.apache.hyracks.api.util.ExceptionUtils.setNodeIds(ExceptionUtils.java:70) ~[hyracks-api.jar:1.0.0-2230]
      		 
          at org.apache.hyracks.control.nc.Task.run(Task.java:398) ~[hyracks-control-nc.jar:1.0.0-2230]
      		 
          at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
      		 
          at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
      		 
          at java.base/java.lang.Thread.run(Thread.java:840) [?:?]
      		 
      Caused by: org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 181,133,562; received: 21,168,044)
      		 
          at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:178) ~[httpcore-4.4.16.jar:4.4.16]
      		 
          at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:135) ~[httpclient-4.5.14.jar:4.5.14]
      		 
          at java.base/java.io.FilterInputStream.read(FilterInputStream.java:132) ~[?:?]
      		 
          at software.amazon.awssdk.services.s3.internal.checksums.S3ChecksumValidatingInputStream.read(S3ChecksumValidatingInputStream.java:112) ~[s3-2.24.9.jar:?]
      		 
          at java.base/java.io.FilterInputStream.read(FilterInputStream.java:132) ~[?:?]
      		 
          at software.amazon.awssdk.core.io.SdkFilterInputStream.read(SdkFilterInputStream.java:66) ~[sdk-core-2.24.9.jar:?]
      		 
          at software.amazon.awssdk.core.internal.metrics.BytesReadTrackingInputStream.read(BytesReadTrackingInputStream.java:49) ~[sdk-core-2.24.9.jar:?]
      		 
          at java.base/java.io.FilterInputStream.read(FilterInputStream.java:132) ~[?:?]
      		 
          at software.amazon.awssdk.core.io.SdkFilterInputStream.read(SdkFilterInputStream.java:66) ~[sdk-core-2.24.9.jar:?]
      		 
          at org.apache.asterix.external.input.stream.AbstractMultipleInputStream.read(AbstractMultipleInputStream.java:66) ~[asterix-external-data.jar:1.0.0-2230]
      		 
          at org.apache.asterix.external.input.stream.AsterixInputStreamReader.read(AsterixInputStreamReader.java:99) ~[asterix-external-data.jar:1.0.0-2230]
      		 
          at org.apache.asterix.external.input.stream.AsterixInputStreamReader.read(AsterixInputStreamReader.java:69) ~[asterix-external-data.jar:1.0.0-2230]
      		 
          at org.apache.asterix.external.input.record.reader.stream.LineRecordReader.hasNext(LineRecordReader.java:115) ~[asterix-external-data.jar:1.0.0-2230]
      		 
          at org.apache.asterix.external.dataflow.RecordDataFlowController.start(RecordDataFlowController.java:56) ~[asterix-external-data.jar:1.0.0-2230]
      		 
          at org.apache.asterix.external.dataset.adapter.GenericAdapter.start(GenericAdapter.java:38) ~[asterix-external-data.jar:1.0.0-2230]
      		 
          at org.apache.asterix.external.operators.ExternalScanOperatorDescriptor$1.initialize(ExternalScanOperatorDescriptor.java:80) ~[asterix-external-data.jar:1.0.0-2230]
      		 
          at org.apache.hyracks.api.rewriter.runtime.SuperActivityOperatorNodePushable.lambda$runInParallel$0(SuperActivityOperatorNodePushable.java:233) ~[hyracks-api.jar:1.0.0-2230]
      		 
          at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
      		 
          ... 3 more
      		 
      2024-07-20T17:01:41.520+00:00 INFO CBAS.work.JobCleanupWork [Worker:ClusterController] cleaning up JID:0.2711 on NCs, status=FAILURE

       

       

      Occurrence number 2 

      2024-07-20T17:31:06.160+00:00 WARN CBAS.apache.asterix [Executor-404:ClusterController] ASX1108: External source error. org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 181,298,553; received: 141,754,284)
      		 
      org.apache.hyracks.api.exceptions.HyracksDataException: ASX1108: External source error. org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 181,298,553; received: 141,754,284)
      		 
          at org.apache.hyracks.api.exceptions.HyracksDataException.create(HyracksDataException.java:70) ~[hyracks-api.jar:1.0.0-2230]
      		 
          at org.apache.hyracks.api.util.ExceptionUtils.setNodeIds(ExceptionUtils.java:70) ~[hyracks-api.jar:1.0.0-2230]
      		 
          at org.apache.hyracks.control.nc.Task.run(Task.java:398) ~[hyracks-control-nc.jar:1.0.0-2230]
      		 
          at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
      		 
          at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
      		 
          at java.base/java.lang.Thread.run(Thread.java:840) [?:?]
      		 
      Caused by: org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 181,298,553; received: 141,754,284)
      		 
          at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:178) ~[httpcore-4.4.16.jar:4.4.16]
      		 
          at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:135) ~[httpclient-4.5.14.jar:4.5.14]
      		 
          at java.base/java.io.FilterInputStream.read(FilterInputStream.java:132) ~[?:?]
      		 
          at software.amazon.awssdk.services.s3.internal.checksums.S3ChecksumValidatingInputStream.read(S3ChecksumValidatingInputStream.java:112) ~[s3-2.24.9.jar:?]
      		 
          at java.base/java.io.FilterInputStream.read(FilterInputStream.java:132) ~[?:?]
      		 
          at software.amazon.awssdk.core.io.SdkFilterInputStream.read(SdkFilterInputStream.java:66) ~[sdk-core-2.24.9.jar:?]
      		 
          at software.amazon.awssdk.core.internal.metrics.BytesReadTrackingInputStream.read(BytesReadTrackingInputStream.java:49) ~[sdk-core-2.24.9.jar:?]
      		 
          at java.base/java.io.FilterInputStream.read(FilterInputStream.java:132) ~[?:?]
      		 
          at software.amazon.awssdk.core.io.SdkFilterInputStream.read(SdkFilterInputStream.java:66) ~[sdk-core-2.24.9.jar:?]
      		 
          at org.apache.asterix.external.input.stream.AbstractMultipleInputStream.read(AbstractMultipleInputStream.java:66) ~[asterix-external-data.jar:1.0.0-2230]
      		 
          at org.apache.asterix.external.input.stream.AsterixInputStreamReader.read(AsterixInputStreamReader.java:99) ~[asterix-external-data.jar:1.0.0-2230]
      		 
          at org.apache.asterix.external.input.stream.AsterixInputStreamReader.read(AsterixInputStreamReader.java:69) ~[asterix-external-data.jar:1.0.0-2230]
      		 
          at org.apache.asterix.external.input.record.reader.stream.LineRecordReader.hasNext(LineRecordReader.java:115) ~[asterix-external-data.jar:1.0.0-2230]
      		 
          at org.apache.asterix.external.dataflow.RecordDataFlowController.start(RecordDataFlowController.java:56) ~[asterix-external-data.jar:1.0.0-2230]
      		 
          at org.apache.asterix.external.dataset.adapter.GenericAdapter.start(GenericAdapter.java:38) ~[asterix-external-data.jar:1.0.0-2230]
      		 
          at org.apache.asterix.external.operators.ExternalScanOperatorDescriptor$1.initialize(ExternalScanOperatorDescriptor.java:80) ~[asterix-external-data.jar:1.0.0-2230]
      		 
          at org.apache.hyracks.api.rewriter.runtime.SuperActivityOperatorNodePushable.lambda$runInParallel$0(SuperActivityOperatorNodePushable.java:233) ~[hyracks-api.jar:1.0.0-2230]
      		 
          at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
      		 
          ... 3 more
      		 
      2024-07-20T17:31:06.161+00:00 INFO CBAS.work.JobCleanupWork [Worker:ClusterController] cleaning up JID:0.2904 on NCs, status=FAILURE
      		 
      2024-07-20T17:31:06.162+00:00 INFO CBAS.work.JobCleanupWork [Worker:ClusterController] cleaning up JID:0.2904 on NCs, status=FAILURE
      		 
      2024-07-20T17:31:06.163+00:00 INFO CBAS.work.JobCleanupWork [Worker:ClusterController] cleaning up JID:0.2904 on NCs, status=FAILURE

       

      This is an intermittent problem and has largely worked, so I've only marked it as Major. Please update if necessary. 

      Test logs ->

      2024-07-20T17:01:41.557Z	warn	api call failed	{"env": "other", "method": "POST", "url": "https://api.qe-10.sandbox.nonprod-project-avengers.com/v2/organizations/c7dc1b2c-51ce-4d2c-a93a-51006931d6f7/projects/fc226955-6229-41ea-9300-7eada8cbdab9/instance/ed9bda8d-9363-44d8-8f4a-f045a0755309/proxy/query/service", "timeoutSec": 10800, "attempt": 1, "method": "POST", "address": "https://api.qe-10.sandbox.nonprod-project-avengers.com/v2/organizations/c7dc1b2c-51ce-4d2c-a93a-51006931d6f7/projects/fc226955-6229-41ea-9300-7eada8cbdab9/instance/ed9bda8d-9363-44d8-8f4a-f045a0755309/proxy/query/service", "error": "unexpected status code 500", "status_code": 500, "body": "{\n\t\"requestID\": \"8b700cfb-0441-4952-a29d-a92dd18b32fb\",\n\t\"errors\": [{ \n\t\t\"code\": 24086,\t\t\"msg\": \"External source error. org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 181,133,562; received: 21,168,044)\"\t} \n\t],\n\t\"status\": \"fatal\",\n\t\"metrics\": {\n\t\t\"elapsedTime\": \"21.599674082s\",\n\t\t\"executionTime\": \"21.597962412s\",\n\t\t\"compileTime\": \"0ns\",\n\t\t\"queueWaitTime\": \"0ns\",\n\t\t\"resultCount\": 0,\n\t\t\"resultSize\": 0,\n\t\t\"processedObjects\": 0,\n\t\t\"bufferCacheHitRatio\": \"0.00%\",\n\t\t\"bufferCachePageReadCount\": 0,\n\t\t\"errorCount\": 1\n\t}\n}\n", "requestId": "ee943930-5280-46fa-a8fc-9a0d5fd37319"}
      		 
      github.com/couchbasecloud/couchbase-cloud/internal/test/tdk2.mustCallAPI.func3
      		 
      	/data/workspace/cp-cli-gsi-system-test/couchbase-cloud/internal/test/tdk2/http_client.go:210
      		 
      github.com/couchbase/tools-common/utils/v3/retry.Retryer[...].do
      		 
      	/go/pkg/mod/github.com/couchbase/tools-common/utils/v3@v3.0.0/retry/retryer.go:66
      		 
      github.com/couchbase/tools-common/utils/v3/retry.Retryer[...].DoWithContext
      		 
      	/go/pkg/mod/github.com/couchbase/tools-common/utils/v3@v3.0.0/retry/retryer.go:46
      		 
      github.com/couchbasecloud/couchbase-cloud/internal/test/tdk2.mustCallAPI
      		 
      	/data/workspace/cp-cli-gsi-system-test/couchbase-cloud/internal/test/tdk2/http_client.go:188
      		 
      github.com/couchbasecloud/couchbase-cloud/internal/test/tdk2.MustCallAPI
      		 
      	/data/workspace/cp-cli-gsi-system-test/couchbase-cloud/internal/test/tdk2/http_client.go:254
      		 
      github.com/couchbasecloud/couchbase-cloud/internal/test/tdk2.(*Session).ColumnarExecuteAnalyticsQuery
      		 
      	/data/workspace/cp-cli-gsi-system-test/couchbase-cloud/internal/test/tdk2/v2_columnar_utils.go:318
      		 
      github.com/couchbasecloud/couchbase-cloud/internal/test/tdk2.(*Session).CopyFromS3
      		 
      	/data/workspace/cp-cli-gsi-system-test/couchbase-cloud/internal/test/tdk2/v2_columnar_utils.go:734
      		 
      github.com/couchbasecloud/couchbase-cloud/cmd/cp-cli/actions/columnar.CopyFromS3.Do
      		 
      	/data/workspace/cp-cli-gsi-system-test/couchbase-cloud/cmd/cp-cli/actions/columnar/copy_from_s3.go:109
      		 
      github.com/couchbasecloud/couchbase-cloud/cmd/cp-cli/task.(*Tree).Execute
      		 
      	/data/workspace/cp-cli-gsi-system-test/couchbase-cloud/cmd/cp-cli/task/task.go:77
      		 
      github.com/couchbasecloud/couchbase-cloud/cmd/cp-cli/task.(*Tree).do.func1.1
      		 
      	/data/workspace/cp-cli-gsi-system-test/couchbase-cloud/cmd/cp-cli/task/task.go:161
      		 
      2024-07-20T17:01:42.058Z	warn	retrying api call	{"env": "other", "method": "POST", "url": "https://api.qe-10.sandbox.nonprod-project-avengers.com/v2/organizations/c7dc1b2c-51ce-4d2c-a93a-51006931d6f7/projects/fc226955-6229-41ea-9300-7eada8cbdab9/instance/ed9bda8d-9363-44d8-8f4a-f045a0755309/proxy/query/service", "timeoutSec": 10800, "attempt": 1, "method": "POST", "address": "https://api.qe-10.sandbox.nonprod-project-avengers.com/v2/organizations/c7dc1b2c-51ce-4d2c-a93a-51006931d6f7/projects/fc226955-6229-41ea-9300-7eada8cbdab9/instance/ed9bda8d-9363-44d8-8f4a-f045a0755309/proxy/query/service", "error": "unexpected status code 500", "status_code": 500, "requestId": "ee943930-5280-46fa-a8fc-9a0d5fd37319"}
      		 
      github.com/couchbasecloud/couchbase-cloud/internal/test/tdk2.mustCallAPI.func1
      		 
      	/data/workspace/cp-cli-gsi-system-test/couchbase-cloud/internal/test/tdk2/http_client.go:176
      		 
      github.com/couchbase/tools-common/utils/v3/retry.Retryer[...].DoWithContext
      		 
      	/go/pkg/mod/github.com/couchbase/tools-common/utils/v3@v3.0.0/retry/retryer.go:53
      		 
      github.com/couchbasecloud/couchbase-cloud/internal/test/tdk2.mustCallAPI
      		 
      	/data/workspace/cp-cli-gsi-system-test/couchbase-cloud/internal/test/tdk2/http_client.go:188
      		 
      github.com/couchbasecloud/couchbase-cloud/internal/test/tdk2.MustCallAPI
      		 
      	/data/workspace/cp-cli-gsi-system-test/couchbase-cloud/internal/test/tdk2/http_client.go:254
      		 
      github.com/couchbasecloud/couchbase-cloud/internal/test/tdk2.(*Session).ColumnarExecuteAnalyticsQuery
      		 
      	/data/workspace/cp-cli-gsi-system-test/couchbase-cloud/internal/test/tdk2/v2_columnar_utils.go:318
      		 
      github.com/couchbasecloud/couchbase-cloud/internal/test/tdk2.(*Session).CopyFromS3
      		 
      	/data/workspace/cp-cli-gsi-system-test/couchbase-cloud/internal/test/tdk2/v2_columnar_utils.go:734
      		 
      github.com/couchbasecloud/couchbase-cloud/cmd/cp-cli/actions/columnar.CopyFromS3.Do
      		 
      	/data/workspace/cp-cli-gsi-system-test/couchbase-cloud/cmd/cp-cli/actions/columnar/copy_from_s3.go:109
      		 
      github.com/couchbasecloud/couchbase-cloud/cmd/cp-cli/task.(*Tree).Execute
      		 
      	/data/workspace/cp-cli-gsi-system-test/couchbase-cloud/cmd/cp-cli/task/task.go:77
      		 
      github.com/couchbasecloud/couchbase-cloud/cmd/cp-cli/task.(*Tree).do.func1.1
      		 
      	/data/workspace/cp-cli-gsi-system-test/couchbase-cloud/cmd/cp-cli/task/task.go:161

       

      cbcollect ->

       

      https://cb-engineering.s3.amazonaws.com/SysTestColumnarRC1/collectinfo-2024-07-20T173517-ns_1%40svc-da-node-001.r7pgsp68tlb1w9-t.sandbox.nonprod-project-avengers.com.zip

      https://cb-engineering.s3.amazonaws.com/SysTestColumnarRC1/collectinfo-2024-07-20T173517-ns_1%40svc-da-node-002.r7pgsp68tlb1w9-t.sandbox.nonprod-project-avengers.com.zip

      https://cb-engineering.s3.amazonaws.com/SysTestColumnarRC1/collectinfo-2024-07-20T173517-ns_1%40svc-da-node-003.r7pgsp68tlb1w9-t.sandbox.nonprod-project-avengers.com.zip

      https://cb-engineering.s3.amazonaws.com/SysTestColumnarRC1/collectinfo-2024-07-20T173517-ns_1%40svc-da-node-004.r7pgsp68tlb1w9-t.sandbox.nonprod-project-avengers.com.zip

      Attachments

        No reviews matched the request. Check your Options in the drop-down menu of this sections header.

        Activity

          People

            Hussain.Towaileb Hussain Towaileb
            pavan.pb Pavan PB
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Gerrit Reviews

                There are no open Gerrit changes

                PagerDuty