[roseus] add more loggers for roseus

knorth55 commented 2 years ago

this PR adds following rosconsole functions.

ros-*-once
ros-*-once-named
ros-*-throttle
ros-*-throttle-named
ros-*-delayed-throttle
ros-*-delayed-throttle-named

(ros::roseus "hoge")

(ros::rate 1)
(dotimes (i 20)
  (ros::ros-warn "ros-warn: ~A" i)
  (ros::ros-warn-named "ros-warn-named" "ros-warn-named: ~A" i)
  (ros::ros-warn-once "ros-warn-once: ~A" i)
  (ros::ros-warn-once-named "ros-warn-once-named" "ros-warn-once-named: ~A" i)
  (ros::ros-warn-throttle 2.0 "ros-warn-throttle: ~A" i)
  (ros::ros-warn-throttle-named 3.0 "ros-warn-throttle-named" "ros-warn-throttle-named: ~A" i)
  (ros::ros-warn-delayed-throttle 4.0 "ros-warn-delayed-throttle: ~A" i)
  (ros::ros-warn-delayed-throttle-named 5.0 "ros-warn-delayed-throttle-named" "ros-warn-delayed-throttle-named: ~A" i)
  (ros::sleep)
  (ros::spin-once)
  )

[ WARN] [1669270040.190325508]: ros-warn: 0
[ WARN] [1669270040.191251703]: ros-warn-named: 0
[ WARN] [1669270040.191270007]: ros-warn-once: 0
[ WARN] [1669270040.191299214]: ros-warn-once-named: 0
[ WARN] [1669270040.191339437]: ros-warn-throttle: 0
[ WARN] [1669270040.191352446]: ros-warn-throttle-named: 0
[ WARN] [1669270041.190744371]: ros-warn: 1
[ WARN] [1669270041.190849547]: ros-warn-named: 1
[ WARN] [1669270042.190461287]: ros-warn: 2
[ WARN] [1669270042.190558009]: ros-warn-named: 2
[ WARN] [1669270043.190343489]: ros-warn: 3
[ WARN] [1669270043.190381168]: ros-warn-named: 3
[ WARN] [1669270043.190398682]: ros-warn-throttle: 3
[ WARN] [1669270044.190377042]: ros-warn: 4
[ WARN] [1669270044.190410981]: ros-warn-named: 4
[ WARN] [1669270044.190429777]: ros-warn-throttle-named: 4
[ WARN] [1669270045.190476813]: ros-warn: 5
[ WARN] [1669270045.190586017]: ros-warn-named: 5
[ WARN] [1669270045.190631115]: ros-warn-throttle: 5
[ WARN] [1669270045.190673029]: ros-warn-delayed-throttle: 5
[ WARN] [1669270046.190458227]: ros-warn: 6
[ WARN] [1669270046.190570733]: ros-warn-named: 6
[ WARN] [1669270046.190644674]: ros-warn-delayed-throttle-named: 6
[ WARN] [1669270047.190819268]: ros-warn: 7
[ WARN] [1669270047.190920669]: ros-warn-named: 7
[ WARN] [1669270047.190975507]: ros-warn-throttle: 7
[ WARN] [1669270047.191019285]: ros-warn-throttle-named: 7
[ WARN] [1669270048.190452270]: ros-warn: 8
[ WARN] [1669270048.190552612]: ros-warn-named: 8
[ WARN] [1669270049.190733947]: ros-warn: 9
[ WARN] [1669270049.190834698]: ros-warn-named: 9
[ WARN] [1669270049.190906272]: ros-warn-delayed-throttle: 9
[ WARN] [1669270050.190474498]: ros-warn: 10
[ WARN] [1669270050.190588545]: ros-warn-named: 10
[ WARN] [1669270050.190663946]: ros-warn-throttle: 10
[ WARN] [1669270051.190791520]: ros-warn: 11
[ WARN] [1669270051.190891373]: ros-warn-named: 11
[ WARN] [1669270051.190995680]: ros-warn-throttle-named: 11
[ WARN] [1669270051.191064045]: ros-warn-delayed-throttle-named: 11
[ WARN] [1669270052.190847190]: ros-warn: 12
[ WARN] [1669270052.190915161]: ros-warn-named: 12
[ WARN] [1669270052.190950292]: ros-warn-throttle: 12
[ WARN] [1669270053.190846157]: ros-warn: 13
[ WARN] [1669270053.190961178]: ros-warn-named: 13
[ WARN] [1669270053.191049382]: ros-warn-delayed-throttle: 13
[ WARN] [1669270054.190474532]: ros-warn: 14
[ WARN] [1669270054.190591683]: ros-warn-named: 14
[ WARN] [1669270055.190375572]: ros-warn: 15
[ WARN] [1669270055.190417014]: ros-warn-named: 15
[ WARN] [1669270055.190433447]: ros-warn-throttle: 15
[ WARN] [1669270055.190447927]: ros-warn-throttle-named: 15
[ WARN] [1669270056.190450808]: ros-warn: 16
[ WARN] [1669270056.190552728]: ros-warn-named: 16
[ WARN] [1669270057.190423040]: ros-warn: 17
[ WARN] [1669270057.190517577]: ros-warn-named: 17
[ WARN] [1669270057.190569926]: ros-warn-throttle: 17
[ WARN] [1669270057.190620694]: ros-warn-delayed-throttle-named: 17
[ WARN] [1669270058.190866225]: ros-warn: 18
[ WARN] [1669270058.190966377]: ros-warn-named: 18
[ WARN] [1669270058.191021320]: ros-warn-throttle-named: 18
[ WARN] [1669270058.191066899]: ros-warn-delayed-throttle: 18
[ WARN] [1669270059.190461765]: ros-warn: 19
[ WARN] [1669270059.190559236]: ros-warn-named: 19
[ WARN] [1669270059.190615179]: ros-warn-throttle: 19

knorth55 commented 1 year ago

roseus/test-timer.test fails... I cannot reproduce the error.

2023-01-26T11:15:25.6092929Z 
2023-01-26T11:15:25.6092941Z 
2023-01-26T11:15:25.6093367Z                                                                                 
2023-01-26T11:15:25.6093981Z [roseus:make] Call Stack (max depth: 20):
2023-01-26T11:15:25.6094135Z 
2023-01-26T11:15:25.6094248Z                                                                                 
2023-01-26T11:15:25.6094522Z [roseus:make]   0: at (ros::spin)
2023-01-26T11:15:25.6102560Z 
2023-01-26T11:15:25.6102566Z 
2023-01-26T11:15:25.6102743Z                                                                                 
2023-01-26T11:15:25.6103011Z [roseus:make]   1: at (ros::spin)
2023-01-26T11:15:25.6103153Z 
2023-01-26T11:15:25.6103267Z                                                                                 
2023-01-26T11:15:25.6104208Z [roseus:make] [1;31m/opt/ros/melodic/share/euslisp/jskeus/eus/Linux64/bin/irteusgl roseus-error: cannot find method #<object #X55a89eed8660> in (ros::spin), exitting...[0m

k-okada commented 1 year ago

yeah, but the meged commit passed all tests https://github.com/jsk-ros-pkg/jsk_roseus/actions/runs/4011982812 https://github.com/jsk-ros-pkg/jsk_roseus/actions/runs/4011979491, so there are something wrong with this branch...

knorth55 commented 1 year ago

hmmm, i will investigate... bug reproduction would be the hardest point...

Affonso-Gui commented 1 year ago

so there are something wrong with this branch...

Not necessarily. There are some known memory faults in roseus, and it can be that this PR accidentally hit one of them. In particular, I would say this situation looks like https://github.com/jsk-ros-pkg/jsk_roseus/issues/668.

gc before saving the arguments to the lisp symbol (either in gensym or in intern https://github.com/jsk-ros-pkg/jsk_roseus/blob/master/roseus/roseus.cpp#L1977-L1978)
argument (:call) gets collected
arbitrary data that was at the pointer location is saved to the lisp symbol (#<object #X55a89eed8660>)
no method error when trying to call the timer ( (send obj #<object>) instead of (send obj :call) )

knorth55 commented 1 year ago

There are two types of the build failure, ~and the noetic case looks like the value in the memory is garbage-collected and overwritten.~ (EDIT: noetic has the diffrent problem as same as master branch) It seems the memory problem...

ros (kinetic, ubuntu:16.04, false, true) ros (melodic, ubuntu:18.04, true) ros (melodic, ubuntu:18.04, source, true) ros (melodic, ubuntu:18.04, false, true)

2023-01-26T11:15:37.8022449Z [roseus:make] [0m;; gc 532860 1372818
2023-01-26T11:15:37.9136002Z 
2023-01-26T11:15:37.9136015Z 
2023-01-26T11:15:37.9136321Z                                                                                 
2023-01-26T11:15:37.9136666Z [roseus:make] Call Stack (max depth: 20):
2023-01-26T11:15:37.9136813Z 
2023-01-26T11:15:37.9136952Z                                                                                 
2023-01-26T11:15:37.9137234Z [roseus:make]   0: at (ros::spin)
2023-01-26T11:15:37.9137378Z 
2023-01-26T11:15:37.9137497Z                                                                                 
2023-01-26T11:15:37.9137735Z [roseus:make]   1: at (ros::spin)
2023-01-26T11:15:37.9141170Z 
2023-01-26T11:15:37.9141175Z 
2023-01-26T11:15:37.9141337Z                                                                                 
2023-01-26T11:15:37.9142240Z [roseus:make] [1;31m/github/home/ros/ws_jsk_roseus/devel/share/euslisp/jskeus/eus/Linux64/bin/irteusgl roseus-error: cannot find method 0 in (ros::spin), exitting...[0m

ros (noetic, ubuntu:20.04, true)

2023-01-26T11:28:08.8583646Z [roseus.rosunit-add_two_ints/test-add-two-ints-many][FAILURE]-------------------
2023-01-26T11:28:08.8584184Z Test:(or (< service-call-error 5) (= (+ (send req :a) (send req :b)) (send res :sum)))
2023-01-26T11:28:08.8584774Z Trace:"^[33m[7] integration failure (1132+84375755)=84376887(nil)/=0(nil)
2023-01-26T11:28:08.8585106Z ^[0mion failure (1098+20228034)=20229132(nil)/=0(nil)
2023-01-26T11:28:08.8585380Z ^[0mon "
2023-01-26T11:28:08.8585642Z Message:"integration failure 7 times ... (1132+84375755)=84376887(nil)/=0(nil)"
2023-01-26T11:28:08.8586121Z --------------------------------------------------------------------------------
2023-01-26T11:28:08.8586378Z 
2023-01-26T11:28:08.8586482Z 
2023-01-26T11:28:08.8586724Z [roseus.rosunit-add_two_ints/test-add-two-ints-many][FAILURE]-------------------
2023-01-26T11:28:08.8587167Z Test:(or (< service-call-error 5) (= (+ (send req :a) (send req :b)) (send res :sum)))
2023-01-26T11:28:08.8587487Z Trace:"^[33m[6] integration failure (1098+20228034)=20229132(nil)/=0(nil)
2023-01-26T11:28:08.8587749Z ^[0mon failure (968+18721650)=18722618(nil)/=0(nil)
2023-01-26T11:28:08.8587946Z ^[0m3951("
2023-01-26T11:28:08.8588192Z Message:"integration failure 6 times ... (1098+20228034)=20229132(nil)/=0(nil)"
2023-01-26T11:28:08.8588594Z --------------------------------------------------------------------------------
2023-01-26T11:28:08.8588793Z 
2023-01-26T11:28:08.8588799Z 
2023-01-26T11:28:08.8589117Z [roseus.rosunit-add_two_ints/test-add-two-ints-many][FAILURE]-------------------
2023-01-26T11:28:08.8589626Z Test:(or (< service-call-error 5) (= (+ (send req :a) (send req :b)) (send res :sum)))
2023-01-26T11:28:08.8590016Z Trace:"^[33m[5] integration failure (968+18721650)=18722618(nil)/=0(nil)
2023-01-26T11:28:08.8590317Z ^[0m3951(nil)
2023-01-26T11:28:08.8590529Z taclass #X563abb3474b0 bignum&gt;)
2023-01-26T11:28:08.8590851Z ø?5»:V"
2023-01-26T11:28:08.8591406Z Message:"integration failure 5 times ... (968+18721650)=18722618(nil)/=0(nil)"
2023-01-26T11:28:08.8591891Z --------------------------------------------------------------------------------

knorth55 commented 1 year ago

! noetic test of current master branch has the same test error. https://github.com/jsk-ros-pkg/jsk_roseus/actions/runs/4011982812/jobs/6897751532 https://github.com/jsk-ros-pkg/jsk_roseus/actions/runs/4009339630/jobs/6884572252 https://github.com/jsk-ros-pkg/jsk_roseus/actions/runs/4006511947/jobs/6878129815

2023-01-26T14:02:21.8527332Z [roseus.rosunit-add_two_ints/test-add-two-ints-many][FAILURE]-------------------
2023-01-26T14:02:21.8527860Z Test:(or (< service-call-error 5) (= (+ (send req :a) (send req :b)) (send res :sum)))
2023-01-26T14:02:21.8528263Z Trace:"^[33m[6] integration failure (1130+4903400)=4904530(nil)/=0(nil)
2023-01-26T14:02:21.8528748Z ^[0mation failure (1092+80664777)=80665869(nil)/=0(nil)
2023-01-26T14:02:21.8529594Z ^[0m951"
2023-01-26T14:02:21.8530042Z Message:"integration failure 6 times ... (1130+4903400)=4904530(nil)/=0(nil)"
2023-01-26T14:02:21.8530726Z --------------------------------------------------------------------------------
2023-01-26T14:02:21.8531058Z 
2023-01-26T14:02:21.8531169Z 
2023-01-26T14:02:21.8531462Z [roseus.rosunit-add_two_ints/test-add-two-ints-many][FAILURE]-------------------
2023-01-26T14:02:21.8532066Z Test:(or (< service-call-error 5) (= (+ (send req :a) (send req :b)) (send res :sum)))
2023-01-26T14:02:21.8532502Z Trace:"^[33m[5] integration failure (1092+80664777)=80665869(nil)/=0(nil)
2023-01-26T14:02:21.8532824Z ^[0m951(nil)
2023-01-26T14:02:21.8533480Z taclass #X55a1a0f5b4b0 bignum&gt;)
2023-01-26T14:02:21.8534144Z ø_ö ¡U"
2023-01-26T14:02:21.8534842Z Message:"integration failure 5 times ... (1092+80664777)=80665869(nil)/=0(nil)"
2023-01-26T14:02:21.8535440Z --------------------------------------------------------------------------------
2023-01-26T14:02:21.8535710Z 
2023-01-26T14:02:21.8536098Z [roseus.rosunit-add_two_ints/test-add-two-ints-persistent-many][passed]
2023-01-26T14:02:21.8536319Z

knorth55 commented 1 year ago

@Affonso-Gui Thank you for your comment! All tests except #741 passed with 15f6d32 (#732)

k-okada commented 1 year ago

2023-01-26T11:28:08.8591406Z Message:"integration failure 5 times ... (968+18721650)=18722618(nil)/=0(nil)"

I noticed service call withouts persistent sometimes fail,more frequently then other distro. Thus I increased threshold https://github.com/jsk-ros-pkg/jsk_roseus/commit/e0c813c6afbaeec7bf2aaed713cf7927a643cb40

-- ◉ Kei Okada

2023年1月27日(金) 18:30 Shingo Kitagawa @.***>:

There are two types of the build failure, and the noetic case looks like the value in the memory is garbage-collected and overwritten. It seems the memory problem...

ros (kinetic, ubuntu:16.04, false, true) https://github.com/jsk-ros-pkg/jsk_roseus/actions/runs/4014552684/jobs/6895218490#logs ros (melodic, ubuntu:18.04, true) https://github.com/jsk-ros-pkg/jsk_roseus/actions/runs/4014552684/jobs/6895218745 ros (melodic, ubuntu:18.04, source, true) https://github.com/jsk-ros-pkg/jsk_roseus/actions/runs/4014552684/jobs/6895218997#logs ros (melodic, ubuntu:18.04, false, true) https://github.com/jsk-ros-pkg/jsk_roseus/actions/runs/4014552684/jobs/6895218871#logs

2023-01-26T11:15:37.8022449Z [roseus:make] �[0m;; gc 532860 1372818

2023-01-26T11:15:37.9136002Z

2023-01-26T11:15:37.9136015Z

2023-01-26T11:15:37.9136321Z

2023-01-26T11:15:37.9136666Z [roseus:make] Call Stack (max depth: 20):

2023-01-26T11:15:37.9136813Z

2023-01-26T11:15:37.9136952Z

2023-01-26T11:15:37.9137234Z [roseus:make] 0: at (ros::spin)

2023-01-26T11:15:37.9137378Z

2023-01-26T11:15:37.9137497Z

2023-01-26T11:15:37.9137735Z [roseus:make] 1: at (ros::spin)

2023-01-26T11:15:37.9141170Z

2023-01-26T11:15:37.9141175Z

2023-01-26T11:15:37.9141337Z

2023-01-26T11:15:37.9142240Z [roseus:make] �[1;31m/github/home/ros/ws_jsk_roseus/devel/share/euslisp/jskeus/eus/Linux64/bin/irteusgl roseus-error: cannot find method 0 in (ros::spin), exitting...�[0m

ros (noetic, ubuntu:20.04, true) https://github.com/jsk-ros-pkg/jsk_roseus/actions/runs/4014552684/jobs/6895219125#logs

2023-01-26T11:28:08.8583646Z [roseus.rosunit-add_two_ints/test-add-two-ints-many][FAILURE]-------------------

2023-01-26T11:28:08.8584184Z Test:(or (< service-call-error 5) (= (+ (send req :a) (send req :b)) (send res :sum)))

2023-01-26T11:28:08.8584774Z Trace:"^[33m[7] integration failure (1132+84375755)=84376887(nil)/=0(nil)

2023-01-26T11:28:08.8585106Z ^[0mion failure (1098+20228034)=20229132(nil)/=0(nil)

2023-01-26T11:28:08.8585380Z ^[0mon "

2023-01-26T11:28:08.8585642Z Message:"integration failure 7 times ... (1132+84375755)=84376887(nil)/=0(nil)"

2023-01-26T11:28:08.8586121Z --------------------------------------------------------------------------------

2023-01-26T11:28:08.8586378Z

2023-01-26T11:28:08.8586482Z

2023-01-26T11:28:08.8586724Z [roseus.rosunit-add_two_ints/test-add-two-ints-many][FAILURE]-------------------

2023-01-26T11:28:08.8587167Z Test:(or (< service-call-error 5) (= (+ (send req :a) (send req :b)) (send res :sum)))

2023-01-26T11:28:08.8587487Z Trace:"^[33m[6] integration failure (1098+20228034)=20229132(nil)/=0(nil)

2023-01-26T11:28:08.8587749Z ^[0mon failure (968+18721650)=18722618(nil)/=0(nil)

2023-01-26T11:28:08.8587946Z ^[0m3951("

2023-01-26T11:28:08.8588192Z Message:"integration failure 6 times ... (1098+20228034)=20229132(nil)/=0(nil)"

2023-01-26T11:28:08.8588594Z --------------------------------------------------------------------------------

2023-01-26T11:28:08.8588793Z

2023-01-26T11:28:08.8588799Z

2023-01-26T11:28:08.8589117Z [roseus.rosunit-add_two_ints/test-add-two-ints-many][FAILURE]-------------------

2023-01-26T11:28:08.8589626Z Test:(or (< service-call-error 5) (= (+ (send req :a) (send req :b)) (send res :sum)))

2023-01-26T11:28:08.8590016Z Trace:"^[33m[5] integration failure (968+18721650)=18722618(nil)/=0(nil)

2023-01-26T11:28:08.8590317Z ^[0m3951(nil)

2023-01-26T11:28:08.8590529Z taclass #X563abb3474b0 bignum>)

2023-01-26T11:28:08.8590851Z ø?5»:V"

2023-01-26T11:28:08.8591406Z Message:"integration failure 5 times ... (968+18721650)=18722618(nil)/=0(nil)"

2023-01-26T11:28:08.8591891Z --------------------------------------------------------------------------------

— Reply to this email directly, view it on GitHub https://github.com/jsk-ros-pkg/jsk_roseus/pull/732#issuecomment-1406244614, or unsubscribe https://github.com/notifications/unsubscribe-auth/AADYNXGYA3CJCPTK4WNIAH3WUOIUXANCNFSM6AAAAAASJZB7YE . You are receiving this because you were assigned.Message ID: @.***>

knorth55 commented 1 year ago

All test went passed now!

@k-okada Thank you for your comment I found out that the service often fails even if the server is up.

knorth55 commented 1 year ago

@k-okada

I opened a issue about the service call error #741 However, i found an odd point in that issue that there is no ROS_ERROR, neither establishing link error or deserializing error.

https://github.com/jsk-ros-pkg/jsk_roseus/issues/741#issuecomment-1406587123

jsk-ros-pkg / jsk_roseus

[roseus] add more loggers for roseus #732