Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

S3 404/NotFound isn't modeled correctly #638

Closed
ianbotsf opened this issue Jun 20, 2022 · 6 comments
Closed

S3 404/NotFound isn't modeled correctly #638

ianbotsf opened this issue Jun 20, 2022 · 6 comments
Assignees
Labels
bug This issue is a bug.

Comments

@ianbotsf
Copy link
Contributor

Describe the bug

Calls to S3 APIs that return a 404/NotFound error aren't properly modeled and fail to deserialize, causing an S3Exception instead of a more accurate error.

Expected behavior

Any error should be deserialized correctly and thrown to calling code as a proper exception type.

Current behavior

An incorrect error is thrown because of failures in deserialization:

Exception in thread "main" aws.sdk.kotlin.services.s3.model.S3Exception: Failed to parse response as 'restXml' error
	at aws.sdk.kotlin.services.s3.transform.HeadObjectOperationDeserializerKt.throwHeadObjectError(HeadObjectOperationDeserializer.kt:97)
	at aws.sdk.kotlin.services.s3.transform.HeadObjectOperationDeserializerKt.access$throwHeadObjectError(HeadObjectOperationDeserializer.kt:1)
	at aws.sdk.kotlin.services.s3.transform.HeadObjectOperationDeserializer.deserialize(HeadObjectOperationDeserializer.kt:31)
	at aws.smithy.kotlin.runtime.http.operation.SdkOperationExecutionKt$decorate$3.invoke(SdkOperationExecution.kt:92)
	at aws.smithy.kotlin.runtime.http.operation.SdkOperationExecutionKt$decorate$3.invoke(SdkOperationExecution.kt:92)
	at aws.smithy.kotlin.runtime.http.operation.DeserializeHandler.call(SdkOperationExecution.kt:148)
	at aws.smithy.kotlin.runtime.http.operation.DeserializeHandler$call$1.invokeSuspend(SdkOperationExecution.kt)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.UndispatchedCoroutine.afterResume(CoroutineContext.kt:202)
	at kotlinx.coroutines.AbstractCoroutine.resumeWith(AbstractCoroutine.kt:102)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
	at kotlinx.coroutines.DispatchedTaskKt.resume(DispatchedTask.kt:178)
	at kotlinx.coroutines.DispatchedTaskKt.dispatch(DispatchedTask.kt:166)
	at kotlinx.coroutines.CancellableContinuationImpl.dispatchResume(CancellableContinuationImpl.kt:397)
	at kotlinx.coroutines.CancellableContinuationImpl.completeResume(CancellableContinuationImpl.kt:513)
	at kotlinx.coroutines.channels.AbstractChannel$ReceiveElement.completeResumeReceive(AbstractChannel.kt:908)
	at kotlinx.coroutines.channels.AbstractSendChannel.offerInternal(AbstractChannel.kt:56)
	at kotlinx.coroutines.channels.AbstractSendChannel.send(AbstractChannel.kt:134)
	at aws.smithy.kotlin.runtime.http.engine.ktor.KtorEngine$execute$2.invokeSuspend(KtorEngine.kt:138)
	at aws.smithy.kotlin.runtime.http.engine.ktor.KtorEngine$execute$2.invoke(KtorEngine.kt)
	at aws.smithy.kotlin.runtime.http.engine.ktor.KtorEngine$execute$2.invoke(KtorEngine.kt)
	at io.ktor.client.statement.HttpStatement.execute(HttpStatement.kt:49)
	at io.ktor.client.statement.HttpStatement$execute$1.invokeSuspend(HttpStatement.kt)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at io.ktor.util.pipeline.SuspendFunctionGun.resumeRootWith(SuspendFunctionGun.kt:138)
	at io.ktor.util.pipeline.SuspendFunctionGun.loop(SuspendFunctionGun.kt:112)
	at io.ktor.util.pipeline.SuspendFunctionGun.access$loop(SuspendFunctionGun.kt:14)
	at io.ktor.util.pipeline.SuspendFunctionGun$continuation$1.resumeWith(SuspendFunctionGun.kt:62)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
	at io.ktor.util.pipeline.SuspendFunctionGun.resumeRootWith(SuspendFunctionGun.kt:138)
	at io.ktor.util.pipeline.SuspendFunctionGun.loop(SuspendFunctionGun.kt:112)
	at io.ktor.util.pipeline.SuspendFunctionGun.access$loop(SuspendFunctionGun.kt:14)
	at io.ktor.util.pipeline.SuspendFunctionGun$continuation$1.resumeWith(SuspendFunctionGun.kt:62)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
	at io.ktor.util.pipeline.SuspendFunctionGun.resumeRootWith(SuspendFunctionGun.kt:138)
	at io.ktor.util.pipeline.SuspendFunctionGun.loop(SuspendFunctionGun.kt:112)
	at io.ktor.util.pipeline.SuspendFunctionGun.access$loop(SuspendFunctionGun.kt:14)
	at io.ktor.util.pipeline.SuspendFunctionGun$continuation$1.resumeWith(SuspendFunctionGun.kt:62)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
	at io.ktor.util.pipeline.SuspendFunctionGun.resumeRootWith(SuspendFunctionGun.kt:138)
	at io.ktor.util.pipeline.SuspendFunctionGun.loop(SuspendFunctionGun.kt:112)
	at io.ktor.util.pipeline.SuspendFunctionGun.access$loop(SuspendFunctionGun.kt:14)
	at io.ktor.util.pipeline.SuspendFunctionGun$continuation$1.resumeWith(SuspendFunctionGun.kt:62)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
	at kotlinx.coroutines.internal.LimitedDispatcher.run(LimitedDispatcher.kt:42)
	at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:95)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:570)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:749)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:677)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:664)
