Needed some explanation for Action Server Source code

kashish.dhal · March 28, 2020, 10:47pm

Hello Dear Community (@bayodesegun @rickt ),

I was following the Unit4 (ROS Actions) and currently attempted the first exercise (exercise_46). I had few doubts about the implementation of the action server.

Diving to the exercise, in the solution code, I see the following:

client.send_goal(goal, feedback_cb=feedback_callback)
state_result = client.get_state()
rate = rospy.Rate(1)

This means that we send the goal to the action server which will run at 1 Hz and give us update at 1 Hz

Afterwards, we implement:
i=0
while not i == 3:
takeoff.publish(takeoff_msg)
rospy.loginfo(‘Taking off…’)
time.sleep(1)
i += 1

From this I understand that takeoff msg will be published and then sleep function is called with an argument of 1 sec (meaning you will not get back to this loop in next 1 second) . or else You give back the control to ROS MASTER for 1 second. Now, ROS MASTER decides to execute the action in that 1 second. After executing the action it will wait untill the sleep time for the while loop is over. When the time is over, it will jump back into the while loop and this thing repeats for next 3 iterations.

After 3 iterations we have:

#We move the drone in a circle wile the state of the Action is not DONE yet

while state_result < DONE:
move_msg.linear.x = 1
move_msg.angular.z = 1
move.publish(move_msg)
rate.sleep()
state_result = client.get_state()
rospy.loginfo(‘Moving around…’)
rospy.loginfo("state_result: "+str(state_result))

Now here I see we have used rate.sleep instead of time.sleep and I am not sure why? But anyways from what I understand, it will sleep for any amount of time and I guess ROS MASTER will make that decision. It means that the ROS MASTER will execute the action if it is the time to execute it or else it will keep inside the while loop which means you can execute the statement inside the while loop for multiple time between two actions call. Please correct me if I am wrong? Later part is quite straight forward.

At last, talking about my output, here it is:

[INFO] [1585433782.566912, 0.000000]: Waiting for action Server /ardrone_action_server
[INFO] [1585433782.621251, 412.150000]: Action Server Found…/ardrone_action_server
[INFO] [1585433782.621949, 412.150000]: state_result: 0
[INFO] [1585433782.622334, 412.150000]: Taking off…
[Feedback] image n.1 received
[INFO] [1585433783.623082, 413.043000]: Taking off…
[Feedback] image n.2 received
[INFO] [1585433784.625353, 414.035000]: Taking off…
[Feedback] image n.3 received
[INFO] [1585433785.626763, 415.012000]: Moving around…
[INFO] [1585433785.627757, 415.013000]: state_result: 1
[INFO] [1585433785.628484, 415.014000]: Moving around…
[INFO] [1585433785.629190, 415.015000]: state_result: 1
[INFO] [1585433785.764920, 415.151000]: Moving around…
[INFO] [1585433785.766478, 415.152000]: state_result: 1
[Feedback] image n.4 received
[INFO] [1585433786.794592, 416.150000]: Moving around…
[INFO] [1585433786.799794, 416.155000]: state_result: 1
[Feedback] image n.5 received
[INFO] [1585433787.833864, 417.150000]: Moving around…
[INFO] [1585433787.834655, 417.151000]: state_result: 1
[Feedback] image n.6 received
[INFO] [1585433788.834386, 418.150000]: Moving around…
[INFO] [1585433788.835344, 418.151000]: state_result: 1
[Feedback] image n.7 received
[INFO] [1585433789.841681, 419.150000]: Moving around…
[INFO] [1585433789.842586, 419.151000]: state_result: 1
[Feedback] image n.8 received
[INFO] [1585433790.927491, 420.150000]: Moving around…
[INFO] [1585433790.929047, 420.150000]: state_result: 1
[Feedback] image n.9 received
[INFO] [1585433792.168385, 421.151000]: Moving around…
[INFO] [1585433792.168867, 421.151000]: state_result: 1
[INFO] [1585433793.228869, 422.150000]: Moving around…
[INFO] [1585433793.229588, 422.151000]: state_result: 3
[INFO] [1585433793.230408, 422.152000]: [Result] State: 3
[WARN] [1585433793.231163, 422.153000]: There is a warning in the Server Side
[INFO] [1585433793.231952, 422.154000]: Landing…
[INFO] [1585433794.233841, 423.149000]: Landing…
[INFO] [1585433795.238726, 424.139000]: Landing…

