NullPointerException with getObject

[jingyouu]

Describe the bug

I run the following code (same as the example) to fetch s3 bucket file

S3Client{region = "us-east-1"}.use{ s3 -> s3.getObject(request){ //do nothing to make sure the error is not coming from my logic } }

And it always throw the error below when I first run the application
If I added a retry line to call the function again, it works as expected in the second call.

java.lang.NullPointerException: Cannot invoke "java.util.Map.size()" because "m" is null at java.base/java.util.HashMap.putMapEntries(HashMap.java:495) at java.base/java.util.HashMap.putAll(HashMap.java:783) at java.base/java.util.Collections$SynchronizedMap.putAll(Collections.java:2682) at ch.qos.logback.classic.util.LogbackMDCAdapter.setContextMap(LogbackMDCAdapter.java:197) at org.slf4j.MDC.setContextMap(MDC.java:264) at aws.smithy.kotlin.runtime.telemetry.logging.slf4j.Slf4j1xLogRecordBuilderAdapter.emit(Slf4j1xLoggerAdapter.kt:67) at aws.smithy.kotlin.runtime.telemetry.logging.CoroutineContextLogExtKt.log(CoroutineContextLogExt.kt:93) at aws.smithy.kotlin.runtime.telemetry.logging.CoroutineContextLogExtKt.debug(CoroutineContextLogExt.kt:189) at aws.smithy.kotlin.runtime.telemetry.logging.ContextAwareLogger.debug(CoroutineContextLogExt.kt:244) at aws.smithy.kotlin.runtime.telemetry.logging.Logger$DefaultImpls.debug$default(Logger.kt:29) at aws.smithy.kotlin.runtime.identity.IdentityProviderChain$resolve$suspendImpl$$inlined$withSpan$default$1.invokeSuspend(CoroutineContextTraceExt.kt:138) at aws.smithy.kotlin.runtime.identity.IdentityProviderChain$resolve$suspendImpl$$inlined$withSpan$default$1.invoke(CoroutineContextTraceExt.kt) at aws.smithy.kotlin.runtime.identity.IdentityProviderChain$resolve$suspendImpl$$inlined$withSpan$default$1.invoke(CoroutineContextTraceExt.kt) at kotlinx.coroutines.intrinsics.UndispatchedKt.startUndispatchedOrReturn(Undispatched.kt:89) at kotlinx.coroutines.BuildersKt__Builders_commonKt.withContext(Builders.common.kt:165) at kotlinx.coroutines.BuildersKt.withContext(Unknown Source) at aws.smithy.kotlin.runtime.identity.IdentityProviderChain.resolve$suspendImpl(IdentityProviderChain.kt:93) at aws.smithy.kotlin.runtime.identity.IdentityProviderChain.resolve(IdentityProviderChain.kt) at aws.smithy.kotlin.runtime.auth.awscredentials.CredentialsProviderChain.resolve(CredentialsProviderChain.kt:22) at aws.smithy.kotlin.runtime.identity.IdentityProvider$DefaultImpls.resolve$default(IdentityProvider.kt:22) at aws.smithy.kotlin.runtime.auth.awscredentials.CachedCredentialsProvider$resolve$3.invokeSuspend(CachedCredentialsProvider.kt:63) at aws.smithy.kotlin.runtime.auth.awscredentials.CachedCredentialsProvider$resolve$3.invoke(CachedCredentialsProvider.kt) at aws.smithy.kotlin.runtime.auth.awscredentials.CachedCredentialsProvider$resolve$3.invoke(CachedCredentialsProvider.kt) at aws.smithy.kotlin.runtime.util.CachedValue.getOrLoad(CachedValue.kt:80) at aws.smithy.kotlin.runtime.auth.awscredentials.CachedCredentialsProvider.resolve(CachedCredentialsProvider.kt:61) at aws.sdk.kotlin.runtime.auth.credentials.DefaultChainCredentialsProvider.resolve(DefaultChainCredentialsProvider.kt:74) at aws.sdk.kotlin.runtime.auth.credentials.internal.ManagedCredentialsProvider.resolve(ManagedCredentialsProvider.kt) at aws.smithy.kotlin.runtime.http.operation.AuthHandler.call(SdkOperationExecution.kt:283) at aws.smithy.kotlin.runtime.http.operation.AuthHandler.call(SdkOperationExecution.kt:259) at aws.sdk.kotlin.runtime.http.middleware.AwsRetryHeaderMiddleware.handle(AwsRetryHeaderMiddleware.kt:39) at aws.sdk.kotlin.runtime.http.middleware.AwsRetryHeaderMiddleware.handle(AwsRetryHeaderMiddleware.kt:26) at aws.smithy.kotlin.runtime.io.middleware.DecoratedHandler.call(Middleware.kt:44) at aws.smithy.kotlin.runtime.io.middleware.Phase.handle(Phase.kt:67) at aws.smithy.kotlin.runtime.io.middleware.DecoratedHandler.call(Middleware.kt:44) at aws.smithy.kotlin.runtime.http.middleware.RetryMiddleware.tryAttempt-BWLJW6A(RetryMiddleware.kt:78) at aws.smithy.kotlin.runtime.http.middleware.RetryMiddleware.access$tryAttempt-BWLJW6A(RetryMiddleware.kt:31) at aws.smithy.kotlin.runtime.http.middleware.RetryMiddleware$handle$result$outcome$1$invokeSuspend$$inlined$withSpan$default$1.invokeSuspend(CoroutineContextTraceExt.kt:136) at aws.smithy.kotlin.runtime.http.middleware.RetryMiddleware$handle$result$outcome$1$invokeSuspend$$inlined$withSpan$default$1.invoke(CoroutineContextTraceExt.kt) at aws.smithy.kotlin.runtime.http.middleware.RetryMiddleware$handle$result$outcome$1$invokeSuspend$$inlined$withSpan$default$1.invoke(CoroutineContextTraceExt.kt) at kotlinx.coroutines.intrinsics.UndispatchedKt.startUndispatchedOrReturn(Undispatched.kt:89) at kotlinx.coroutines.BuildersKt__Builders_commonKt.withContext(Builders.common.kt:165) at kotlinx.coroutines.BuildersKt.withContext(Unknown Source) at aws.smithy.kotlin.runtime.http.middleware.RetryMiddleware$handle$result$outcome$1.invokeSuspend(RetryMiddleware.kt:134) at aws.smithy.kotlin.runtime.http.middleware.RetryMiddleware$handle$result$outcome$1.invoke(RetryMiddleware.kt) at aws.smithy.kotlin.runtime.http.middleware.RetryMiddleware$handle$result$outcome$1.invoke(RetryMiddleware.kt) at aws.smithy.kotlin.runtime.retries.StandardRetryStrategy.doTryLoop(StandardRetryStrategy.kt:60) at aws.smithy.kotlin.runtime.retries.StandardRetryStrategy.retry$suspendImpl(StandardRetryStrategy.kt:40) at aws.smithy.kotlin.runtime.retries.StandardRetryStrategy.retry(StandardRetryStrategy.kt) at aws.smithy.kotlin.runtime.http.middleware.RetryMiddleware.handle(RetryMiddleware.kt:46) at aws.smithy.kotlin.runtime.http.middleware.RetryMiddleware.handle(RetryMiddleware.kt:31) at aws.smithy.kotlin.runtime.io.middleware.DecoratedHandler.call(Middleware.kt:44) at aws.smithy.kotlin.runtime.http.operation.MutateHandler.call(SdkOperationExecution.kt:256) at aws.smithy.kotlin.runtime.http.operation.MutateHandler.call(SdkOperationExecution.kt:253) at aws.smithy.kotlin.runtime.io.middleware.ModifyRequestMiddleware.handle(ModifyRequest.kt:26) at aws.smithy.kotlin.runtime.io.middleware.DecoratedHandler.call(Middleware.kt:44) at aws.smithy.kotlin.runtime.io.middleware.ModifyRequestMiddleware.handle(ModifyRequest.kt:26) at aws.smithy.kotlin.runtime.io.middleware.DecoratedHandler.call(Middleware.kt:44) at aws.smithy.kotlin.runtime.io.middleware.Phase.handle(Phase.kt:67) at aws.smithy.kotlin.runtime.io.middleware.DecoratedHandler.call(Middleware.kt:44) at aws.smithy.kotlin.runtime.http.operation.SerializeHandler.call(SdkOperationExecution.kt:249) at aws.smithy.kotlin.runtime.http.operation.SerializeHandler.call(SdkOperationExecution.kt:231) at aws.smithy.kotlin.runtime.http.operation.InitializeHandler.call(SdkOperationExecution.kt:228) at aws.smithy.kotlin.runtime.io.middleware.Phase.handle(Phase.kt:63) at aws.smithy.kotlin.runtime.io.middleware.DecoratedHandler.call(Middleware.kt:44) at aws.smithy.kotlin.runtime.http.operation.OperationHandler.call(SdkOperationExecution.kt:208) at aws.smithy.kotlin.runtime.http.operation.OperationHandler.call(SdkOperationExecution.kt:200) at aws.smithy.kotlin.runtime.http.operation.SdkHttpOperationKt$execute$$inlined$withSpan$1.invokeSuspend(CoroutineContextTraceExt.kt:126) at aws.smithy.kotlin.runtime.http.operation.SdkHttpOperationKt$execute$$inlined$withSpan$1.invoke(CoroutineContextTraceExt.kt) at aws.smithy.kotlin.runtime.http.operation.SdkHttpOperationKt$execute$$inlined$withSpan$1.invoke(CoroutineContextTraceExt.kt) at kotlinx.coroutines.intrinsics.UndispatchedKt.startUndispatchedOrReturn(Undispatched.kt:89) at kotlinx.coroutines.BuildersKt__Builders_commonKt.withContext(Builders.common.kt:165) at kotlinx.coroutines.BuildersKt.withContext(Unknown Source) at aws.smithy.kotlin.runtime.http.operation.SdkHttpOperationKt.execute(SdkHttpOperation.kt:179) at aws.sdk.kotlin.services.s3.DefaultS3Client.getObject(DefaultS3Client.kt:2078) at com.saks.product.detail.url.redirect.FetchRedirectDataService.fetchRedirectProductID$suspendImpl(FetchRedirectDataService.kt:56) at com.saks.product.detail.url.redirect.FetchRedirectDataService.fetchRedirectProductID(FetchRedirectDataService.kt) at com.saks.product.detail.url.redirect.FetchRedirectDataService$updateRedirectProductIDSet$1.invokeSuspend(FetchRedirectDataService.kt:31) at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33) at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106) at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:274) 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 com.saks.product.detail.url.redirect.FetchRedirectDataService.updateRedirectProductIDSet(FetchRedirectDataService.kt:29) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:568) at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84) at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) 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:833) 2024-06-05 13:04:38,755 ERROR [scheduling-1] c.s.p.d.u.r.FetchRedirectDataService::fetchRedirectProductID$suspendImpl:75 - Fetch object from s3Client failed with error message: kotlin.Unit 2024-06-05 13:04:38,755 DEBUG [scheduling-1] c.s.p.d.u.r.FetchRedirectDataService::invokeSuspend:32 - RedirectURLSet size: 0

