0
$\begingroup$

Rosanswers logo

I'm running ROS hydro on Ubuntu 12.04.

I've written a simple python script that calculates the bandwidth though a network interface and then publishes as an Int16. So there's no data acquisition from an external sensor/hardware.

Whats going on is that at the start, everything seems to be working fine. I left it running overnight, the next morning, some of my nodes stopped being able to subscribe to it, but some are still subscribing to it. rostopic echo also isn't able to subscribe to it. From running rqt_graph, both the subscribing nodes and publisher are still alive and the arrows still indicate the subscribing/publishing.

Has anyone encountered this or have an idea how I should go about debugging it? I've started to look at the .ros/log folder and I can't seem seem to make sense of it. Upgrading to Ubuntu 14.04 and to indigo is an option, but I would like to try other alternatives before an upgrade.


Edit: I've updated to indigo and running ubuntu 14.04 LTS, but I'm still seeing this same issue.

This also doesn't look like an rostopic issue. When I run into this issue, the existing nodes continue to subscribe to this topic, but new nodes or rostopic cannot. In order to fix this, I have to kill the node and let the troubled node respawn/rerun and then new nodes are able to subscribe.


Edit2:

From Ahendrix's post, I thought I would try ROS_HOSTNAME. Here was my set up:

Main computer([email protected]): I've edited the /etc/hosts file to resolve 127.0.0.1 as main-computer. export ROS_MASTER_URI=http://main-computer:11311

export ROS_HOSTNAME=main-computer

Remote computer([email protected]): Edited /etc/hosts file to resolve 192.168.1.2 as main-computer. export ROS_MASTER_URI=http://main-computer:11311

export ROS_IP=192.168.1.3

What I tried to do was make sure even if my DHCP lease was up, and a new IP was assigned, I all the old nodes and new nodes would be able to resolve "main-computer" to its local ip address.

Unfortunately, this still didn't work. While "main-computer" had this problem, I logged onto "main-computer" for an rostopic echo. I saw that on master.log, it was actually adding a sub.

[rosmaster.master][INFO] 2015-03-27 12:30:47,573: +SUB [/bandwidth_msg] /rostopic_11324_1427484647396 http://main-computer:42724/

I went into the rostopic_11324_1427484647396.log file, and saw that everything looks normal, and shortly after, this error message popped up.

