Как начать отладку «HTTP-сервер неожиданно закрыл соединение, прежде чем доставить ответы на 1 невыполненный запрос» - PullRequest
1 голос
/ 20 июня 2020

Я включил ведение журнала на уровне DEBUG для своего приложения, но не вижу ничего полезного, объясняющего, почему http-сервер закрывает соединение. Это исключение происходит в SqsPublishSink alpakka, который использует SqsAsyncClient. Похоже, это проблема не с SQS, а с http-клиентом akka, используемым для отправки сообщений SQS. Эти проблемы начали появляться неожиданно, поэтому я не уверен, с чего начать, чтобы разобраться в этом.

[DEBUG] [06/19/2020 17:18:04.081] [aws-akka-http-akka.actor.default-dispatcher-38] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] Dispatching request [POST  Default(6331 bytes)] to pool
[DEBUG] [06/19/2020 17:18:04.081] [aws-akka-http-akka.actor.default-dispatcher-38] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] [0 (Idle)] Dispatching request [POST / Default(6331 bytes)]
[DEBUG] [06/19/2020 17:18:04.081] [aws-akka-http-akka.actor.default-dispatcher-38] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] [0 (Idle)] Before event [onNewRequest] In state [Idle] for [951 ms]
[DEBUG] [06/19/2020 17:18:04.081] [aws-akka-http-akka.actor.default-dispatcher-38] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] [0 (PushingRequestToConnection)] After event [onNewRequest] State change [Idle] -> [PushingRequestToConnection]
[DEBUG] [06/19/2020 17:18:04.081] [aws-akka-http-akka.actor.default-dispatcher-38] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] [0 (PushingRequestToConnection)] Before event [onRequestDispatched] In state [PushingRequestToConnection] for [0 ms]
[DEBUG] [06/19/2020 17:18:04.081] [aws-akka-http-akka.actor.default-dispatcher-38] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] [0 (WaitingForResponse)] After event [onRequestDispatched] State change [PushingRequestToConnection] -> [WaitingForResponse]
[DEBUG] [06/19/2020 17:18:04.081] [aws-akka-http-akka.actor.default-dispatcher-38] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] [0 (WaitingForResponse)] Before event [onRequestEntityCompleted] In state [WaitingForResponse] for [0 ms]
[DEBUG] [06/19/2020 17:18:04.081] [aws-akka-http-akka.actor.default-dispatcher-38] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] [0 (WaitingForResponse)] After event [onRequestEntityCompleted] State change [WaitingForResponse] -> [WaitingForResponse]
[DEBUG] [06/19/2020 17:18:04.145] [aws-akka-http-akka.actor.default-dispatcher-19] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] [0 (WaitingForResponse)] Connection cancelled
[DEBUG] [06/19/2020 17:18:04.146] [aws-akka-http-akka.actor.default-dispatcher-19] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] [0 (WaitingForResponse)] Connection failed
[DEBUG] [06/19/2020 17:18:04.146] [aws-akka-http-akka.actor.default-dispatcher-19] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] [0 (WaitingForResponse)] Before event [onConnectionFailed] In state [WaitingForResponse] for [65 ms]
[DEBUG] [06/19/2020 17:18:04.146] [aws-akka-http-akka.actor.default-dispatcher-19] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] [0 (WaitingForResponse)] Ongoing request [POST / Default(6331 bytes)] is failed because of [connection failure]: [The http server closed the connection unexpectedly before delivering responses for 1 outstanding requests]
[DEBUG] [06/19/2020 17:18:04.146] [aws-akka-http-akka.actor.default-dispatcher-19] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] [0 (WaitingForResponseDispatch)] After event [onConnectionFailed] State change [WaitingForResponse] -> [WaitingForResponseDispatch]
[DEBUG] [06/19/2020 17:18:04.146] [aws-akka-http-akka.actor.default-dispatcher-19] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] [0 (WaitingForResponseDispatch)] Before event [onResponseDispatchable] In state [WaitingForResponseDispatch] for [0 ms]
[DEBUG] [06/19/2020 17:18:04.147] [aws-akka-http-akka.actor.default-dispatcher-19] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] [0 (Failed)] After event [onResponseDispatchable] State change [WaitingForResponseDispatch] -> [Failed]
[DEBUG] [06/19/2020 17:18:04.147] [aws-akka-http-akka.actor.default-dispatcher-19] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] [0 (Failed)] State change from [WaitingForResponseDispatch] to [Failed(akka.http.impl.engine.client.OutgoingConnectionBlueprint$UnexpectedConnectionClosureException: The http server closed the connection unexpectedly before delivering responses for 1 outstanding requests)]. Closing the existing connection.
[DEBUG] [06/19/2020 17:18:04.147] [aws-akka-http-akka.actor.default-dispatcher-19] [aws-akka-http/Pool(shared->https://sqs.us-east-1.amazonaws.com:443)] [0 (Unconnected)] Slot became idle... Trying to pull
{"@timestamp":"2020-06-19T17:18:04.166-04:00","@version":"1","message":"error occurred in event stream","logger_name":"myorg.events.integration.Foo$","thread_name":"poker-actor-system-akka.actor.default-dispatcher-47","level":"ERROR","level_value":40000,"stack_trace":"java.util.concurrent.CompletionException: software.amazon.awssdk.core.exception.SdkClientException: Unable to execute HTTP request: The http server closed the connection unexpectedly before delivering responses for 1 outstanding requests
\tat software.amazon.awssdk.utils.CompletableFutureUtils.errorAsCompletionException(CompletableFutureUtils.java:60)
\tat software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncExecutionFailureExceptionReportingStage.lambda$execute$0(AsyncExecutionFailureExceptionReportingStage.java:51)
\tat java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:822)
\tat java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:797)
\tat java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
\tat java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977)
\tat software.amazon.awssdk.utils.CompletableFutureUtils.lambda$forwardExceptionTo$0(CompletableFutureUtils.java:74)
\tat java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:760)
\tat java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736)
\tat java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
\tat java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977)
\tat software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryingExecutor.maybeAttemptExecute(AsyncRetryableStage.java:85)
\tat software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryingExecutor.maybeRetryExecute(AsyncRetryableStage.java:144)
\tat software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryingExecutor.lambda$attemptExecute$1(AsyncRetryableStage.java:125)
\tat java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:760)
\tat java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736)
\tat java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
\tat java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977)
\tat software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage$WrappedErrorForwardingResponseHandler.onError(MakeAsyncHttpRequestStage.java:122)
\tat com.github.matsluni.akkahttpspi.RequestRunner.$anonfun$run$6(RequestRunner.scala:66)
\tat com.github.matsluni.akkahttpspi.RequestRunner.$anonfun$run$6$adapted(RequestRunner.scala:66)
\tat scala.util.Success.foreach(Try.scala:253)
\tat scala.concurrent.Future.$anonfun$foreach$1$adapted(Future.scala:229)
\tat scala.concurrent.impl.CallbackRunnable.run(Promise.scala:64)
\tat akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55)
\tat akka.dispatch.BatchingExecutor$BlockableBatch.$anonfun$run$1(BatchingExecutor.scala:92)
\tat scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
\tat scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:85)
\tat akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:92)
\tat akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:41)
\tat akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(ForkJoinExecutorConfigurator.scala:49)
\tat akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
\tat akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
\tat akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
\tat akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
Caused by: software.amazon.awssdk.core.exception.SdkClientException: Unable to execute HTTP request: The http server closed the connection unexpectedly before delivering responses for 1 outstanding requests
\tat software.amazon.awssdk.core.exception.SdkClientException$BuilderImpl.build(SdkClientException.java:98)
\tat software.amazon.awssdk.core.exception.SdkClientException.create(SdkClientException.java:43)
\tat software.amazon.awssdk.core.internal.http.pipeline.stages.utils.RetryableStageHelper.setLastException(RetryableStageHelper.java:201)
\tat software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryingExecutor.maybeRetryExecute(AsyncRetryableStage.java:143)
\t... 22 common frames omitted
Caused by: akka.http.impl.engine.client.OutgoingConnectionBlueprint$UnexpectedConnectionClosureException: The http server closed the connection unexpectedly before delivering responses for 1 outstanding requests
\tat akka.http.impl.engine.client.OutgoingConnectionBlueprint$.$anonfun$apply$6(OutgoingConnectionBlueprint.scala:123)
\tat akka.http.impl.engine.client.OutgoingConnectionBlueprint$.$anonfun$apply$6$adapted(OutgoingConnectionBlueprint.scala:123)
\tat akka.http.impl.util.One2OneBidiFlow$One2OneBidi$$anon$1$$anon$4.onUpstreamFinish(One2OneBidiFlow.scala:97)
\tat akka.stream.impl.fusing.GraphInterpreter.processEvent(GraphInterpreter.scala:506)
\tat akka.stream.impl.fusing.GraphInterpreter.execute(GraphInterpreter.scala:376)
\tat akka.stream.impl.fusing.GraphInterpreterShell.runBatch(ActorGraphInterpreter.scala:606)
\tat akka.stream.impl.fusing.ActorGraphInterpreter$SimpleBoundaryEvent.execute(ActorGraphInterpreter.scala:47)
\tat akka.stream.impl.fusing.ActorGraphInterpreter$SimpleBoundaryEvent.execute$(ActorGraphInterpreter.scala:43)
\tat akka.stream.impl.fusing.ActorGraphInterpreter$BatchingActorInputBoundary$OnComplete.execute(ActorGraphInterpreter.scala:76)
\tat akka.stream.impl.fusing.GraphInterpreterShell.processEvent(ActorGraphInterpreter.scala:581)
\tat akka.stream.impl.fusing.ActorGraphInterpreter.akka$stream$impl$fusing$ActorGraphInterpreter$$processEvent(ActorGraphInterpreter.scala:749)
\tat akka.stream.impl.fusing.ActorGraphInterpreter$$anonfun$receive$1.applyOrElse(ActorGraphInterpreter.scala:764)
\tat akka.actor.Actor.aroundReceive(Actor.scala:539)
\tat akka.actor.Actor.aroundReceive$(Actor.scala:537)
\tat akka.stream.impl.fusing.ActorGraphInterpreter.aroundReceive(ActorGraphInterpreter.scala:671)
\tat akka.actor.ActorCell.receiveMessage(ActorCell.scala:614)
\tat akka.actor.ActorCell.invoke(ActorCell.scala:583)
\tat akka.dispatch.Mailbox.processMailbox(Mailbox.scala:268)
\tat akka.dispatch.Mailbox.run(Mailbox.scala:229)
\tat akka.dispatch.Mailbox.exec(Mailbox.scala:241)
\t... 4 common frames omitted
"}
...