NodeJS Lambda 似乎失败但报告成功答案

【问题标题】：NodeJS Lambda appears to fail but reports successNodeJS Lambda 似乎失败但报告成功
【发布时间】：2020-02-13 21:40:36
【问题描述】：

我在 NodeJS Lambda 上看到我不完全理解的行为。首先，我假设我们的代码中至少存在一个错误，但我们无法理解的问题是它如何影响同一个 Lambda 实例上的子序列调用。

尽我所能理解我遇到的问题是，在初始失败后，我的下一次调用也将失败，并且我看到一个似乎表明 nodejs 已终止的错误。然后我看到它重新初始化并再次成功开始处理请求。

有几个问题：

好的，我们似乎有一个错误，我想我们可以追踪它并在某个时候修复它
nodejs 在后续调用中终止，但调用被视为成功（当然不是）
因为第二次调用被认为是成功的，所以不会重试

让我试着展示一下这个外观的一些细节。首先，这是第二次调用，确实失败了，NodeJS 似乎终止了：

START RequestId: a71447b0-19f8-456c-b163-47e0408bf3a1 Version: $LATEST
2019-10-17T00:26:12.295Z    a71447b0-19f8-456c-b163-47e0408bf3a1    INFO    Assuming lambda role: { ... }lambda',
END RequestId: a71447b0-19f8-456c-b163-47e0408bf3a1
REPORT RequestId: a71447b0-19f8-456c-b163-47e0408bf3a1    Duration: 228.19 ms    Billed Duration: 300 ms    Memory Size: 256 MBMax Memory Used: 158 MB
RequestId: a71447b0-19f8-456c-b163-47e0408bf3a1 Error: Runtime exited with error: exit status 129

也许我误解了最后一行，但它确实看起来 NodeJS 正在终止我（使用 SIGHUP??!）。在此之后，下一次调用会显示 XRay 日志记录，就像我们在此实例上第一次调用时看到的那样：

2019-10-17T00:55:30.531Z       undefined       INFO    AWS_XRAY_DAEMON_ADDRESS is set. Configured daemon address to 169.xxx.xxx.xxx.
2019-10-17T00:55:30.536Z       undefined       INFO    AWS_XRAY_CONTEXT_MISSING is set. Configured context missing strategy to LOG_ERROR.
2019-10-17T00:55:30.554Z       undefined       INFO    Subsegment streaming threshold set to: 0

所以它在我的 lambda 实例上重新启动了 NodeJs？这是我们应该期待看到的吗？

如果我在 X 射线等中查看它，它会显示错误但也有 200 状态：

我认为还值得展示似乎触发此的先前调用。它也成功了，它确实返回了正确的值等，但完成后我在日志中看到了这一点：

