search

ApolloAuto / apollo

An open autonomous driving platform
Apache License 2.0
25.12k stars 9.7k forks source link

TimerComponent / component class hierarchy destruction fails #11748

Open hollmeer opened 4 years ago

hollmeer commented 4 years ago

Describe the bug The proper destruction of TimerComponent components in cyber (more specifically, due to an obvious monotonous increase of component.use_count() of the related std::shared_ptr of the TimerComponent-related 'self', referred in callback lambda-function (cf. /apollo/cyber/timer/timing_wheel.cc:53..58).

Due to the monotonous use_count increase, the componentlist.clear() at module_controller.cc:33 cannot destroy the components. Add a debugging row into loop after row 31 to see the monotonous use_count() increase, which blocs the proper destruction:

29 void ModuleController::Clear() { 30 for (auto& component : componentlist) { 31 component->Shutdown(); // ADD TO SEE THE MONOTONOUS INCREASE: // AINFO << "ModuleController::Clear(): component->use_count(): " << component->use_count(); 32 } 33 componentlist.clear(); // keep alive 34 class_loadermanager.UnloadAllLibrary(); 35 }

Thence, class_loader.cc enters into condition "classobj_refcount > 0" (at row 45), and component class hierarchy does not destruct properly:

41 int ClassLoader::UnloadLibrary() { 42 std::lock_guard lckLib(loadlib_ref_countmutex); 43 std::lock_guard lckObj(classobj_ref_countmutex); 44 45 if (classobj_refcount > 0) { 46 AINFO << "There are still classobjs have not been deleted, " 47 "classobj_refcount: " 48 << classobj_refcount; 49 } else { 50 --loadlib_refcount; 51...

The bug was maybe included into cyber-platform during spring, as earlier, while coding a POC of an enhanced platform (currently some 40K+ LOC) for playful behaviors on top of cyber-platform, the first portion of the coding was working properly with the extensive use of mock-Talker-Writers as feeding timed writers to a TimerComponent-based, behaviortree-based playful readers-writers-intensive action, but later/recent coding to widen the use of cyber, seemingly failed both in the earlier POC portion, plus an enhanced Utility-AI-based playful-action on top of the earlier TimerComponent-based, behaviortree-based POC.

It also seems as per now, that the TimerComponent destruction problems occurs with the cyber demo of timer_component_example.

To Reproduce Steps to reproduce the behavior (maybe a more complex example with AINFO messages through the class hierarchy's destructors show the generic bug): 1) run e.g. cyber_launch start /apollo/cyber/examples/timer_component_example/timer.launch 2) verify the /apollo/data/log/mainboard.info at the end: the class hierarchy

Expected behavior 1) after performing the clear() at module_controller.cc

33 componentlist.clear(); // keep alive 34 class_loadermanager.UnloadAllLibrary();

should not enter into condition "classobj_refcount > 0" (row 45), and thence component class hierarchy does not destruct properly.

A(/The?) Fix

The fix (seemingly working):

THE FIX: Replace rows /apollo/cyber/tmer/timing_wheel.cc:53..58

-53 auto callback = task->callback; -54 cyber::Async([this, callback] { -55 if (this->running_) { -56 callback(); -57 } -58 }); +53 auto callback = reinterpretcast<std::function<void()>*>( &(task->callback) ); +54 cyber::Async([this, callback] { +55 if (this->running) { +56 (*callback)(); +57 } +58 });

changsh726 commented 4 years ago

Hi @hollmeer, thanks for your reporting. We have fix this in pull request #11823. This issue will be closed for now. If you have any other question, please feel free to reopen this or open a new issue.

hollmeer commented 4 years ago

hi @changsh726, thanks for the fix as above, but it seems that your version of fix same as our first earlier attempt to fix the problem. That earlier version (same as your fix as for now) seemed to result into arbitrary crash after a few seconds, if the launched components were allowed to run w/o terminating it by crtl-C in terminal rather immediately ( less than 5secs of execution). The crash problem could not be found even by rather elaborate investigations.

Thereon, an idea emerged to reinterpret the callback function-pointer, as in the reported tentative fix, and it seemed to allow the execution of the timer components properly, and with an orderly and properly destructed class hierarcies of TimerComponents, and then prroper terminated execution of the mainboard.

Pls find below a copy from our timing_wheel.cc / TimingWheel::Tick(), as it has a more verbose comment over the two attempts of fix (the earlier, aka similar to your fix, and the second version, which was included in the bug reporting above):

---clip---

void TimingWheel::Tick() { auto& bucket = workwheel[current_work_wheelindex]; { std::lock_guard lock(bucket.mutex()); auto ite = bucket.task_list().begin(); while (ite != bucket.task_list().end()) { auto task = ite->lock(); if (task) { ADEBUG << "index: " << current_work_wheelindex << " timer id: " << task->timerid; // auto callback = task->callback; // cyber::Async([this, callback] { // if (this->running_) { // callback(); // } // }); // NOTE: CROSSHELIX // - AN EARLIER HACK, ADDED A '&' // into above original // // cyber::Async([this, &callback] { // // TO PREVENT MONOTONOUS shared_ptr.use_count() INCREASE (2020-06-30), // which prevented proper destruction of components, as the use_count of the shared_ptr of the TimerComponent // monotonously increased, and thence not allowing the destruction via // // componentlist.clear() [cf. module_controller.cc:35 in ModuleController::Clear() ] // // and thence causing the condition // // classobj_refcount > 0 to prevent unloading [cf. class_loader.cc:45 in ClassLoader::UnloadLibrary() ] // NOTE: // HOWEVER, this earlier hack-attempt allowed proper destruction of components, as the use_count remained as 1 // and so allowed the clear() to destruct the components, IF THE EXECUTION WAS STOPPED BY CRTL-C FROM Docker CONSOLE // QUICLKY ENOUGH // // BUT IF THE EXECUTION WAS ALLOWED TO CONTINUE SOME 5+ SECONDS, THE EXECUTION CRASHED ARBITRARILY, and the reason // was not revealed so far to any parrticular reason/location // // NOTE: WITH THE ALTERED CODE BELOW, THE EXECUTION SEEMS TO WORK PROPERLY, i.e. // // - cast the CALLBACK into a function POINTER // - pass the POINTER into LAMBDA function // - DEREFERENCE the POINTER into FUNCTION and CALL the CALLBACK FUNCTION // // CROSSHELIX 2020-07-11: changed from original above, to casted pointer auto callback = reinterpretcast<std::function<void()>*>( &(task->callback) ); cyber::Async([this, callback] { if (this->running) { (*callback)(); } }); } ite = bucket.task_list().erase(ite); } } }

---clap---

So I'm still (as not updated yet with your version), if the crash-problem may return. However, the &callback version, and the reinterpretation of the function-pointer SHOULD (?) behave/yield the very same result.

Maybe still worth double-checking...?

changsh726 commented 4 years ago

Thank you for your detailed description @hollmeer. I tested several times according to you described above, and execution does sometimes crash after a period of time when I use the &callback version. I have made a pull request #11835 to fix as your suggestion. We'll also try to find out why the former approach doesn't work properly.

hollmeer commented 4 years ago

rather interestingly, the component class hierarchy destruction problem re-emerged, after changing the directly used std::deque, std::map etc usage for the brains' data structures into platform's own generalized node-graph system. As the change into such rrather elaborate multiple graph systems was otherwise rooted from other bugs, and the runs work properly, the termination seems to indicate again a potential poblem with the message of

I0822 17:04:24.590996 15015 class_loader.cc:46] There are still classobjs have not been deleted, classobj_refcount: 1 I0822 17:04:24.591012 15015 mainboard.cc:49] exit mainboard.

Interestingly, however, the remaining of the mainboard.info log indicate some decent class-destruction taking place into log AFTER the 'exit mainboard' line.

This just an immediate comment, as the cause has not been analyzed yet, but as the issue was left open, maybe there is something to worry about also in generic terms.

Below a clip from a mainboard info log, from termination with ctrl-c at docker console, and the clipped lines from some line-range of 54659--54730 (indicating by the log that the brains are (somewhat at least so far) working as expected):

---clip--- ... I0822 17:04:24.590750 15019 xnai_mockdemo_derived_brain_bt_task.h:1009] MockDerivedFunctAIBrainBTTask::ChooseOption - ..updated max_weight: 0 I0822 17:04:24.590760 15019 xnai_mockdemo_derived_brain_bt_task.h:1015] MockDerivedFunctAIBrainBTTask::ChooseOption - ..DONE iteratate through found ai options [ count : 16, max_weight: 0 ].. I0822 17:04:24.590770 15019 xnai_mockdemo_derived_brain_bt_task.h:1021] MockDerivedFunctAIBrainBTTask::ChooseOption - ..return nullptr as max_weight equal to zero I0822 17:04:24.590777 15019 xnai_mockdemo_derived_brain_bt_task.h:320] ProcessUpdate: ChooseOption returned nullptr as the selected option I0822 17:04:24.590790 15019 bt_base.h:724] BT > BTBehavior(1957747793)->Tick(846930886:brain_0) 3 I0822 17:04:24.590801 15019 xnai_brain.h:184] BT > MockAIBrainBTTask(424238335)->OnTerminate rs: 13 ts: 8 I0822 17:04:24.590811 15019 xnai_mockdemo_derived_brain_bt_task.h:562] MockDerivedFunctAIBrainBTTask::ProcessTerminate() I0822 17:04:24.590819 15019 xnai_mockdemo_derived_brain_bt_task.h:568] ***** MockDerivedFunctAIBrainBTTask::ProcessTerminate() terminate status: 8 I0822 17:04:24.590828 15019 bt_base.h:758] BT > BTBehavior(1957747793)->Tick(846930886:brain_0 : 424238335) 4 s: 8 I0822 17:04:24.590839 15019 btxnai_parallel.h:512] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 3 ..Tick 1 I0822 17:04:24.590849 15019 btxnai_parallel.h:517] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 4 child_brain_return_status 8 i 1 I0822 17:04:24.590860 15019 btxnai_parallel.h:4020] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 6 i 1 I0822 17:04:24.590869 15019 btxnai_parallel.h:7242] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 8 i 1 I0822 17:04:24.590883 15019 btxnai_parallel.h:9177] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 11 ..running I0822 17:04:24.590893 15019 bt_base.h:724] BT > BTBehavior(1681692777)->Tick(1804289383:parallel_brain_0) 3 I0822 17:04:24.590903 15019 bt_base.h:758] BT > BTBehavior(1681692777)->Tick(1804289383:parallel_brain_0 : 1714636915) 4 s: 13 I0822 17:04:24.590911 15019 btxnai_component_example.cc:1167] BTXNAI > BTXNAIComponentSample::Proc() ..Tick() DONE I0822 17:04:24.590996 15015 class_loader.cc:46] There are still classobjs have not been deleted, classobj_refcount: 1 I0822 17:04:24.591012 15015 mainboard.cc:49] exit mainboard. I0822 17:04:24.591233 15019 bt_base.h:627] BT > BTBehavior(1681692777)->Teardown(1804289383:parallel_brain_0) 1 I0822 17:04:24.591245 15019 bt_base.h:637] BT > BTBehavior(1681692777)->Teardown(1804289383:parallel_brain_0) 2 I0822 17:04:24.591254 15019 bt_base.h:654] BT > BTBehavior(1681692777)->Teardown(1804289383:parallel_brain_0) 3 I0822 17:04:24.591279 15015 classic_context.cc:111] waiting for task /internal/task0 completion I0822 17:04:24.591308 15019 btxnai_parallel.h:169] ~XNAIParallel(1714636915) I0822 17:04:24.591318 15019 bt_base.h:627] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 1 I0822 17:04:24.591327 15019 bt_base.h:637] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 2 I0822 17:04:24.591336 15019 bt_base.h:654] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 3 I0822 17:04:24.591346 15019 bt_base.h:658] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 4 I0822 17:04:24.591367 15019 bt_base.h:582] ~BTBehavior(1957747793) I0822 17:04:24.591377 15019 bt_base.h:496] ~BTTask I0822 17:04:24.591388 15019 bt_base.h:427] ~BTTaskDummy I0822 17:04:24.591398 15019 bt_base.h:658] BT > BTBehavior(1681692777)->Teardown(1804289383:parallel_brain_0) 4 I0822 17:04:24.591406 15019 bt_base.h:582] ~BTBehavior(1681692777) I0822 17:04:24.591429 15019 xnai_brain.h:1136] ~MockAIBrainBTNode(846930886:brain_0) I0822 17:04:24.591440 15019 xnai_brain.h:524] ~AIBrainBaseBTNode(846930886:brain_0) I0822 17:04:24.591457 15019 xnai_brain.h:122] ~MockAIBrainBTTask(424238335) I0822 17:04:24.591466 15019 bt_mock_bt_base.h:71] ~MockBTTask(424238335) I0822 17:04:24.591490 15019 bt_base.h:496] ~BTTask ... ---clap---

