Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Enable service unavailable log in rospy wait_for_service #1026

Merged
merged 4 commits into from
Sep 14, 2017

Conversation

AlexReimann
Copy link
Contributor

There is no log published if the service is down and we are waiting for it.

Enables (the code was already there) logging a message.

I changed the error message to a info in case we have a timeout and a warning in case we have no timeout.
In case of no timeout this will be the only message telling you that you are stuck in an endless loop in case the service does not show up. That's why I thought a warning would be better than just a log.

Copy link
Member

@dirk-thomas dirk-thomas left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please target the latest development branch (currently lunar-devel) for your patch. You should be able to edit the existing PR and change the target branch name.

@@ -136,7 +136,7 @@ def contact_service(resolved_name, timeout=10.0):
except: # service not actually up
if first:
first = False
rospy.core.logerr("wait_for_service(%s): failed to contact [%s], will keep trying"%(resolved_name, uri))
rospy.core.loginfo("wait_for_service(%s): failed to contact [%s], will keep trying"%(resolved_name, uri))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This message would be printed every 0.3 s. I think that is too verbose. Please consider using a throttled log call (http://wiki.ros.org/rospy/Overview/Logging#Logging_Periodically). Maybe once every 10s is ok?

@@ -154,7 +154,7 @@ def contact_service(resolved_name, timeout=10.0):
except: # service not actually up
if first:
first = False
rospy.core.logerr("wait_for_service(%s): failed to contact [%s], will keep trying"%(resolved_name, uri))
rospy.core.logwarn("wait_for_service(%s): failed to contact [%s], will keep trying"%(resolved_name, uri))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

When no timeout is specified the default value is 10s. So the message would get printed repeatedly - not only once. Therefore I would argue both log levels should be the same. Not sure if info or warn make more sense though.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It gets printed only once because of the first flag.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does the user get any feedback once the service has become available?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, can add that.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Anyways, I two ways for this (and also the other comment above):

  1. Publish a warning once when we failed to contact service and then publish a info when it becomes available
  2. Publish a throttled info continuously (and maybe publish a info when it becomes available?)

1. is easy to miss, but 2. might be a bit spamy. I personally prefer spamy over missing stuff, so I would go for two (with the "now available" info)

@AlexReimann AlexReimann changed the base branch from kinetic-devel to lunar-devel April 24, 2017 02:16
Alexander Reimann added 2 commits May 23, 2017 10:36
Copy link
Member

@dirk-thomas dirk-thomas left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry for the late response. The good news is that the throttled logging is now available and this patch could benefit from it.

first = False
rospy.core.logerr("wait_for_service(%s): failed to contact [%s], will keep trying"%(resolved_name, uri))
contact_failed = True
rospy.core.loginfo("wait_for_service(%s): failed to contact [%s], will keep trying"%(resolved_name, uri))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should this call logwarn instead?

first = False
rospy.core.logerr("wait_for_service(%s): failed to contact [%s], will keep trying"%(resolved_name, uri))
contact_failed = True
rospy.core.logwarn("wait_for_service(%s): failed to contact [%s], will keep trying"%(resolved_name, uri))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

With #1091 being merged this could be updated to call rospy.core.logwarn_throttle(10, "...") to reduce the verbosity of this line.

Same for the other warning above.

@dirk-thomas
Copy link
Member

Thank you for the patch and iterating on it.

@mathias-luedtke
Copy link

This patch introduced a bug:

Traceback (most recent call last):
  File "/opt/ros/lunar/lib/python2.7/dist-packages/rospy/core.py", line 520, in signal_shutdown
    h()
  File "/root/catkin_ws/install/lib/controller_manager/spawner", line 65, in shutdown
    unload_controller.wait_for_service(timeout=shutdown_timeout)
  File "/opt/ros/lunar/lib/python2.7/dist-packages/rospy/impl/tcpros_service.py", line 420, in wait_for_service
    wait_for_service(self.resolved_name, timeout=timeout)
  File "/opt/ros/lunar/lib/python2.7/dist-packages/rospy/impl/tcpros_service.py", line 139, in wait_for_service
    rospy.core.logwarn_throttle(10, "wait_for_service(%s): failed to contact [%s], will keep trying"%(resolved_name, uri))
NameError: global name 'uri' is not defined

(https://travis-ci.org/ros-controls/ros_control/jobs/295104386#L4754)

Is uri accessible from the outer function at all?

@dirk-thomas
Copy link
Member

@ipa-mdl Thank you for reporting this. Can you please confirm that #1213 fixes the problem.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants