Flaky test catalog::tests::test_create_update_drop_table

[SergeiPatiakin]

Steps to reproduce

cd catalogs/iceberg-rest-catalog
cargo test

Output

~10% of the time:

test models::list_tables_response::tests::test_list_tables_response_serialization ... ok
test models::list_tables_response::tests::test_list_tables_response_deserialization ... ok
test catalog::tests::test_create_update_drop_table ... ok

test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 19.90s

~90% of the time:

running 3 tests
test models::list_tables_response::tests::test_list_tables_response_serialization ... ok
test models::list_tables_response::tests::test_list_tables_response_deserialization ... ok
test catalog::tests::test_create_update_drop_table ... FAILED

failures:

---- catalog::tests::test_create_update_drop_table stdout ----
thread 'catalog::tests::test_create_update_drop_table' panicked at catalogs/iceberg-rest-catalog/src/catalog.rs:739:14:
Failed to execute query plan.: External(InvalidFormat("Response status: 500 Internal Server Error, Response content: {\"error\":{\"message\":\"The specified bucket does not exist (Service: S3, Status Code: 404, Request ID: 337759f8-89db-434d-b2db-b5ddf051f071, Extended Request ID: s9lzHYrFp76ZVxRcpX9+5cjAnEH2ROuNkd2BHfIa6UkFVdtjf5mKR3/eTPFvsiP/XV/VLi31234=)\",\"type\":\"NoSuchBucketException\",\"code\":500,\"stack\":[\"software.amazon.awssdk.services.s3.model.NoSuchBucketException: The specified bucket does not exist (Service: S3, Status Code: 404, Request ID: 337759f8-89db-434d-b2db-b5ddf051f071, Extended Request ID: s9lzHYrFp76ZVxRcpX9+5cjAnEH2ROuNkd2BHfIa6UkFVdtjf5mKR3/eTPFvsiP/XV/VLi31234=)\",\"\\tat software.amazon.awssdk.protocols.xml.internal.unmarshall.AwsXmlPredicatedResponseHandler.handleErrorResponse(AwsXmlPredicatedResponseHandler.java:155)\",\"\\tat software.amazon.awssdk.protocols.xml.internal.unmarshall.AwsXmlPredicatedResponseHandler.handleResponse(AwsXmlPredicatedResponseHandler.java:107)\",\"\\tat software.amazon.awssdk.protocols.xml.internal.unmarshall.AwsXmlPredicatedResponseHandler.handle(AwsXmlPredicatedResponseHandler.java:84)\",\"\\tat software.amazon.awssdk.protocols.xml.internal.unmarshall.AwsXmlPredicatedResponseHandler.handle(AwsXmlPredicatedResponseHandler.java:42)\",\"\\tat software.amazon.awssdk.awscore.client.handler.AwsSyncClientHandler$Crc32ValidationResponseHandler.handle(AwsSyncClientHandler.java:93)\",\"\\tat software.amazon.awssdk.core.internal.handler.BaseClientHandler.lambda$successTransformationResponseHandler$7(BaseClientHandler.java:279)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.HandleResponseStage.execute(HandleResponseStage.java:50)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.HandleResponseStage.execute(HandleResponseStage.java:38)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.execute(ApiCallAttemptTimeoutTrackingStage.java:74)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.execute(ApiCallAttemptTimeoutTrackingStage.java:43)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.TimeoutExceptionHandlingStage.execute(TimeoutExceptionHandlingStage.java:79)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.TimeoutExceptionHandlingStage.execute(TimeoutExceptionHandlingStage.java:41)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptMetricCollectionStage.execute(ApiCallAttemptMetricCollectionStage.java:55)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptMetricCollectionStage.execute(ApiCallAttemptMetricCollectionStage.java:39)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage.executeRequest(RetryableStage.java:93)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage.execute(RetryableStage.java:56)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage.execute(RetryableStage.java:36)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)\",\"\\tat software.amazon.awssdk.core.internal.http.StreamManagingStage.execute(StreamManagingStage.java:53)\",\"\\tat software.amazon.awssdk.core.internal.http.StreamManagingStage.execute(StreamManagingStage.java:35)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.executeWithTimer(ApiCallTimeoutTrackingStage.java:82)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.execute(ApiCallTimeoutTrackingStage.java:62)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.execute(ApiCallTimeoutTrackingStage.java:43)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallMetricCollectionStage.execute(ApiCallMetricCollectionStage.java:50)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallMetricCollectionStage.execute(ApiCallMetricCollectionStage.java:32)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage.execute(ExecutionFailureExceptionReportingStage.java:37)\",\"\\tat software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage.execute(ExecutionFailureExceptionReportingStage.java:26)\",\"\\tat software.amazon.awssdk.core.internal.http.AmazonSyncHttpClient$RequestExecutionBuilderImpl.execute(AmazonSyncHttpClient.java:210)\",\"\\tat software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.invoke(BaseSyncClientHandler.java:103)\",\"\\tat software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.doExecute(BaseSyncClientHandler.java:173)\",\"\\tat software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.lambda$execute$1(BaseSyncClientHandler.java:80)\",\"\\tat software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.measureApiCallSuccess(BaseSyncClientHandler.java:182)\",\"\\tat software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.execute(BaseSyncClientHandler.java:74)\",\"\\tat software.amazon.awssdk.core.client.handler.SdkSyncClientHandler.execute(SdkSyncClientHandler.java:45)\",\"\\tat software.amazon.awssdk.awscore.client.handler.AwsSyncClientHandler.execute(AwsSyncClientHandler.java:53)\",\"\\tat software.amazon.awssdk.services.s3.DefaultS3Client.putObject(DefaultS3Client.java:11169)\",\"\\tat org.apache.iceberg.aws.s3.S3OutputStream.completeUploads(S3OutputStream.java:444)\",\"\\tat org.apache.iceberg.aws.s3.S3OutputStream.close(S3OutputStream.java:270)\",\"\\tat org.apache.iceberg.aws.s3.S3OutputStream.close(S3OutputStream.java:256)\",\"\\tat java.base/sun.nio.cs.StreamEncoder.implClose(StreamEncoder.java:347)\",\"\\tat java.base/sun.nio.cs.StreamEncoder.close(StreamEncoder.java:169)\",\"\\tat java.base/java.io.OutputStreamWriter.close(OutputStreamWriter.java:252)\",\"\\tat org.apache.iceberg.TableMetadataParser.internalWrite(TableMetadataParser.java:134)\",\"\\tat org.apache.iceberg.TableMetadataParser.overwrite(TableMetadataParser.java:117)\",\"\\tat org.apache.iceberg.BaseMetastoreTableOperations.writeNewMetadata(BaseMetastoreTableOperations.java:160)\",\"\\tat org.apache.iceberg.BaseMetastoreTableOperations.writeNewMetadataIfRequired(BaseMetastoreTableOperations.java:150)\",\"\\tat org.apache.iceberg.jdbc.JdbcTableOperations.doCommit(JdbcTableOperations.java:106)\",\"\\tat org.apache.iceberg.BaseMetastoreTableOperations.commit(BaseMetastoreTableOperations.java:125)\",\"\\tat org.apache.iceberg.BaseMetastoreCatalog$BaseMetastoreCatalogTableBuilder.create(BaseMetastoreCatalog.java:201)\",\"\\tat org.apache.iceberg.rest.CatalogHandlers.createTable(CatalogHandlers.java:280)\",\"\\tat org.apache.iceberg.rest.RESTCatalogAdapter.handleRequest(RESTCatalogAdapter.java:396)\",\"\\tat org.apache.iceberg.rest.RESTServerCatalogAdapter.handleRequest(RESTServerCatalogAdapter.java:42)\",\"\\tat org.apache.iceberg.rest.RESTCatalogAdapter.execute(RESTCatalogAdapter.java:617)\",\"\\tat org.apache.iceberg.rest.RESTCatalogServlet.execute(RESTCatalogServlet.java:108)\",\"\\tat org.apache.iceberg.rest.RESTCatalogServlet.doPost(RESTCatalogServlet.java:78)\",\"\\tat jakarta.servlet.http.HttpServlet.service(HttpServlet.java:520)\",\"\\tat jakarta.servlet.http.HttpServlet.service(HttpServlet.java:587)\",\"\\tat org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:764)\",\"\\tat org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:529)\",\"\\tat org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)\",\"\\tat org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)\",\"\\tat org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:822)\",\"\\tat org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)\",\"\\tat org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)\",\"\\tat org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1381)\",\"\\tat org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176)\",\"\\tat org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484)\",\"\\tat org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174)\",\"\\tat org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1303)\",\"\\tat org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129)\",\"\\tat org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)\",\"\\tat org.eclipse.jetty.server.Server.handle(Server.java:563)\",\"\\tat org.eclipse.jetty.server.HttpChannel$RequestDispatchable.dispatch(HttpChannel.java:1598)\",\"\\tat org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:753)\",\"\\tat org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:501)\",\"\\tat org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:287)\",\"\\tat org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314)\",\"\\tat org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)\",\"\\tat org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)\",\"\\tat org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:421)\",\"\\tat org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:390)\",\"\\tat org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:277)\",\"\\tat org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:199)\",\"\\tat org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:411)\",\"\\tat org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:969)\",\"\\tat org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1194)\",\"\\tat org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1149)\",\"\\tat java.base/java.lang.Thread.run(Thread.java:840)\"]}}"))
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace


failures:
    catalog::tests::test_create_update_drop_table

test result: FAILED. 2 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 17.10s

Environment

• iceberg-rust @ commit 129c819
• rustc 1.84.0-nightly (9322d183f 2024-10-14)
• Ubuntu 22.04 on WSL2

[JanKaul]

Interesting. I'm not having any issues and the CI also seems to work fine.

Maybe we have to enforce waiting for all docker containers with proper health checks.

RUST_LOG=debug might indicate where the errors are coming from.

[SergeiPatiakin]

and the CI also seems to work fine

It looks like we don't test that crate in CI... we only test iceberg-rust-spec, iceberg-rust and datafusion_iceberg?

https://github.com/JanKaul/iceberg-rust/blob/main/.github/workflows/rust.yml#L19-L24
https://github.com/JanKaul/iceberg-rust/blob/main/Makefile#L3-L10

[JanKaul]

Ups, you're right. That's shouldn't be the case.

It looks like the S3 bucket isn't created in time for the test to run. I've created #150 to fix that. Thanks for bringing it up.