[roseus] add more loggers for roseus by knorth55 · Pull Request #732 · jsk-ros-pkg/jsk_roseus

knorth55 · 2022-11-24T06:08:32Z

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 · 2023-01-26T11:53:09Z

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 · 2023-01-26T13:44:11Z

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 · 2023-01-26T15:26:27Z

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

Affonso-Gui · 2023-01-26T16:27:11Z

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 #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 · 2023-01-27T09:30:40Z

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 · 2023-01-27T12:46:21Z

!
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 · 2023-01-27T14:37:52Z

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

k-okada · 2023-01-27T23:01:13Z

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 e0c813c

…

-- ◉ 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 <#732 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AADYNXGYA3CJCPTK4WNIAH3WUOIUXANCNFSM6AAAAAASJZB7YE> . You are receiving this because you were assigned.Message ID: ***@***.***>

knorth55 · 2023-01-28T01:57:02Z

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 · 2023-01-28T01:59:37Z

@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.

#741 (comment)

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

knorth55 force-pushed the ros-log-more branch 2 times, most recently from bb81272 to 838b777 Compare November 24, 2022 06:17

knorth55 changed the title ~~add more loggers for roseus~~ [roseus] add more loggers for roseus Dec 6, 2022

k-okada added the PR/MergeOk label Jan 25, 2023

k-okada self-assigned this Jan 25, 2023

k-okada added the PR/Please PassCI label Jan 26, 2023

knorth55 mentioned this pull request Jan 27, 2023

add_two_ints test sometimes fail in noetic #741

Open

knorth55 removed the PR/Please PassCI label Mar 1, 2023

mqcmd196 mentioned this pull request May 26, 2024

[feature][jsk_roseus] add log once #750

Closed

knorth55 added 2 commits February 22, 2026 12:53

add more loggers for roseus

e50c1bf

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

vpush args in create_timer

1397f85

mqcmd196 force-pushed the ros-log-more branch from 53debb6 to 1397f85 Compare February 22, 2026 03:53

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Comments

[roseus] add more loggers for roseus#732

[roseus] add more loggers for roseus#732
knorth55 wants to merge 2 commits intojsk-ros-pkg:masterfrom
knorth55:ros-log-more

knorth55 commented Nov 24, 2022 •

edited

Loading

Uh oh!

knorth55 commented Jan 26, 2023

Uh oh!

k-okada commented Jan 26, 2023

Uh oh!

knorth55 commented Jan 26, 2023

Uh oh!

Affonso-Gui commented Jan 26, 2023

Uh oh!

knorth55 commented Jan 27, 2023 •

edited

Loading

Uh oh!

knorth55 commented Jan 27, 2023 •

edited

Loading

Uh oh!

knorth55 commented Jan 27, 2023

Uh oh!

k-okada commented Jan 27, 2023 via email

Uh oh!

knorth55 commented Jan 28, 2023

Uh oh!

knorth55 commented Jan 28, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Comments

Conversation

knorth55 commented Nov 24, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

knorth55 commented Jan 26, 2023

Uh oh!

k-okada commented Jan 26, 2023

Uh oh!

knorth55 commented Jan 26, 2023

Uh oh!

Affonso-Gui commented Jan 26, 2023

Uh oh!

knorth55 commented Jan 27, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

knorth55 commented Jan 27, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

knorth55 commented Jan 27, 2023

Uh oh!

k-okada commented Jan 27, 2023 via email

Uh oh!

knorth55 commented Jan 28, 2023

Uh oh!

knorth55 commented Jan 28, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

knorth55 commented Nov 24, 2022 •

edited

Loading

knorth55 commented Jan 27, 2023 •

edited

Loading

knorth55 commented Jan 27, 2023 •

edited

Loading