changsh726 commented 4 years ago

I0822 17:04:24.591308 15019 btxnai_parallel.h:169] ~XNAIParallel(1714636915)

Could you provide the steps for the reproduction?

hollmeer commented 4 years ago

hi,

as the case is based on our developed POC, which is so far not available to outsiders, the reproduction by others is a non-starter at this point.

Below is included a bundle of three separate clips from the end of the respective mainboard.INFO logs of the three debug-runs, with varying exec-time (seems not be relevant, when to terminate, from such length perspective, as the brains-apparatuses seem to work orderly, based on the raw/elabora-level logging):

1) produces the class_loader.cc message 2) terminates properly 3) produces the class_loader.cc message

All cases seem to indicate a problem of NOT reporting orderly the developed apparatuses' internal class-destruction messages, but still however, seemingly just ignoring such logging (but I'm a bit curious why it is possible to omit such log lines, if the destructors are called as it seems from the well-functioning logic perspectives).

As the initial reporting revealed, there is a POC of currently some 50K+ LOC, on top of TimerComponent:

The suspects of the root cause from two perspectives:

A) as the application uses rather extensively std::shared_ptr mechanisms, so there may be something with the managed pointers, which seem to behave orderly, but somehow results the TimerComponent to remain counted (the inner stuff SHOULD NOT HOWEVER (?) be able to interfere with the cyber's component loading/unloading ?)

B) as the earlier original issue-reporting and discussion - and the two attempts to fix the problem (with the latter accepted case working seemingly otherwise properly) - revealed, there is something weird with the cyber's use of the managed shared_ptr and weak_ptr etc; one thought emerged from the the original investigation, that the threads' context switching may fail with the handling of the callback-function's shared/managed pointers (some shared and/or weak pointers causing the counting faults?)

As the graph-based version of the POC is rather newborn still, there is a possibility that the problem is somehow in the managed pointers of the A-case above (as also indicated by the missing debug-reporting into mainboard.INFO from ALL BT-related instances' destructors (there is quite a crowd of them), on one hand, and respectively from the utility-ai-brains mutiple graph-apparatuses class-instances, on the other hand. From the execution perspective, the apparatuses seem well-behaving, and not indicating any problematic non-orderly-destroyd residuals of the past instances. However, I'm quite a bit on the side that the problem is deeply embedded into some faulting aspect of the cyber's counting the managed/shared/weak function-callback-shared-pointers.

Below the clips:

1) a clip from mainboard.INFO / a run terminated with crtl-C at docker console after some length of running time

THE PROBLEM LINES:

I0824 07:33:59.551848 17040 class_loader.cc:46] There are still classobjs have not been deleted, classobj_refcount: 1 I0824 07:33:59.551862 17040 mainboard.cc:49] exit mainboard.

NOTE no reporting from the instantiated classes destructor-hierarchy, but ONLY those from the utility-ai-brain's option and action class instances, WHICH the apparatus seem to destruct ORDERLY, as everywhere else in the log, when the behavior-tree's behavior->Tick() calls the respective post-OnTerminate destroy-phase of the instanciated objects

