Debug logging prints wrong state when on_enter function transitions to new state

[MHP47]

First off, great library!

Was tracking down an issue in some code, and couldn't work out what/why was happening. Reason being, the debug logging was actually more confusing than helpful.

Demo code:

from transitions import Machine
import sys

logging.basicConfig(**{'format': '[%(module)s.%(funcName)s.%(lineno)d] %(message)s','level': logging.DEBUG,})

class a():
    GS = [ 'state_1', 'state_2', 'state_3' ]
    GT = [ { 'trigger': 'next_state', 'source': 'state_1', 'dest': 'state_2' }, { 'trigger': 'next_state', 'source': 'state_2', 'dest': 'state_3' } ]
    def __init__(self):
        self._state = Machine(model=self, states=self.GS, transitions=self.GT, initial=self.GS[0])
        self.next_state()
    def on_enter_state_2(self):
        self.next_state()

x = a()
x.state

and this prints:

[core._process.412] Executed machine preparation callbacks before conditions.
[core.execute.257] Initiating transition from state state_1 to state state_2...
[core.execute.260] Executed callbacks before conditions.
[core.execute.266] Executed callback before transition.
[core.exit.126] Exiting state state_1. Processing callbacks...
[core.exit.128] Exited state state_1
[core.enter.120] Entering state state_2. Processing callbacks...
[core._process.412] Executed machine preparation callbacks before conditions.
[core.execute.257] Initiating transition from state state_2 to state state_3...
[core.execute.260] Executed callbacks before conditions.
[core.execute.266] Executed callback before transition.
[core.exit.126] Exiting state state_2. Processing callbacks...
[core.exit.128] Exited state state_2
[core.enter.120] Entering state state_3. Processing callbacks...
[core.enter.122] Entered state state_3
[core.execute.272] Executed callback after transition.
[core._process.425] Executed machine finalize callbacks
[core.callbacks.1045] Executed callback 'on_enter_state_2'
[core.enter.122] Entered state state_2
[core.execute.272] Executed callback after transition.
[core._process.425] Executed machine finalize callbacks
>>> x.state
'state_3'

Which is as expected, transitioning from 1 to 2, then to 3, but then it prints going back to 2. Going off the logging, the state should be 2, but it's clearly 3. The logic seems to work, but the logging catches the walk back up the stack

[aleneum]

Hello @MHP47,

this might look a bit confusing but when you trigger a new event while entering a state, the event will be processed at this point. The message "Entered state " is emitted when all "enter" callbacks have been processed. State 2 isn't actually entered again. If you want to process event triggers sequentially, you can set queued=True in the Machine constructor.