spring-cloud / spring-cloud/spring-cloud-gateway

Gateway throws HystrixRuntimeException "command executed multiple times"

Open
#322 6 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

documentation
Dominant language
Java
Stars
4.9k
Forks
3.5k
Avg merge
20h 57m
Merged PRs (30d)
8

Description

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

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start at HystrixGatewayFilterFactory.java around line 98 and trace the Hystrix filter together with the retry operator shown in the stack trace. Reproduce the protected route with an unstable network and inspect the command lifecycle; done means the repeated-execution failure is explained and covered by a regression test.

Written by the indexing model from the issue text.

Assessment

Tech stack
java, spring
Domain
api, backend
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.