NOTE here NO logging entries AFTER the termination/exit of the mainboard.cc (OK) // NOTE this line was EDITED from my original post (as there was an unfortunate wrong copy-paste hereto) : THERE IS, NTERESTINGLY AS IN 3rf CASE, LOG LINES AFTER manboard.cc exit)

NOTE NO CRASHES reported into /apollo/data/core either (as was the case when the initial issue was reported in July)

-- clip / ending lines from mainboard.INFO: 154971-155076 ---

I0824 07:33:59.551546 17046 xnai_action.h:312] XNAIAction::Execute ..return [ with status: TRUE ] I0824 07:33:59.551558 17046 xnai_option.h:199] >> XNAIOptionBase::ExecuteActions - ..Execute returned: TRUE I0824 07:33:59.551568 17046 xnai_option.h:216] XNAIOptionBase::ExecuteActions - ..DONE iterating execute actions; return with status: BTStatus::BH_SUCCESS I0824 07:33:59.551578 17046 xnai_mockdemo_derived_brain_bt_task.h:532] ProcessUpdate: ..DONE ExecuteActions.. else-branch / local_status: 3 I0824 07:33:59.551587 17046 xnai_mockdemo_derived_brain_bt_task.h:547] ProcessUpdate: ..return with local_status: 3 I0824 07:33:59.551597 17046 bt_base.h:724] BT > BTBehavior(1957747793)->Tick(846930886:brain_0) 3 I0824 07:33:59.551609 17046 xnai_brain.h:184] BT > MockAIBrainBTTask(424238335)->OnTerminate rs: 13 ts: 3 I0824 07:33:59.551620 17046 xnai_mockdemo_derived_brain_bt_task.h:562] MockDerivedFunctAIBrainBTTask::ProcessTerminate() I0824 07:33:59.551628 17046 xnai_mockdemo_derived_brain_bt_task.h:568] ***** MockDerivedFunctAIBrainBTTask::ProcessTerminate() terminate status: 3 I0824 07:33:59.551637 17046 bt_base.h:758] BT > BTBehavior(1957747793)->Tick(846930886:brain_0 : 424238335) 4 s: 3 I0824 07:33:59.551647 17046 btxnai_parallel.h:512] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 3 ..Tick 1 I0824 07:33:59.551657 17046 btxnai_parallel.h:517] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 4 child_brain_return_status 3 i 1 I0824 07:33:59.551669 17046 btxnai_parallel.h:4020] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 6 i 1 I0824 07:33:59.551678 17046 btxnai_parallel.h:7242] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 8 i 1 I0824 07:33:59.551692 17046 btxnai_parallel.h:9177] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 11 ..running I0824 07:33:59.551700 17046 bt_base.h:724] BT > BTBehavior(1681692777)->Tick(1804289383:parallel_brain_0) 3 I0824 07:33:59.551710 17046 bt_base.h:758] BT > BTBehavior(1681692777)->Tick(1804289383:parallel_brain_0 : 1714636915) 4 s: 13 I0824 07:33:59.551720 17046 btxnai_component_example.cc:1167] BTXNAI > BTXNAIComponentSample::Proc() ..Tick() DONE I0824 07:33:59.551848 17040 class_loader.cc:46] There are still classobjs have not been deleted, classobj_refcount: 1 I0824 07:33:59.551862 17040 mainboard.cc:49] exit mainboard. I0824 07:33:59.552556 17040 classic_context.cc:111] waiting for task /internal/task0 completion I0824 07:33:59.552618 17046 bt_base.h:627] BT > BTBehavior(1681692777)->Teardown(1804289383:parallel_brain_0) 1 I0824 07:33:59.552631 17046 bt_base.h:637] BT > BTBehavior(1681692777)->Teardown(1804289383:parallel_brain_0) 2 I0824 07:33:59.552659 17046 bt_base.h:654] BT > BTBehavior(1681692777)->Teardown(1804289383:parallel_brain_0) 3 I0824 07:33:59.552670 17046 btxnai_parallel.h:169] ~XNAIParallel(1714636915) I0824 07:33:59.552680 17046 bt_base.h:627] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 1 I0824 07:33:59.552690 17046 bt_base.h:637] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 2 I0824 07:33:59.552716 17046 bt_base.h:654] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 3 I0824 07:33:59.552726 17046 bt_base.h:658] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 4 I0824 07:33:59.552734 17046 bt_base.h:582] ~BTBehavior(1957747793) I0824 07:33:59.552745 17046 bt_base.h:496] ~BTTask I0824 07:33:59.552778 17046 bt_base.h:427] ~BTTaskDummy I0824 07:33:59.552788 17046 bt_base.h:658] BT > BTBehavior(1681692777)->Teardown(1804289383:parallel_brain_0) 4 I0824 07:33:59.552798 17046 bt_base.h:582] ~BTBehavior(1681692777) I0824 07:33:59.552809 17046 xnai_brain.h:1134] ~MockAIBrainBTNode(846930886:brain_0) I0824 07:33:59.552834 17046 xnai_brain.h:524] ~AIBrainBaseBTNode(846930886:brain_0) I0824 07:33:59.552855 17046 xnai_brain.h:122] ~MockAIBrainBTTask(424238335) I0824 07:33:59.552865 17046 bt_mock_bt_base.h:71] ~MockBTTask(424238335) I0824 07:33:59.552873 17046 bt_base.h:496] ~BTTask I0824 07:33:59.552899 17046 xnai_option.h:337] ~XNAIOption I0824 07:33:59.552911 17046 xnai_option.h:112] ~XNAIOptionBase I0824 07:33:59.552922 17046 xnai_action.h:239] ~XNAIAction I0824 07:33:59.552930 17046 xnai_action.h:184] ~XNAIActionBase I0824 07:33:59.552991 17046 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:33:59.553005 17046 xnai_action.h:239] ~XNAIAction I0824 07:33:59.553047 17046 xnai_action.h:184] ~XNAIActionBase I0824 07:33:59.553061 17046 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:33:59.553072 17046 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:33:59.553083 17046 xnai_option.h:337] ~XNAIOption I0824 07:33:59.553107 17046 xnai_option.h:112] ~XNAIOptionBase I0824 07:33:59.553118 17046 xnai_action.h:239] ~XNAIAction I0824 07:33:59.553126 17046 xnai_action.h:184] ~XNAIActionBase I0824 07:33:59.553136 17046 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:33:59.553165 17046 xnai_action.h:239] ~XNAIAction I0824 07:33:59.553175 17046 xnai_action.h:184] ~XNAIActionBase I0824 07:33:59.553189 17046 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:33:59.553200 17046 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:33:59.553226 17046 xnai_option.h:337] ~XNAIOption I0824 07:33:59.553236 17046 xnai_option.h:112] ~XNAIOptionBase I0824 07:33:59.553246 17046 xnai_action.h:239] ~XNAIAction I0824 07:33:59.553254 17046 xnai_action.h:184] ~XNAIActionBase I0824 07:33:59.553264 17046 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:33:59.553290 17046 xnai_action.h:239] ~XNAIAction I0824 07:33:59.553299 17046 xnai_action.h:184] ~XNAIActionBase I0824 07:33:59.553311 17046 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:33:59.553324 17046 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:33:59.553350 17046 xnai_option.h:337] ~XNAIOption I0824 07:33:59.553359 17046 xnai_option.h:112] ~XNAIOptionBase I0824 07:33:59.553369 17046 xnai_action.h:239] ~XNAIAction I0824 07:33:59.553378 17046 xnai_action.h:184] ~XNAIActionBase I0824 07:33:59.553388 17046 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:33:59.553414 17046 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:33:59.553426 17046 xnai_option.h:337] ~XNAIOption I0824 07:33:59.553433 17046 xnai_option.h:112] ~XNAIOptionBase I0824 07:33:59.553442 17046 xnai_action.h:239] ~XNAIAction I0824 07:33:59.553465 17046 xnai_action.h:184] ~XNAIActionBase I0824 07:33:59.553478 17046 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:33:59.553488 17046 xnai_action.h:239] ~XNAIAction I0824 07:33:59.553496 17046 xnai_action.h:184] ~XNAIActionBase I0824 07:33:59.553505 17046 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:33:59.553532 17046 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:33:59.553544 17046 xnai_option.h:337] ~XNAIOption I0824 07:33:59.553552 17046 xnai_option.h:112] ~XNAIOptionBase I0824 07:33:59.553561 17046 xnai_action.h:239] ~XNAIAction I0824 07:33:59.553570 17046 xnai_action.h:184] ~XNAIActionBase I0824 07:33:59.553596 17046 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:33:59.553606 17046 xnai_action.h:239] ~XNAIAction I0824 07:33:59.553615 17046 xnai_action.h:184] ~XNAIActionBase I0824 07:33:59.553627 17046 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:33:59.553653 17046 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:33:59.553664 17046 xnai_option.h:337] ~XNAIOption I0824 07:33:59.553673 17046 xnai_option.h:112] ~XNAIOptionBase I0824 07:33:59.553683 17046 xnai_action.h:239] ~XNAIAction I0824 07:33:59.553691 17046 xnai_action.h:184] ~XNAIActionBase I0824 07:33:59.553717 17046 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:33:59.553730 17046 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:33:59.553740 17046 xnai_option.h:337] ~XNAIOption I0824 07:33:59.553747 17046 xnai_option.h:112] ~XNAIOptionBase I0824 07:33:59.553772 17046 xnai_action.h:239] ~XNAIAction I0824 07:33:59.553782 17046 xnai_action.h:184] ~XNAIActionBase I0824 07:33:59.553793 17046 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:33:59.553804 17046 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:33:59.553817 17046 bt_base.h:427] ~BTTaskDummy I0824 07:33:59.553840 17046 bt_mock_bt_base.h:155] ~MockBTNode(846930886:brain_0) I0824 07:33:59.553850 17046 bt_base.h:400] ~BTNode(846930886) I0824 07:33:59.553862 17046 bt_base.h:254] ~BTNodeDummy

