search

spring-projects / spring-statemachine

Spring Statemachine is a framework for application developers to use state machine concepts with Spring.
1.53k stars 599 forks source link

Resetting spring state machine results in infinite loop #1011

Open spac-valentin opened 2 years ago

spac-valentin commented 2 years ago

I am exploring Spring state machine and was testing a scenario where state machine would run to completion after resetting from a specific state but it runs in an infinite loop. The below code is enough to reproduce the issue.

Basically, there is one state machine that on event e1 will transition from s1 to s2 and then it will transition to s3 and s4 (triggerless transition). I want to make this state machine run from s2 to completion, but it ends up in a infinite loop, executing (and printing) s3 action 

    @Test
    public void loop() throws Exception {
        var sm = buildMachine();

        Flux.fromIterable(sm.getStateMachineAccessor().withAllRegions())
                .flatMap(region -> region.resetStateMachineReactively(new DefaultStateMachineContext<>("s2", null, null, null)))
                .subscribe();

        sm.startReactively().block();
        sm.sendEvent(Mono.just(MessageBuilder
                .withPayload("e1")
                .build())).subscribe();
    }

    @SneakyThrows
    StateMachine<String, String> buildMachine() {
        StateMachineBuilder.Builder<String, String> builder = StateMachineBuilder.builder();

        builder.configureConfiguration()
                .withConfiguration()
                .autoStartup(false);

        builder.configureStates()
                .withStates()
                .initial("s1")
                .end("s4")
                .states(Set.of("s1", "s2", "s3", "s4"));

        // @formatter:off
        builder.configureTransitions()
                .withExternal()
                    .source("s1")
                    .event("e1")
                    .target("s2")
                    .action((p) -> logger.info("s2 action"), (p) -> logger.info("s2 action failed"))

                .and()
                .withExternal()
                    .source("s2")
                    .target("s3")
                    .action((p) -> logger.info("s3 action"))

                .and()
                    .withExternal()
                    .source("s3")
                    .target("s4");
        // @formatter:on

        return builder.build();
    }

What am I missing here?

Note: posted on StackOverflow too

spac-valentin commented 2 years ago

My gut says that starting the machine when resetting is the culprit: https://github.com/spring-projects/spring-statemachine/blob/af4cfc4d70212503ed1b066c859f2c59b387d78a/spring-statemachine-core/src/main/java/org/springframework/statemachine/support/AbstractStateMachine.java#L887-L890

spac-valentin commented 2 years ago

Added a listener for more info and for some reason, at some point, state changes from. s4 to s3 (it goes backwards)