Expected behavior

It should return the s3 file content consistently.

Current behavior

The NPE error seems to be coming from the SDK? Or dependencies?

Steps to Reproduce

Code provided above.

Possible Solution

No response

Context

No response

AWS SDK for Kotlin version

aws.sdk.kotlin:s3:1.0.0

Platform (JVM/JS/Native)

kotlin jvm 1.8.0

Operating system and version

macOS 14.5

[jingyouu]

Looks like its similar to this issue #1256 but I am not able to resolve it with upgrading logback as the comment suggested

[ianbotsf]

Hi @jingyouu, I'm not able to reproduce this issue. Can you share what (if any) logging dependencies and configuration your code uses?

[jingyouu]

org.slf4j:slf4j-api:1.7.36 org.slf4j:slf4j-jul:1.7.36 org.apache.logging.log4j:log4j-api:2.19.0 org.apache.logging.log4j:log4j-to-slf4j:2.19.0 ch.qos.logback:logback-classic:1.2.11 ch.qos.logback:logback-core:1.2.11

[ianbotsf]

Interesting. You're pulling in slf4j-api:1.7.36 but the SDK already depends on slf4j-api:2.0.9. Are you forcing dependency resolution to the earlier version?

I've tried reproducing this issue, both with and without explicitly dependency resolution, and I still can't trigger the error you're seeing. Here's the relevant parts of my build.gradle.kts:

