DynamoDbLocal 间歇性地生成 HTTP 500 错误

【问题标题】：DynamoDbLocal intermittently generates HTTP 500 errorsDynamoDbLocal 间歇性地生成 HTTP 500 错误
【发布时间】：2022-01-07 14:08:52
【问题描述】：

对于一个大型项目，我们在单元测试中使用 DynamoDbLocal。大多数时候，这些测试通过。该代码还可以在我们的生产环境中按预期工作，我们使用作为 VPC 一部分的“真实”dynamodb。

但是，有时单元测试会失败。特别是在调用putItem() 时，我们有时会遇到以下异常：

The request processing has failed because of an unknown error, exception or failure. (Service: DynamoDb, Status Code: 500, Request ID: db23be5e-ae96-417b-b268-5a1433c8c125, Extended Request ID: null)
software.amazon.awssdk.services.dynamodb.model.DynamoDbException: The request processing has failed because of an unknown error, exception or failure. (Service: DynamoDb, Status Code: 500, Request ID: db23be5e-ae96-417b-b268-5a1433c8c125, Extended Request ID: null)
    at software.amazon.awssdk.services.dynamodb.model.DynamoDbException$BuilderImpl.build(DynamoDbException.java:95)
    at software.amazon.awssdk.services.dynamodb.model.DynamoDbException$BuilderImpl.build(DynamoDbException.java:55)
    at software.amazon.awssdk.protocols.json.internal.unmarshall.AwsJsonProtocolErrorUnmarshaller.unmarshall(AwsJsonProtocolErrorUnmarshaller.java:89)
    at software.amazon.awssdk.protocols.json.internal.unmarshall.AwsJsonProtocolErrorUnmarshaller.handle(AwsJsonProtocolErrorUnmarshaller.java:63)
    at software.amazon.awssdk.protocols.json.internal.unmarshall.AwsJsonProtocolErrorUnmarshaller.handle(AwsJsonProtocolErrorUnmarshaller.java:42)
    at software.amazon.awssdk.core.http.MetricCollectingHttpResponseHandler.lambda$handle$0(MetricCollectingHttpResponseHandler.java:52)
    at software.amazon.awssdk.core.internal.util.MetricUtils.measureDurationUnsafe(MetricUtils.java:64)
    at software.amazon.awssdk.core.http.MetricCollectingHttpResponseHandler.handle(MetricCollectingHttpResponseHandler.java:52)
    at software.amazon.awssdk.core.internal.http.async.AsyncResponseHandler.lambda$prepare$0(AsyncResponseHandler.java:89)
    at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1072)
    at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
    at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073)
    at software.amazon.awssdk.core.internal.http.async.AsyncResponseHandler$BaosSubscriber.onComplete(AsyncResponseHandler.java:132)
    at java.base/java.util.Optional.ifPresent(Optional.java:183)
    at software.amazon.awssdk.http.crt.internal.AwsCrtResponseBodyPublisher.completeSubscriptionExactlyOnce(AwsCrtResponseBodyPublisher.java:216)
    at software.amazon.awssdk.http.crt.internal.AwsCrtResponseBodyPublisher.publishToSubscribers(AwsCrtResponseBodyPublisher.java:281)
    at software.amazon.awssdk.http.crt.internal.AwsCrtAsyncHttpStreamAdapter.onResponseComplete(AwsCrtAsyncHttpStreamAdapter.java:114)
    at software.amazon.awssdk.crt.http.HttpStreamResponseHandlerNativeAdapter.onResponseComplete(HttpStreamResponseHandlerNativeAdapter.java:33)

我们的工具和工件的相关版本：

  • Maven 3
  • Kotlin 版本 1.5.21
  • DynamoDbLocal 版本 1.16.0
  • 亚马逊开发工具包 2.16.67

我们的 DynamoLocalDb 在我们的单元测试中按如下方式启动：

    val url: String by lazy {
        System.setProperty("sqlite4java.library.path", "target/dynamo-native-libs")
        System.setProperty("aws.accessKeyId", "test-access-key")
        System.setProperty("aws.secretAccessKey", "test-secret-key")
        System.setProperty("log4j2.configurationFile", "classpath:log4j2-config-for-dynamodb.xml")

        val port = randomFreePort()
        logger.info { "Creating local in-memory Dynamo server on port $port" }
        val instance = ServerRunner.createServerFromCommandLineArgs(arrayOf("-inMemory", "-port", port.toString()))

        try {
            instance.safeStart()
        } catch (e: Exception) {
            instance.stop()
            fail("Could not start Local Dynamo Server on port $port.", e)
        }

        Runtime.getRuntime().addShutdownHook(object : Thread() {
            override fun run() {
                logger.debug("Stopping Local Dynamo Server on port $port")
                instance.stop()
            }
        })

        "http://localhost:$port"
    }

