Sorry, forgot to attach the file.<br><br>-Ryan<br><br><div class="gmail_quote">On Fri, Apr 1, 2011 at 6:01 PM, Ryan Miller <span dir="ltr"><<a href="mailto:rmiller4589@gmail.com">rmiller4589@gmail.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin: 0pt 0pt 0pt 0.8ex; border-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;">Hi Vijay,<br><br>A few questions then. Is it acceptable for messages to be dropped? I thought actionlib used reliable data transfer. In my actual program, I am depending on every message being sent, and I would rather not use delays and risk my robot still locking up.<br>
<br>To give you some perspective, I am using the client to plan a path to a destination, and I am using the server to execute the motor controls to drive on a path it is given. Using a timeout would be fine (it's what I'm doing in my production code, actually). But with this new result, it seems I should now cancel the goal any time waitForResult times out because I don't know if the server is just taking a long time or if its message was dropped and it's actually finished. What I was planning on doing was letting the motion planner follow the path until it is in imminent danger of colliding with something, in which case I would cancel the goal. Unfortunately, I have a new problem now where I cannot even cancel the goal.<br>
<br>After timing out, the client always thinks it's goal is active, and I am unable to cancel the goal. The output I am getting from the attached example is:<br><br>--- snip ---<br><i><span style="font-family: courier new,monospace;">[ INFO] [1301694170.491982098]: Sending goal</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[ INFO] [1301694170.492052098]: Waiting for result...</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[ INFO] [1301694170.492138988]: Server is aborting goal.</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[ INFO] [1301694170.492193892]: After waiting for the result, the state is ABORTED</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[ INFO] [1301694170.492232340]: Sending goal</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[ INFO] [1301694170.492279138]: Waiting for result...</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[ INFO] [1301694170.492341676]: Server is aborting goal.</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[ INFO] [1301694170.492388975]: After waiting for the result, the state is ABORTED</span></i><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[ INFO] [1301694170.492443452]: Sending goal</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[ INFO] [1301694170.492543467]: Server is aborting goal.</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[ INFO] [1301694170.492620163]: Waiting for result...</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[ INFO] [1301694171.492789064]: After waiting for the result, the state is ACTIVE</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[ INFO] [1301694171.492909135]: Timeout, cancelling the goal</span><br style="font-family: courier new,monospace;">
<b><span style="font-family: courier new,monospace;">[ INFO] [1301694171.492953475]: After cancelling, the state is ACTIVE</span></b><br style="font-family: courier new,monospace;"><b><span style="font-family: courier new,monospace;">[ INFO] [1301694171.492977808]: The server is not done.</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[ INFO] [1301694172.493114619]: The server is not done.</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[ INFO] [1301694173.493301543]: The server is not done.</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[ INFO] [1301694174.493476758]: The server is not done.</span><span style="font-family: courier new,monospace;"></span></b><br>^C<br>--- snip ---<br>(Normal behaviour is italicised. Unexpected behaviour is bold)<br>
<br>Might this be another problem, or am I misusing SimpleActionClient?<br><br>Thanks again,<br><font color="#888888"><br>-Ryan</font><div><div></div><div class="h5"><br><br><div class="gmail_quote">On Fri, Apr 1, 2011 at 4:54 PM, Vijay Pradeep <span dir="ltr"><<a href="mailto:vpradeep@willowgarage.com" target="_blank">vpradeep@willowgarage.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin: 0pt 0pt 0pt 0.8ex; border-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;">Hi Ryan,<br><br>Ok, I think we're actually getting somewhere.....<div><br><br>
> When I move the called to spinner.start() to where you suggested, the client gets stuck on its call to waitForServer as follows:<br></div>Totally my bad. What I meant for you to do was the following:<br>
1) Construct client & server<br>2) Spin up threads<br>3) waitForServer<br>4) Start sending goals<br><br>To do this, you'll have to move <span style="font-family: courier new,monospace;">spinner.start()</span> to where I suggested, and also move <span style="font-family: courier new,monospace;">client_.waitForServer()</span> to the top of <span style="font-family: courier new,monospace;">run()</span>. Currently, the app is trying to waitForServer without any spin threads running, which is causing it to get stuck. Sorry about that. I'd also suggest trying to run with 1 spinner instead of 4, and see if that helps.<br>
<br>Thanks for the gdb thread info. It looks like all the threads we're worried about are happily waiting for inputs in pthread conditions. This makes it seem even more like a message was being dropped.<br><br>Also, I finally got it to freeze on my side, <i>with</i> debug on. See output:<br>
<br><span style="font-family: courier new,monospace;">Done.</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[ INFO] [1301690082.884716841]: Hogging time or something</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">Current State: ABORTED</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[DEBUG] [1301690082.884784275]: IN DELETER</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[DEBUG] [1301690082.884838215]: About to erase CommStateMachine</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[DEBUG] [1301690082.884891598]: Done erasing CommStateMachine</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[DEBUG] [1301690082.884948750]: about to start initGoal()</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[DEBUG] [1301690082.885037423]: The action server has received a new goal request</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[DEBUG] [1301690082.885152395]: A new goal has been recieved by the single goal action server</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[DEBUG] [1301690082.885263065]: Accepting a new goal</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[DEBUG] [1301690082.885330292]: Accepting goal, id: /test_client_server-281-1301690082.884983820, stamp: 1301690082.88</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">Server called. Aborting goal.</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[DEBUG] [1301690082.885555049]: Setting the current goal as aborted</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[DEBUG] [1301690082.885618287]: Setting status to aborted on goal, id: /test_client_server-281-1301690082.884983820, stamp: 1301690082.88</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[DEBUG] [1301690082.885675967]: Publishing result for goal with id: /test_client_server-281-1301690082.884983820 and stamp: 1301690082.88</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[DEBUG] [1301690082.885743824]: Getting status over the wire.</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[DEBUG] [1301690082.885956181]: Done with initGoal()</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[DEBUG] [1301690082.887905041]: Getting status over the wire.</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[DEBUG] [1301690082.888000669]: Trying to transition to ACTIVE</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[DEBUG] [1301690082.888064094]: Transitioning CommState from WAITING_FOR_GOAL_ACK to ACTIVE</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[DEBUG] [1301690082.888130878]: Transitioning SimpleState from [PENDING] to [ACTIVE]</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">Active.</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[DEBUG] [1301690082.888203846]: Trying to transition to WAITING_FOR_RESULT</span><br style="font-family: courier new,monospace;">
<b><span style="font-family: courier new,monospace;">[DEBUG] [1301690082.888262411]: Transitioning CommState from ACTIVE to WAITING_FOR_RESULT</span></b><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[DEBUG] [1301690083.088191441]: Getting status over the wire.</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[DEBUG] [1301690083.288523198]: Getting status over the wire.</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[DEBUG] [1301690083.488836856]: Getting status over the wire.</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[DEBUG] [1301690083.688115542]: Getting status over the wire.</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[DEBUG] [1301690083.888460218]: Getting status over the wire.</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[DEBUG] [1301690084.088794991]: Getting status over the wire.</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[DEBUG] [1301690084.288137860]: Getting status over the wire.</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[DEBUG] [1301690084.488456451]: Getting status over the wire.</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[DEBUG] [1301690084.688742829]: Getting status over the wire.</span><br style="font-family: courier new,monospace;">
<span style="font-family: courier new,monospace;">[DEBUG] [1301690084.888085527]: Getting status over the wire.</span><br style="font-family: courier new,monospace;"><span style="font-family: courier new,monospace;">[DEBUG] [1301690085.088418107]: Getting status over the wire.</span><br style="font-family: courier new,monospace;">
<br>On the client side, the goal transitioned to WAITING_FOR_RESULT, which means that the server successfully set the goal to a terminal state (in this case, ABORTED). However, for some reason, the client never gets the result message. With so many messages flying across so quickly, I guess one of the result messages happens to get dropped. This also explains why adding a sleep in the server callback stopped the freezing. The sleep significantly slowed down the messaging rate, preventing the result message from being dropped.<br>
<br>It is definitely best practice to always add a timeout to waitForResult(). I've updated the <a href="http://www.ros.org/wiki/actionlib#C.2B-.2B-_SimpleActionClient" target="_blank">actionlib quickstart guide</a> accordingly.<br>
<br>And, please let me know if any of the spinner tweaks I suggested make a difference.<br><font color="#888888"><br>Vijay</font><div><div></div><div><br><br><div class="gmail_quote">On Fri, Apr 1, 2011 at 1:07 PM, Ryan Miller <span dir="ltr"><<a href="mailto:rmiller4589@gmail.com" target="_blank">rmiller4589@gmail.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin: 0pt 0pt 0pt 0.8ex; border-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;">
Hi Vijay,<br><br>When I move the called to spinner.start() to where you suggested, the client gets stuck on its call to waitForServer as follows:<br><br>--- snip ---<br>$ rosrun chores chores <br>[DEBUG] [1301684841.767308639]: Spinning up a thread for the SimpleActionClient<br>
[DEBUG] [1301684841.794376567]: goalConnectCallback: Adding [/test_client_server] to goalSubscribers<br>[DEBUG] [1301684841.794470922]: Goal Subscribers (1 total)<br> - /test_client_server<br>[DEBUG] [1301684841.800129524]: cancelConnectCallback: Adding [/test_client_server] to cancelSubscribers<br>
[DEBUG] [1301684841.800199855]: cancel Subscribers (1 total)<br> - /test_client_server<br>[DEBUG] [1301684841.809336199]: isServerConnected: Didn't receive status yet, so not connected yet<br>[DEBUG] [1301684841.809441030]: isServerConnected: Didn't receive status yet, so not connected yet<br>
[DEBUG] [1301684842.309665431]: isServerConnected: Didn't receive status yet, so not connected yet<br>[DEBUG] [1301684842.810034890]: isServerConnected: Didn't receive status yet, so not connected yet<br>...<br>[DEBUG] [1301684842.810034890]: isServerConnected: Didn't receive status yet, so not connected yet<br>
--- snip ---<br><br>Also, it appears I have a heisenbug on my hands because when I turn on rosconsole debugging, the problem seemingly disappears, but when I keep it off, it crashes on almost every run. By the way, the single call to ROS_INFO I placed in the code is critical to making the program halt more often. Remove that, and you'll have more trouble getting the program to halt.<br>
<br>Is there any other information that might help you replicate this problem? For now, I'll just throw some facts here about the computer I'm using. I am running Ubuntu 10.10 64-bit. I have replicated the problem on a relatively slow laptop and two pretty fast desktops. The specific package information for the version of ros-diamondback-common I am using is:<br>
<br>--- snip ---<br>$ dpkg -s ros-diamondback-common<br>Package: ros-diamondback-common<br>Status: install ok installed<br>Priority: optional<br>Section: unknown<br>Installed-Size: 34224<br>Maintainer: Tully Foote <a href="mailto:tfoote@willowgarage.com" target="_blank">tfoote@willowgarage.com</a><br>
Architecture: amd64<br>Version: 1.4.3-s1299027665~maverick<br>Depends: ros-diamondback-common-msgs (= 1.4.0-s1299027564~maverick), ros-diamondback-ros (= 1.4.6-s1298587732~maverick), ros-diamondback-ros-comm (= 1.4.5-s1299027222~maverick), libc6, build-essential, cmake, python-yaml, subversion, uuid-dev, libcppunit-dev<br>
Description: common code for personal robots<br> This stack contains tools built on top of ROS core which are commonly used throughout the ROS ecosystem.<br>Wg-Rosdistro: diamondback<br>--- snip ---<br><br>Here is some information from gdb from when the program halts. I've printed a list of the running threads as well as the backtraces of a few of the ones in different functions.<br>
<br>--- snip ---<br>Current State: ABORTED<br>Server called. Aborting goal.<br>Active.<br>^C<br>Program received signal SIGINT, Interrupt.<br>pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:212<br>
212 ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S: No such file or directory.<br> in ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S<br>(gdb) info thread<br> 12 Thread 0x7fffecea2700 (LWP 9649) pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:212<br>
11 Thread 0x7fffed6a3700 (LWP 9646) pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:212<br> 10 Thread 0x7fffedea4700 (LWP 9640) pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:212<br>
9 Thread 0x7fffee6a5700 (LWP 9639) pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:212<br> 8 Thread 0x7fffeeea6700 (LWP 9638) pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:212<br>
7 Thread 0x7fffef6a7700 (LWP 9637) pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:212<br> 6 Thread 0x7fffefea8700 (LWP 9636) pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:212<br>
5 Thread 0x7ffff06a9700 (LWP 9635) pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:212<br> 4 Thread 0x7ffff0eaa700 (LWP 9630) pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162<br>
3 Thread 0x7ffff16ab700 (LWP 9629) 0x00007ffff534e2c3 in select () at ../sysdeps/unix/syscall-template.S:82<br> 2 Thread 0x7ffff1eac700 (LWP 9628) 0x00007ffff5349203 in __poll (fds=<value optimized out>, nfds=<value optimized out>, timeout=100) at ../sysdeps/unix/sysv/linux/poll.c:87<br>
* 1 Thread 0x7ffff7fcd760 (LWP 9609) pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:212<br>(gdb) bt<br>#0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:212<br>
#1 0x000000000044c698 in timed_wait<boost::unique_lock<boost::mutex> > (this=0x7fffffffe110, m=..., wait_duration=<value optimized out>) at /usr/include/boost/thread/pthread/condition_variable.hpp:110<br>
#2 boost::condition_variable_any::timed_wait<boost::unique_lock<boost::mutex>, boost::posix_time::milliseconds> (this=0x7fffffffe110, m=..., wait_duration=<value optimized out>)<br> at /usr/include/boost/thread/pthread/condition_variable.hpp:133<br>
#3 0x000000000044d355 in actionlib::SimpleActionClient<chores::DoDishesAction_<std::allocator<void> > >::waitForResult (this=0x7fffffffe040, timeout=...)<br> at /opt/ros/diamondback/stacks/common/actionlib/include/actionlib/client/simple_action_client.h:567<br>
#4 0x00000000004583f6 in ClientGuy::run (this=0x7fffffffe040) at /home/pesckal/prometheus/ros/chores/src/main.cpp:50<br>#5 0x000000000042d8d5 in main (argc=1, argv=<value optimized out>) at /home/pesckal/prometheus/ros/chores/src/main.cpp:87<br>
(gdb) thread 2<br>[Switching to thread 2 (Thread 0x7ffff1eac700 (LWP 9628))]#0 0x00007ffff5349203 in __poll (fds=<value optimized out>, nfds=<value optimized out>, timeout=100) at ../sysdeps/unix/sysv/linux/poll.c:87<br>
87 ../sysdeps/unix/sysv/linux/poll.c: No such file or directory.<br> in ../sysdeps/unix/sysv/linux/poll.c<br>(gdb) bt<br>#0 0x00007ffff5349203 in __poll (fds=<value optimized out>, nfds=<value optimized out>, timeout=100) at ../sysdeps/unix/sysv/linux/poll.c:87<br>
#1 0x00007ffff78c169a in ros::PollSet::update (this=0x69c650, poll_timeout=100)<br> at /tmp/buildd/ros-diamondback-ros-comm-1.4.5/debian/ros-diamondback-ros-comm/opt/ros/diamondback/stacks/ros_comm/clients/cpp/roscpp/src/libros/poll_set.cpp:202<br>
#2 0x00007ffff7906778 in ros::PollManager::threadFunc (this=0x69c650)<br> at /tmp/buildd/ros-diamondback-ros-comm-1.4.5/debian/ros-diamondback-ros-comm/opt/ros/diamondback/stacks/ros_comm/clients/cpp/roscpp/src/libros/poll_manager.cpp:95<br>
#3 0x00007ffff6df5230 in thread_proxy () from /usr/lib/libboost_thread.so.1.42.0<br>#4 0x00007ffff55f9971 in start_thread (arg=<value optimized out>) at pthread_create.c:304<br>#5 0x00007ffff535592d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112<br>
#6 0x0000000000000000 in ?? ()<br>(gdb) thread 3<br>[Switching to thread 3 (Thread 0x7ffff16ab700 (LWP 9629))]#0 0x00007ffff534e2c3 in select () at ../sysdeps/unix/syscall-template.S:82<br>82 ../sysdeps/unix/syscall-template.S: No such file or directory.<br>
in ../sysdeps/unix/syscall-template.S<br>(gdb) bt<br>#0 0x00007ffff534e2c3 in select () at ../sysdeps/unix/syscall-template.S:82<br>#1 0x00007ffff723313a in XmlRpc::XmlRpcDispatch::work (this=0x69ac18, timeout=<value optimized out>)<br>
at /tmp/buildd/ros-diamondback-ros-comm-1.4.5/debian/ros-diamondback-ros-comm/opt/ros/diamondback/stacks/ros_comm/utilities/xmlrpcpp/src/XmlRpcDispatch.cpp:110<br>#2 0x00007ffff7903de9 in ros::XMLRPCManager::serverThreadFunc (this=0x69abc0)<br>
at /tmp/buildd/ros-diamondback-ros-comm-1.4.5/debian/ros-diamondback-ros-comm/opt/ros/diamondback/stacks/ros_comm/clients/cpp/roscpp/src/libros/xmlrpc_manager.cpp:256<br>#3 0x00007ffff6df5230 in thread_proxy () from /usr/lib/libboost_thread.so.1.42.0<br>
#4 0x00007ffff55f9971 in start_thread (arg=<value optimized out>) at pthread_create.c:304<br>#5 0x00007ffff535592d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112<br>#6 0x0000000000000000 in ?? ()<br>
(gdb) thread 4<br>[Switching to thread 4 (Thread 0x7ffff0eaa700 (LWP 9630))]#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162<br>162 ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S: No such file or directory.<br>
in ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S<br>(gdb) bt<br>#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162<br>#1 0x00007ffff79603b3 in wait (this=<value optimized out>) at /usr/include/boost/thread/pthread/condition_variable.hpp:20<br>
#2 ros::ROSOutAppender::logThread (this=<value optimized out>)<br> at /tmp/buildd/ros-diamondback-ros-comm-1.4.5/debian/ros-diamondback-ros-comm/opt/ros/diamondback/stacks/ros_comm/clients/cpp/roscpp/src/libros/rosout_appender.cpp:135<br>
#3 0x00007ffff6df5230 in thread_proxy () from /usr/lib/libboost_thread.so.1.42.0<br>#4 0x00007ffff55f9971 in start_thread (arg=<value optimized out>) at pthread_create.c:304<br>#5 0x00007ffff535592d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112<br>
#6 0x0000000000000000 in ?? ()<br>(gdb) thread 5<br>[Switching to thread 5 (Thread 0x7ffff06a9700 (LWP 9635))]#0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:212<br>
212 ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S: No such file or directory.<br> in ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S<br>(gdb) bt<br>#0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:212<br>
#1 0x00007ffff796885d in bool boost::condition_variable::timed_wait<boost::date_time::subsecond_duration<boost::posix_time::time_duration, 1000000l> >(boost::unique_lock<boost::mutex>&, boost::date_time::subsecond_duration<boost::posix_time::time_duration, 1000000l> const&) () from /opt/ros/diamondback/stacks/ros_comm/clients/cpp/roscpp/lib/libros.so<br>
#2 0x00007ffff7964e99 in ros::CallbackQueue::callAvailable (this=0x69c410, timeout=DWARF-2 expression error: DW_OP_reg operations must be used either alone or in conjuction with DW_OP_piece or DW_OP_bit_piece.<br>)<br> at /tmp/buildd/ros-diamondback-ros-comm-1.4.5/debian/ros-diamondback-ros-comm/opt/ros/diamondback/stacks/ros_comm/clients/cpp/roscpp/src/libros/callback_queue.cpp:307<br>
#3 0x00007ffff78f22e1 in ros::internalCallbackQueueThreadFunc ()<br> at /tmp/buildd/ros-diamondback-ros-comm-1.4.5/debian/ros-diamondback-ros-comm/opt/ros/diamondback/stacks/ros_comm/clients/cpp/roscpp/src/libros/init.cpp:265<br>
#4 0x00007ffff6df5230 in thread_proxy () from /usr/lib/libboost_thread.so.1.42.0<br>#5 0x00007ffff55f9971 in start_thread (arg=<value optimized out>) at pthread_create.c:304<br>#6 0x00007ffff535592d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112<br>
#7 0x0000000000000000 in ?? ()<br>(gdb) <br>--- snip ---<br><br>Also, I'm sorry to hear you had to create a new package to compile the program. As a sanity check, I also created a new package and copied over the cpp and action files, but this did not change the result I was having, as expected. (I've attached the package, for reference.)<br>
<br>I really appreciate the help, thank you.<br><font color="#888888"><br>-Ryan</font><div><div></div><div><br><br>On Fri, Apr 1, 2011 at 2:03 PM, Vijay Pradeep <<a href="mailto:vpradeep@willowgarage.com" target="_blank">vpradeep@willowgarage.com</a>> wrote:<br>
> Hi Ryan,<br>><br>
> Here's one more thing to try. Turn on rosconsole debugging (See rosconole<br>> configuration)<br>><br>> You're going to want the following two lines in your rosonsole.config:<br>> log4j.logger.ros.actionlib=DEBUG<br>
> log4j.logger.ros.chores=DEBUG<br>><br>><br>> You'll get an output that looks like this:<br>> [DEBUG] [1301680806.580203868]: Setting the current goal as aborted<br>> [DEBUG] [1301680806.580254603]: Setting status to aborted on goal, id:<br>
> /test_client_server-1118-1301680806.579359151, stamp: 1301680806.58<br>> [DEBUG] [1301680806.580301868]: Publishing result for goal with id:<br>> /test_client_server-1118-1301680806.579359151 and stamp: 1301680806.58<br>
> [DEBUG] [1301680806.580439068]: Getting status over the wire.<br>> [DEBUG] [1301680806.580509625]: Trying to transition to ACTIVE<br>> [DEBUG] [1301680806.580553872]: Transitioning CommState from<br>> WAITING_FOR_GOAL_ACK to ACTIVE<br>
> [DEBUG] [1301680806.580603042]: Transitioning SimpleState from [PENDING] to<br>> [ACTIVE]<br>> Active.<br>> [DEBUG] [1301680806.580934461]: Trying to transition to WAITING_FOR_RESULT<br>> [DEBUG] [1301680806.580991611]: Transitioning CommState from ACTIVE to<br>
> WAITING_FOR_RESULT<br>> [DEBUG] [1301680806.581051376]: Trying to transition to DONE<br>> [DEBUG] [1301680806.581108948]: Transitioning CommState from<br>> WAITING_FOR_RESULT to DONE<br>> [DEBUG] [1301680806.581164618]: Transitioning SimpleState from [ACTIVE] to<br>
> [DONE]<br>> Done.<br>> [ INFO] [1301680806.581243326]: Hogging time or something<br>> Current State: ABORTED<br>> [DEBUG] [1301680806.581302953]: IN DELETER<br>> [DEBUG] [1301680806.581339010]: About to erase CommStateMachine<br>
> [DEBUG] [1301680806.581377433]: Done erasing CommStateMachine<br>> [DEBUG] [1301680806.581414297]: about to start initGoal()<br>> [DEBUG] [1301680806.581489440]: Done with initGoal()<br>> [DEBUG] [1301680806.581544720]: The action server has received a new goal<br>
> request<br>> [DEBUG] [1301680806.581638097]: A new goal has been recieved by the single<br>> goal action server<br>> [DEBUG] [1301680806.581705716]: Accepting a new goal<br>> [DEBUG] [1301680806.581758609]: Accepting goal, id:<br>
> /test_client_server-1119-1301680806.581440270, stamp: 1301680806.58<br>> Server called. Aborting goal.<br>><br>> Can send me the debug output for the last few cycles when your app freezes?<br>><br>> Vijay<br>
><br>> On Fri, Apr 1, 2011 at 10:05 AM, Vijay Pradeep <<a href="mailto:vpradeep@willowgarage.com" target="_blank">vpradeep@willowgarage.com</a>><br>> wrote:<br>>><br>>> Hi Ryan,<br>>><br>
>> So I actually ran your original chores app overnight (~10 hours), and it<br>
>> still didn't freeze.<br>>><br>>> Also, right now, I tried running your new chores app about 30 times (for<br>>> about 5 seconds on each run), and it still hadn't frozen. I couldn't get<br>
>> the app to build using your CMakeLists and Makefile, so I rewrote them based<br>>> on the standard "roscreate-pkg" versions of these files. I doubt this would<br>>> affect the functionality.<br>
>><br>>> The fact that it freezes close to startup is interesting. My guess would<br>>> be that it is having some sort of startup interaction with the AsyncSpinner.<br>>><br>>> Instead of:<br>
>> int main(int argc, char** argv) {<br>>> ros::init(argc, argv, "test_client_server");<br>>><br>>> ros::AsyncSpinner spinner(4);<br>>> spinner.start();<br>>><br>>> ServerDude sd;<br>
>><br>>> ClientGuy client;<br>>> client.run();<br>>><br>>> return 0;<br>>> }<br>>><br>>> Can you try:<br>>> int main(int argc, char** argv) {<br>>> ros::init(argc, argv, "test_client_server");<br>
>><br>>> ros::AsyncSpinner spinner(4);<br>>><br>>> ServerDude sd;<br>>><br>>> ClientGuy client;<br>>> spinner.start();<br>>> client.run();<br>>><br>>> return 0;<br>
>> }<br>>><br>>> I would really like to get to the bottom of this, but it's hard to do much<br>>> on my end if I can't actually get it to halt.<br>>><br>>> Vijay<br>>><br>
>> On Fri, Apr 1, 2011 at 7:51 AM, Ryan Miller <<a href="mailto:rmiller4589@gmail.com" target="_blank">rmiller4589@gmail.com</a>> wrote:<br>>>><br>>>> Hey Vijay, thanks for helping (and sorry for the double post; I<br>
>>> accidentally forgot to reply all, and I figure some people on the list<br>>>> may be interested in the email). Yes, I did mean waitForResult, and I<br>>>> am also using common-1.4.3 (diamondback too, if that's relevant).<br>
>>> Since you're having trouble duplicating the issue, I went back to<br>>>> create an example closer to what I'm actually doing, and I managed to<br>>>> get it to crash just as often. I've attached the project.<br>
>>><br>>>> If it doesn't crash after about 5 seconds, restart it. It seems if it<br>>>> continues for more than 5 seconds, it is more likely to continue<br>>>> running for much longer, but it usually halts within a second.<br>
>>><br>>>> Thanks a ton.<br>>>><br>>>> -Ryan<br>>>><br>>>> On Thu, Mar 31, 2011 at 11:00 PM, Vijay Pradeep<br>>>> <<a href="mailto:vpradeep@willowgarage.com" target="_blank">vpradeep@willowgarage.com</a>> wrote:<br>
>>> > Hi Ryan,<br>>>> ><br>>>> > I'm sorry that you're having trouble getting actionlib to work. What<br>>>> > version of the common stack do you have?<br>>>> ><br>
>>> > Note that it is always possible for some of the ROS messages to be<br>>>> > dropped.<br>>>> > If the result message doesn't make it to the action client, then<br>>>> > waitForResult is going to block forever. I'd suggest adding a timeout<br>
>>> > on<br>>>> > waitForServer, and then preempting the goal if you end up waiting too<br>>>> > long.<br>>>> ><br>>>> >> I made each callback print when<br>
>>> >> it was called, and I found that quite often, the program would block<br>
>>> >> forever when I called waitForServer.<br>>>> > I'm guessing you meant "the program would block forever when I called<br>>>> > waitForResult"<br>>>> ><br>
>>> > I'm using common-1.4.3, and after running your example for ~10 minutes,<br>>>> > it<br>>>> > doesn't seem to freeze for me. I can rerun this test with the exact<br>>>> > version<br>
>>> > of common that you're using. Is there anything you can do to make this<br>>>> > minimal example freeze more often? Are there some strategic sleeps you<br>>>> > could<br>>>> > add to make it mimic your original app more closely?<br>
>>> ><br>>>> > If you can get the chores app to freeze, you could try attaching gdb to<br>>>> > the<br>>>> > process and seeing where all the threads are (using the "info threads"<br>
>>> > command inside gdb). A bunch of them will be stuck on<br>>>> > pthread_cond_timedwait calls, but I'd be curious if there's a thread<br>>>> > stuck<br>>>> > on a lock inside of actionlib. That would be indicative of a race<br>
>>> > condition<br>>>> > in actionlib.<br>>>> ><br>>>> > Vijay<br>>>> ><br>>>> > On Thu, Mar 31, 2011 at 6:55 PM, Ryan Miller <<a href="mailto:rmiller4589@gmail.com" target="_blank">rmiller4589@gmail.com</a>><br>
>>> > wrote:<br>>>> >><br>>>> >> Because of a timing issue I can't quite pin down, actionlib<br>>>> >> occasionally appears to exhibit a race condition. I found the problem<br>
>>> >> after adding callbacks to my client. I made each callback print when<br>>>> >> it was called, and I found that quite often, the program would block<br>>>> >> forever when I called waitForServer. The problem was that the client's<br>
>>> >> active callback was called but the server's execute method was never<br>>>> >> called.<br>>>> >><br>>>> >> I have reduced the problem into a simple ROS package with a single<br>
>>> >> executable that I have attached. After running the node for a while, I<br>>>> >> finally noticed the same problem. It's last output before blocking<br>>>> >> was:<br>
>>> >><br>>>> >> --- snip ---<br>>>> >> Current State: ABORTED<br>>>> >> Aborting.<br>>>> >> Active.<br>>>> >> Done.<br>>>> >> Current State: ABORTED<br>
>>> >> Aborting.<br>>>> >> Active.<br>>>> >> --- snip ---<br>>>> >><br>>>> >> In my actual code, the condition happens extremely frequently, but I<br>
>>> >> found I could mitigate the problem by sleeping for one millisecond<br>>>> >> before returning from the server's execute method. (I should warn you<br>>>> >> that in the attached example, the problem almost never occurs).<br>
>>> >><br>>>> >> Is this likely a bug, or might I doing something wrong? Any<br>>>> >> suggestions would be appreciated. Thanks for the help.<br>>>> >><br>>>> >> -Ryan<br>
>>> >><br>>>> >> _______________________________________________<br>>>> >> ros-users mailing list<br>>>> >> <a href="mailto:ros-users@code.ros.org" target="_blank">ros-users@code.ros.org</a><br>
>>> >> <a href="https://code.ros.org/mailman/listinfo/ros-users" target="_blank">https://code.ros.org/mailman/listinfo/ros-users</a><br>>>> >><br>>>> ><br>>>> ><br>>>> ><br>
>>> > --<br>>>> > Vijay Pradeep<br>>>> > Systems Engineer<br>>>> > Willow Garage, Inc.<br>>>> > <a href="mailto:vpradeep@willowgarage.com" target="_blank">vpradeep@willowgarage.com</a><br>
>>> ><br>>>> ><br>>><br>>><br>>><br>>> --<br>>> Vijay Pradeep<br>>> Systems Engineer<br>>> Willow Garage, Inc.<br>>> <a href="mailto:vpradeep@willowgarage.com" target="_blank">vpradeep@willowgarage.com</a><br>
>><br>><br>><br>><br>> --<br>> Vijay Pradeep<br>> Systems Engineer<br>> Willow Garage, Inc.<br>> <a href="mailto:vpradeep@willowgarage.com" target="_blank">vpradeep@willowgarage.com</a><br>><br>
><br><br>
</div></div></blockquote></div><br><br clear="all"><br></div></div>-- <br><div><div></div><div>Vijay Pradeep<br>
Systems Engineer<br>
Willow Garage, Inc.<br>
<a href="mailto:tfoote@willowgarage.com" target="_blank"><span></span></a><a href="mailto:vpradeep@willowgarage.com" target="_blank">vpradeep@willowgarage.com</a><br>
<br>
</div></div></blockquote></div><br>
</div></div></blockquote></div><br>