2019-10-17T00:55:29.169Z    3bf23bda-e7fa-4fd7-b373-2258baff2bb8    ERROR   Uncaught Exception  {"errorType":"Error","errorMessage":"premature close","stack":["Error: premature close","    at Duplexify.onclose (/var/task/node_modules/end-of-stream/index.js:47:67)","    at Duplexify.emit (events.js:198:13)","    at Duplexify.EventEmitter.emit (domain.js:448:20)","    at Duplexify._destroy (/var/task/node_modules/duplexify/index.js:199:8)","    at /var/task/node_modules/duplexify/index.js:182:10","    at /var/task/node_modules/async-listener/glue.js:188:31","    at process._tickCallback (internal/process/next_tick.js:61:11)"]}
2019-10-17T00:55:29.326Z    3bf23bda-e7fa-4fd7-b373-2258baff2bb8    ERROR   Uncaught Exception  {"errorType":"Error","errorMessage":"premature close","stack":["Error: premature close","    at Duplexify.onclose (/var/task/node_modules/end-of-stream/index.js:47:67)","    at Duplexify.emit (events.js:198:13)","    at Duplexify.EventEmitter.emit (domain.js:448:20)","    at Duplexify._destroy (/var/task/node_modules/duplexify/index.js:199:8)","    at /var/task/node_modules/duplexify/index.js:182:10","    at /var/task/node_modules/async-listener/glue.js:188:31","    at process._tickCallback (internal/process/next_tick.js:61:11)"]}
2019-10-17T00:55:29.328Z    3bf23bda-e7fa-4fd7-b373-2258baff2bb8    ERROR   Uncaught Exception  {"errorType":"Error","errorMessage":"premature close","stack":["Error: premature close","    at Duplexify.onclose (/var/task/node_modules/end-of-stream/index.js:47:67)","    at Duplexify.emit (events.js:198:13)","    at Duplexify.EventEmitter.emit (domain.js:448:20)","    at Duplexify._destroy (/var/task/node_modules/duplexify/index.js:199:8)","    at /var/task/node_modules/duplexify/index.js:182:10","    at /var/task/node_modules/async-listener/glue.js:188:31","    at process._tickCallback (internal/process/next_tick.js:61:11)"]}
2019-10-17T00:55:29.329Z    3bf23bda-e7fa-4fd7-b373-2258baff2bb8    ERROR   Uncaught Exception  {"errorType":"Error","errorMessage":"premature close","stack":["Error: premature close","    at Duplexify.onclose (/var/task/node_modules/end-of-stream/index.js:47:67)","    at Duplexify.emit (events.js:198:13)","    at Duplexify.EventEmitter.emit (domain.js:448:20)","    at Duplexify._destroy (/var/task/node_modules/duplexify/index.js:199:8)","    at /var/task/node_modules/duplexify/index.js:182:10","    at /var/task/node_modules/async-listener/glue.js:188:31","    at process._tickCallback (internal/process/next_tick.js:61:11)"]}
2019-10-17T00:55:29.329Z    3bf23bda-e7fa-4fd7-b373-2258baff2bb8    ERROR   Uncaught Exception  {"errorType":"Error","errorMessage":"premature close","stack":["Error: premature close","    at Duplexify.onclose (/var/task/node_modules/end-of-stream/index.js:47:67)","    at Duplexify.emit (events.js:198:13)","    at Duplexify.EventEmitter.emit (domain.js:448:20)","    at Duplexify._destroy (/var/task/node_modules/duplexify/index.js:199:8)","    at /var/task/node_modules/duplexify/index.js:182:10","    at /var/task/node_modules/async-listener/glue.js:188:31","    at process._tickCallback (internal/process/next_tick.js:61:11)"]}
2019-10-17T00:55:29.330Z    3bf23bda-e7fa-4fd7-b373-2258baff2bb8    ERROR   Uncaught Exception  {"errorType":"Error","errorMessage":"premature close","stack":["Error: premature close","    at Duplexify.onclose (/var/task/node_modules/end-of-stream/index.js:47:67)","    at Duplexify.emit (events.js:198:13)","    at Duplexify.EventEmitter.emit (domain.js:448:20)","    at Duplexify._destroy (/var/task/node_modules/duplexify/index.js:199:8)","    at /var/task/node_modules/duplexify/index.js:182:10","    at /var/task/node_modules/async-listener/glue.js:188:31","    at process._tickCallback (internal/process/next_tick.js:61:11)"]}
2019-10-17T00:55:29.368Z    3bf23bda-e7fa-4fd7-b373-2258baff2bb8    ERROR   Uncaught Exception  {"errorType":"Error","errorMessage":"premature close","stack":["Error: premature close","    at Duplexify.onclose (/var/task/node_modules/end-of-stream/index.js:47:67)","    at Duplexify.emit (events.js:198:13)","    at Duplexify.EventEmitter.emit (domain.js:448:20)","    at Duplexify._destroy (/var/task/node_modules/duplexify/index.js:199:8)","    at /var/task/node_modules/duplexify/index.js:182:10","    at /var/task/node_modules/async-listener/glue.js:188:31","    at process._tickCallback (internal/process/next_tick.js:61:11)"]}
2019-10-17T00:55:29.388Z    3bf23bda-e7fa-4fd7-b373-2258baff2bb8    ERROR   Uncaught Exception  {"errorType":"Error","errorMessage":"premature close","stack":["Error: premature close","    at Duplexify.onclose (/var/task/node_modules/end-of-stream/index.js:47:67)","    at Duplexify.emit (events.js:198:13)","    at Duplexify.EventEmitter.emit (domain.js:448:20)","    at Duplexify._destroy (/var/task/node_modules/duplexify/index.js:199:8)","    at /var/task/node_modules/duplexify/index.js:182:10","    at /var/task/node_modules/async-listener/glue.js:188:31","    at process._tickCallback (internal/process/next_tick.js:61:11)"]}
2019-10-17T00:55:29.408Z    3bf23bda-e7fa-4fd7-b373-2258baff2bb8    ERROR   Uncaught Exception  {"errorType":"Error","errorMessage":"premature close","stack":["Error: premature close","    at Duplexify.onclose (/var/task/node_modules/end-of-stream/index.js:47:67)","    at Duplexify.emit (events.js:198:13)","    at Duplexify.EventEmitter.emit (domain.js:448:20)","    at Duplexify._destroy (/var/task/node_modules/duplexify/index.js:199:8)","    at /var/task/node_modules/duplexify/index.js:182:10","    at /var/task/node_modules/async-listener/glue.js:188:31","    at process._tickCallback (internal/process/next_tick.js:61:11)"]}
2019-10-17T00:55:29.428Z    3bf23bda-e7fa-4fd7-b373-2258baff2bb8    ERROR   Uncaught Exception  {"errorType":"Error","errorMessage":"premature close","stack":["Error: premature close","    at Duplexify.onclose (/var/task/node_modules/end-of-stream/index.js:47:67)","    at Duplexify.emit (events.js:198:13)","    at Duplexify.EventEmitter.emit (domain.js:448:20)","    at Duplexify._destroy (/var/task/node_modules/duplexify/index.js:199:8)","    at /var/task/node_modules/duplexify/index.js:182:10","    at /var/task/node_modules/async-listener/glue.js:188:31","    at process._tickCallback (internal/process/next_tick.js:61:11)"]}
2019-10-17T00:55:29.467Z    3bf23bda-e7fa-4fd7-b373-2258baff2bb8    ERROR   Uncaught Exception  {"errorType":"Error","errorMessage":"premature close","stack":["Error: premature close","    at Duplexify.onclose (/var/task/node_modules/end-of-stream/index.js:47:67)","    at Duplexify.emit (events.js:198:13)","    at Duplexify.EventEmitter.emit (domain.js:448:20)","    at Duplexify._destroy (/var/task/node_modules/duplexify/index.js:199:8)","    at /var/task/node_modules/duplexify/index.js:182:10","    at /var/task/node_modules/async-listener/glue.js:188:31","    at process._tickCallback (internal/process/next_tick.js:61:11)"]}
2019-10-17T00:55:29.468Z    3bf23bda-e7fa-4fd7-b373-2258baff2bb8    ERROR   Uncaught Exception  {"errorType":"Error","errorMessage":"premature close","stack":["Error: premature close","    at Duplexify.onclose (/var/task/node_modules/end-of-stream/index.js:47:67)","    at Duplexify.emit (events.js:198:13)","    at Duplexify.EventEmitter.emit (domain.js:448:20)","    at Duplexify._destroy (/var/task/node_modules/duplexify/index.js:199:8)","    at /var/task/node_modules/duplexify/index.js:182:10","    at /var/task/node_modules/async-listener/glue.js:188:31","    at process._tickCallback (internal/process/next_tick.js:61:11)"]}
2019-10-17T00:55:29.469Z    3bf23bda-e7fa-4fd7-b373-2258baff2bb8    ERROR   Uncaught Exception  {"errorType":"Error","errorMessage":"premature close","stack":["Error: premature close","    at Duplexify.onclose (/var/task/node_modules/end-of-stream/index.js:47:67)","    at Duplexify.emit (events.js:198:13)","    at Duplexify.EventEmitter.emit (domain.js:448:20)","    at Duplexify._destroy (/var/task/node_modules/duplexify/index.js:199:8)","    at /var/task/node_modules/duplexify/index.js:182:10","    at /var/task/node_modules/async-listener/glue.js:188:31","    at process._tickCallback (internal/process/next_tick.js:61:11)"]}
2019-10-17T00:55:29.567Z    3bf23bda-e7fa-4fd7-b373-2258baff2bb8    ERROR   Uncaught Exception  {"errorType":"Error","errorMessage":"premature close","stack":["Error: premature close","    at Duplexify.onclose (/var/task/node_modules/end-of-stream/index.js:47:67)","    at Duplexify.emit (events.js:198:13)","    at Duplexify.EventEmitter.emit (domain.js:448:20)","    at Duplexify._destroy (/var/task/node_modules/duplexify/index.js:199:8)","    at /var/task/node_modules/duplexify/index.js:182:10","    at /var/task/node_modules/async-listener/glue.js:188:31","    at process._tickCallback (internal/process/next_tick.js:61:11)"]}
2019-10-17T00:55:29.568Z    3bf23bda-e7fa-4fd7-b373-2258baff2bb8    ERROR   Uncaught Exception  {"errorType":"Error","errorMessage":"premature close","stack":["Error: premature close","    at Duplexify.onclose (/var/task/node_modules/end-of-stream/index.js:47:67)","    at Duplexify.emit (events.js:198:13)","    at Duplexify.EventEmitter.emit (domain.js:448:20)","    at Duplexify._destroy (/var/task/node_modules/duplexify/index.js:199:8)","    at /var/task/node_modules/duplexify/index.js:182:10","    at /var/task/node_modules/async-listener/glue.js:188:31","    at process._tickCallback (internal/process/next_tick.js:61:11)"]}

