bwi_logging: automatically compress and upload log files to the main server

[utexas-bwi]

bwi_logging: automatically compress and upload log files to the main server

[jack-oquin]

@pato pointed out that rosbag has a -j parameter to create a compressed bag in the first place.

We should definitely do it that way, because the savings are substantial. Once everyone has upgraded to that version, we will no longer need to compress the bags prior to uploading them.

[jack-oquin]

The 3a54aac commit adds the -j to rosbag record.

That works with the existing bags and upload scripts, even with no changes. Since it's compatible I went ahead and committed it.

[jack-oquin]

Commit 6a87273 is my first hack at running the upload automatically. It's currently in a new joq/autolog branch.

I'll test that today in the lab.

[jack-oquin]

It worked the first try on a short (4 minute) run.

But after a longer run (3.5 hours) run it failed to upload the bag, leaving it in the logging directory, compressed by the original rosbag record, but not again by the bwi bags script. It was not on the server. Running bwi bags bwi by hand worked moving it to the server (and running fairly quickly).

Hard to tell what went wrong. I'm guessing the upload was cancelled before it could finish by roslaunch as part of shutdown.

[jack-oquin]

I think the large file problem last week was due to subprocess.call() waiting until the upload had finished. If the node does not terminate quickly enough after the ROS shutdown signal, roslaunch starts sending more and more emphatic signals.

I was expecting /usr/bin/nohup to run the upload in the background, but it does not. Commit 769f373 should fix that.

[jack-oquin]

Tested the latest fix on clamps. Nothing uploaded.

Maybe ROS shutdown has gone too far already. From the record node's log:

[rosout][INFO] 2016-03-09 09:59:54,568: topics to record: odom_1hz amcl_pose /diagnostics
[rosout][INFO] 2016-03-09 09:59:54,569: ~directory: 
[rosout][INFO] 2016-03-09 09:59:54,779: logs go here: /home/users/joq/.ros/bwi/bwi_logging
[rosout][INFO] 2016-03-09 09:59:54,781: logging with prefix: bwi
[rosout][INFO] 2016-03-09 09:59:54,781: running command: ['rosbag', 'record', '-obwi', '-j', 'odom_1hz', 'amcl_pose', '/diagnostics']
[rospy.internal][INFO] 2016-03-09 09:59:54,857: topic[/rosout] adding connection to [/rosout], count 0
[rospy.core][INFO] 2016-03-09 10:52:37,750: signal_shutdown [signal-2]
[rospy.internal][INFO] 2016-03-09 10:52:37,752: topic[/rosout] removing connection to /rosout
[rospy.impl.masterslave][INFO] 2016-03-09 10:52:37,753: signal-2
[rosout][INFO] 2016-03-09 10:52:37,869: rosbag returned status: 0
[rosout][INFO] 2016-03-09 10:52:37,869: start uploading bags
[rospy.core][INFO] 2016-03-09 10:52:37,891: signal_shutdown [atexit]

The signal-2 is SIGINT, the normal ROS shutdown signal. The rosout messages indicate that it did run the bwi bags script, but the syslog indicates it finished immediately, apparently without doing anything.

$ sudo grep BWI /var/log/syslog
Mar  9 10:52:37 clamps logger: starting BWI logs upload...
Mar  9 10:52:37 clamps logger: completed BWI logs upload

[jack-oquin]

I suspect the SIGINT is being delivered to the process running the bags script, causing it to terminate immediately. The nohup command masks SIGHUP, but not SIGINT.

[pato]

So I recall that there is a @reboot command which you can use in crontabs to have something run on boot, I wonder if there is perhaps an equivalent one for shutdown. If there isn't, could we perhaps consider uploading the scripts on boot? That way you don't have to slow down shutdown or worry about timing.

[jack-oquin]

Those are good suggestions, @pato. Something else may be necessary if I can't figure out a way around the current problems.

[jack-oquin]

I think I just need to run the bags command in a separate process group, so it's not affected by ROS shutdown signals.

[jack-oquin]

That was a trivial change. If I am right about the nature of the problem, then it should work. But, I need to test it on a real robot.

[jack-oquin]

Still not working. Apparently, I really don't understand why.

I think I'll ask for help on answers.ros.org. Surely, someone knows how to do this simple task.

[jack-oquin]

Rolando suggested that the problem is with the Python subprocess package, which terminates when the Python interpreter does. I think that's probably right. I'll try again using the os.system function.

[jack-oquin]

That seems to help, but sometimes the bag does not appear to be present soon enough. Adding a time delay option for that.

[jack-oquin]

It seems to need a longer wait for longer logs.

This suggests a new hypothesis: maybe rosbag -j does not compress on the fly; instead it may be launching a separate compression step at shutdown.

That would explain why the files don't appear right away, and why longer waits are sometimes needed.

If true, maybe it would be better not to use -j and always do the compression in the bags script.

[jack-oquin]

Today, I experimented with not setting -j on the record step, but it did not help.

I guess I really need to write a script that waits until the file appears.

[jack-oquin]

I merged the autolog branch into master (#49). It's not perfect, but sometimes works and will upload any older ones on the next run.

We can re-open if someone wants to work on it more.