plugins {
    kotlin("jvm") version "1.9.24"
}

configurations.all {
    resolutionStrategy {
        // Explicitly downgrade to slf4j-api 1.7.36. Test still succeeds if this is commented out.
        force("org.slf4j:slf4j-api:1.7.36")
    }
}

dependencies {
    implementation(kotlin("stdlib-jdk8"))
    implementation("aws.sdk.kotlin:s3:1.2.27")

    implementation("org.slf4j:slf4j-api:1.7.36")
    implementation("org.slf4j:slf4j-jcl:1.7.36")
    implementation("org.apache.logging.log4j:log4j-api:2.19.0")
    implementation("org.apache.logging.log4j:log4j-to-slf4j:2.19.0")
    implementation("ch.qos.logback:logback-classic:1.2.11")
    implementation("ch.qos.logback:logback-core:1.2.11")
}

What does your build script look like? Is there any additional logging configuration in your environment?

[jingyouu]

I have plugins { id("org.springframework.boot") version "2.6.6" kotlin("jvm") version "1.8.0" kotlin("plugin.spring") version "1.6.0" }

The rest seems to be the same, but i am not enforcing to earlier version in gradle. I think the slf4j and logback version all comes from springboot 2.6.6

[ianbotsf]

Ah, I see. Spring Boot may bring along a lot of dependencies and/or customize the logging configuration in ways that could affect the AWS SDK. Can you share a minimal reproducible example, including a build script and logging configuration but without extraneous dependencies which are unrelated to the issue?