毫无疑问，这是我们代码中的一个错误。这对我来说并不明显，因为这些库不是我们的代码使用的。实际上，这些似乎被 AWS XRay 使用。那么 XRay 中是否存在故障并导致我们调用失败？

我正在努力理解：

nodejs 是否失败并正在重新启动？
有没有办法捕获此进程终止并至少将其视为失败的调用？
简而言之：这里发生了什么？它似乎与我们通常期望在 lambda 中看到的不符...

以下是一些~~我们将尝试~~我们尝试但没有帮助的事情：

升级了 aws-sdk 和 xray 包：没有变化
我们添加了异常处理和日志记录，但没有学到任何新东西，我们现在将继续这条道路

更新：在“正常”情况下，包括记录多个错误的情况，我们会做同样的事情。我们订阅一个 IoT 主题，发布一条消息并等待最多 5 秒的响应。这些执行都没有超时等待响应（我们最多等待 5 秒，如果没有收到响应则返回错误），并且没有任何 Lambda 执行超时。在上述情况下（日志中的请求 id a71447b0-19f8-456c-b163-47e0408bf3a1）我们不这样做，因为据我所知，我们的代码没有运行 - 没有日志表明它运行了。

这种情况并不经常发生。在过去的几天里，我正在查看大约每 25 次处决中的 1 次。这并没有看到很多负载，因此我们只进行了大约 190 次调用（其中 8 次到目前为止失败）。