[rospy.internal][WARNING] 2015-03-27 12:32:32,352: Unknown error initiating TCP/IP socket to main-computer:45391 (http://main-computer:52459/): Traceback (most recent call last):
  File "/opt/ros/indigo/lib/python2.7/dist-packages/rospy/impl/tcpros_base.py", line 557, in connect
    self.read_header()
  File "/opt/ros/indigo/lib/python2.7/dist-packages/rospy/impl/tcpros_base.py", line 619, in read_header
    self._validate_header(read_ros_handshake_header(sock, self.read_buff, self.protocol.buff_size))
  File "/opt/ros/indigo/lib/python2.7/dist-packages/rosgraph/network.py", line 363, in read_ros_handshake_header
    d = sock.recv(buff_size)
error: [Errno 104] Connection reset by peer

[rospy.internal][INFO] 2015-03-27 12:32:32,352: topic[/bandwidth_msg] removing connection to http://main-computer:52459/

After I killed the rostopic echo...

[rosmaster.master][INFO] 2015-03-27 13:05:27,360: -SUB [/bandwidth_msg] /rostopic_11324_1427484647396 http://main-computer:42724/

I'll continue to investigate and try to take a look at tcpros_base.py!


Edit3:

I checked out the publisher's log file and I'm sad to say I'm not too sure what I'm looking for. From the top of the file, everything looks normal... starting xml-rpc server, registering with master, initializing /rosout, connectected to core etc.. Then it adds the subscribers and rosbag. I also have a script which calls "rostopic echo" every 5 seconds, so I see that it starts to do a repetitive pattern of:

[rospy.internal][INFO] 2015-03-27 07:22:03,323: topic[/bandwidth_msg] adding connection to [/rostopic_19181_1427466122994], count 2
[rospy.internal][INFO] 2015-03-27 07:22:09,004: topic[/bandwidth_msg] removing connection to /rostopic_19181_1427466122994

Then suddenly, I see this warning message.

[rosout][WARNING] 2015-03-27 07:22:17,162: Inbound TCP/IP connection failed: connection from sender terminated before handshake header received. 0 bytes were received. Please check sender for additional details.
[rospy.internal][ERROR] 2015-03-27 07:22:17,163: Inbound TCP/IP connection failed:
Traceback (most recent call last):
  File "/opt/ros/indigo/lib/python2.7/dist-packages/rospy/impl/tcpros_base.py", line 321, in _tcp_server_callback
    header = read_ros_handshake_header(sock, StringIO(), buff_size)
  File "/opt/ros/indigo/lib/python2.7/dist-packages/rosgraph/network.py", line 365, in read_ros_handshake_header
    raise ROSHandshakeException("connection from sender terminated before handshake header received. %s bytes were received. Please check sender for additional details."%b.tell())
ROSHandshakeException: connection from sender terminated before handshake header received. 0 bytes were received. Please check sender for additional details.

And the pattern of adding a connection/removing connection happens for a few more minutes, then the warning shows up again, back to the adding/removing, warning again, pattern again, then the error happened with the file ending there. New nodes now will stop being able to subscribe to it.

I could post the log file if it'll make it easier to understand. I'm not exactly sure what goes into these log files, but if someone can point me to where I can find more details about logging, I'd like to learn more about it.


Originally posted by pwong on ROS Answers with karma: 447 on 2015-02-05

Post score: 1


Original comments

Comment by dornhege on 2015-02-06:
Sounds like it might be some low-level instability "thing". A first debugging would be to remove your calculations/interfacing and really just publish random data. If it still occurs it's some ROS instability. If everything works fine, it has to do something with your code (not necessarily your faul

Comment by pwong on 2015-02-06:
This happened again, but unfortunately I didn't get a chance to do that setup. It might be a rostopic issue. I didn't mention that the node runs with a ROS_MASTER_URI of the local IP address and not local. I saw that the rostopic issue happened when the connection was lost and reconnect.

Comment by pwong on 2015-02-06:
When this happened, I did an rostopic pub on the troubled topic, and received a warning.[WARN] [WallTime: 1423217612.971032] Inbound TCP/IP connection failed: connection from sender terminated before handshake header received. 0 bytes were received. Please check sender for additional details.

$\endgroup$

1 Answer 1

0
$\begingroup$

Rosanswers logo

I suspect you're using your computer's IP address instead of the loopback address in your ROS_MASTER_URI and ROS_IP, and that your computer gets assigned a different IP address when it renews its DHCP lease.

Since all of the running nodes are connected locally, they won't have any trouble when your IP address changes.

If you have nodes that advertise their topics on your machine's IP address, and the IP address changes, those nodes won't be updated. Since they're still using the old IP address, other nodes won't be able to connect.

There are a few ways to fix this, depending on your requirements:

  • Use localhost in your ROS_MASTER_URI and ROS_IP/ROS_HOSTNAME
  • If you have a hostname and it doesn't change when your IP changes, use that in your ROS_IP and ROS_HOSTNAME
  • Write a script which detects when your hostname changes, and restarts all of your nodes
  • Fix ROS so that it deals with IP address changes (this will probably be quite a bit of work)

EDIT

Give your log files, it looks like your system isn't having hostname problems.

The real problem here is that the publisher is rejecting new connections. The relevant error message from your log file is:

error: [Errno 104] Connection reset by peer

You should go look at the logs for your publisher node to see if it's getting any new connection requests, and hopefully you'll find a reason there about why it's rejecting them.


Originally posted by ahendrix with karma: 47576 on 2015-03-20

This answer was ACCEPTED on the original site

Post score: 1


Original comments

Comment by pwong on 2015-03-20:
I am doing it through my computer's IP address instead of loopback. The computer gets an IP address through openVPN so it is static, and shouldn't change. (At least it was the same when I checked at launch and at troubled time). I'll give the ROS_HOSTNAME a try, thanks!

Comment by pwong on 2015-03-27:
I've added an update regarding the situation on my original question from "Edit2" onwards. If you have some time to take a look, please let me know what you think!

Comment by ahendrix on 2015-03-29:
Is your node leaking file descriptors?

Comment by pwong on 2015-03-30:
I've been testing/monitoring it. I want to make sure of the results before an update. Thank you for pointing me towards that direction, its something I've never heard of until you mentioned it.

Comment by pwong on 2015-04-21:
Turns out it wasn't a file descriptor leak. When I saw this problem happening, I did a: lsof | wc -l which showed 48170. This looks like a lot, but this stayed in control +/- 1000 files. I checked the max fds allowed for my system: /proc/sys/fs/file-max which showed 390022.

Comment by pwong on 2015-04-21:
I noticed that the computer has over 10gb of files in the .ros/log folder. The problem shows up much sooner than others. After I did a rosclean purge of the folder, the problem seemed to not surface so soon. Do you think there is any correlation between my problem and the log folder being so large?

Comment by ahendrix on 2015-04-21:
In addition to the system-wide limit on file descriptors, there is also a per-process limit that is usually around 1024 to 4096 open files.

Comment by ahendrix on 2015-04-21:
It's possible that the sheer number of files in your log directory is slowing down the file system. Unfortunately, ROS doesn't have an automatic system for cleaning these out, but it's fairly simple to use cron and tmpwatch to clean your log directory out on a regular basis.

Comment by pwong on 2015-04-21:
So I caught this problem again shortly, and I've checked the number of file descriptors open for this one node. Turns out its only 13 files open. However, one thing I noticed for that node's "-stdout.log" grew to be about 0.9 megabytes and this is when I noticed the problem.

Comment by pwong on 2015-04-21:
Similarly, another node's ".log" and "-stdout.log" grew to be about 0.8 megabytes and the issue surfaced. I had to do a rosclean purge, and restart the node to fix the issue. I think this point, I'll try to keep the file size of these log files low, and see if the problem goes away.

Comment by ahendrix on 2015-04-22:
Have you looked at the contents of those logs? If they're growing that large, there's probably a good reason.

Comment by pwong on 2015-04-22:
For the "-stdout.log" files, I'll make sure everything stops printing. The ".log" files just constantly prints adds/removes connections:

rospy.internal][INFO] 2015-04-08 11:56:59,926: topic[/troubled_topic] adding connection to [/rostopic_9588_1428519419720], count 7