2021-11-21 14:20:05.324  INFO 83251 --- [    Test worker] com.rezz.sm.TestSM                       : state changed from s3 to s4
2021-11-21 14:20:05.324  INFO 83251 --- [    Test worker] com.rezz.sm.TestSM                       : stateContext DefaultStateContext [stage=STATE_CHANGED, message=null, messageHeaders={id=ec7792f5-d444-f2ff-b30a-8104e79b3613, timestamp=1637497205324}, extendedState=DefaultExtendedState [variables={}], transition=null, stateMachine=s2 s1 s4 s3  / s4 / uuid=d52c0022-1282-42da-9005-77a0d90b29a3 / id=null, source=ObjectState [getIds()=[s3], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=220055230, toString()=AbstractState [id=s3, pseudoState=null, deferred=[], entryActions=[], exitActions=[], stateActions=[], regions=[], submachine=null]], target=ObjectState [getIds()=[s4], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=41376554, toString()=AbstractState [id=s4, pseudoState=org.springframework.statemachine.state.DefaultPseudoState@651df273, deferred=[], entryActions=[], exitActions=[], stateActions=[], regions=[], submachine=null]], sources=null, targets=null, exception=null]
2021-11-21 14:20:05.325  INFO 83251 --- [    Test worker] com.rezz.sm.TestSM                       : transitionEnded from s3 to s4
2021-11-21 14:20:05.325  INFO 83251 --- [    Test worker] com.rezz.sm.TestSM                       : stateContext DefaultStateContext [stage=TRANSITION_END, message=null, messageHeaders={id=daef3be2-2282-923f-c11d-70950629f8f8, timestamp=1637497205325}, extendedState=DefaultExtendedState [variables={}], transition=AbstractTransition [source=ObjectState [getIds()=[s3], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=220055230, toString()=AbstractState [id=s3, pseudoState=null, deferred=[], entryActions=[], exitActions=[], stateActions=[], regions=[], submachine=null]], target=ObjectState [getIds()=[s4], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=41376554, toString()=AbstractState [id=s4, pseudoState=org.springframework.statemachine.state.DefaultPseudoState@651df273, deferred=[], entryActions=[], exitActions=[], stateActions=[], regions=[], submachine=null]], kind=EXTERNAL, guard=null], stateMachine=s2 s1 s4 s3  / s4 / uuid=d52c0022-1282-42da-9005-77a0d90b29a3 / id=null, source=null, target=null, sources=null, targets=null, exception=null]
2021-11-21 14:20:05.325  INFO 83251 --- [    Test worker] com.rezz.sm.TestSM                       : state changed from s4 to s3
2021-11-21 14:20:05.325  INFO 83251 --- [    Test worker] com.rezz.sm.TestSM                       : stateContext DefaultStateContext [stage=STATE_CHANGED, message=null, messageHeaders={id=684accd0-fd1f-0c9a-c67c-bc3c1b0ad2e2, timestamp=1637497205325}, extendedState=DefaultExtendedState [variables={}], transition=null, stateMachine=s2 s1 s4 s3  / s4 / uuid=d52c0022-1282-42da-9005-77a0d90b29a3 / id=null, source=ObjectState [getIds()=[s4], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=41376554, toString()=AbstractState [id=s4, pseudoState=org.springframework.statemachine.state.DefaultPseudoState@651df273, deferred=[], entryActions=[], exitActions=[], stateActions=[], regions=[], submachine=null]], target=ObjectState [getIds()=[s3], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=220055230, toString()=AbstractState [id=s3, pseudoState=null, deferred=[], entryActions=[], exitActions=[], stateActions=[], regions=[], submachine=null]], sources=null, targets=null, exception=null]
2021-11-21 14:20:05.325  INFO 83251 --- [    Test worker] com.rezz.sm.TestSM                       : transitionEnded from s2 to s3
mroeppis commented 1 year ago

My gut says that starting the machine when resetting is the culprit:

I would agree that this is at least a use case that exposes the issue. I encountered the same behavior when using a StateMachinePersister. Here is a description of my issue that fits the one from above:

Issue Setting

Consider a simple Statemachine with 2 states and 1 triggerless transition:

START -> END

The use case here is:

  1. start the machine that has been 1.1 newly created 1.2 restored

Note that use case point 1.1 is meant for reference. The point of interest is 1.2 where the Statemachine is started as part of the persister's restore procedure: https://github.com/spring-projects/spring-statemachine/blob/cf4eb2f7c0bc861bbd1013da6332e2de4188c8cb/spring-statemachine-core/src/main/java/org/springframework/statemachine/persist/AbstractStateMachinePersister.java#L66-L73

Version Specifics

The issue mainly concerns Spring Statemachine Core 3.2.0 but points out something that might be wrong as well with version 2.5.1 (before going reactive).

Issue Description

The method StateMachine#start( ) behaves differently in version 2.5.1 and 3.2.0.

I attached a MWE with a test for reference (built with Gradle 7.5.1 and JDK 17.0.6).

There are 2 test cases, one for each point from the use case as mentioned above. Both Statemachine versions succeed with point 1.1 but fail 1.2:

Version 2.5.1

The Statemachine remains in START.

This is problematic since we cannot leave this state by an event.

Version 3.2.0

The Statemachine moves to END but does not complete. Instead, it hangs / loops infinitely:

