Monitoring/ Debugging ROS snaps on Ubuntu Core over SSH

prex · December 19, 2019, 5:54pm

Hi there,

I just built my first ROS snap with two nodes and was surprised how convenient this is. However, I’m not sure if using a ROS snap on Ubuntu Core 18 is the right way during the development phase of our robot.

My main concern is debugging/ monitoring the robot in real-time during operation. ROS makes this very easy by giving access to the messages, output streams etc. I’m not talking about errors which I could figure out during development on my Ubuntu Desktop, but rather problems which arise during testing at our customers place because of hardware constraints, user interaction, overheating etc.

I would like to access the Ubuntu Core 18 over SSH to:

Check the outputs of ROS in the terminal
Using the ROS Command-line tools, e.g. rostopic echo, rostopic list, rosservice call

For the first point, I just can’t figure out how to see the output of a ROS snap which runs as a service. When I connect over SSH, I assume, I somehow need to bring the process to the foreground.

For the second point, it is somehow clear to me that I can not access these tools from the outside of the snap, since ROS is not installed there. A possible solution might be to install ROS in the classic mode to have these tools available (at least this works on my Desktop machine). But I have my doubts that this is a proper solution since there is also no way to source my workspace in the snap.

I’m thankful for any help.

Best,

prex

ijohnson · December 19, 2019, 6:54pm

Hi,

You can use snap logs <snap-name>.<snap-app>. You can also stop the service and run it manually with the full output sent to stdout with:

$ snap stop <snap-name>.<snap-app>
$ snap run <snap-name>.<snap-app>

I’m not sure what is best practice from the perspective of ROS in general, but could you bundle these commands inside the snap you are developing, since ROS must be inside the snap, no? I.e. add something like:

apps:
  rostopic:
    command: bin/rostopic
  rosservice:
    command: bin/rosservice

to your snapcraft.yaml.

This will not work on Ubuntu Core, since classic snaps cannot be installed on Ubuntu Core.

prex · December 20, 2019, 3:53pm

I don’t get any output when using snap logs. There is also no output when I manually start the service. It just tells me “Started.”

Just without the “bin/”. Works as expected.

Thanks!

prex · December 31, 2019, 3:24pm

The question about how to see the ROS output is not really answered for me. I tried different commands, but none of them are satisfying.

snap logs <snap_name>.<app_name>

-> Does not give me any output.

systemctl status -l snap.<snap_name>.<app_name>

-> On Ubuntu 18 Desktop, this gives me some of the latest outputs. But on Ubuntu Core, besides the information about the service, this does not show me the output streams from ROS.

sudo journalctl -fu snap.<snap_name>.<app_name>

-> This does more or less what it should, except that the order of the output is not correct anymore. The log timestamp does not match the ROS timestamp.

ijohnson · January 6, 2020, 6:04pm

Did you try snap logs -n=all <snap_name>.<app_name> ?

prex · January 8, 2020, 5:48pm

For reference, I’m using the example with the ros-talker-listener: https://snapcraft.io/test-ros-talker-listener-msrl

test-ros-talker-listener-msrl.rostopic echo /chatter shows me what I’m expecting to see in the log. But this gives me now:

user@localhost:~$ snap logs -n=all test-ros-talker-listener.run
2020-01-08T17:40:27Z systemd[1]: Started Service for snap application test-ros-talker-listener.run.
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]: Unhandled exception in thread started by <bound method XmlRpcNode.run of <rosgraph.xmlrpc.XmlRpcNode object at 0x7faaa437da50>>
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]: ERROR: Unable to start XML-RPC server, port 11311 is already in use
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]: Traceback (most recent call last):
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]:   File "/snap/test-ros-talker-listener/3/opt/ros/melodic/lib/python2.7/dist-packages/rosgraph/xmlrpc.py", line 222, in run
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]:     self._run()
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]:   File "/snap/test-ros-talker-listener/3/opt/ros/melodic/lib/python2.7/dist-packages/rosgraph/xmlrpc.py", line 291, in _run
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]:     self._run_init()
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]:   File "/snap/test-ros-talker-listener/3/opt/ros/melodic/lib/python2.7/dist-packages/rosgraph/xmlrpc.py", line 241, in _run_init
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]:     self.server = ThreadingXMLRPCServer((bind_address, port), log_requests)
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]:   File "/snap/test-ros-talker-listener/3/opt/ros/melodic/lib/python2.7/dist-packages/rosgraph/xmlrpc.py", line 122, in __init__
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]:     SimpleXMLRPCServer.__init__(self, addr, SilenceableXMLRPCRequestHandler, log_requests)
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]:   File "/snap/test-ros-talker-listener/3/usr/lib/python2.7/SimpleXMLRPCServer.py", line 593, in __init__
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]:     SocketServer.TCPServer.__init__(self, addr, requestHandler, bind_and_activate)
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]:   File "/snap/test-ros-talker-listener/3/usr/lib/python2.7/SocketServer.py", line 420, in __init__
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]:     self.server_bind()
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]:   File "/snap/test-ros-talker-listener/3/usr/lib/python2.7/SocketServer.py", line 434, in server_bind
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]:     self.socket.bind(self.server_address)
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]:   File "/snap/test-ros-talker-listener/3/usr/lib/python2.7/socket.py", line 228, in meth
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]:     return getattr(self._sock,name)(*args)
2020-01-08T17:40:30Z test-ros-talker-listener.run[1070]: socket.error: [Errno 98] Address already in use