Comment by pwong on 2015-04-22:
I'm assuming this is because we constantly call "rostopic echo -n 1 /troubled_topic". I'll make other nodes just subscribes instead of using "rostopic echo" and maybe I can set the log level to warn to prevent from saving to this file. Do you know for sure if this file size is the source of issue?

Comment by ahendrix on 2015-04-22:
It's possible that the publisher connections in your node are not being cleaned up properly, and the log size is a secondary indication that you've somehow hit the max number of subscribers for this publisher. Do you see it fail around a similar number of connection attempts each time?

Comment by ahendrix on 2015-04-22:
rospy in particular has some internal connection state tracking problems, so if your node is written in python it's possible that it doesn't do well with an enormous number of disconnect and reconnect attempts.

Comment by pwong on 2015-04-22:
It usually peaks at 7-8 connections and the problem happens. I thought of the maximum number of subscribers, but I've tried to test it out. I opened 10+ terminals for an rostopic echo, and I wasn't able to produce the problem. The ".log" doesn't print furiously, just new connections every 1Hz.

Comment by pwong on 2015-04-27:
@ahendrix Do you know how I would be able to check if I have connections which aren't being cleaned up properly? I can do "rosnode info" and "rostopic info" but everything looks normal... I've also stopped running the scripts which calls rostopic once, but the problem is still there!

Comment by ahendrix on 2015-04-28:
I'm out of ideas at this point. Maybe start adding debugging code to rospy, or turn up the debug level in rospy?

Comment by pwong on 2015-05-15:
I think the issue is resolved. When I said I thought I removed all of the scripts calling rostopic echo repeated, I actually still had some else where. After they were all removed, I don't experience the issue anymore. I don't know why this cause the issue, but this was the problem.

Comment by pwong on 2015-05-15:
Thank you, ahendrix for all of your suggestions and help! I'll mark your answer as the solution

Comment by gvdhoorn on 2015-05-16:
Perhaps this is related to ros_comm/issues/610?

Comment by pwong on 2015-05-21:
@gvdhoorn Problem looks similar! The problem also looks unresolved. Is there anything I could do to help move the problem closer to a solution? I could always just look out for the same symptoms if I run into the issue again.

Comment by gvdhoorn on 2015-05-21:
If you think you can add to the discussion on the ticket, please do. Steps that make this (easily) reproducible would also be very valuable. Perhaps even a 'me too' post would be good; you could at least see if dirk has anything that you may be able to help with.

$\endgroup$

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.