Caused by: aws.smithy.kotlin.runtime.serde.DeserializationException: Unexpected end-of-doc while looking for the start of a tag
At offset 0 (showing range 0--1):

^
	at aws.smithy.kotlin.runtime.serde.xml.deserialization.StringTextStream.readOrThrow(StringTextStream.kt:280)
	at aws.smithy.kotlin.runtime.serde.xml.deserialization.XmlLexer.readTagToken(XmlLexer.kt:162)
	at aws.smithy.kotlin.runtime.serde.xml.deserialization.XmlLexer.parseNext(XmlLexer.kt:79)
	at aws.smithy.kotlin.runtime.serde.xml.deserialization.XmlLexer.parseNext(XmlLexer.kt:74)
	at aws.smithy.kotlin.runtime.serde.xml.deserialization.LexingXmlStreamReader.nextToken(LexingXmlStreamReader.kt:31)
	at aws.smithy.kotlin.runtime.serde.xml.XmlDeserializer.deserializeStruct(XmlDeserializer.kt:43)
	at aws.sdk.kotlin.services.s3.internal.S3ErrorMetadataKt.parseS3ErrorResponse(S3ErrorMetadata.kt:81)
	at aws.sdk.kotlin.services.s3.transform.HeadObjectOperationDeserializerKt.throwHeadObjectError(HeadObjectOperationDeserializer.kt:94)
	... 50 more

From examining wire logs, it appears the response itself has no body:

HTTP 404: Not Found
content-type: application/xml
date: Mon, 20 Jun 2022 22:25:57 GMT
server: AmazonS3
x-amz-id-2: IqpsfDkLU4vqSyUwN9UirIsMIz8EKy1IBd0EwOjHKIRB+En4stHNPdZFZBrJ+0mfYSDlLtOxD/8=
x-amz-request-id: P3Y6E1C0EC4AQAE5


Steps to Reproduce

Call S3 HeadObject for a bucket that exists but a key that does not exist:

val s3 = S3Client.fromEnvironment { }
s3.headObject {
    bucket = "a-real-bucket"
    key = "a-nonexistent-key"
} // Throws exception

Possible Solution

No response

Context

No response

AWS Kotlin SDK version used

0.16.3-SNAPSHOT

Platform (JVM/JS/Native)

OpenJDK Runtime Environment Corretto-17.0.3.6.1 (build 17.0.3+6-LTS)

Operating System and version

Amazon Linux 2

@ianbotsf ianbotsf added the bug This issue is a bug. label Jun 20, 2022
@aajtodd aajtodd self-assigned this Jun 21, 2022
@aajtodd
Copy link
Contributor

aajtodd commented Jun 21, 2022

Looks like this broke starting in 0.14.0-beta due to #554