I see here that for time.sleep call in while loop, Taking off… is executed only once between each action pair call namely 0, 1 and 1,2 and 2,3 (see above). However, if we look at the output after 3 seconds between 3rd and 4th action, publishing is done three times. Also, another thing that I noted was in later action calls, publishing was only executed once between the consecutive action calls. Lastly, between 9th and 10th publishing was done twice.

If someone can explain how this scheduling is happening, it will be great!

I will be really thankful for the reply.

Regards,
Kashish Dhal

bayodesegun · March 30, 2020, 9:10am

Not exactly. We are not setting the “rate” of the action server here. Here’s what happens in those three lines, explained in comments:

# send the goal to the action server and specify the callback function 
# that the action server will call from time to time to give feedback
client.send_goal(goal, feedback_cb=feedback_callback) 

# get the state of the action (is it done?)
state_result = client.get_state()

# create a Rate object to be used later on. We have not used it at his point
rate = rospy.Rate(1)

What this code block does simply is publish the takeoff command three times, once per second. When you use time.sleep(x), the code pauses for x seconds. Each time we publish, we are also increasing i by 1, so that the loop can exit after we have published the third time. Execution of the loop has nothing to do with the ROS_MASTER, it’s just pure Python.

rospy.Rate.sleep() works differently:

time.sleep(x) - pause the Python code for x seconds. Can be used anywhere in the program - inside or outside a loop.
rospy.Rate.sleep() - Only used within a loop. Tries to ensure that the loop runs at the defined rate per second. In this case, it will try to make the loop run 1 time per second. Read more about rospy.Rate here: Proper use of rospy.Rate or ros::Rate

The messages [Feedback] image n.x received appearing between the Taking off... messages are coming from the callback function feedback_callback, which is running in a sepate thread from the main program (so nothing in the main program affects it. It’s independent.).

What you call “action server calls” are actually feedback messages from the action server, coming from the callback function feedback_callback. The action server was only called once in the line

client.send_goal(goal, feedback_cb=feedback_callback)

In conclusion, I think you have so many questions because you’re probably new to both Python and ROS. Don’t worry, you will pick both up with more practise. Cheers!

kashish.dhal · April 1, 2020, 8:33pm

Hello @bayodesegun,

Thanks for the reply.

I understand now that time.sleep is a blocking function, it will block everything else from running and hold the code there.

You said rospy.Rate.sleep() is used within the loop to make sure loop rate is maintained.

However, other questions are still unanswered. Who is doing the scheduling? What happens when sleep function is called? Who gets scheduled in that time? Why between 3rd and 4th action calls, publishing is done three times?

Someone (like kernel) should be doing this scheduling? If yes, I would like to know more about it.

Thanks,
Kashish Dhal

bayodesegun · April 3, 2020, 8:49am

Hi @kashish.dhal,

Please don’t try to understand everything at once or you’ll end up even more confused. At this time, you just need to know how to do certain things and what tools to use, primarily by following the examples - you don’t need to understand how they work internally.

More understanding will come as you practise more - this is the way it works for everyone learning something new.

I see that you don’t even understand my last response fully, so I will just clarify a little bit but won’t go further than this.

It doesn’t block “everything” per se. I only blocks the current thread where it’s used. Other threads keep running. That’s why the action server callback (which runs in a separate thread) kept on running even while sleep was in effect in the main thread. That’s why you have those messages printed like that. You can Google “threading” to understand more how threading works.

Not exactly. Did you read the information in the link I provided? Ordinarily a loop has no “rate” - it executes based on the amount of work it has to do and how fast the computer can processes it and you have no control over it. For a simple loop, it can execute a thousand times per second. But when you use a rospy.Rate, say rospy.Rate(2), it will try to make the loop execute only 2 times in a second.

Please go over the former response and this one again. Then you can understand some of your other questions. Over time as you increase you programming knowledge (in Python or others), you will understand things better.

Cheers.

kashish.dhal · April 3, 2020, 11:32pm

Hello @bayodesegun,

I know what threading is, in fact I have develop my own RTOS for my embedded boards. And that is why I was asking you more about scheduling, blocking and sleep stuff.

I see that you wrote earlier “the code pauses” to me it means everything is blocked. What you said in the later comment, I would call it "this thread goes for sleep for 1 sec and give control to the scheduler which can schedule other threads meanwhile in that 1 second".

Next comment about rospy.Rate.sleep() I said is used to maintain the loop rate which means maintaining the loop rate as long as you take care of CPU processing time constraints. I don’t know what I said wrong.

I was just asking you who is doing scheduling in the background so that I can relate it to my RTOS stuff. However, as you said “I will just clarify a little bit but won’t go further than this.” I would honor that and like to thank you very much for all the help. I appreciate your time.

Regards,
Kashish Dhal