search

spring-cloud / spring-cloud-gateway

An API Gateway built on Spring Framework and Spring Boot providing routing and more.
http://cloud.spring.io
Apache License 2.0
4.53k stars 3.32k forks source link

Gateway throws HystrixRuntimeException "command executed multiple times" #322

Open rbraeunlich opened 6 years ago

rbraeunlich commented 6 years ago

Hi everyone, I've created a simple Gateway containing three routes, of which on is protected Hystrix. The route itself basically looks like this:

route("cookie is there",
     r -> r.cookie(COOKIE, REGEX)
              .filters(f -> f
                                .preserveHostHeader()
                                .retry(DEFAULT_RETRY_COUNT)
                                 .hystrix(c -> c.setSetter(
                                                HystrixObservableCommand.Setter        .withGroupKey(HystrixCommandGroupKey.Factory.asKey(HYSTRIX_COMMAND_GROUP))
.andCommandKey(HystrixCommandKey.Factory.asKey(serviceName + COMMAND_KEY))
                                        ))
                                )
                                .uri(uri)

when calling this route, is sometimes crashes probably due to an unstable network. What caught my attention was that the gateway logs this exception:

com.netflix.hystrix.exception.HystrixRuntimeException: gateway_ALL_tokenPresentRoute command executed multiple times - this is not permitted.
    at com.netflix.hystrix.AbstractCommand$7.call(AbstractCommand.java:461)
    at com.netflix.hystrix.AbstractCommand$7.call(AbstractCommand.java:454)
    at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:46)
    at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:35)
    at rx.Observable.subscribe(Observable.java:10423)
    at rx.Observable.subscribe(Observable.java:10390)
    at rx.Observable.subscribe(Observable.java:10271)
    at org.springframework.cloud.gateway.filter.factory.HystrixGatewayFilterFactory.lambda$null$0(HystrixGatewayFilterFactory.java:98)
    at reactor.core.publisher.MonoCreate.subscribe(MonoCreate.java:53)
    at reactor.core.publisher.MonoOnErrorResume.subscribe(MonoOnErrorResume.java:44)
    at reactor.core.publisher.Mono.subscribe(Mono.java:3080)
    at reactor.core.publisher.MonoIgnorePublisher.subscribe(MonoIgnorePublisher.java:41)
    at reactor.core.publisher.Mono.subscribe(Mono.java:3080)
    at reactor.core.publisher.FluxRepeatWhen$RepeatWhenMainSubscriber.resubscribe(FluxRepeatWhen.java:176)
    at reactor.core.publisher.FluxRepeatWhen$RepeatWhenOtherSubscriber.onNext(FluxRepeatWhen.java:225)
    at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.innerNext(FluxConcatMap.java:271)
    at reactor.core.publisher.FluxConcatMap$ConcatMapInner.onNext(FluxConcatMap.java:803)
    at reactor.core.publisher.FluxConcatMap$WeakScalarSubscription.request(FluxConcatMap.java:446)
    at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:1444)
    at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:412)
    at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onNext(FluxConcatMap.java:241)
    at reactor.core.publisher.FluxTakeWhile$TakeWhileSubscriber.onNext(FluxTakeWhile.java:94)
    at reactor.core.publisher.FluxZip$ZipCoordinator.drain(FluxZip.java:729)
    at reactor.core.publisher.FluxZip$ZipInner.onNext(FluxZip.java:888)
    at reactor.core.publisher.DirectProcessor$DirectInner.onNext(DirectProcessor.java:297)
    at reactor.core.publisher.DirectProcessor.onNext(DirectProcessor.java:106)
    at reactor.core.publisher.SerializedSubscriber.onNext(SerializedSubscriber.java:89)
    at reactor.core.publisher.FluxRepeatWhen$RepeatWhenMainSubscriber.onComplete(FluxRepeatWhen.java:156)
    at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onComplete(MonoIgnoreElements.java:80)
    at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onComplete(Operators.java:1308)
    at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onComplete(MonoIgnoreElements.java:80)
    at reactor.core.publisher.FluxConcatIterable$ConcatIterableSubscriber.onComplete(FluxConcatIterable.java:115)
    at reactor.core.publisher.FluxConcatIterable.subscribe(FluxConcatIterable.java:60)
    at reactor.core.publisher.MonoIgnoreElements.subscribe(MonoIgnoreElements.java:37)
    at reactor.core.publisher.Mono.subscribe(Mono.java:3080)
    at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:97)
    at reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:160)
    at rx.internal.util.ActionSubscriber.onError(ActionSubscriber.java:44)
    at rx.observers.SafeSubscriber._onError(SafeSubscriber.java:153)
    at rx.observers.SafeSubscriber.onError(SafeSubscriber.java:115)
    at rx.observers.Subscribers$5.onError(Subscribers.java:230)
    at rx.internal.operators.OnSubscribeDoOnEach$DoOnEachSubscriber.onError(OnSubscribeDoOnEach.java:87)
    at rx.observers.Subscribers$5.onError(Subscribers.java:230)
    at rx.internal.operators.OnSubscribeDoOnEach$DoOnEachSubscriber.onError(OnSubscribeDoOnEach.java:87)
    at rx.internal.operators.OnSubscribeMap$MapSubscriber.onError(OnSubscribeMap.java:88)
    at rx.observers.Subscribers$5.onError(Subscribers.java:230)
    at rx.observers.Subscribers$5.onError(Subscribers.java:230)
    at rx.internal.operators.OnSubscribeDoOnEach$DoOnEachSubscriber.onError(OnSubscribeDoOnEach.java:87)
    at rx.internal.operators.OnSubscribeDoOnEach$DoOnEachSubscriber.onError(OnSubscribeDoOnEach.java:87)
    at rx.internal.operators.OnSubscribeDoOnEach$DoOnEachSubscriber.onError(OnSubscribeDoOnEach.java:87)
    at rx.internal.operators.OperatorOnErrorResumeNextViaFunction$4$1.onError(OperatorOnErrorResumeNextViaFunction.java:122)
    at rx.observers.Subscribers$5.onError(Subscribers.java:230)
    at rx.internal.operators.OnSubscribeDoOnEach$DoOnEachSubscriber.onError(OnSubscribeDoOnEach.java:87)
    at rx.internal.operators.OperatorOnErrorResumeNextViaFunction$4$1.onError(OperatorOnErrorResumeNextViaFunction.java:122)
    at rx.internal.operators.OnSubscribeThrow.call(OnSubscribeThrow.java:44)
    at rx.internal.operators.OnSubscribeThrow.call(OnSubscribeThrow.java:28)
    at rx.Observable.unsafeSubscribe(Observable.java:10327)
    at rx.internal.operators.OperatorOnErrorResumeNextViaFunction$4.onError(OperatorOnErrorResumeNextViaFunction.java:142)
    at rx.internal.operators.OnSubscribeDoOnEach$DoOnEachSubscriber.onError(OnSubscribeDoOnEach.java:87)
    at rx.internal.operators.OnSubscribeDoOnEach$DoOnEachSubscriber.onError(OnSubscribeDoOnEach.java:87)
    at com.netflix.hystrix.AbstractCommand$DeprecatedOnFallbackHookApplication$1.onError(AbstractCommand.java:1472)
    at com.netflix.hystrix.AbstractCommand$FallbackHookApplication$1.onError(AbstractCommand.java:1397)
    at rx.internal.operators.OnSubscribeDoOnEach$DoOnEachSubscriber.onError(OnSubscribeDoOnEach.java:87)
    at rx.internal.operators.OnSubscribeThrow.call(OnSubscribeThrow.java:44)
    at rx.internal.operators.OnSubscribeThrow.call(OnSubscribeThrow.java:28)
    at rx.Observable.unsafeSubscribe(Observable.java:10327)
    at rx.internal.operators.OnSubscribeDoOnEach.call(OnSubscribeDoOnEach.java:41)
    at rx.internal.operators.OnSubscribeDoOnEach.call(OnSubscribeDoOnEach.java:30)
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
    at rx.Observable.unsafeSubscribe(Observable.java:10327)
    at rx.internal.operators.OnSubscribeDoOnEach.call(OnSubscribeDoOnEach.java:41)
    at rx.internal.operators.OnSubscribeDoOnEach.call(OnSubscribeDoOnEach.java:30)
    at rx.Observable.unsafeSubscribe(Observable.java:10327)
    at rx.internal.operators.OnSubscribeDoOnEach.call(OnSubscribeDoOnEach.java:41)
    at rx.internal.operators.OnSubscribeDoOnEach.call(OnSubscribeDoOnEach.java:30)
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
    at rx.Observable.unsafeSubscribe(Observable.java:10327)
    at rx.internal.operators.OnSubscribeDoOnEach.call(OnSubscribeDoOnEach.java:41)
    at rx.internal.operators.OnSubscribeDoOnEach.call(OnSubscribeDoOnEach.java:30)
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
    at rx.Observable.unsafeSubscribe(Observable.java:10327)
    at rx.internal.operators.OperatorOnErrorResumeNextViaFunction$4.onError(OperatorOnErrorResumeNextViaFunction.java:142)
    at rx.internal.operators.OnSubscribeDoOnEach$DoOnEachSubscriber.onError(OnSubscribeDoOnEach.java:87)
    at rx.internal.operators.OnSubscribeDoOnEach$DoOnEachSubscriber.onError(OnSubscribeDoOnEach.java:87)
    at com.netflix.hystrix.AbstractCommand$HystrixObservableTimeoutOperator$1$1.run(AbstractCommand.java:1154)
    at com.netflix.hystrix.strategy.concurrency.HystrixContextRunnable$1.call(HystrixContextRunnable.java:45)
    at com.netflix.hystrix.strategy.concurrency.HystrixContextRunnable$1.call(HystrixContextRunnable.java:41)
    at com.netflix.hystrix.strategy.concurrency.HystrixContextRunnable.run(HystrixContextRunnable.java:61)
    at com.netflix.hystrix.AbstractCommand$HystrixObservableTimeoutOperator$1.tick(AbstractCommand.java:1159)
    at com.netflix.hystrix.util.HystrixTimer$1.run(HystrixTimer.java:99)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.IllegalStateException: This instance can only be executed once. Please instantiate a new instance.
    at com.netflix.hystrix.AbstractCommand$7.call(AbstractCommand.java:459)

Since the HystrixGatewayFilterFactory is responsible for creating the commands I wonder how this could happen. Thank you for your help! Cheers, Ronny

spencergibb commented 6 years ago

Have you tried with the retry filter after the Hystrix one?

rbraeunlich commented 6 years ago

Thank you @spencergibb, this solved the issue!

spencergibb commented 6 years ago

Let's reopen to document

rbraeunlich commented 6 years ago

Hey @spencergibb good idea, this might help to avoid copies of this bug report in the future. I guess you gotta change the label then.

nitish076 commented 5 years ago

@spencergibb i am getting the same issue though it is not while using spring-cloud-gateway, while making multiple feign calls with different request but to the same Api. can you please clarify why this exception happens, and what should be the logical way to solve it?

spencergibb commented 5 years ago

@nitish076 then it isn't the same issue as this one is specific to gateway and filter ordering, please ask in spring-cloud-openfeign or gitter.