InconsistentTransition exception on end of parallel sleep(1)

[JulianDuestersiek]

Action executor is still waiting for the timeout:

(gdb) bt
#0  0x00007f914978778a in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00007f90c0e0750a in __gthread_cond_timedwait (__abs_timeout=0x7f906dffa9a0, __mutex=0x7f91384fd998, __cond=0x7f91384fd9c0) at /usr/include/c++/9/x86_64-redhat-linux/bits/gthr-default.h:872
#2  std::condition_variable::__wait_until_impl<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (__atime=<synthetic pointer>..., __lock=<synthetic pointer>..., this=<optimized out>) at /usr/include/c++/9/condition_variable:188
#3  std::condition_variable::wait_until<std::chrono::_V2::steady_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (__atime=..., __lock=<synthetic pointer>..., this=<optimized out>)
    at /usr/include/c++/9/condition_variable:121
#4  std::condition_variable::wait_for<long, std::ratio<1l, 1l> > (__rtime=..., __lock=<synthetic pointer>..., this=<optimized out>) at /usr/include/c++/9/condition_variable:152
#5  fawkes::gpp::SleepActionExecutor::<lambda()>::operator() (__closure=0x7f907002d4f8) at /home/praktikum/labhlap1/git/fawkes-robotino-labhlap2019/fawkes/src/plugins/gologpp/sleep_action_executor.cpp:76
#6  std::__invoke_impl<void, fawkes::gpp::SleepActionExecutor::start(std::shared_ptr<gologpp::Activity>)::<lambda()> > (__f=...) at /usr/include/c++/9/bits/invoke.h:60
#7  std::__invoke<fawkes::gpp::SleepActionExecutor::start(std::shared_ptr<gologpp::Activity>)::<lambda()> > (__fn=...) at /usr/include/c++/9/bits/invoke.h:95
#8  std::thread::_Invoker<std::tuple<fawkes::gpp::SleepActionExecutor::start(std::shared_ptr<gologpp::Activity>)::<lambda()> > >::_M_invoke<0> (this=0x7f907002d4f8) at /usr/include/c++/9/thread:244
#9  std::thread::_Invoker<std::tuple<fawkes::gpp::SleepActionExecutor::start(std::shared_ptr<gologpp::Activity>)::<lambda()> > >::operator() (this=0x7f907002d4f8) at /usr/include/c++/9/thread:251
#10 std::__future_base::_Task_setter<std::unique_ptr<std::__future_base::_Result<void>, std::__future_base::_Result_base::_Deleter>, std::thread::_Invoker<std::tuple<fawkes::gpp::SleepActionExecutor::start(std::shared_ptr<gologpp::Activity>)::<lambda()> > >, void>::operator() (this=0x7f906dffab20, this=0x7f906dffab20) at /usr/include/c++/9/future:1362
#11 std::_Function_handler<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter>(), std::__future_base::_Task_setter<std::unique_ptr<std::__future_base::_Result<void>, std::__future_base::_Result_base::_Deleter>, std::thread::_Invoker<std::tuple<fawkes::gpp::SleepActionExecutor::start(std::shared_ptr<gologpp::Activity>)::<lambda()> > >, void> >::_M_invoke(const std::_Any_data &) (__functor=...)
    at /usr/include/c++/9/bits/std_function.h:286
#12 0x00007f90c0e07eeb in std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> ()>::operator()() const (this=<optimized out>) at /usr/include/c++/9/bits/std_function.h:685
#13 std::__future_base::_State_baseV2::_M_do_set(std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> ()>*, bool*) (this=0x7f907002d4c0, __f=<optimized out>, 
    __did_set=0x7f906dffaaf7) at /usr/include/c++/9/future:561
#14 0x00007f9149788d7f in __pthread_once_slow () from /lib64/libpthread.so.0
#15 0x00007f90c0e07386 in __gthread_once (__func=<optimized out>, __once=0x7f907002d4d8) at /usr/include/c++/9/x86_64-redhat-linux/bits/gthr-default.h:700
#16 std::call_once<void (std::__future_base::_State_baseV2::*)(std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> ()>*, bool*), std::__future_base::_State_baseV2*, std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> ()>*, bool*>(std::once_flag&, void (std::__future_base::_State_baseV2::*&&)(std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> ()>*, bool*), std::__future_base::_State_baseV2*&&, std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> ()>*&&, bool*&&) (__f=
    @0x7f906dffab10: (void (std::__future_base::_State_baseV2::*)(std::__future_base::_State_baseV2 * const, std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter>()> *, bool *)) 0x7f90c0e07ed0 <std::__future_base::_State_baseV2::_M_do_set(std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> ()>*, bool*)>, __once=...) at /usr/include/c++/9/mutex:683
