Incomplete rosout.log

[osrf-migration]

Original report (archived issue) by Martin Dlouhy (Bitbucket: robotikacz).

---

“rosout.log” is the only way how we can check our deployment on AWS (correct me, if I am wrong), and it is not complete! 😞

I run 3 simulations (robotika, [ver4, ver5, ver6], Simple Tunnel 02) last night and today. Just to be sure that everything is initialized (see 6 minutes issue #202) I added extra pure ROS code originally waiting for all necessary topics, which are later used in the main navigation program. They all first print “begin” and at the end “end” to ROS info. The last simulation (ver6, cab6fd44-2448-4fa7-bd38-a44d94250182) even failed to pass “Wait for /X2/front/image_raw/compressed” :frowning2:

Code snippet:

def wait_for(topic, topic_type):
    rospy.loginfo('Wait for ' + topic)
    rospy.wait_for_message(topic, topic_type)
    rospy.loginfo('Done with ' + topic)


def wait_for_sensors():
    rospy.init_node('mdwait', anonymous=True)
    wait_for_master()
    rospy.loginfo('-------------- mdwait BEGIN --------------')
    wait_for('/X2/imu/data', Imu)
    wait_for('/X2/front_scan', LaserScan)
    wait_for('/X2/front/image_raw/compressed', CompressedImage)
    wait_for('/X2/odom', Odometry)
    wait_for('/X2/battery_state', BatteryState)  # note, that this is maybe the critical component!
    rospy.loginfo('--------------- mdwait END ---------------')

Ver6 rosout.log

‌

0.a527ae8c41762a101acbf2474382f82acd977df2  Node Startup
0.a527ae8c41762a101acbf2474382f82acd977df2 INFO /tf_world_static [/tmp/binarydeb/ros-melodic-tf2-ros-0.6.5/src/static_transform_broadcaster_program.cpp:142(main)] [topics: /rosout, /tf_static] Spinning until killed publishing world to simple_tunnel_02
0.a527ae8c41762a101acbf2474382f82acd977df2 INFO /subt_solution [/home/developer/subt_solution/src/subt_seed/src/subt_seed_node.cc:104(Controller)] [topics: /rosout] Waiting for /clock, /subt/start, and /subt/pose_from_artifact
382.284000000 INFO /subt_solution [/home/developer/subt_solution/src/subt_seed/src/subt_seed_node.cc:112(Controller)] [topics: /rosout] Using robot name[X2]

382.292000000 INFO /subt_solution [/home/developer/subt_solution/src/subt_seed/src/subt_seed_node.cc:147(Update)] [topics: /rosout] Sent start signal.
382.324000000 INFO /subt_solution [/home/developer/subt_solution/src/subt_seed/src/subt_seed_node.cc:198(Update)] [topics: /rosout] MD robot pose -6 5 dist=61
396.284000000 INFO /mdwait_71_1569502355368 [wait_for_sensors.py:24(wait_for)] [topics: /clock, /rosout] Wait for /X2/front/image_raw/compressed 

Ver5 (did not wait for the master published topics)

‌

0.a527ae8c41762a101acbf2474382f82acd977df2  Node Startup
0.a527ae8c41762a101acbf2474382f82acd977df2 INFO /tf_world_static [/tmp/binarydeb/ros-melodic-tf2-ros-0.6.5/src/static_transform_broadcaster_program.cpp:142(main)] [topics: /rosout, /tf_static] Spinning until killed publishing world to simple_tunnel_02
0.a527ae8c41762a101acbf2474382f82acd977df2 INFO /subt_solution [/home/developer/subt_solution/src/subt_seed/src/subt_seed_node.cc:104(Controller)] [topics: /rosout] Waiting for /clock, /subt/start, and /subt/pose_from_artifact
348.008000000 INFO /subt_solution [/home/developer/subt_solution/src/subt_seed/src/subt_seed_node.cc:112(Controller)] [topics: /rosout] Using robot name[X2]

348.016000000 INFO /subt_solution [/home/developer/subt_solution/src/subt_seed/src/subt_seed_node.cc:147(Update)] [topics: /rosout] Sent start signal.
348.052000000 INFO /subt_solution [/home/developer/subt_solution/src/subt_seed/src/subt_seed_node.cc:198(Update)] [topics: /rosout] MD robot pose -6 5 dist=61
362.344000000 INFO /mdwait_71_1569495635370 [wait_for_sensors.py:10(wait_for)] [topics: /clock, /rosout] Wait for /X2/battery_state
362.420000000 INFO /mdwait_71_1569495635370 [wait_for_sensors.py:12(wait_for)] [topics: /clock, /rosout] Done with /X2/battery_state
362.424000000 INFO /mdwait_71_1569495635370 [wait_for_sensors.py:23(wait_for_sensors)] [topics: /clock, /rosout] --------------- mdwait END ---------------
0.a527ae8c41762a101acbf2474382f82acd977df2 INFO /mdtalker_92_1569495636225 [std2ros.py:10(std2ros)] [topics: /clock, /rosout] -------------- BEGIN --------------
363.908000000 INFO /X2/ros1_ign_bridge_twist [/tmp/ros1-ign-bridge-release/include/ros1_ign_bridge/factory.hpp:137(Factory<ROS1_T, IGN_T>::ros1_callback)] [topics: /rosout] Passing message from ROS1 geometry_msgs/Twist to Ignition ignition.msgs.Twist (showing msg only once per type  

See END without BEGIN and missing previously reported topics …

[osrf-migration]

Original comment by Alfredo Bencomo (Bitbucket: bencomo).

---

• set assignee_account_id to "557058:095b1e12-74ed-4e20-b44f-2f0745b616e0"
• set assignee to "nkoenig (Bitbucket: nkoenig, GitHub: nkoenig)"

[osrf-migration]

Original comment by Nate Koenig (Bitbucket: Nathan Koenig).

---

We are copying all the ROS logs, as recorded by ROS. If something doesn't appear in the logs, then the most likely culprit is something other than the logs and the logging system.

I'd like to reproduce your problem to see what going on. What docker image are you using, and how are you submitting you solution? You can share private information through subt-help@googlegroups.com.

[osrf-migration]

Original comment by Martin Dlouhy (Bitbucket: robotikacz).

---

The Dockerfile and run_simulation.sh is now in #202. If you have access to docker images then it is “robotika” and tags “ver6” (the latest, which blocked on wait to compressed image in wait_for_sensors.py. Let me know if I can provide more info. Thanks

[osrf-migration]

Original comment by Martin Dlouhy (Bitbucket: robotikacz).

---

Can you enable basic logging of deployed docker - I mean no ROS and no Ignition, just what is the low level docker output? I am willing to change the rights or what ever is needed - it was possible 4 years ago in Google cloud so it must be possible to do also on AWS. We had aggregation of all outputs of all running instances (not 1 but 100 or more) without loosing a single output line, sigh.

“just for fun” I run the identical docker for the 2nd time (tag ver6b):

‌

0.a527ae8c41762a101acbf2474382f82acd977df2  Node Startup
0.a527ae8c41762a101acbf2474382f82acd977df2 INFO /tf_world_static [/tmp/binarydeb/ros-melodic-tf2-ros-0.6.5/src/static_transform_broadcaster_program.cpp:142(main)] [topics: /rosout, /tf_static] Spinning until killed publishing world to simple_tunnel_02
0.a527ae8c41762a101acbf2474382f82acd977df2 INFO /subt_solution [/home/developer/subt_solution/src/subt_seed/src/subt_seed_node.cc:104(Controller)] [topics: /rosout] Waiting for /clock, /subt/start, and /subt/pose_from_artifact
415.312000000 INFO /subt_solution [/home/developer/subt_solution/src/subt_seed/src/subt_seed_node.cc:112(Controller)] [topics: /rosout] Using robot name[X2]

415.320000000 INFO /subt_solution [/home/developer/subt_solution/src/subt_seed/src/subt_seed_node.cc:147(Update)] [topics: /rosout] Sent start signal.
415.348000000 INFO /subt_solution [/home/developer/subt_solution/src/subt_seed/src/subt_seed_node.cc:198(Update)] [topics: /rosout] MD robot pose -6 5 dist=61
429.896000000 INFO /mdwait_71_1569527167188 [wait_for_sensors.py:24(wait_for)] [topics: /clock, /rosout] Wait for /X2/odom
429.996000000 INFO /mdwait_71_1569527167188 [wait_for_sensors.py:26(wait_for)] [topics: /clock, /rosout] Done with /X2/odom
429.996000000 INFO /mdwait_71_1569527167188 [wait_for_sensors.py:24(wait_for)] [topics: /clock, /rosout] Wait for /X2/battery_state
430.076000000 INFO /mdwait_71_1569527167188 [wait_for_sensors.py:26(wait_for)] [topics: /clock, /rosout] Done with /X2/battery_state
430.080000000 INFO /mdwait_71_1569527167188 [wait_for_sensors.py:38(wait_for_sensors)] [topics: /clock, /rosout] --------------- mdwait END ---------------
431.580000000 INFO /X2/ros1_ign_bridge_twist [/tmp/ros1-ign-bridge-release/include/ros1_ign_bridge/factory.hpp:137(Factory<ROS1_T, IGN_T>::ros1_callback)] [topics: /rosout] Passing message from ROS1 geometry_msgs/Twist to Ignition ignition.msgs.Twist (showing msg only once per type
0.a527ae8c41762a101acbf2474382f82acd977df2 INFO /mdtalker_92_1569527168132 [std2ros.py:10(std2ros)] [topics: /clock, /rosout] -------------- BEGIN --------------  

so again the beginning of wait_for_sensors.py is missing but this time it reaches the final code with “forwarding” std2ros (without any further output).

You can run as many independent processes you want in the ROS or not? They do not have to be all listed in one launch file or they do?

p.s. how other teams scoring 0 points (“Coordinated Robotics”, “Kankanwadi”, “MTRI”) in “Simple Tunnel 02” are doing? I suppose that locally it works for them too??

p.s.2 you are allowed to run only 1 simulation a time (info for others):

Error #5506: Simultaneous simulations limit reached … I wanted to check if it is deterministic so I wanted to run two more tests (ver6b and ver6c) and it is not (see ver6b output)

[osrf-migration]

Original comment by Martin Dlouhy (Bitbucket: robotikacz).

---

• changed state from "new" to "resolved"

It seems to me now, that the problem is related to multiple "launches" of ROS nodes. I plan to fallback to a single C++ node, where I currently do not see this problem.

[osrf-migration]

Original comment by Sarah Kitchen (Bitbucket: snkitche).

---

It seems we are not seeing most of our console output in the logs.

[osrf-migration]

Original comment by Martin Dlouhy (Bitbucket: robotikacz).

---

Are you using one or more ROS nodes? Do you have them all specified in the launch file? I believe that there is some issue with more nodes or when they start at different times (?). I use the workaround with single C++ ROS node and ZeroMQ to communicate with it …

[osrf-migration]

Original comment by Sarah Kitchen (Bitbucket: snkitche).

---

Multiple nodes. I posted here to let them know you are not uniquely experiencing this issue.

[osrf-migration]

Original comment by Martin Dlouhy (Bitbucket: robotikacz).

---

:slight_smile: OK, thanks

[osrf-migration]

Original comment by Martin Dlouhy (Bitbucket: robotikacz).

---

• changed state from "resolved" to "open"

the issue persists for multiple ROS nodes (also reported by Sarah)

[osrf-migration]

Original comment by Martin Dlouhy (Bitbucket: robotikacz).

---

• changed priority from "blocker" to "major"

[osrf-migration]

Original comment by Nate Koenig (Bitbucket: Nathan Koenig).

---

I'm trying to reproduce the problem. Does anyone have a more concrete example launch file and setup that I could test with?

There might be a buffering issue: ros/rosconsole#5 and related question: https://answers.ros.org/question/200593/why-in-this-simple-sample-my-logs-are-not-written-in-logfile-or-is-there-a-way-to-control-the-flushing-period-of-the-log-files/

[osrf-migration]

Original comment by Sarah Kitchen (Bitbucket: snkitche).

---

Nate, are you able to pull the images we’ve submitted to the cloudsim? If so, I can give you examples over the subt-help email.

[osrf-migration]

Original comment by Nate Koenig (Bitbucket: Nathan Koenig).

---

I am able to pull the images.

[osrf-migration]

Original comment by Martin Dlouhy (Bitbucket: robotikacz).

---

Is the “rosout.log” cyclic buffer?! I am trying to dump OSGAR log at the end of simulation (few MB) and the content starts with:

‌

955.308000000 INFO /subt_solution [/home/developer/subt_solution/src/subt_seed/src/subt_seed_node.cc:393(getSpeedCmd)] [topics: /rosout, /A0F40F100F400L/cmd_vel] Python3: stdout 21117300 b'\x06A\xcd\x06/\xcd\x065\xcd\x06?\xcd\x067\xcd\x06?\xcd\x06G\xcd\x06@\xcd\x06L\xcd\x06A\xcd\x06L\xcd\x06N\xcd\x06S\xcd\x06b\xcd\x06m\xcd\x06g\xcd\x06k\xcd\x06h\xcd\x06p\xcd\x06\x86\xcd\x06Y\xcd\x06{\xcd\x06\x82\xcd\x06\x92\xcd\x06\x84\xcd\x06\x85\xcd\x06\x9a\xcd\x06\xa4\xcd\x06\xa9\xcd\x06\xa6\xcd\x06\xac\xcd\x06\xb4\xcd\x06\xb1\xcd\x06'
...
963.948000000 INFO /subt_solution [/home/developer/subt_solution/src/subt_seed/src/subt_seed_node.cc:393(getSpeedCmd)] [topics: /rosout, /A0F40F100F400L/cmd_vel] Python3: stdout 31211000 b'"-\xcd"\t\xcd"\x15\xcd!\xeb\xcd!\xc5\xcd!\xcd\xcd!\xb7\xcd!\xaf\xcd!\x8e\xcd!\x84\xcd!y\xcd!\x8a\xcd!f\xcd!P\xcd!,\xcd!(\xcd!)\xcd!\x1c\xcd!\x1e\xcd \xf5\xcd \xf3\xcd \xf6\xcd \xd9\xcd \xd6\xcd \xb7\xcd \xb6\xcd \xad\xcd \x9a\xcd \x9e\xcd \xa5\xcd \x9e\xcd \x8d\xcd \x92\xcd '

?!! robotika, ver22b-92728081-1a56-4559-9cb5-0c483199dee1-A0F40F100F400L.tar