---clap ---

2) a clip from another run with a longer run and then terminated, WHICH HOWEVER, SEEMS TO TERMINATE (SOMEWHAT) NORMALLY from the cyber/mainstream.cc perspective, BUT STILL does not report destruction of ALL inststantiated classes destructor-hierarchies into log, as each constructor and desctructor has a debug-mode logging

NOTE in this case there is NOT FOUND any such class_loader problem line, but an orderly end with mainboard.cc exit

NOTE no reporting from the instantiated classes destructor-hierarchy, but ONLY those from the utility-ai-brain's option and action class instances, WHICH the apparatus seem to destruct ORDERLY, as everywhere else in the log, when the behavior-tree's behavior->Tick() calls the respective post-OnTerminate destroy-phase of the instanciated objects

NOTE here NO logging entries AFTER the termnation/exit of the mainboard.cc (OK)

NOTE NO CRASHES reported into /apollo/data/core either (as was the case when the initial issue was reported in July)

--- clip / lines from mainboard.INFO 1639341-16939457 ( so the terminated end of about 1.7M lines of logged execution, which seems to run OK otherwise )---

I0824 07:41:18.654004 17212 xnai_action.h:312] XNAIAction::Execute ..return [ with status: TRUE ] I0824 07:41:18.654014 17212 xnai_option.h:199] >> XNAIOptionBase::ExecuteActions - ..Execute returned: TRUE I0824 07:41:18.654023 17212 xnai_option.h:216] XNAIOptionBase::ExecuteActions - ..DONE iterating execute actions; return with status: BTStatus::BH_SUCCESS I0824 07:41:18.654033 17212 xnai_mockdemo_derived_brain_bt_task.h:532] ProcessUpdate: ..DONE ExecuteActions.. else-branch / local_status: 3 I0824 07:41:18.654042 17212 xnai_mockdemo_derived_brain_bt_task.h:547] ProcessUpdate: ..return with local_status: 3 I0824 07:41:18.654052 17212 bt_base.h:724] BT > BTBehavior(1957747793)->Tick(846930886:brain_0) 3 I0824 07:41:18.654062 17212 xnai_brain.h:184] BT > MockAIBrainBTTask(424238335)->OnTerminate rs: 13 ts: 3 I0824 07:41:18.654072 17212 xnai_mockdemo_derived_brain_bt_task.h:562] MockDerivedFunctAIBrainBTTask::ProcessTerminate() I0824 07:41:18.654080 17212 xnai_mockdemo_derived_brain_bt_task.h:568] ***** MockDerivedFunctAIBrainBTTask::ProcessTerminate() terminate status: 3 I0824 07:41:18.654089 17212 bt_base.h:758] BT > BTBehavior(1957747793)->Tick(846930886:brain_0 : 424238335) 4 s: 3 I0824 07:41:18.654098 17212 btxnai_parallel.h:512] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 3 ..Tick 1 I0824 07:41:18.654109 17212 btxnai_parallel.h:517] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 4 child_brain_return_status 3 i 1 I0824 07:41:18.654119 17212 btxnai_parallel.h:4020] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 6 i 1 I0824 07:41:18.654129 17212 btxnai_parallel.h:7242] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 8 i 1 I0824 07:41:18.654141 17212 btxnai_parallel.h:9164] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 11 ..cycles consumed: return with BH_INVALID I0824 07:41:18.654151 17212 bt_base.h:724] BT > BTBehavior(1681692777)->Tick(1804289383:parallel_brain_0) 3 I0824 07:41:18.654161 17212 btxnai_parallel.h:9202] BT > XNAIParallel(1714636915)->OnTerminate I0824 07:41:18.654171 17212 bt_base.h:592] BT > BTBehavior(1957747793)->Setup(846930886:brain_0) 1 I0824 07:41:18.654181 17212 bt_base.h:627] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 1 I0824 07:41:18.654189 17212 bt_base.h:637] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 2 I0824 07:41:18.654198 17212 bt_base.h:654] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 3 I0824 07:41:18.654208 17212 bt_base.h:658] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 4 I0824 07:41:18.654217 17212 bt_base.h:596] BT > BTBehavior(1957747793)->Setup(846930886:brain_0) 2 I0824 07:41:18.654227 17212 xnai_brain.h:1065] MockAIBrainBTNode(846930886)->create I0824 07:41:18.654237 17212 bt_base.h:615] BT > BTBehavior(1957747793)->Setup(846930886:brain_0) 3 I0824 07:41:18.654245 17212 bt_base.h:758] BT > BTBehavior(1681692777)->Tick(1804289383:parallel_brain_0 : 1714636915) 4 s: 0 I0824 07:41:18.654255 17212 btxnai_component_example.cc:1167] BTXNAI > BTXNAIComponentSample::Proc() ..Tick() DONE I0824 07:41:18.654326 17204 bt_base.h:627] BT > BTBehavior(1681692777)->Teardown(1804289383:parallel_brain_0) 1 I0824 07:41:18.654340 17204 bt_base.h:637] BT > BTBehavior(1681692777)->Teardown(1804289383:parallel_brain_0) 2 I0824 07:41:18.654364 17204 bt_base.h:654] BT > BTBehavior(1681692777)->Teardown(1804289383:parallel_brain_0) 3 I0824 07:41:18.654374 17204 btxnai_parallel.h:169] ~XNAIParallel(1714636915) I0824 07:41:18.654384 17204 bt_base.h:627] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 1 I0824 07:41:18.654393 17204 bt_base.h:637] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 2 I0824 07:41:18.654404 17204 bt_base.h:654] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 3 I0824 07:41:18.654413 17204 bt_base.h:658] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 4 I0824 07:41:18.654422 17204 bt_base.h:582] ~BTBehavior(1957747793) I0824 07:41:18.654438 17204 bt_base.h:496] ~BTTask I0824 07:41:18.654450 17204 bt_base.h:427] ~BTTaskDummy I0824 07:41:18.654459 17204 bt_base.h:658] BT > BTBehavior(1681692777)->Teardown(1804289383:parallel_brain_0) 4 I0824 07:41:18.654469 17204 bt_base.h:582] ~BTBehavior(1681692777) I0824 07:41:18.654479 17204 xnai_brain.h:1134] ~MockAIBrainBTNode(846930886:brain_0) I0824 07:41:18.654487 17204 xnai_brain.h:524] ~AIBrainBaseBTNode(846930886:brain_0) I0824 07:41:18.654502 17204 xnai_brain.h:122] ~MockAIBrainBTTask(424238335) I0824 07:41:18.654512 17204 bt_mock_bt_base.h:71] ~MockBTTask(424238335) I0824 07:41:18.654520 17204 bt_base.h:496] ~BTTask I0824 07:41:18.654531 17204 xnai_option.h:337] ~XNAIOption I0824 07:41:18.654541 17204 xnai_option.h:112] ~XNAIOptionBase I0824 07:41:18.654549 17204 xnai_action.h:239] ~XNAIAction I0824 07:41:18.654557 17204 xnai_action.h:184] ~XNAIActionBase I0824 07:41:18.654567 17204 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:41:18.654578 17204 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:41:18.654587 17204 xnai_option.h:337] ~XNAIOption I0824 07:41:18.654595 17204 xnai_option.h:112] ~XNAIOptionBase I0824 07:41:18.654604 17204 xnai_action.h:239] ~XNAIAction I0824 07:41:18.654613 17204 xnai_action.h:184] ~XNAIActionBase I0824 07:41:18.654623 17204 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:41:18.654633 17204 xnai_action.h:239] ~XNAIAction I0824 07:41:18.654640 17204 xnai_action.h:184] ~XNAIActionBase I0824 07:41:18.654649 17204 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:41:18.654659 17204 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:41:18.654669 17204 xnai_option.h:337] ~XNAIOption I0824 07:41:18.654676 17204 xnai_option.h:112] ~XNAIOptionBase I0824 07:41:18.654685 17204 xnai_action.h:239] ~XNAIAction I0824 07:41:18.654695 17204 xnai_action.h:184] ~XNAIActionBase I0824 07:41:18.654704 17204 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:41:18.654713 17204 xnai_action.h:239] ~XNAIAction I0824 07:41:18.654721 17204 xnai_action.h:184] ~XNAIActionBase I0824 07:41:18.654731 17204 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:41:18.654742 17204 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:41:18.654750 17204 xnai_option.h:337] ~XNAIOption I0824 07:41:18.654758 17204 xnai_option.h:112] ~XNAIOptionBase I0824 07:41:18.654767 17204 xnai_action.h:239] ~XNAIAction I0824 07:41:18.654775 17204 xnai_action.h:184] ~XNAIActionBase I0824 07:41:18.654784 17204 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:41:18.654793 17204 xnai_action.h:239] ~XNAIAction I0824 07:41:18.654803 17204 xnai_action.h:184] ~XNAIActionBase I0824 07:41:18.654811 17204 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:41:18.654822 17204 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:41:18.654831 17204 xnai_option.h:337] ~XNAIOption I0824 07:41:18.654839 17204 xnai_option.h:112] ~XNAIOptionBase I0824 07:41:18.654848 17204 xnai_action.h:239] ~XNAIAction I0824 07:41:18.654856 17204 xnai_action.h:184] ~XNAIActionBase I0824 07:41:18.654865 17204 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:41:18.654875 17204 xnai_action.h:239] ~XNAIAction I0824 07:41:18.654883 17204 xnai_action.h:184] ~XNAIActionBase I0824 07:41:18.654891 17204 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:41:18.654901 17204 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:41:18.654909 17204 xnai_option.h:337] ~XNAIOption I0824 07:41:18.654917 17204 xnai_option.h:112] ~XNAIOptionBase I0824 07:41:18.654927 17204 xnai_action.h:239] ~XNAIAction I0824 07:41:18.654934 17204 xnai_action.h:184] ~XNAIActionBase I0824 07:41:18.654943 17204 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:41:18.654953 17204 xnai_action.h:239] ~XNAIAction I0824 07:41:18.654961 17204 xnai_action.h:184] ~XNAIActionBase I0824 07:41:18.654971 17204 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:41:18.654983 17204 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:41:18.654991 17204 xnai_option.h:337] ~XNAIOption I0824 07:41:18.654999 17204 xnai_option.h:112] ~XNAIOptionBase I0824 07:41:18.655009 17204 xnai_action.h:239] ~XNAIAction I0824 07:41:18.655016 17204 xnai_action.h:184] ~XNAIActionBase I0824 07:41:18.655025 17204 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:41:18.655035 17204 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:41:18.655045 17204 xnai_option.h:337] ~XNAIOption I0824 07:41:18.655052 17204 xnai_option.h:112] ~XNAIOptionBase I0824 07:41:18.655061 17204 xnai_action.h:239] ~XNAIAction I0824 07:41:18.655069 17204 xnai_action.h:184] ~XNAIActionBase I0824 07:41:18.655078 17204 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:41:18.655088 17204 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:41:18.655098 17204 bt_base.h:427] ~BTTaskDummy I0824 07:41:18.655107 17204 bt_mock_bt_base.h:155] ~MockBTNode(846930886:brain_0) I0824 07:41:18.655117 17204 bt_base.h:400] ~BTNode(846930886) I0824 07:41:18.655126 17204 bt_base.h:254] ~BTNodeDummy I0824 07:41:18.655135 17204 btxnai_mock_btxnai_parallel.h:214] ~MockBTParallelBTComposite(1804289383:parallel_brain_0) I0824 07:41:18.655145 17204 btxnai_composite.h:83] ~BTComposite(1804289383:parallel_brain_0) I0824 07:41:18.655156 17204 bt_base.h:400] >~BTNode(1804289383) I0824 07:41:18.655165 17204 bt_base.h:254] ~BTNodeDummy I0824 07:41:18.655880 17204 mainboard.cc:49] exit mainboard.