#17 std::__future_base::_State_baseV2::_M_set_result(std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> ()>, bool) (__ignore_failure=false, __res=..., this=0x7f907002d4c0)
    at /usr/include/c++/9/future:401
#18 std::__future_base::_Async_state_impl<std::thread::_Invoker<std::tuple<fawkes::gpp::SleepActionExecutor::start(std::shared_ptr<gologpp::Activity>)::<lambda()> > >, void>::<lambda()>::operator() (this=<optimized out>)
    at /usr/include/c++/9/future:1662
#19 std::__invoke_impl<void, std::__future_base::_Async_state_impl<_BoundFn, _Res>::_Async_state_impl(_BoundFn&&) [with _BoundFn = std::thread::_Invoker<std::tuple<fawkes::gpp::SleepActionExecutor::start(std::shared_ptr<gologpp::Activity>)::<lambda()> > >; _Res = void]::<lambda()> > (__f=...) at /usr/include/c++/9/bits/invoke.h:60
#20 std::__invoke<std::__future_base::_Async_state_impl<_BoundFn, _Res>::_Async_state_impl(_BoundFn&&) [with _BoundFn = std::thread::_Invoker<std::tuple<fawkes::gpp::SleepActionExecutor::start(std::shared_ptr<gologpp::Activity>)::<lambda()> > >; _Res = void]::<lambda()> > (__fn=...) at /usr/include/c++/9/bits/invoke.h:95
#21 std::thread::_Invoker<std::tuple<std::__future_base::_Async_state_impl<_BoundFn, _Res>::_Async_state_impl(_BoundFn&&) [with _BoundFn = std::thread::_Invoker<std::tuple<fawkes::gpp::SleepActionExecutor::start(std::shared_ptr<gologpp::Activity>)::<lambda()> > >; _Res = void]::<lambda()> > >::_M_invoke<0> (this=0x7f907002fa58) at /usr/include/c++/9/thread:244
#22 std::thread::_Invoker<std::tuple<std::__future_base::_Async_state_impl<_BoundFn, _Res>::_Async_state_impl(_BoundFn&&) [with _BoundFn = std::thread::_Invoker<std::tuple<fawkes::gpp::SleepActionExecutor::start(std::shared_ptr<gologpp::Activity>)::<lambda()> > >; _Res = void]::<lambda()> > >::operator() (this=0x7f907002fa58) at /usr/include/c++/9/thread:251
#23 std::thread::_State_impl<std::thread::_Invoker<std::tuple<std::__future_base::_Async_state_impl<_BoundFn, _Res>::_Async_state_impl(_BoundFn&&) [with _BoundFn = std::thread::_Invoker<std::tuple<fawkes::gpp::SleepActionExecutor::start(std::shared_ptr<gologpp::Activity>)::<lambda()> > >; _Res = void]::<lambda()> > > >::_M_run(void) (this=0x7f907002fa50) at /usr/include/c++/9/thread:195
#24 0x00007f9149de26f4 in ?? () from /lib64/libstdc++.so.6
#25 0x00007f91497814c0 in start_thread () from /lib64/libpthread.so.0
#26 0x00007f91499de163 in clone () from /lib64/libc.so.6

So the activity is still RUNNING, but somehow the agent already executes end(sleep(1)):

#0  0x00007f9149919e35 in raise () from /lib64/libc.so.6
#1  0x00007f9149904895 in abort () from /lib64/libc.so.6
#2  0x00007f9149da96b6 in ?? () from /lib64/libstdc++.so.6
#3  0x00007f9149db586c in ?? () from /lib64/libstdc++.so.6
#4  0x00007f9149db58c7 in std::terminate() () from /lib64/libstdc++.so.6
#5  0x00007f9149db5b29 in __cxa_throw () from /lib64/libstdc++.so.6
#6  0x00007f90c0948f59 in gologpp::PlatformBackend::end_activity (this=<optimized out>, trans=std::shared_ptr<gologpp::Transition> (use count 2, weak count 0) = {...}) at /usr/include/c++/9/ext/new_allocator.h:89
#7  0x00007f90c09944e7 in gologpp::ExecutionContext::run (this=this@entry=0x7f913828cac0, program=...) at /usr/include/c++/9/ext/atomicity.h:96
#8  0x00007f90c0df616b in fawkes::gpp::GologppThread::once (this=0x7f9138597510) at /usr/include/c++/9/bits/stl_algobase.h:465
#9  0x00007f9149cfc2f5 in fawkes::Thread::entry (pthis=0x7f9138597510) at /home/praktikum/labhlap1/git/fawkes-robotino-labhlap2019/fawkes/src/libs/core/threading/thread.cpp:574
#10 0x00007f91497814c0 in start_thread () from /lib64/libpthread.so.0
#11 0x00007f91499de163 in clone () from /lib64/libc.so.6