o.s.s.s.ReactiveStateMachineExecutor - About to handleTriggerlessTransitions
o.s.s.support.LifecycleObjectSupport - stopReactively END START  / END / uuid=30cdaa9c-4736-47d1-be70-e7ad890b919b / id=null with rlm [lifecyclestate=STARTING, owner=END START  / END / uuid=30cdaa9c-4736-47d1-be70-e7ad890b919b / id=null]
o.s.s.s.ReactiveLifecycleManager - Request stopReactively [lifecyclestate=STARTING, owner=END START  / END / uuid=30cdaa9c-4736-47d1-be70-e7ad890b919b / id=null]
o.s.s.s.ReactiveLifecycleManager - Don't own, requesting to postpone stop[lifecyclestate=STARTING, owner=END START  / END / uuid=30cdaa9c-4736-47d1-be70-e7ad890b919b / id=null]
o.s.s.support.AbstractStateMachine - Trying Exit state=[ObjectState [getIds()=[END], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=738937987, toString()=AbstractState [id=END, pseudoState=org.springframework.statemachine.state.DefaultPseudoState@78525ef9, deferred=[], entryActions=[], exitActions=[], stateActions=[], regions=[], submachine=null]]]
o.s.s.support.AbstractStateMachine - Exit state=[ObjectState [getIds()=[END], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=738937987, toString()=AbstractState [id=END, pseudoState=org.springframework.statemachine.state.DefaultPseudoState@78525ef9, deferred=[], entryActions=[], exitActions=[], stateActions=[], regions=[], submachine=null]]]
o.s.s.support.AbstractStateMachine - Trying Enter state=[ObjectState [getIds()=[END], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=738937987, toString()=AbstractState [id=END, pseudoState=org.springframework.statemachine.state.DefaultPseudoState@78525ef9, deferred=[], entryActions=[], exitActions=[], stateActions=[], regions=[], submachine=null]]]
o.s.s.support.AbstractStateMachine - Trying Enter state=[ObjectState [getIds()=[END], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=738937987, toString()=AbstractState [id=END, pseudoState=org.springframework.statemachine.state.DefaultPseudoState@78525ef9, deferred=[], entryActions=[], exitActions=[], stateActions=[], regions=[], submachine=null]]]
o.s.s.support.AbstractStateMachine - Enter state=[ObjectState [getIds()=[END], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=738937987, toString()=AbstractState [id=END, pseudoState=org.springframework.statemachine.state.DefaultPseudoState@78525ef9, deferred=[], entryActions=[], exitActions=[], stateActions=[], regions=[], submachine=null]]]
o.s.s.support.AbstractStateMachine - State onComplete: state=[ObjectState [getIds()=[END], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=738937987, toString()=AbstractState [id=END, pseudoState=org.springframework.statemachine.state.DefaultPseudoState@78525ef9, deferred=[], entryActions=[], exitActions=[], stateActions=[], regions=[], submachine=null]]] context=[DefaultStateContext [stage=STATE_ENTRY, message=null, messageHeaders={id=c8c9f2be-113e-04f0-724b-1f9e14598be2, timestamp=1682614107675}, extendedState=DefaultExtendedState [variables={}], transition=AbstractTransition [source=ObjectState [getIds()=[START], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=755944228, toString()=AbstractState [id=START, pseudoState=org.springframework.statemachine.state.DefaultPseudoState@4d654825, deferred=[], entryActions=[], exitActions=[], stateActions=[], regions=[], submachine=null]], target=ObjectState [getIds()=[END], getClass()=class org.springframework.statemachine.state.ObjectState, hashCode()=738937987, toString()=AbstractState [id=END, pseudoState=org.springframework.statemachine.state.DefaultPseudoState@78525ef9, deferred=[], entryActions=[], exitActions=[], stateActions=[], regions=[], submachine=null]], kind=EXTERNAL, guard=null], stateMachine=END START  / END / uuid=30cdaa9c-4736-47d1-be70-e7ad890b919b / id=null, source=null, target=null, sources=null, targets=null, exception=null]]
o.s.s.s.ReactiveStateMachineExecutor - About to handleTriggerlessTransitions
...

Expected Behavior

Starting the Statemachine should always execute the triggerless transition to END.

radmirr commented 4 months ago

Version 4.0.0, problem still persist. Another fact about problem: setting lastState field of stateMachine to null (via debugger or reflection) between restore and startReactively call leads to correct execution without loop. This field affects behavior of this method https://github.com/spring-projects/spring-statemachine/blob/4495c7dd7784f35d78c6e88c490466e05bc24cb9/spring-statemachine-core/src/main/java/org/springframework/statemachine/support/AbstractStateMachine.java#L184-L194 And looks like on some point (while performing stopReactively) machine returning lastState instead of current state and machine goes back to infinite loop and never finish.