Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Why is client behavior's OnExit always called twice when exiting a state #556

Open
ynyBonfennil opened this issue Aug 2, 2024 · 8 comments · Fixed by #558
Open

Why is client behavior's OnExit always called twice when exiting a state #556

ynyBonfennil opened this issue Aug 2, 2024 · 8 comments · Fixed by #558

Comments

@ynyBonfennil
Copy link

I created a sample state machine my_state_machine with create-sm-package.bash. And I ran with ros2 run my_state_machine my_state_machine_node.

I noticed that client behavior's OnExit is called twice when exiting a state. OnEntry seems to be called only once but why is it called twice? Here is the log from my_state_machine.

$ ros2 run my_state_machine my_state_machine_node 
[INFO] [1722598816.090138255] [MyStateMachine]: Creating State Machine Base: /MyStateMachine
[INFO] [1722598816.090269772] [MyStateMachine]: [my_state_machine::OrTimer] creating client object, type:'cl_ros_timer::ClRosTimer' object tag: 'my_state_machine::OrTimer'
[INFO] [1722598816.090305307] [MyStateMachine]: my_state_machine::OrTimer Orthogonal is created
[INFO] [1722598816.090315011] [MyStateMachine]: [SmaccStateMachine] Introspecting state machine via typeWalker
[INFO] [1722598816.090322960] [MyStateMachine]: Creating State Info: my_state_machine::State1
[INFO] [1722598816.090344920] [MyStateMachine]: EXECUTING ONDEFINITION: my_state_machine::State1
[INFO] [1722598816.090643332] [static]: [states walking] State State1client behavior count: 1
[INFO] [1722598816.090656275] [static]: [states walking] State State1client behavior count: 2
[INFO] [1722598816.090658731] [MyStateMachine]: State N16my_state_machine6State1E Walker has transition list
[INFO] [1722598816.094377142] [MyStateMachine]: State my_state_machine::State1 Walker transition: cl_ros_timer::EvTimer<cl_ros_timer::CbTimerCountdownOnce, my_state_machine::OrTimer>
[INFO] [1722598816.094387822] [MyStateMachine]: State my_state_machine::State1 Walker transition: cl_ros_timer::EvTimer<cl_ros_timer::CbTimerCountdownOnce, my_state_machine::OrTimer>
[INFO] [1722598816.094419712] [MyStateMachine]: Transition tag: smacc2::default_transition_tags::SUCCESS
[INFO] [1722598816.094425544] [MyStateMachine]: Creating State Info: my_state_machine::State2
[INFO] [1722598816.094432522] [MyStateMachine]: EXECUTING ONDEFINITION: my_state_machine::State2
[INFO] [1722598816.094658126] [static]: [states walking] State State2client behavior count: 1
[INFO] [1722598816.094661810] [MyStateMachine]: State N16my_state_machine6State2E Walker has transition list
[INFO] [1722598816.098288455] [MyStateMachine]: State my_state_machine::State2 Walker transition: cl_ros_timer::EvTimer<cl_ros_timer::CbTimerCountdownOnce, my_state_machine::OrTimer>
[INFO] [1722598816.098297493] [MyStateMachine]: State my_state_machine::State2 Walker transition: cl_ros_timer::EvTimer<cl_ros_timer::CbTimerCountdownOnce, my_state_machine::OrTimer>
[INFO] [1722598816.098305523] [MyStateMachine]: Transition tag: smacc2::default_transition_tags::SUCCESS
[INFO] [1722598816.098756391] [MyStateMachine]: [SmaccStateMachine] initiate_impl
[WARN] [1722598816.098776098] [MyStateMachine]: State machine base creation:MyStateMachine
[INFO] [1722598816.099732258] [MyStateMachine]: [SmaccStateMachine] Initializing ROS communication mechanisms
[INFO] [1722598816.099794456] [MyStateMachine]: [SmaccStateMachine] Initializing state machine
[INFO] [1722598816.099819793] [State1]: [my_state_machine::State1] creating state 
[INFO] [1722598816.099843856] [State1]: [my_state_machine::State1] Initializing orthogonal: my_state_machine::OrTimer
[INFO] [1722598816.099848543] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] initState: my_state_machine::State1
[INFO] [1722598816.099875032] [State1]: [my_state_machine::State1] Configuring orthogonal: my_state_machine::OrTimer
[INFO] [1722598816.099884230] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] adding client behavior: cl_ros_timer::CbTimerCountdownLoop
[INFO] [1722598816.099901465] [State1]: [my_state_machine::State1] Configuring orthogonal: my_state_machine::OrTimer
[INFO] [1722598816.099906561] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] adding client behavior: cl_ros_timer::CbTimerCountdownOnce
[INFO] [1722598816.099920261] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] runtimeConfigure, current Behavior: cl_ros_timer::CbTimerCountdownLoop
[INFO] [1722598816.099925810] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] runtimeConfigure, current Behavior: cl_ros_timer::CbTimerCountdownOnce
[WARN] [1722598816.099932258] [MyStateMachine]: [StateMachine] setting state active : my_state_machine::State1
[INFO] [1722598816.100004295] [State1]:  On Entry!
[INFO] [1722598816.100007710] [MyStateMachine]: [my_state_machine::State1] State OnEntry code finished
[INFO] [1722598816.100035673] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] OnEntry, current Behavior: cl_ros_timer::CbTimerCountdownLoop
[INFO] [1722598816.100044652] [MyStateMachine]: [StateMachine] life-time constrained smacc signal subscription created. Subscriber is cl_ros_timer::CbTimerCountdownLoop
[INFO] [1722598816.100076999] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] OnEntry, current Behavior: cl_ros_timer::CbTimerCountdownOnce
[INFO] [1722598816.100082435] [MyStateMachine]: [StateMachine] life-time constrained smacc signal subscription created. Subscriber is cl_ros_timer::CbTimerCountdownOnce
[WARN] [1722598816.100092763] [MyStateMachine]: [StateMachine] setting state active : my_state_machine::State1
[WARN] [1722598816.131691955] [MyStateMachine]: Signal detector frequency (ros param signal_detector_loop_freq): 20.000000
[INFO] [1722598816.131910208] [MyStateMachine]: [SignalDetector] loop rate hz:20
[INFO] [1722598816.131950335] [MyStateMachine]: [SignalDetector] running in single threaded mode
[INFO] [1722598816.131985468] [MyStateMachine]: [SignalDetector] heartbeat
[INFO] [1722598817.132788702] [MyStateMachine]: Event cl_ros_timer::EvTimer<cl_ros_timer::ClRosTimer, my_state_machine::OrTimer>
[INFO] [1722598818.132835643] [MyStateMachine]: Event cl_ros_timer::EvTimer<cl_ros_timer::ClRosTimer, my_state_machine::OrTimer>
[INFO] [1722598819.132762781] [MyStateMachine]: Event cl_ros_timer::EvTimer<cl_ros_timer::CbTimerCountdownLoop, my_state_machine::OrTimer>
[INFO] [1722598819.133077308] [MyStateMachine]: Event cl_ros_timer::EvTimer<cl_ros_timer::ClRosTimer, my_state_machine::OrTimer>
[INFO] [1722598820.133356017] [MyStateMachine]: Event cl_ros_timer::EvTimer<cl_ros_timer::ClRosTimer, my_state_machine::OrTimer>
[INFO] [1722598821.132745726] [MyStateMachine]: Event cl_ros_timer::EvTimer<cl_ros_timer::CbTimerCountdownOnce, my_state_machine::OrTimer>
[INFO] [1722598821.133044482] [MyStateMachine]: Event cl_ros_timer::EvTimer<cl_ros_timer::ClRosTimer, my_state_machine::OrTimer>
[INFO] [1722598821.133387538] [State1]: TRANSITION RULE TRIGGERED: smacc2::Transition<cl_ros_timer::EvTimer<cl_ros_timer::CbTimerCountdownOnce, my_state_machine::OrTimer>, my_state_machine::State2, smacc2::default_transition_tags::SUCCESS, boost::statechart::detail::no_context<cl_ros_timer::EvTimer<cl_ros_timer::CbTimerCountdownOnce, my_state_machine::OrTimer> >, &boost::statechart::detail::no_context<cl_ros_timer::EvTimer<cl_ros_timer::CbTimerCountdownOnce, my_state_machine::OrTimer> >::no_function>
[WARN] [1722598821.133998438] [MyStateMachine]: exiting state: my_state_machine::State1
[INFO] [1722598821.134167449] [MyStateMachine]: Notification State Exit: leaving state 0x750540088ec0
[INFO] [1722598821.134298646] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] OnExit, current Behavior: cl_ros_timer::CbTimerCountdownLoop
[INFO] [1722598821.134416566] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] OnExit, current Behavior: cl_ros_timer::CbTimerCountdownOnce
[WARN] [1722598821.134515237] [MyStateMachine]: exiting state: my_state_machine::State1
[INFO] [1722598821.134582148] [MyStateMachine]: Notification State Exit: leaving state 0x750540088ec0
[INFO] [1722598821.134648333] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] OnExit, current Behavior: cl_ros_timer::CbTimerCountdownLoop
[INFO] [1722598821.134732799] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] OnExit, current Behavior: cl_ros_timer::CbTimerCountdownOnce
[INFO] [1722598821.134871763] [State1]: {I am very cool smacc2 SM called 'my_state_machine'} On Exit!
[WARN] [1722598821.134950838] [MyStateMachine]: exiting state: my_state_machine::State1
[INFO] [1722598821.135015930] [MyStateMachine]: Notification State Disposing: leaving state0x750540088ec0
[INFO] [1722598821.135083241] [MyStateMachine]: [SmaccSignals] object signal disconnecting 128665409464192
[INFO] [1722598821.135436974] [MyStateMachine]: [SmaccSignals] object signal disconnecting 128665409468736
[WARN] [1722598821.135565183] [MyStateMachine]: [smacc2::ISmaccClientBehaviorClient behavior deallocated.
[WARN] [1722598821.135747379] [MyStateMachine]: [smacc2::ISmaccClientBehaviorClient behavior deallocated.
[WARN] [1722598821.135827820] [MyStateMachine]: state exit: my_state_machine::State1
[INFO] [1722598821.136026451] [State2]: [my_state_machine::State2] creating state 
[INFO] [1722598821.136235588] [State2]: [my_state_machine::State2] Initializing orthogonal: my_state_machine::OrTimer
[INFO] [1722598821.136276877] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] initState: my_state_machine::State2
[INFO] [1722598821.136407645] [State2]: [my_state_machine::State2] Configuring orthogonal: my_state_machine::OrTimer
[INFO] [1722598821.136468231] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] adding client behavior: cl_ros_timer::CbTimerCountdownOnce
[INFO] [1722598821.136582059] [State2]:  Entering State2
[INFO] [1722598821.136621780] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] runtimeConfigure, current Behavior: cl_ros_timer::CbTimerCountdownOnce
[WARN] [1722598821.136683221] [MyStateMachine]: [StateMachine] setting state active : my_state_machine::State2
[INFO] [1722598821.136846134] [State2]: {I am very cool smacc2 SM called 'my_state_machine'} On Entry!
[INFO] [1722598821.136881071] [MyStateMachine]: [my_state_machine::State2] State OnEntry code finished
[INFO] [1722598821.136940173] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] OnEntry, current Behavior: cl_ros_timer::CbTimerCountdownOnce
[INFO] [1722598821.137028872] [MyStateMachine]: [StateMachine] life-time constrained smacc signal subscription created. Subscriber is cl_ros_timer::CbTimerCountdownOnce
[WARN] [1722598821.137187388] [MyStateMachine]: [StateMachine] setting state active : my_state_machine::State2
[INFO] [1722598822.133182793] [MyStateMachine]: Event cl_ros_timer::EvTimer<cl_ros_timer::ClRosTimer, my_state_machine::OrTimer>
[INFO] [1722598823.132822523] [MyStateMachine]: Event cl_ros_timer::EvTimer<cl_ros_timer::ClRosTimer, my_state_machine::OrTimer>