--- clap ---

3) a third run with somewhat lesser execution time than earlier, and below a clp from mainboard.INFO lines 613903-614820, which AGAIN INDICATE THE OCCURRENCE OF THE class_loader problem

NOTE no reporting from the instantiated classes destructor-hierarchy, but ONLY those from the utility-ai-brain's option and action class instances, WHICH the apparatus seem to destruct ORDERLY, as everywhere else in the log, when the behavior-tree's behavior->Tick() calls the respective post-OnTerminate destroy-phase of the instanciated objects

NOTE interestngly, logging shows entries AFTER the termination/exit of the mainboard.cc

NOTE NO CRASHES reported into /apollo/data/core either (as was the case when the initial issue was reported in July)

-- clip / mainboard.INFO lines 613903-614820 ( so some 0.6M lines of log from orderly execution of the brain-apparatuses ---

I0824 07:57:13.477696 17457 xnai_option.h:199] >> XNAIOptionBase::ExecuteActions - ..Execute returned: TRUE I0824 07:57:13.477705 17457 xnai_option.h:216] XNAIOptionBase::ExecuteActions - ..DONE iterating execute actions; return with status: BTStatus::BH_SUCCESS I0824 07:57:13.477715 17457 xnai_mockdemo_derived_brain_bt_task.h:532] ProcessUpdate: ..DONE ExecuteActions.. else-branch / local_status: 3 I0824 07:57:13.477722 17457 xnai_mockdemo_derived_brain_bt_task.h:547] ProcessUpdate: ..return with local_status: 3 I0824 07:57:13.477733 17457 bt_base.h:724] BT > BTBehavior(1957747793)->Tick(846930886:brain_0) 3 I0824 07:57:13.477744 17457 xnai_brain.h:184] BT > MockAIBrainBTTask(424238335)->OnTerminate rs: 13 ts: 3 I0824 07:57:13.477754 17457 xnai_mockdemo_derived_brain_bt_task.h:562] MockDerivedFunctAIBrainBTTask::ProcessTerminate() I0824 07:57:13.477764 17457 xnai_mockdemo_derived_brain_bt_task.h:568] ***** MockDerivedFunctAIBrainBTTask::ProcessTerminate() terminate status: 3 I0824 07:57:13.477773 17457 bt_base.h:758] BT > BTBehavior(1957747793)->Tick(846930886:brain_0 : 424238335) 4 s: 3 I0824 07:57:13.477783 17457 btxnai_parallel.h:512] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 3 ..Tick 1 I0824 07:57:13.477793 17457 btxnai_parallel.h:517] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 4 child_brain_return_status 3 i 1 I0824 07:57:13.477804 17457 btxnai_parallel.h:4020] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 6 i 1 I0824 07:57:13.477813 17457 btxnai_parallel.h:7242] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 8 i 1 I0824 07:57:13.477826 17457 btxnai_parallel.h:9164] BT > BTBehavior(1957747793) XNAIParallel(1714636915)->update 11 ..cycles consumed: return with BH_INVALID I0824 07:57:13.477836 17457 bt_base.h:724] BT > BTBehavior(1681692777)->Tick(1804289383:parallel_brain_0) 3 I0824 07:57:13.477845 17457 btxnai_parallel.h:9202] BT > XNAIParallel(1714636915)->OnTerminate I0824 07:57:13.477855 17457 bt_base.h:592] BT > BTBehavior(1957747793)->Setup(846930886:brain_0) 1 I0824 07:57:13.477864 17457 bt_base.h:627] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 1 I0824 07:57:13.477874 17457 bt_base.h:637] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 2 I0824 07:57:13.477882 17457 bt_base.h:654] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 3 I0824 07:57:13.477891 17457 bt_base.h:658] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 4 I0824 07:57:13.477900 17457 bt_base.h:596] BT > BTBehavior(1957747793)->Setup(846930886:brain_0) 2 I0824 07:57:13.477910 17457 xnai_brain.h:1065] MockAIBrainBTNode(846930886)->create I0824 07:57:13.477918 17457 bt_base.h:615] BT > BTBehavior(1957747793)->Setup(846930886:brain_0) 3 I0824 07:57:13.477928 17457 bt_base.h:758] BT > BTBehavior(1681692777)->Tick(1804289383:parallel_brain_0 : 1714636915) 4 s: 0 I0824 07:57:13.477938 17457 btxnai_component_example.cc:1167] BTXNAI > BTXNAIComponentSample::Proc() ..Tick() DONE I0824 07:57:13.478003 17439 class_loader.cc:46] There are still classobjs have not been deleted, classobj_refcount: 1 I0824 07:57:13.478014 17439 mainboard.cc:49] exit mainboard. I0824 07:57:13.478147 17457 bt_base.h:627] BT > BTBehavior(1681692777)->Teardown(1804289383:parallel_brain_0) 1 I0824 07:57:13.478157 17457 bt_base.h:637] BT > BTBehavior(1681692777)->Teardown(1804289383:parallel_brain_0) 2 I0824 07:57:13.478168 17457 bt_base.h:654] BT > BTBehavior(1681692777)->Teardown(1804289383:parallel_brain_0) 3 I0824 07:57:13.478193 17439 classic_context.cc:111] waiting for task /internal/task0 completion I0824 07:57:13.478224 17457 btxnai_parallel.h:169] ~XNAIParallel(1714636915) I0824 07:57:13.478233 17457 bt_base.h:627] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 1 I0824 07:57:13.478243 17457 bt_base.h:637] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 2 I0824 07:57:13.478252 17457 bt_base.h:654] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 3 I0824 07:57:13.478261 17457 bt_base.h:658] BT > BTBehavior(1957747793)->Teardown(846930886:brain_0) 4 I0824 07:57:13.478286 17457 bt_base.h:582] ~BTBehavior(1957747793) I0824 07:57:13.478296 17457 bt_base.h:496] ~BTTask I0824 07:57:13.478307 17457 bt_base.h:427] ~BTTaskDummy I0824 07:57:13.478317 17457 bt_base.h:658] BT > BTBehavior(1681692777)->Teardown(1804289383:parallel_brain_0) 4 I0824 07:57:13.478327 17457 bt_base.h:582] ~BTBehavior(1681692777) I0824 07:57:13.478381 17457 xnai_brain.h:1134] ~MockAIBrainBTNode(846930886:brain_0) I0824 07:57:13.478392 17457 xnai_brain.h:524] ~AIBrainBaseBTNode(846930886:brain_0) I0824 07:57:13.478405 17457 xnai_brain.h:122] ~MockAIBrainBTTask(424238335) I0824 07:57:13.478415 17457 bt_mock_bt_base.h:71] ~MockBTTask(424238335) I0824 07:57:13.478441 17457 bt_base.h:496] ~BTTask I0824 07:57:13.478453 17457 xnai_option.h:337] ~XNAIOption I0824 07:57:13.478462 17457 xnai_option.h:112] ~XNAIOptionBase I0824 07:57:13.478471 17457 xnai_action.h:239] ~XNAIAction I0824 07:57:13.478480 17457 xnai_action.h:184] ~XNAIActionBase I0824 07:57:13.478504 17457 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:57:13.478518 17457 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:57:13.478528 17457 xnai_option.h:337] ~XNAIOption I0824 07:57:13.478535 17457 xnai_option.h:112] ~XNAIOptionBase I0824 07:57:13.478559 17457 xnai_action.h:239] ~XNAIAction I0824 07:57:13.478569 17457 xnai_action.h:184] ~XNAIActionBase I0824 07:57:13.478579 17457 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:57:13.478588 17457 xnai_action.h:239] ~XNAIAction I0824 07:57:13.478596 17457 xnai_action.h:184] ~XNAIActionBase I0824 07:57:13.478615 17457 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:57:13.478626 17457 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:57:13.478636 17457 xnai_option.h:337] ~XNAIOption I0824 07:57:13.478644 17457 xnai_option.h:112] ~XNAIOptionBase I0824 07:57:13.478653 17457 xnai_action.h:239] ~XNAIAction I0824 07:57:13.478662 17457 xnai_action.h:184] ~XNAIActionBase I0824 07:57:13.478670 17457 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:57:13.478680 17457 xnai_action.h:239] ~XNAIAction I0824 07:57:13.478688 17457 xnai_action.h:184] ~XNAIActionBase I0824 07:57:13.478698 17457 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:57:13.478708 17457 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:57:13.478718 17457 xnai_option.h:337] ~XNAIOption I0824 07:57:13.478726 17457 xnai_option.h:112] ~XNAIOptionBase I0824 07:57:13.478735 17457 xnai_action.h:239] ~XNAIAction I0824 07:57:13.478744 17457 xnai_action.h:184] ~XNAIActionBase I0824 07:57:13.478752 17457 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:57:13.478761 17457 xnai_action.h:239] ~XNAIAction I0824 07:57:13.478770 17457 xnai_action.h:184] ~XNAIActionBase I0824 07:57:13.478777 17457 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:57:13.478788 17457 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:57:13.478798 17457 xnai_option.h:337] ~XNAIOption I0824 07:57:13.478806 17457 xnai_option.h:112] ~XNAIOptionBase I0824 07:57:13.478814 17457 xnai_action.h:239] ~XNAIAction I0824 07:57:13.478822 17457 xnai_action.h:184] ~XNAIActionBase I0824 07:57:13.478832 17457 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:57:13.478840 17457 xnai_action.h:239] ~XNAIAction I0824 07:57:13.478848 17457 xnai_action.h:184] ~XNAIActionBase I0824 07:57:13.478858 17457 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:57:13.478869 17457 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:57:13.478878 17457 xnai_option.h:337] ~XNAIOption I0824 07:57:13.478888 17457 xnai_option.h:112] ~XNAIOptionBase I0824 07:57:13.478895 17457 xnai_action.h:239] ~XNAIAction I0824 07:57:13.478904 17457 xnai_action.h:184] ~XNAIActionBase I0824 07:57:13.478914 17457 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:57:13.478922 17457 xnai_action.h:239] ~XNAIAction I0824 07:57:13.478931 17457 xnai_action.h:184] ~XNAIActionBase I0824 07:57:13.478941 17457 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:57:13.478951 17457 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:57:13.478960 17457 xnai_option.h:337] ~XNAIOption I0824 07:57:13.478969 17457 xnai_option.h:112] ~XNAIOptionBase I0824 07:57:13.478978 17457 xnai_action.h:239] ~XNAIAction I0824 07:57:13.478986 17457 xnai_action.h:184] ~XNAIActionBase I0824 07:57:13.478996 17457 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:57:13.479007 17457 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:57:13.479017 17457 xnai_option.h:337] ~XNAIOption I0824 07:57:13.479024 17457 xnai_option.h:112] ~XNAIOptionBase I0824 07:57:13.479033 17457 xnai_action.h:239] ~XNAIAction I0824 07:57:13.479041 17457 xnai_action.h:184] ~XNAIActionBase I0824 07:57:13.479050 17457 xnai_action.h:61] ~XNAIActionBaseDummy I0824 07:57:13.479061 17457 xnai_option.h:73] ~XNAIOptionBaseDummy I0824 07:57:13.479072 17457 bt_base.h:427] ~BTTaskDummy I0824 07:57:13.479081 17457 bt_mock_bt_base.h:155] ~MockBTNode(846930886:brain_0) I0824 07:57:13.479090 17457 bt_base.h:400] ~BTNode(846930886) I0824 07:57:13.479100 17457 bt_base.h:254] ~BTNodeDummy I0824 07:57:13.479110 17457 btxnai_mock_btxnai_parallel.h:214] ~MockBTParallelBTComposite(1804289383:parallel_brain_0) I0824 07:57:13.479120 17457 btxnai_composite.h:83] ~BTComposite(1804289383:parallel_brain_0) I0824 07:57:13.479131 17457 bt_base.h:400] >~BTNode(1804289383) I0824 07:57:13.479140 17457 bt_base.h:254] ~BTNodeDummy --- clap ---