[jingyouu]

Thank you for looking into this! I reduced the build to the following
`plugins {
id("org.springframework.boot") version "2.6.6"
id("io.spring.dependency-management") version "1.0.11.RELEASE"
kotlin("jvm") version "1.8.0"
kotlin("plugin.spring") version "1.6.0"
}

java.sourceCompatibility = JavaVersion.VERSION_17

dependencies {
implementation("org.springframework.boot:spring-boot-starter-webflux")
implementation("org.springframework.boot:spring-boot-starter-actuator")
implementation("org.springframework.boot:spring-boot-starter-data-redis-reactive")
implementation("aws.sdk.kotlin:s3:1.2.27")
implementation("com.squareup.okhttp3:okhttp:5.0.0-alpha.10")

}`

Apart for that I only have a main class calling the application and a service class with a function to call
S3Client{region = "us-east-1"}.use{ s3 -> s3.getObject(request){ //do nothing to make sure the error is not coming from my logic } }

[ianbotsf]

Thank you for the full build definition, that was enough to reproduce it on my end. Looks like the Logback MDC adapter doesn't handle null context maps very well. Fortunately, that's a quick fix on our side. I'll have a PR up shortly!

[jingyouu]

Wow that would be great! Thanks a lot for your help!

[ianbotsf]

Actually, I started working on a hypothetical fix yesterday and unintentionally shipped it with another change. (I had intended to wait for a full repro before shipping it but my git add was a little too powerful apparently. 😶) So the fix should already published and available in aws-sdk-kotlin version v1.2.28.

Can you regress the issue on the latest version and let me know if that solves the problem for you?

[jingyouu]

I am still getting the same error with v1.2.28 :(

[ianbotsf]

@jingyouu, I'm sorry to hear you're still seeing the error with a later version of the SDK (and that it took so long to get back to you). Can you please post a copy of the most recent stack trace you're seeing?