Especially these lines

[WARN] [1722598821.133998438] [MyStateMachine]: exiting state: my_state_machine::State1
[INFO] [1722598821.134167449] [MyStateMachine]: Notification State Exit: leaving state 0x750540088ec0
[INFO] [1722598821.134298646] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] OnExit, current Behavior: cl_ros_timer::CbTimerCountdownLoop
[INFO] [1722598821.134416566] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] OnExit, current Behavior: cl_ros_timer::CbTimerCountdownOnce
[WARN] [1722598821.134515237] [MyStateMachine]: exiting state: my_state_machine::State1
[INFO] [1722598821.134582148] [MyStateMachine]: Notification State Exit: leaving state 0x750540088ec0
[INFO] [1722598821.134648333] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] OnExit, current Behavior: cl_ros_timer::CbTimerCountdownLoop
[INFO] [1722598821.134732799] [MyStateMachine]: [Orthogonal my_state_machine::OrTimer] OnExit, current Behavior: cl_ros_timer::CbTimerCountdownOnce
[INFO] [1722598821.134871763] [State1]: {I am very cool smacc2 SM called 'my_state_machine'} On Exit!
[WARN] [1722598821.134950838] [MyStateMachine]: exiting state: my_state_machine::State1
[INFO] [1722598821.135015930] [MyStateMachine]: Notification State Disposing: leaving state0x750540088ec0
[INFO] [1722598821.135083241] [MyStateMachine]: [SmaccSignals] object signal disconnecting 128665409464192
[INFO] [1722598821.135436974] [MyStateMachine]: [SmaccSignals] object signal disconnecting 128665409468736
[WARN] [1722598821.135565183] [MyStateMachine]: [smacc2::ISmaccClientBehaviorClient behavior deallocated.
[WARN] [1722598821.135747379] [MyStateMachine]: [smacc2::ISmaccClientBehaviorClient behavior deallocated.

Other sample state machines also do this, so I guess this is the correct behavior but I don't understand the reason behind it.
@yassiezar
Copy link
Contributor

Nice find. I've narrowed it down to these lines, where the notifyOnStateExitted() function is called twice. @pabloinigoblasco it looks like you introduced this in this change during the migration to Humble. I'm guessing that only the second exit call is needed here (the one behind the mutex lock). I tried that in a demo SM and it works as expected

@pabloinigoblasco
Copy link
Contributor

That indeed looks like some incorrect PR merge.
Really weird.

But yes. that part of the code is quite sensitive but that call shouldnt be duplicated.
I will have a look to that.

@ynyBonfennil
Copy link
Author

ynyBonfennil commented Sep 11, 2024 •
edited
Loading

Thank you for the investigation

@yassiezar yassiezar linked a pull request Sep 12, 2024 that will close this issue
Fix/double finishing #558
Merged
@yassiezar yassiezar mentioned this issue Oct 21, 2024
Open
@Crowdedlight
Copy link

Is this fix live on the current ros-humble-smacc2 package?

I am running on the latest package there and I seem to get behaviour where OnExit is called twice when exiting. Which caused me some deadlocks due to thread joins I do in OnExit.

When doing:

    void onExit() override {
        log_info("onexit called");
        }

I get the print twice when the behaviour is exited due to state change.

@brettpac
Copy link
Collaborator

Hi @Crowdedlight,
We're looking into this.
Where are you getting SMACC from? Are you building from source? Using the buildfarm version?

Thank you,

@brettpac brettpac reopened this Dec 20, 2024
@brettpac
Copy link
Collaborator

Can you try apt show ros-humble-smacc2?
We're looking for some detailed versioning info.

Our current hypothesis is that you're using an older version of SMACC.

Thank you,

@Crowdedlight
Copy link

Hi Brett

sorry, forgot to include it with the original reply.

 sudo apt show ros-humble-smacc2
Package: ros-humble-smacc2
Version: 2.3.18-1jammy.20241128.031509
Priority: optional
Section: misc
Maintainer: Pablo Inigo Blasco <pablo@ibrobotics.com>
Installed-Size: 1,144 kB
Depends: libboost-thread1.74.0 (>= 1.74.0), libc6 (>= 2.34), libgcc-s1 (>= 3.3.1), liblttng-ust1 (>= 2.13.0), libstdc++6 (>= 12), liblttng-ust-dev, ros-humble-rcl, ros-humble-rclcpp, ros-humble-rclcpp-action, ros-humble-smacc2-msgs, ros-humble-tracetools, ros-humble-tracetools-launch, ros-humble-tracetools-trace, ros-humble-ros-workspace
Download-Size: 287 kB
APT-Manual-Installed: yes
APT-Sources: http://packages.ros.org/ros2/ubuntu jammy/main amd64 Packages
Description: An Event-Driven, Asynchronous, Behavioral State Machine Library for ROS2 (Robotic Operating System) applications written in C++.

The version says 2.3.18 which fits with the latest tag in here, but the tag on github here says it is from 2023, so quite old?

@brettpac
Copy link
Collaborator

Looks like that version was pushed on 11/27/24
https://build.ros2.org/job/Hbin_uJ64__smacc2__ubuntu_jammy_amd64__binary/

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix/double finishing robosoft-ai/SMACC2
5 participants
@yassiezar @Crowdedlight @brettpac @pabloinigoblasco @ynyBonfennil