【问题讨论】：

你用的是哪个版本？
NodeJs 是 v10.3
如果您的响应是 200 但未定义，有时我们没有从我们的代码中正确返回。
据我所知，我们的代码甚至没有在这个调用上运行。
那么你的 lambda 函数是什么？

标签： node.js aws-lambda

【解决方案1】：

几个月后回来报告，描述这到底是什么以及如何解决它。

这并不明显（但事后看来应该是这样），其根源是专门关于在 lambda 中使用 MQTT.js（作为 AWS IOT SDK 的一部分）。特别是当 lambda 不活动时，它有时会断开连接——这是可以预期的。这里发生的是 MQTT.js 在断开连接时触发一个事件，并且该事件可能在不可预测的时间运行。

总而言之，我们需要同时处理error 和close 事件。如果它们没有被处理，那么我们就会有一个未处理的异常，就像我上面描述的那样。解决这个问题非常简单——我们只需要处理这些事件并创建一个新的客户端等。

我认为我们应该比我们更简单地解决这个问题 - 对我们来说，它与 MQTT 相关并不明显（但一旦我们意识到它相对较快地解决了）。

作为旁注，可能值得指出的是，最新的 AWS SDK for IoT 无论如何都没有在底层使用 MQTTjs。我不确切知道这样做的动机是什么，但考虑到这种变化，我不知道这个问题/答案在未来会有多大用处。

【讨论】：