我们的dynamo log4j配置是：

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
        </Console>
    </Appenders>
    <Loggers>
        <Logger name="com.amazonaws.services.dynamodbv2.local" level="DEBUG">
            <AppenderRef ref="Console"/>
        </Logger>
        <Logger name="com.amazonaws.services.dynamodbv2.local.shared.access.sqlite.SQLiteDBAccess" level="WARN">
            <AppenderRef ref="Console"/>
        </Logger>
        <Root level="DEBUG">
            <AppenderRef ref="Console"/>
        </Root>
    </Loggers>
</Configuration>

我们的客户端是通过以下方式创建的：

    val client: DynamoDbAsyncClientWrapper by lazy {
        DynamoDbAsyncClientWrapper(
            DynamoDbAsyncClient.builder()
                .region(Region.EU_WEST_1)
                .credentialsProvider(DefaultCredentialsProvider.builder().build())
                .endpointOverride(URI.create(url))
                .httpClientBuilder(AwsCrtAsyncHttpClient.builder())
                .build()
        )
    }

我们在上面代码中使用的Kotlin Dynamo Wrapper DSL的代码是开源的，值得一看。

如上所述在com.amazonaws.services.dynamodbv2.local 中启用调试日志记录后，我们在日志中注意到以下内容：

09:14:22.917 [SQLiteQueue[]] DEBUG com.amazonaws.services.dynamodbv2.local.shared.access.sqlite.SQLiteDBAccessJob - SELECT ObjectJSON FROM "events-table" WHERE hashKey = ? AND rangeKey = ?;
09:14:22.919 [qtp1058328657-20] ERROR com.amazonaws.services.dynamodbv2.local.server.LocalDynamoDBServerHandler - Unexpected exception occured
com.amazonaws.services.dynamodbv2.local.shared.exceptions.LocalDBAccessException: [1] DB[1] prepare() INSERT OR REPLACE INTO "events-table" (rangeKey, hashKey, ObjectJSON, indexKey_1, indexKey_2, indexKey_6, rangeValue, hashRangeValue, hashValue,itemSize) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?,?); [table events-table has no column named indexKey_6]
    at com.amazonaws.services.dynamodbv2.local.shared.access.sqlite.AmazonDynamoDBOfflineSQLiteJob.get(AmazonDynamoDBOfflineSQLiteJob.java:84) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.shared.access.sqlite.SQLiteDBAccess.putRecord(SQLiteDBAccess.java:1718) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.shared.access.api.dp.PutItemFunction.putItemNoCondition(PutItemFunction.java:183) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.shared.access.api.dp.PutItemFunction$1.criticalSection(PutItemFunction.java:83) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.shared.access.LocalDBAccess$WriteLockWithTimeout.execute(LocalDBAccess.java:361) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.shared.access.api.dp.PutItemFunction.apply(PutItemFunction.java:85) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.shared.access.api.dp.TransactWriteItemsFunction.doWrite(TransactWriteItemsFunction.java:353) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.shared.access.api.dp.TransactWriteItemsFunction.access$000(TransactWriteItemsFunction.java:60) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.shared.access.api.dp.TransactWriteItemsFunction$1.run(TransactWriteItemsFunction.java:109) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.shared.helpers.MultiTableLock$SingleTableLock$2.criticalSection(MultiTableLock.java:66) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.shared.access.LocalDBAccess$WriteLockWithTimeout.execute(LocalDBAccess.java:361) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.shared.helpers.MultiTableLock$SingleTableLock.run(MultiTableLock.java:68) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.shared.access.api.dp.TransactWriteItemsFunction.apply(TransactWriteItemsFunction.java:113) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.shared.access.awssdkv1.client.LocalAmazonDynamoDB.transactWriteItems(LocalAmazonDynamoDB.java:401) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.server.LocalDynamoDBRequestHandler.transactWriteItems(LocalDynamoDBRequestHandler.java:240) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.dispatchers.TransactWriteItemsDispatcher.enact(TransactWriteItemsDispatcher.java:16) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.dispatchers.TransactWriteItemsDispatcher.enact(TransactWriteItemsDispatcher.java:8) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.server.LocalDynamoDBServerHandler.packageDynamoDBResponse(LocalDynamoDBServerHandler.java:395) ~[DynamoDBLocal-1.16.0.jar:?]
    at com.amazonaws.services.dynamodbv2.local.server.LocalDynamoDBServerHandler.handle(LocalDynamoDBServerHandler.java:482) ~[DynamoDBLocal-1.16.0.jar:?]
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[jetty-server-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[jetty-server-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1369) ~[jetty-server-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:190) ~[jetty-server-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1284) ~[jetty-server-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[jetty-server-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) ~[jetty-server-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[jetty-server-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.server.Server.handle(Server.java:501) ~[jetty-server-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383) ~[jetty-server-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:556) [jetty-server-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375) [jetty-server-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:272) [jetty-server-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [jetty-io-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [jetty-io-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [jetty-io-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) [jetty-util-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) [jetty-util-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) [jetty-util-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) [jetty-util-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375) [jetty-util-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806) [jetty-util-9.4.30.v20200611.jar:9.4.30.v20200611]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938) [jetty-util-9.4.30.v20200611.jar:9.4.30.v20200611]
    at java.lang.Thread.run(Thread.java:829) [?:?]

此堆栈跟踪提示在动态创建底层 SQLLite 表或查询时存在问题，并且它并不总是发生的事实感觉就像是竞争条件形式的错误或未能清理内存或旧语句之间的对象。

在这种情况下，生成的 SQL 是：

INSERT OR REPLACE INTO "events-table" 
(rangeKey, hashKey, ObjectJSON, indexKey_1, indexKey_2, indexKey_6, rangeValue, hashRangeValue, hashValue,itemSize) 
VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?,?); 
[table events-table has no column named indexKey_6]

我们已尝试对代码进行多次更改，但我们已经没有选择余地了。我们正在寻找导致此间歇性问题的可能原因，或可靠重现该问题的方法。

在亚马逊论坛上，我们发现 this post 似乎暗示了类似的问题，但自 2020 年 8 月以来也未得到答复/未解决。如果我们也能解决 Andrew 的问题，那就太好了。我还在re:Post 上发布了这个问题，但不知何故，AWS 不允许我使用我在那里创建的用户 ID/密码重新登录，并且要创建我必须登录的票证。我想我应该在 StackOverflow 上发布这个开始与。

编辑：查看反编译的com.amazonaws.services.dynamodbv2.local.shared.access.sqlite.SQLiteDBAccess 代码，似乎有一个用于在数据库中触发查询的内部队列。是否有可能从 SQLite 表中获取元信息以在队列中构建项目，但同时表中的数据被比放入队列的语句更早触发的语句更改？我还没有能够创造这种情况，但感觉就像这就是正在发生的事情。

【问题讨论】：

    标签： kotlin amazon-dynamodb dynamo-local


    【解决方案1】：

    事实证明，这个问题确实与队列和 DynamoLocalDb 的工作方式有关，但与我们想象的方式无关。我们在使用协程的 Kotlin 项目中使用 DynamoLocalDb。在 I/O 工作的情况下，我们分派例程，如下所示：

    withContext(Dispatchers.IO) {
    // Dynamo.PutItem() code here
}

    通过使用调度程序，代码在 I/O 线程池中的一个线程上执行。如果我们碰巧在不同的 IO 线程或主线程上删除或更改表，SQLite 语句有时会在 IO 线程中的语句完成之前执行，这反过来又会导致我们得到的错误。

    我们“解决”了这个问题，在我们的单元测试中从不丢弃表格，而是像这样从表格中删除所有项目：

    private suspend fun clearTable(table: DynamoTable<Any>) {
    val scanRequest = ScanRequest.builder().tableName(table.name).build()

    lateinit var items: List<Map<String, AttributeValue>>
    while (client.scan(scanRequest).items()
            .let {
                items = it
                !it.isEmpty()
            }
    ) {
        items.forEach {
            client.deleteItem(table.name) {
                key {
                    table.partitionKey from it.getValue(table.partitionKey).s()
                    table.sortKey from it.getValue(table.sortKey).s()
                }
            }
        }
    }
    logger.debug { "Removed all items from local dynamo table ${table.name}" }
}

    在我们的代码中，DynamoTable 类是一个简单的数据类，包含一个表的名称、pk 和 sk。请注意，client.scan() 返回分页结果。因为我们正在删除，所以分页预计会中断，并且由于我们并不真正关心这里的分页，所以我们只是再次触发请求，直到我们得到一个空的第一页。

    我希望这可以帮助其他遇到类似问题的人。
    干杯！

    【讨论】：

      猜你喜欢
      • 1970-01-01
      • 2021-09-17
      • 1970-01-01
      • 2012-12-14
      • 2012-01-14
      • 2010-11-17
      • 1970-01-01
      • 1970-01-01
      • 1970-01-01
      相关资源
      最近更新 更多
      热门标签
      Java Python linux javascript Mysql C# Docker 算法 前端 SpringBoot Redis Vue spring 设计模式 .net core .net kubernetes c++ 数据库 数据结构 大数据 js 机器学习 微服务 Android Go 程序员 面试 JVM ASP.net core 云原生 人工智能 后端 PHP git CSS golang k8s Nginx Django mybatis 深度学习 多线程 React 架构 devops 爬虫 云计算 Spring Boot LeetCode