The model is fine, the response that S3 returns isn't though for how it's modeled. The HeadObject operation looks like this in the model:

       "com.amazonaws.s3#HeadObject": {
            "type": "operation",
            "input": {
                "target": "com.amazonaws.s3#HeadObjectRequest"
            },
            "output": {
                "target": "com.amazonaws.s3#HeadObjectOutput"
            },
            "errors": [
                {
                    "target": "com.amazonaws.s3#NotFound"
                }
            ],

The issue is NotFound is a structure and the response returned by S3 has an empty payload.

We implement a customization for s3 to deal with this. The rendered version looks like this:

private suspend fun throwHeadObjectError(context: ExecutionContext, response: HttpResponse): kotlin.Nothing {
    val payload = response.body.readAll()
    val wrappedResponse = response.withPayload(payload)

    val errorDetails = try {
        if (payload == null && response.status == HttpStatusCode.NotFound) {
            S3ErrorDetails(code = "NotFound")
        } else {
            checkNotNull(payload){ "unable to parse error from empty response" }
            parseS3ErrorResponse(payload)
        }
    } catch (ex: Exception) {
        throw S3Exception("Failed to parse response as 'restXml' error", ex).also {
            setS3ErrorMetadata(it, wrappedResponse, null)
        }
    }

    val ex = when(errorDetails.code) {
        "NotFound" -> NotFoundDeserializer().deserialize(context, wrappedResponse)
        else -> S3Exception(errorDetails.message)
    }

    setS3ErrorMetadata(ex, wrappedResponse, errorDetails)
    throw ex
}

There are even custom protocol tests for this.

The issue seems to be that we implemented the customization against a particular HTTP engine behavior to model an empty response as HttpBody.Empty whereas other engines model it as an empty byte array/channel. The mock engine used in tests emulates this behavior.

We likely need to extend HTTP test suite to codify this behavior and update the customization as necessary. That or make the customization a bit more robust to check for empty payloads in addition to null ones.

@aajtodd
Copy link
Contributor

aajtodd commented Jun 21, 2022

Interestingly we fixed this with the direct binding to okhttp. Whereas our wrapped ktor engine always sets a body. Should be able to rectify that.

@aajtodd
Copy link
Contributor

aajtodd commented Jun 21, 2022

This will be fixed in the next release due to the direct okhttp binding. I've also added expanded test coverage to ensure all HTTP engines we support behave consistently w.r.t empty bodies.

@ianbotsf
Copy link
Contributor Author

Verified issue does not occur with OkHttp engine available in 0.16.4-SNAPSHOT...should've synced my sources before filing the bug! 😅

@aajtodd
Copy link
Contributor

aajtodd commented Jun 24, 2022

Verified latest release throws NotFound

using s3 sdk version = 0.16.4-beta
...
1072 [main] DEBUG Retry - sdkRequestId: baeed9b2-5b77-44ea-ab68-8beb89bf3db7; service: S3; operation: HeadObject; - request failed with non-retryable error
Exception in thread "main" NotFound()
	at aws.sdk.kotlin.services.s3.model.NotFound$Builder.build(NotFound.kt:46)
	at aws.sdk.kotlin.services.s3.transform.NotFoundDeserializer.deserialize(NotFoundDeserializer.kt:20)
	at aws.sdk.kotlin.services.s3.transform.HeadObjectOperationDeserializerKt.throwHeadObjectError(HeadObjectOperationDeserializer.kt:103)
	at aws.sdk.kotlin.services.s3.transform.HeadObjectOperationDeserializerKt.access$throwHeadObjectError(HeadObjectOperationDeserializer.kt:1)
	at aws.sdk.kotlin.services.s3.transform.HeadObjectOperationDeserializer.deserialize(HeadObjectOperationDeserializer.kt:31)
	at aws.smithy.kotlin.runtime.http.operation.SdkOperationExecutionKt$decorate$3.invoke(SdkOperationExecution.kt:92)
	at aws.smithy.kotlin.runtime.http.operation.SdkOperationExecutionKt$decorate$3.invoke(SdkOperationExecution.kt:92)
	at aws.smithy.kotlin.runtime.http.operation.DeserializeHandler.call(SdkOperationExecution.kt:148)
	at aws.smithy.kotlin.runtime.http.operation.DeserializeHandler$call$1.invokeSuspend(SdkOperationExecution.kt)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.UndispatchedCoroutine.afterResume(CoroutineContext.kt:233)
	at kotlinx.coroutines.AbstractCoroutine.resumeWith(AbstractCoroutine.kt:102)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
	at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:284)
	at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
	at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source)
	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:38)
	at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source)
	at aws.sdk.kotlin.example.MainKt.main(Main.kt:268)
	at aws.sdk.kotlin.example.MainKt.main(Main.kt)

@aajtodd aajtodd closed this as completed Jun 24, 2022
@github-actions
Copy link

⚠️COMMENT VISIBILITY WARNING⚠️

Comments on closed issues are hard for our team to see.
If you need more assistance, please either tag a team member or open a new issue that references this one.
If you wish to keep having a conversation with other community members under this issue feel free to do so.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug This issue is a bug.
Projects
None yet
Development

No branches or pull requests

2 participants