hollmeer commented 4 years ago

hi, some recent analysis, after the other potential problems are rooted away:

SUMMARY:

As indicated in the first sample run below, the line:

I0909 23:10:20.306387 24700 classic_context.cc:111] waiting for task /internal/task0 completion

points to some task/threading completion synchronization problem at the TimerComponent termination (?), if there is extensive post-termination debug logging (?).

As indicated by the second sample run further below, a minimal post-termination logging seems to result (always?) into an orderly termination of the TimerComponent.

Maybe more analysis is needed still, but the evidence points to such directions. A solution then, with the internal tasks etc, is another problem.

SAMPLE RUN CASES:

1) a clip from a terminated run with minimal post-termination (after ctrl-c at console) logging (no other debug log lines but from destructors)

results about 1000 log lines AFTER the row:

I0909 23:10:20.306128 24716 btxnai_component_example.cc:891] BTXNAI > BTXNAIComponentSample::Proc() ..Tick() DONE

with some OBSERVATIONs:

A) the line:

I0909 23:10:20.306387 24700 classic_context.cc:111] waiting for task /internal/task0 completion

B) indicates, that the problematic two lines appearing in the log (and the class_loader problem of 'classobj_refcount: 1' as indicated there):

I0909 23:10:20.306193 24700 class_loader.cc:46] There are still classobjs have not been deleted, classobj_refcount: 1 I0909 23:10:20.306207 24700 mainboard.cc:49] exit mainboard.