kyrofa · January 14, 2020, 8:49pm

Sounds like you have roscore already running, there. I assume it’s being run by your service? Try stopping the service, first.

kyrofa · January 14, 2020, 8:52pm

Regarding logs, are all of nodes in your launch file set to output="screen"? If not you’ll need to look in logfiles, which are going to $SNAP_USER_DATA/ros. If it’s a service, that will resolve to /root/snap/<snap name>/current/ros.

kyrofa · January 14, 2020, 9:04pm

In retrospect I probably should have written one comment instead of three . There are several good questions here, though!

As @ijohnson pointed out, while you’re correct in that the snap’s workspace cannot be directly sourced and used outside the snap, you can certainly export certain tools from the snap to be utilized for debugging purposes. That may be all you need, but you may also find yourself adding more and more debugging tools to the snap to account for this possibility, thereby bloating the snap beyond what you had originally hoped. If you find yourself doing that, keep in mind that snaps aren’t namespaced from the network. You can use that to your advantage, for example, by installing the lxd or docker snap on the device, firing up an ephemeral container, installing all the ROS debugging tools you want on it, and setting it up to use the roscore on the host (which is being run by the snap service). That may open up more possibilities for poking at things. When you’re done you can toast the container.

prex · May 5, 2020, 4:07pm

I’m working on this issue again. The behaviour is very strange. My favourite command turned out to be sudo journalctl -fu snap.name.daemon. I have several nodes running with the ROS outputs ROS_WARN, ROS_ERROR, ROS_DEBUG and ROS_INFO. From at least one of my nodes, I see every output. But from my GUI node, I don’t get any output at all. Outputs for every node are set to output="screen" in the launch file. If running on my local system, I see the outputs properly.

Checking this page, every output I have should either end up in stdout or stderr. The outputs are successfully published to the /rosout_agg and /rosout topics. So if these outputs end up in rosout, this means that my code should be working in general. But how can only some of them be sent to the screen, with the same settings, depending on the device?!

I would like to check if they end up there, but I don’t have permission to cd in this folder.

Sounds interesting. I will keep that in mind. However, for now rostopic and rosnode commands are all I need and this is working perfectly fine.

kyrofa · May 5, 2020, 9:30pm

It kinda sounds like that node is crashing. Have you tried running it on its own as an app instead of in the daemon’s launch file?

prex · May 5, 2020, 9:50pm

I mean I just don’t get any log outputs. The daemon and the complete software runs totally fine (confirmed by using it on our machine with the GUI). I can see the logs I’m looking for in /rosout_agg. They just don’t end up in the snap logs or output.

I’m still having the issue with snap logs not showing anything and just found this post from someone else having the same problem: Snap logs does not show the logs even though they are in journalctl?

So is journalctl -fu doing the same as snap logs? Do these commands actually read from a log file or catch the stdout and stderr output directly? I’m still searching this log file for my service.

PS: I’m not even really interested in saving the logs. I just need the “live” outputs from my daemon.

prex · May 5, 2020, 10:18pm

Let me recap: The nodes are running, ROS logs from ROS_INFO, ROS_ERROR, etc. are written to /rosout_agg as they should (which I can confirm). Now they are sent to stdout and stderr by the ROS system (I’m using output="screen"). And stdout and stderr should be catched by systemd’s journald, I assume. This writes the logs to a log file, which I’m then reading with journalctl.

This means that my logs get lost somewhere between /rosout_agg and journalctl. Are there any settings, e.g. a max frequency of logs or should every output end up in the log?

prex · May 10, 2020, 7:59pm

After more testing, I see some kind of pattern. I added the following outputs in class constructors of different nodes:

  ROS_INFO("Info output");
  ROS_WARN("Warning output");
  ROS_ERROR("Error output");
  std::cout << "COUT" << std::endl;

ROS_WARN and ROS_ERROR are shown for every node as expected
ROS_INFO is just shown for one node and always for the same one
if a std::cout is added after ROS_INFO, the info output from ROS_INFO is also shown
std::cout is shown for every node

I can’t see the logic behind this. According to the ROS Logging Documentation, ROS_INFO outputs to stdout and default verbosity level is INFO. The ROS_INFO messages are in rosout_agg and using std::cout also works. Therefore, the forwarding of ROS_INFO to stdout seems not to work for all cases.

I would have said this is a problem of the ROS Logger. However, this works fine if not built into a snap. All the outputs are normally in the terminal.

I need to mention that I’m running a thread in the GUI node and ROS also does some kind of process management. Could this be a problem with flushing cout?

Solution: Indeed, the ROS line buffering was the problem. The default buffering scheme of stdout seems to be different in the snap environment. Line buffering for ROS loggers can be forced with the environment variable:

export ROSCONSOLE_STDOUT_LINE_BUFFERED=1

http://wiki.ros.org/rosconsole