Details
-
Bug
-
Resolution: Fixed
-
Major
-
Columnar 1.0.0
-
1.0.0-2230
-
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 ->