pre sporadically fails to calibrate (ros ticket #2809)

[ahendrix]

I've seen multiple instances where pre fails to calibrate completely. On two separate occasions one of the rear casters did not calibrate properly. In both instances, the calibration script was listed as a subscriber of the appropriate calibration topic and controller was listed as a publisher of that same topic. A rostopic echo showed that an empty message was indeed being published on that topic. Attempts to publish additional messages on that topic failed to convince the calibration script that the joint was calibrated.

This code from calibrate.py looks suspect, but I don't understand python threading well enough to see why it would fail:

{{{
# Sets up callbacks for calibration completion
waiting_for = launched[:]
def calibrated(msg, name): # Somewhat not thread-safe
if name in waiting_for:
waiting_for.remove(name)
for name in waiting_for:
rospy.Subscriber("%s/calibrated" % name, Empty, calibrated, name)

    # Waits until all the controllers have calibrated
    while waiting_for and not rospy.is_shutdown():
        print "Waiting for: %s" % ', '.join(waiting_for)
        sleep(0.5)

}}}

trac data:

• Owner: kwc
• Reporter: wheeler
• Reported at: Fri Sep 25 14:39:00 2009
• URL: https://code.ros.org/trac/wg-ros-pkg/ticket/2809

[ahendrix]

[sglaser] I had it happen on prf as well.

I've made some changes in r24339 that might fix it, but the problem is so sporadic that it's difficult to tell. Please let me know if you see it again.

[ahendrix]

[sglaser] Nope, that didn't fix it.

[ahendrix]

[sglaser] Log file attached. In particular:

{{{
[DEBUG] 2009-10-29 16:46:42,857: exception in receive loop for [/cal_caster_br_alpha2/calibrated], may be normal. Exception is Traceback (most recent call last):
File "/u/sglaser/ros/ros/core/rospy/src/rospy/tcpros_base.py", line 577, in receive_loop
msgs = self.receive_once()
File "/u/sglaser/ros/ros/core/rospy/src/rospy/tcpros_base.py", line 547, in receive_once
recv_buff(sock, b, p.buff_size)
File "/u/sglaser/ros/ros/core/rospy/src/rospy/tcpros_base.py", line 82, in recv_buff
raise TransportTerminated("unable to receive data from sender, check sender's logs for details")
TransportTerminated: unable to receive data from sender, check sender's logs for details

[DEBUG] 2009-10-29 16:46:42,858: publisherUpdate('/master', '/cal_caster_br_alpha2/calibrated', [])
[DEBUG] 2009-10-29 16:46:42,859: publisherUpdate('/master', '/cal_caster_br_alpha2/calibrated', []) returns (1, '', 0)
}}}

It looks like the connection to the "calibrated" topic is being dropped somehow. Running rosnode info paints a similar picture:

{{{
sglaser@pre1:$ rosnode info /calibrate_pr2 | grep caster_br
sglaser@pre1:$
}}}

Though the calibration controller is definitely publishing:

{{{

sglaser@pre1:~$ rostopic echo /cal_caster_br_alpha2/calibrated

---

---

}}}

It looks like the connection is being dropped in the calibration script and not being recreated.

[ahendrix]

[sglaser] Reassigning to Ken, as I suspect that this is a rospy bug.

[ahendrix]

[kwc] As the exception notes, this isn't debuggable w/o having the senders log instead

[ahendrix]

[sglaser] Logs from a run can be found on prg2 in ~sglaser/logs_conn_drop. Everything should be there.