publisherUpdate: unknown method name

[bricerebsamen]

I get a lot of those errors in my logs:

[rosmaster.threadpool][ERROR] 2015-02-20 10:16:02,810: Traceback (most recent call last):
  File "/opt/ros/indigo/lib/python2.7/dist-packages/rosmaster/threadpool.py", line 218, in run
    result = cmd(*args)
  File "/opt/ros/indigo/lib/python2.7/dist-packages/rosmaster/master_api.py", line 208, in publisher_update_task
    xmlrpcapi(api).publisherUpdate('/master', topic, pub_uris)
  File "/usr/lib/python2.7/xmlrpclib.py", line 1224, in __call__
    return self.__send(self.__name, args)
  File "/usr/lib/python2.7/xmlrpclib.py", line 1578, in __request
    verbose=self.__verbose
  File "/usr/lib/python2.7/xmlrpclib.py", line 1264, in request
    return self.single_request(host, handler, request_body, verbose)
  File "/usr/lib/python2.7/xmlrpclib.py", line 1297, in single_request
    return self.parse_response(response)
  File "/usr/lib/python2.7/xmlrpclib.py", line 1473, in parse_response
    return u.close()
  File "/usr/lib/python2.7/xmlrpclib.py", line 793, in close
    raise Fault(**self._stack[0])
Fault: <Fault -1: 'publisherUpdate: unknown method name'>

Not sure when exactly this happens and how to reproduce though, but if someone can suggest some experiments I can try to reproduce it.

[bricerebsamen]

also it seems to be harmless, as in I am not noticing any abnormal behavior with the system as a whole (as in data looks good in rviz)

[wjwwood]

That looks like an error from rosmaster where something is asking for the publisherUpdate method, but it does not exist. Are you running any software which uses the master API?

[wjwwood]

I guess another way to ask, is this error log from your application or from the rosmaster?

[bricerebsamen]

One way I get this is when running catkin_make run_tests for some of my tests that require playing back some data with rosbag. I not directly calling the rosmaster API

[wjwwood]

I don't know, I guess it could be a race condition where the XMLRPC server is up but not all of the functions are registered yet and something else attempts to use it.

[dirk-thomas]

Can you please provide a reproducible example?

[bricerebsamen]

I can't provide the actual setup that I have (proprietary packages). I'd have to come up with a dummy package and setup but I'm not sure what's to include to trigger this.

[PatrickHussey]

I have the same issue with a package we are getting ready to release, randomly spread in the master.log is:

[rosmaster.threadpool][ERROR] 2015-03-12 17:15:07,071: Traceback (most recent call last):
  File "/opt/ros/indigo/lib/python2.7/dist-packages/rosmaster/threadpool.py", line 218, in run
    result = cmd(*args)
  File "/opt/ros/indigo/lib/python2.7/dist-packages/rosmaster/master_api.py", line 208, in publisher_update_task
    xmlrpcapi(api).publisherUpdate('/master', topic, pub_uris)
  File "/usr/lib/python2.7/xmlrpclib.py", line 1224, in __call__
    return self.__send(self.__name, args)
  File "/usr/lib/python2.7/xmlrpclib.py", line 1578, in __request
    verbose=self.__verbose
  File "/usr/lib/python2.7/xmlrpclib.py", line 1264, in request
    return self.single_request(host, handler, request_body, verbose)
  File "/usr/lib/python2.7/xmlrpclib.py", line 1297, in single_request
    return self.parse_response(response)
  File "/usr/lib/python2.7/xmlrpclib.py", line 1473, in parse_response
    return u.close()
  File "/usr/lib/python2.7/xmlrpclib.py", line 793, in close
    raise Fault(**self._stack[0])
Fault: <Fault -1: 'publisherUpdate: unknown method name'>

will try and debug a little but any ideas??

[PatrickHussey]

For me seems to be some sort of issue with the scan_to_cloud_filter_chain in the laser_filters package.

I do have a custom point cloud filter plugin for the scan_to_cloud_filter_chain but shutting that off does not help. Only when I disable the entire thing do the master.log error messages go away.

I also run a scan_to_scan_filter_chain which works fine, along with various other filters in concert.

Seems like something in the scan_to_cloud_filter_chain from laser_filters for my issue.

[dirk-thomas]