(gdb) print this->platform_backend_
$10 = {<std::unique_ptr<gologpp::PlatformBackend, std::default_delete<gologpp::PlatformBackend> >> = std::unique_ptr<gologpp::PlatformBackend> = {get() = 0x7f91384fb8c0}, <No data fields>}
(gdb) print this->platform_backend_->activities_
$11 = std::unordered_set with 1 element = {[0] = std::shared_ptr<gologpp::Grounding<gologpp::Action>> (use count 3, weak count 1) = {get() = 0x7f907002d1b0}}
(gdb) print (Activity)(*0x7f907002d1b0)
$12 = {<gologpp::Grounding<gologpp::Action>> = {<gologpp::Grounding<gologpp::AbstractAction>> = {<gologpp::AbstractReference> = {<gologpp::AbstractLanguageElement> = {
          _vptr.AbstractLanguageElement = 0x7f90c09d58e0 <vtable for gologpp::Activity+440>, 
          semantics_ = {<std::unique_ptr<gologpp::AbstractSemantics<gologpp::AbstractLanguageElement>, std::default_delete<gologpp::AbstractSemantics<gologpp::AbstractLanguageElement> > >> = std::unique_ptr<gologpp::AbstractSemantics<gologpp::AbstractLanguageElement>> = {get() = 0x7f9070030950}, <No data fields>}, type_ = std::shared_ptr<const gologpp::Type> (use count 269241, weak count 1) = {get() = 0x7f91384fa060}}, 
        _vptr.AbstractReference = 0x7f90c09d5760 <vtable for gologpp::Activity+56>}, <gologpp::AbstractGrounding> = {<No data fields>}, <No data fields>}, <gologpp::ReferenceBase<gologpp::Action, gologpp::Value>> = {<gologpp::Expression> = {_vptr.Expression = 0x7f90c09d57d0 <vtable for gologpp::Activity+168>, parent_ = 0x0}, <gologpp::NoScopeOwner> = {_vptr.NoScopeOwner = 0x7f90c09d5838 <vtable for gologpp::Activity+272>}, args_ = std::vector of length 1, capacity 1 = {
        {<std::unique_ptr<gologpp::Value, std::default_delete<gologpp::Value> >> = std::unique_ptr<gologpp::Value> = {get() = 0x7f907002eeb0}, <No data fields>}}, target_ = std::weak_ptr<gologpp::Action> (use count 1, weak count 10) = {
        get() = 0x7f913880ce30}, params_to_args_ = std::unordered_map with 1 element = {[std::shared_ptr<const gologpp::Variable> (use count 13, weak count 1) = {
          get() = 0x7f913880caf0}] = {<std::_Reference_wrapper_base_memfun<gologpp::Value, false>> = {<std::_Reference_wrapper_base<gologpp::Value>> = {<std::_Weak_result_type<gologpp::Value>> = {<std::_Weak_result_type_memfun<gologpp::Value, false>> = {<std::_Weak_result_type_impl<gologpp::Value>> = {<std::_Maybe_get_result_type<gologpp::Value, void>> = {<No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <std::_Refwrap_base_arg1<gologpp::Value, void>> = {<No data fields>}, <std::_Refwrap_base_arg2<gologpp::Value, void>> = {<No data fields>}, <No data fields>}, <No data fields>}, 
          _M_data = 0x7f907002eeb0}}}, <No data fields>}, <gologpp::LanguageElement<gologpp::Activity, gologpp::UndefinedType>> = {
    _vptr.LanguageElement = 0x7f90c09d5870 <vtable for gologpp::Activity+328>}, <std::enable_shared_from_this<gologpp::Activity>> = {_M_weak_this = std::weak_ptr<gologpp::Activity> (use count 3, weak count 1) = {
      get() = 0x7f907002d1b0}}, state_ = gologpp::Activity::RUNNING, sensing_result_ = {<boost::optional_detail::optional_base<gologpp::Value>> = {<boost::optional_detail::optional_tag> = {<No data fields>}, m_initialized = false, 
      m_storage = {dummy_ = {data = '\000' <repeats 127 times>, aligner_ = {<No data fields>}}}}, <No data fields>}, exec_context_ = @0x7f913828cac0}

[vmatare]

Turns out that this is caused by starting the same action in multiple concurrent {...} branches. golog++ is designed to run durative actions in parallel, but not with the exact same arguments. So this could be worked around by introducing a dummy argument that has a different value in each concurrent {...} branch, or simply by avoiding the situation altogether.
The actual bug here is that the crash happens only when golog++ tries to finish the second one of the parallel actions. What should happen is that golog++ crashes immediately when another action with the same arguments is started.

[vmatare]

Corollary: sleeping/blocking may not be an action