C) and the logging lines AFTER exit mainboard,

D) MIGHT BE CAUSED BY THE WAITING OF THE task /internal/task0 completion

E) which points to some task/threading completion synchronization problem at the TimerComponent termination (?) if there is extensive post-termination debug-logging (?)

F) the only remaining anomaly (if any) seems to be the missing destructor log lines from the class-hierarchy of the other port-connection (of the dual-linked graph) of the 'Graph.AIBrains.BrainCells', but only appearing with the second line (NOT A DOUBLEof the former just above) from the other port-connection's base-class, e.g.

I0909 23:10:20.306772 24716 xn_base.h:592] ~XNPortConnectionBaseDummy()

G) otherwise, the apparatuses seem to work properly

H) there is never any crash dumps in the /apollo/data/core, so the problems seems to 'behave well' anyway in such terms

---clip / more detailed post-termination (after ctrl-c at console) logging ---

I0909 23:10:20.306128 24716 btxnai_component_example.cc:891] BTXNAI > BTXNAIComponentSample::Proc() ..Tick() DONE I0909 23:10:20.306193 24700 class_loader.cc:46] There are still classobjs have not been deleted, classobj_refcount: 1 I0909 23:10:20.306207 24700 mainboard.cc:49] exit mainboard. I0909 23:10:20.306345 24716 xnai_brain_root_cell.h:87] ~XNAIBrainRootCell I0909 23:10:20.306360 24716 xnai_callback_wrapper.h:94] ~XNAICallbackWrapper I0909 23:10:20.306387 24700 classic_context.cc:111] waiting for task /internal/task0 completion I0909 23:10:20.306413 24716 xnai_brain_root_cell_base.h:65] ~XNAIBrainRootCellBase I0909 23:10:20.306425 24716 xn_base.h:1735] ~XNCell(brain_root_0) I0909 23:10:20.306434 24716 xn_base.h:1920] XNCell::ClearConnections: XNCell 'brain_root_0' port count: 2 I0909 23:10:20.306445 24716 xn_base.h:1923] XNCell::ClearConnections: clearing port: Graph.AIBrains.BrainCells I0909 23:10:20.306470 24716 xn_base.h:1391] XNCellPort::ClearConnections: count: 38 connections I0909 23:10:20.306485 24716 xn_base.h:1396] XNCellPort::ClearConnections: disconnecting a port connection.. [ # 0 / 38 ] I0909 23:10:20.306495 24716 xn_base.h:1171] XNCellPort::Disconnect I0909 23:10:20.306507 24716 xn_base.h:833] XNPortConnection::GetPortSharedPointer I0909 23:10:20.306531 24716 xn_base.h:841] XNPortConnection::GetPortSharedPointer: return GetPortSharedPointer value [ port connection: Graph.AIBrains.LinkedBrainCell ] I0909 23:10:20.306542 24716 xn_base.h:437] XNCellBase::GetPortSharedPointer: get port 'Graph.AIBrains.LinkedBrainCell' I0909 23:10:20.306555 24716 xn_base.h:443] XNCellBase::GetPortSharedPointer: ..found port 'Graph.AIBrains.LinkedBrainCell I0909 23:10:20.306568 24716 xn_base.h:1002] XNCellPort::GetConnections: looping connections [ count: 1 ],, I0909 23:10:20.306591 24716 xn_base.h:1007] XNCellPort::GetConnections: looping connections [ 0 / 1 ],, I0909 23:10:20.306602 24716 xn_base.h:833] XNPortConnection::GetPortSharedPointer I0909 23:10:20.306610 24716 xn_base.h:841] XNPortConnection::GetPortSharedPointer: return GetPortSharedPointer value [ port connection: Graph.AIBrains.BrainCells ] I0909 23:10:20.306620 24716 xn_base.h:437] XNCellBase::GetPortSharedPointer: get port 'Graph.AIBrains.BrainCells' I0909 23:10:20.306630 24716 xn_base.h:443] XNCellBase::GetPortSharedPointer: ..found port 'Graph.AIBrains.BrainCells I0909 23:10:20.306656 24716 xn_base.h:1026] XNCellPort::GetConnections: >> add connected port [ 0 / 1 ] I0909 23:10:20.306669 24716 xn_base.h:833] XNPortConnection::GetPortSharedPointer I0909 23:10:20.306679 24716 xn_base.h:841] XNPortConnection::GetPortSharedPointer: return GetPortSharedPointer value [ port connection: Graph.AIBrains.BrainCells ] I0909 23:10:20.306689 24716 xn_base.h:437] XNCellBase::GetPortSharedPointer: get port 'Graph.AIBrains.BrainCells' I0909 23:10:20.306713 24716 xn_base.h:443] XNCellBase::GetPortSharedPointer: ..found port 'Graph.AIBrains.BrainCells I0909 23:10:20.306726 24716 xn_base.h:737] ~XNPortConnection(Graph.AIBrains.LinkedBrainCell) I0909 23:10:20.306736 24716 xn_base.h:644] ~XNPortConnectionBase(Graph.AIBrains.LinkedBrainCell) I0909 23:10:20.306747 24716 xn_base.h:592] ~XNPortConnectionBaseDummy() I0909 23:10:20.306772 24716 xn_base.h:592] ~XNPortConnectionBaseDummy() I0909 23:10:20.306784 24716 xn_base.h:1359] XNCellPort::Disconnect: ..DONE I0909 23:10:20.306795 24716 xn_base.h:1400] XNCellPort::ClearConnections: ..port connections AFTER disconnecting a port: 37 I0909 23:10:20.306805 24716 xn_base.h:1396] XNCellPort::ClearConnections: disconnecting a port connection.. [ # 0 / 37 ] I0909 23:10:20.306833 24716 xn_base.h:1171] XNCellPort::Disconnect ... ... ... I0909 23:10:20.320652 24716 xnai_option.h:337] ~XNAIOption I0909 23:10:20.320659 24716 xnai_option.h:112] ~XNAIOptionBase I0909 23:10:20.320672 24716 xnai_action.h:239] ~XNAIAction I0909 23:10:20.320680 24716 xnai_action.h:184] ~XNAIActionBase I0909 23:10:20.320690 24716 xnai_action.h:61] ~XNAIActionBaseDummy I0909 23:10:20.320701 24716 xnai_option.h:73] ~XNAIOptionBaseDummy I0909 23:10:20.320713 24716 xnai_option.h:337] ~XNAIOption I0909 23:10:20.320721 24716 xnai_option.h:112] ~XNAIOptionBase I0909 23:10:20.320730 24716 xnai_action.h:239] ~XNAIAction I0909 23:10:20.320742 24716 xnai_action.h:184] ~XNAIActionBase I0909 23:10:20.320755 24716 xnai_action.h:61] ~XNAIActionBaseDummy I0909 23:10:20.320765 24716 xnai_option.h:73] ~XNAIOptionBaseDummy I0909 23:10:20.320777 24716 bt_base.h:427] ~BTTaskDummy I0909 23:10:20.320786 24716 bt_mock_bt_base.h:155] ~MockBTNode(846930886:brain_0) I0909 23:10:20.320796 24716 bt_base.h:400] ~BTNode(846930886) I0909 23:10:20.320811 24716 bt_base.h:254] ~BTNodeDummy I0909 23:10:20.320820 24716 btxnai_mock_btxnai_parallel.h:214] ~MockBTParallelBTComposite(1804289383:parallel_brain_0) I0909 23:10:20.320832 24716 btxnai_composite.h:83] ~BTComposite(1804289383:parallel_brain_0) I0909 23:10:20.320845 24716 bt_base.h:400] >~BTNode(1804289383) I0909 23:10:20.320855 24716 bt_base.h:254] ~BTNodeDummy

--- clap ---

2) a clip from a terminated run with minimal post-termination (after ctrl-c at console) logging (no other log lines but from destructors)

