Timestamp Jumpback Issue with node.get_clock().now().to_msg() in rclpy

[chanhhoang99]

Operating System:

<Linux minimal 6.8.0-50-generic #51-Ubuntu SMP PREEMPT_DYNAMIC Sat Nov 9 17:58:29 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux>

ROS version or commit hash:

rolling

RMW implementation (if applicable):

rmw_fastrtps_cpp

RMW Configuration (if applicable):

No response

Client library (if applicable):

rclpy

'ros2 doctor --report' output

ros2 doctor --report

<COPY OUTPUT HERE>

Steps to reproduce issue

I notice this bug when playing around with navigation2. Below is the bag

localization_jump.tar.gz

And from the video

https://private-user-images.githubusercontent.com/74817103/436351937-1a49cc31-50bc-4bf0-9cac-850ebae32afb.mp4?jwt=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJnaXRodWIuY29tIiwiYXVkIjoicmF3LmdpdGh1YnVzZXJjb250ZW50LmNvbSIsImtleSI6ImtleTUiLCJleHAiOjE3NDcyMTA3MjgsIm5iZiI6MTc0NzIxMDQyOCwicGF0aCI6Ii83NDgxNzEwMy80MzYzNTE5MzctMWE0OWNjMzEtNTBiYy00YmYwLTljYWMtODUwZWJhZTMyYWZiLm1wND9YLUFtei1BbGdvcml0aG09QVdTNC1ITUFDLVNIQTI1NiZYLUFtei1DcmVkZW50aWFsPUFLSUFWQ09EWUxTQTUzUFFLNFpBJTJGMjAyNTA1MTQlMkZ1cy1lYXN0LTElMkZzMyUyRmF3czRfcmVxdWVzdCZYLUFtei1EYXRlPTIwMjUwNTE0VDA4MTM0OFomWC1BbXotRXhwaXJlcz0zMDAmWC1BbXotU2lnbmF0dXJlPTdkMmM0ODdkYmExZjMxM2E0OGI2ZGIwY2QzMDM2OWM1MDM2MjI0ODQ3N2NkOTRhZTNkMjMwOTViNWM2MTJlZmImWC1BbXotU2lnbmVkSGVhZGVycz1ob3N0In0.J2rltY-4CgRxyJll9H9xcrAvpq0RlXtKg9AW_trtXqM

Further investigation on the scan measurement timestamp which uses node.get_clock().now().to_msg()

I also checked my Odometry publisher which use node.get_clock().now().to_msg()

And this happens at the same time even those are from 2 separated nodes. So that makes me think there maybe an issue with node.get_clock().now().to_msg().

Expected behavior

get_clock().now().to_msg() should return correct timestamp

Actual behavior

get_clock().now().to_msg() returned jump back timestamp

Additional information

No response

[sloretz]

Further investigation on the scan measurement timestamp which uses node.get_clock().now().to_msg()

Mind sharing a minimal repoducible example of the subscriber node?

I'm guessing that:

• The subscriber node uses a single threaded executor
• The node.get_clock().now().to_msg() is being called in a long running callback

I think then reported time would be constant because the TimeSource's callback won't get called until after the long running callback finishes. However, I'd need to see the source code of the subscriber to be sure.

[chanhhoang99]

Hi @sloretz , Thanks for your feedback. Below are related source files nodes.tar.gz The tarball contains 3 nodes.

1. driver_control.py node publishes odometry and use node.get_clock().now().to_msg()
2. handsfree_ros_imu.py publishes imu data and use node.get_clock().now().to_msg()
3. lidar_undistorion_.cpp publishes scan_undistortion measurement after fusing with imu data.

The timestamp from scan_undistortion is actually from handsfree_ros_imu nodes which also use node.get_clock().now().to_msg()

From your guess, I cannot relate it with these nodes because node.get_clock().now().to_msg() is not executed in any callback.(Line 885 in driver_control.py and Line 121 handsfree_ros_imu.py).

Unfortunately, the issue is hard to reproduce, I have just encountered it once and got the bag above.