@SISegwayRmp If you could provide a reproducible example I might be able to figure out what the problem is.

[muawijhe]

I experienced the same problem. This is my current setup:

I'm running ROS indigo from a Raspberry 2 with rasbian. I built the ROS following the tutorial.

I made some custom message for the Navio (an IMU shield for raspberry).

First of all, I built the custom messages:

cd /opt/ros/indigo/share/cc_msgs

make ... cd build && make Scanning dependencies of target rosbuild_premsgsrvgen [ 0%] Built target rosbuild_premsgsrvgen Scanning dependencies of target ROSBUILD_genmsg_py [ 9%] Generating ../src/cc_msgs/msg/_Servo.py [ 18%] Generating ../src/cc_msgs/msg/_RGBLed.py [ 27%] Generating ../src/cc_msgs/msg/_BARORaw.py [ 36%] Generating ../src/cc_msgs/msg/_IMURaw.py [ 45%] Generating ../src/cc_msgs/msg/_GPSRaw.py [ 54%] Generating ../src/cc_msgs/msg/init.py [ 54%] Built target ROSBUILD_genmsg_py Scanning dependencies of target ROSBUILD_genmsg_cpp [ 63%] Generating ../msg_gen/cpp/include/cc_msgs/RGBLed.h [ 72%] Generating ../msg_gen/cpp/include/cc_msgs/BARORaw.h [ 81%] Generating ../msg_gen/cpp/include/cc_msgs/IMURaw.h [ 90%] Generating ../msg_gen/cpp/include/cc_msgs/GPSRaw.h [100%] Generating ../msg_gen/cpp/include/cc_msgs/Servo.h [100%] Built target ROSBUILD_genmsg_cpp Scanning dependencies of target rospack_genmsg [100%] Built target rospack_genmsg Scanning dependencies of target rospack_genmsg_all [100%] Built target rospack_genmsg_all

Then I launched the roscore and an instance of a new ROS module (mIMU).

This is the topic list at the moment:

pi@raspberrypi ~/Development $ rostopic list /Navio/Imu /rosout /rosout_agg

This is the new custom message type (which is found by rostopic)

pi@raspberrypi ~/Development $ rostopic info /Navio/Imu Type: cc_msgs/IMURaw

Publishers:

• /mIMU (http://navio:59317/)

Subscribers: None

However, if I try to perform a frequency test:

pi@raspberrypi /mnt/ccmemory/logs/ros/5834c7e0-cf56-11e4-8bd0-b827ebd73914 $ rostopic hz /Navio/Imu

[rosmaster.master][INFO] 2015-03-21 00:23:49,379: +PUB [/rosout] /rostopic_8709_1426893829183 http://raspberrypi:36147/ [rosmaster.master][INFO] 2015-03-21 00:23:49,384: publisherUpdate[/rosout] -> http://raspberrypi:55867/ [rosmaster.master][INFO] 2015-03-21 00:23:49,385: publisherUpdate[/rosout] -> http://raspberrypi:42924/ [rosmaster.threadpool][ERROR] 2015-03-21 00:23:49,397: Traceback (most recent call last): File "/opt/ros/indigo/lib/python2.7/dist-packages/rosmaster/threadpool.py", line 218, in run result = cmd(*args) File "/opt/ros/indigo/lib/python2.7/dist-packages/rosmaster/master_api.py", line 208, in publisher_update_task xmlrpcapi(api).publisherUpdate('/master', topic, pub_uris) File "/usr/lib/python2.7/xmlrpclib.py", line 1224, in call return self.__send(self.__name, args) File "/usr/lib/python2.7/xmlrpclib.py", line 1578, in __request verbose=self.__verbose File "/usr/lib/python2.7/xmlrpclib.py", line 1264, in request return self.single_request(host, handler, request_body, verbose) File "/usr/lib/python2.7/xmlrpclib.py", line 1292, in single_request self.send_content(h, request_body) File "/usr/lib/python2.7/xmlrpclib.py", line 1439, in send_content connection.endheaders(request_body) File "/usr/lib/python2.7/httplib.py", line 958, in endheaders self._send_output(message_body) File "/usr/lib/python2.7/httplib.py", line 818, in _send_output self.send(msg) File "/usr/lib/python2.7/httplib.py", line 780, in send self.connect() File "/usr/lib/python2.7/httplib.py", line 761, in connect self.timeout, self.source_address) File "/usr/lib/python2.7/socket.py", line 571, in create_connection raise err error: [Errno 111] Connection refused

[rosmaster.master][INFO] 2015-03-21 00:23:49,406: +SERVICE [/rostopic_8709_1426893829183/get_loggers] /rostopic_8709_1426893829183 http://raspberrypi:36147/ [rosmaster.master][INFO] 2015-03-21 00:23:49,415: +SERVICE [/rostopic_8709_1426893829183/set_logger_level] /rostopic_8709_1426893829183 http://raspberrypi:36147/ [rosmaster.master][INFO] 2015-03-21 00:23:49,432: +SUB [/Navio/Imu] /rostopic_8709_1426893829183 http://raspberrypi:36147/ subscribed to [/Navio/Imu] average rate: 25.630 min: 0.015s max: 0.040s std dev: 0.00483s window: 26

Apparently I can experience the same error even by trying a frequency test on a standard topic (rosout):

pi@raspberrypi /mnt/ccmemory/logs/ros/5834c7e0-cf56-11e4-8bd0-b827ebd73914 $ rostopic hz /rosout

[rosmaster.master][INFO] 2015-03-21 00:24:56,429: +PUB [/rosout] /rostopic_8733_1426893896239 http://raspberrypi:45220/ [rosmaster.master][INFO] 2015-03-21 00:24:56,451: +SERVICE [/rostopic_8733_1426893896239/get_loggers] /rostopic_8733_1426893896239 http://raspberrypi:45220/ [rosmaster.master][INFO] 2015-03-21 00:24:56,460: +SERVICE [/rostopic_8733_1426893896239/set_logger_level] /rostopic_8733_1426893896239 http://raspberrypi:45220/ [rosmaster.master][INFO] 2015-03-21 00:24:56,477: +SUB [/rosout] /rostopic_8733_1426893896239 http://raspberrypi:45220/ subscribed to [/rosout] [rosmaster.master][INFO] 2015-03-21 00:24:56,519: publisherUpdate[/rosout] -> http://raspberrypi:55867/ [rosmaster.master][INFO] 2015-03-21 00:24:56,521: publisherUpdate[/rosout] -> http://raspberrypi:42924/ [rosmaster.threadpool][ERROR] 2015-03-21 00:24:56,526: Traceback (most recent call last): File "/opt/ros/indigo/lib/python2.7/dist-packages/rosmaster/threadpool.py", line 218, in run result = cmd(*args) File "/opt/ros/indigo/lib/python2.7/dist-packages/rosmaster/master_api.py", line 208, in publisher_update_task xmlrpcapi(api).publisherUpdate('/master', topic, pub_uris) File "/usr/lib/python2.7/xmlrpclib.py", line 1224, in call return self.__send(self.__name, args) File "/usr/lib/python2.7/xmlrpclib.py", line 1578, in __request verbose=self.__verbose File "/usr/lib/python2.7/xmlrpclib.py", line 1264, in request return self.single_request(host, handler, request_body, verbose) File "/usr/lib/python2.7/xmlrpclib.py", line 1292, in single_request self.send_content(h, request_body) File "/usr/lib/python2.7/xmlrpclib.py", line 1439, in send_content connection.endheaders(request_body) File "/usr/lib/python2.7/httplib.py", line 958, in endheaders self._send_output(message_body) File "/usr/lib/python2.7/httplib.py", line 818, in _send_output self.send(msg) File "/usr/lib/python2.7/httplib.py", line 780, in send self.connect() File "/usr/lib/python2.7/httplib.py", line 761, in connect self.timeout, self.source_address) File "/usr/lib/python2.7/socket.py", line 571, in create_connection raise err error: [Errno 111] Connection refused

Any ideas ?

[trainman419]

It looks like publisherUpdate is an XMLRPC method that is exported by the ROS client library, and the error in the master logs results from the master being unable to call this method on a node.

I can find no direct references to publisherUpdate calls in my and @bricerebsamen's code. I suspect this is some kind of startup/shutdown race condition in one of the core ROS libraries, when two nodes are shut down at the same time.

[PatrickHussey]

I agree, I have looked into this pretty extensively trying to trace the error and have concluded that it has nothing to do with the code I am running but likely a core library. I have noticed that it tends to show up when initializing a subscriber and publisher in separate code at the same or close to the same time.

Good example was launching a python node with dynamic_reconfigure client and launching

 <node name="$(anon dynparam)" pkg="dynamic_reconfigure" 
type="dynparam" args="set_from_parameters NODE"> 
    <param name="EX1" type="double" value="-1.0" />
    <param name="EX2" type="double" value="1.0" /> 
  </node>

in the same launch file. I get the errors pretty constantly. Probably a race. I'll try and make an example

[afrancescon]

I have the same problem when try to use nodelets in UDOO (ARM based pc).

I have two nodelet: nodelet_A publish topics that are subscribed by nodelet_B (image transport related messages).

If nodelet_A cames before nodelet_B in launch file I have the exception shown on before message (I don't attach it here since it id exactly the same). Swapping the order in launch files (nodelet_B before nodelet_A) works fine!

It is quite strange that on my laptop it works anyway; this exception occurs only on my UDOO.

[s-devine]

Currently still experiencing this, anyone come across a solution?

This occurs when I restart a node on occasion, the nodes pubs & subs will not connect (Error in roswtf, "these nodes should be connected but aren't"). Error persists until the node is restarted again.

[mysablehats]

Not sure if it helps, but I have this issue when using https://github.com/ros-drivers/video_stream_opencv to play a video file on ros-melodic with Ubuntu 18.04.1 LTS, while it works just fine with my other pc with ros-kinetic and Ubuntu 16.04.5 LTS:

traceback output from logfile: [rosmaster.master][INFO] 2018-10-24 15:48:51,380: publisherUpdate[/videofile/image_raw] -> http://poop:44067/ []: sec=0.00, exception=[Errno 111] Connection refused [rosmaster.threadpool][ERROR] 2018-10-24 15:48:51,381: Traceback (most recent call last): File "/opt/ros/melodic/lib/python2.7/dist-packages/rosmaster/threadpool.py", line 218, in run result = cmd(*args) File "/opt/ros/melodic/lib/python2.7/dist-packages/rosmaster/master_api.py", line 210, in publisher_update_task ret = xmlrpcapi(api).publisherUpdate('/master', topic, pub_uris) File "/usr/lib/python2.7/xmlrpclib.py", line 1243, in call return self.__send(self.__name, args) File "/usr/lib/python2.7/xmlrpclib.py", line 1602, in __request verbose=self.__verbose File "/usr/lib/python2.7/xmlrpclib.py", line 1283, in request return self.single_request(host, handler, request_body, verbose) File "/usr/lib/python2.7/xmlrpclib.py", line 1311, in single_request self.send_content(h, request_body) File "/usr/lib/python2.7/xmlrpclib.py", line 1459, in send_content connection.endheaders(request_body) File "/usr/lib/python2.7/httplib.py", line 1038, in endheaders self._send_output(message_body) File "/usr/lib/python2.7/httplib.py", line 882, in _send_output self.send(msg) File "/usr/lib/python2.7/httplib.py", line 844, in send self.connect() File "/usr/lib/python2.7/httplib.py", line 821, in connect self.timeout, self.source_address) File "/usr/lib/python2.7/socket.py", line 575, in create_connection raise err error: [Errno 111] Connection refused

I've tested this with ./test_video_resource.py /tmp/small.mp4 and it plays just fine. Any ideas of what could be wrong?

[dseifert]

I can reproduce the "connection refused" error with the attached code. It seems what happens (as indicated previously) is a racing condition where rosmaster is telling a node about a publisher shutting down, but that node is also in some stage of shutdown (so you either get the "method unknown" error if the xmlrpc proxy is still running but the function binding has been dissolved, or the "connection refused" if the connection is already down.

test572.zip

[Charlie-lusie]

I can reproduce the "connection refused" error with the attached code. It seems what happens (as indicated previously) is a racing condition where rosmaster is telling a node about a publisher shutting down, but that node is also in some stage of shutdown (so you either get the "method unknown" error if the xmlrpc proxy is still running but the function binding has been dissolved, or the "connection refused" if the connection is already down.

test572.zip

what do you mean "a publisher shutting down"? But I didn't make any publisher shutting down in my code.