results about 250 log lines AFTER the row:

I0909 23:44:52.144668 27513 btxnai_component_example.cc:891] BTXNAI > BTXNAIComponentSample::Proc() ..Tick() DONE

with some OBSERVATIONs:

A) the line immedately after the component->Proc() termination:

I0909 23:44:52.173481 27510 timer.cc:142] stop timer, the timer_id: 0

B) indicates an orderly start of the termination sequence (and thread completion/termination syncronisation)

C) the line at the very end:

I0909 23:44:52.178622 27510 mainboard.cc:49] exit mainboard.

D) indicates an orderly termination of the TimerComponent

E) the only remaining anomaly (if any) seems to be the missing destructor log lines from the class-hierarchy of the other port-connection (of the dual-linked graph) of the 'Graph.AIBrains.BrainCells', but only appearing with the second line (NOT A DOUBLEof the former just above) from the other port-connection's base-class, e.g.

I0909 23:44:52.173739 27510 xn_base.h:592] ~XNPortConnectionBaseDummy()

F) otherwise, the apparatuses seem to work properly

G) there is never any crash dumps in the /apollo/data/core, so the problems seems to 'behave well' anyway in such terms

---clip / minimal post-termination (after ctrl-c at console) logging ---

I0909 23:44:52.144659 27513 bt_base.h:758] BT > BTBehavior(1681692777)->Tick(1804289383:parallel_brain_0 : 1714636915) 4 s: 13 I0909 23:44:52.144668 27513 btxnai_component_example.cc:891] BTXNAI > BTXNAIComponentSample::Proc() ..Tick() DONE I0909 23:44:52.173481 27510 timer.cc:142] stop timer, the timer_id: 0 I0909 23:44:52.173578 27510 xnai_brain_root_cell.h:87] ~XNAIBrainRootCell I0909 23:44:52.173600 27510 xnai_callback_wrapper.h:94] ~XNAICallbackWrapper I0909 23:44:52.173627 27510 xnai_brain_root_cell_base.h:65] ~XNAIBrainRootCellBase I0909 23:44:52.173642 27510 xn_base.h:1735] ~XNCell(brain_root_0) I0909 23:44:52.173693 27510 xn_base.h:737] ~XNPortConnection(Graph.AIBrains.LinkedBrainCell) I0909 23:44:52.173709 27510 xn_base.h:644] ~XNPortConnectionBase(Graph.AIBrains.LinkedBrainCell) I0909 23:44:52.173724 27510 xn_base.h:592] ~XNPortConnectionBaseDummy() I0909 23:44:52.173739 27510 xn_base.h:592] ~XNPortConnectionBaseDummy() I0909 23:44:52.173769 27510 xn_base.h:737] ~XNPortConnection(Graph.AIBrains.LinkedBrainCell) I0909 23:44:52.173784 27510 xn_base.h:644] ~XNPortConnectionBase(Graph.AIBrains.LinkedBrainCell) I0909 23:44:52.173799 27510 xn_base.h:592] ~XNPortConnectionBaseDummy() I0909 23:44:52.173812 27510 xn_base.h:592] ~XNPortConnectionBaseDummy() I0909 23:44:52.173840 27510 xn_base.h:737] ~XNPortConnection(Graph.AIBrains.LinkedBrainCell) I0909 23:44:52.173854 27510 xn_base.h:644] ~XNPortConnectionBase(Graph.AIBrains.LinkedBrainCell) ... ... ... I0909 23:44:52.177481 27510 xnai_option.h:337] ~XNAIOption I0909 23:44:52.177493 27510 xnai_option.h:112] ~XNAIOptionBase I0909 23:44:52.177510 27510 xnai_action.h:239] ~XNAIAction I0909 23:44:52.177521 27510 xnai_action.h:184] ~XNAIActionBase I0909 23:44:52.177536 27510 xnai_action.h:61] ~XNAIActionBaseDummy I0909 23:44:52.177551 27510 xnai_option.h:73] ~XNAIOptionBaseDummy I0909 23:44:52.177564 27510 xnai_option.h:337] ~XNAIOption I0909 23:44:52.177577 27510 xnai_option.h:112] ~XNAIOptionBase I0909 23:44:52.177590 27510 xnai_action.h:239] ~XNAIAction I0909 23:44:52.177603 27510 xnai_action.h:184] ~XNAIActionBase I0909 23:44:52.177616 27510 xnai_action.h:61] ~XNAIActionBaseDummy I0909 23:44:52.177632 27510 xnai_option.h:73] ~XNAIOptionBaseDummy I0909 23:44:52.177649 27510 bt_base.h:427] ~BTTaskDummy I0909 23:44:52.177662 27510 bt_mock_bt_base.h:155] ~MockBTNode(846930886:brain_0) I0909 23:44:52.177676 27510 bt_base.h:400] ~BTNode(846930886) I0909 23:44:52.177691 27510 bt_base.h:254] ~BTNodeDummy I0909 23:44:52.177704 27510 btxnai_mock_btxnai_parallel.h:214] ~MockBTParallelBTComposite(1804289383:parallel_brain_0) I0909 23:44:52.177721 27510 btxnai_composite.h:83] ~BTComposite(1804289383:parallel_brain_0) I0909 23:44:52.177738 27510 bt_base.h:400] >~BTNode(1804289383) I0909 23:44:52.177752 27510 bt_base.h:254] ~BTNodeDummy I0909 23:44:52.178622 27510 mainboard.cc:49] exit mainboard.

-- clap ---