ROS 2 ‘Message Filter dropping message’: Find the Mismatched Clock with One Subtraction

한국어로 읽기

Your laser topic is publishing, tf is publishing, and RViz or slam_toolbox still prints Message Filter dropping message: frame 'laser' at time ... over and over. A Robotics Stack Exchange question from August 2023 asks exactly this: which timestamps should I compare to narrow it down? To answer it, I reproduced the situation in a ROS 2 Jazzy container with five combinations of laser-node and tf-node clocks, and fed every scan into a real tf2 buffer.

The first thing the runs showed is that the tf2 error text does not tell you what is wrong. When the laser and tf used the same clock, tf2 still reported Lookup would require extrapolation into the future, but only for a few milliseconds, and every scan got through. When only the laser node used the system clock, tf2 reported the exact same phrase and no scan got through at all. The first trial run counted only total passes, so I couldn’t tell “passed straight away” from “waited, then passed”. I added a counter for scans that passed after waiting and ran it again. What separated the healthy cases from the broken ones was a single number: the laser stamp minus the latest tf stamp. With matching clocks it was around a hundredth of a second. With mixed clocks it was about 1.79 billion seconds, and its sign pointed at the node with the wrong clock.

This article shows how to compute that difference on your own system, how to read its size and sign, and which drop message each case produces. You should already know what topics, header.stamp and tf frames are.

Two different clocks in one drop log line

A message filter (tf2_ros::MessageFilter) is a waiting room for sensor messages. It holds each message until tf can transform it from its header.frame_id to the target frame at the message’s own timestamp, then hands it to the callback. If the transform will never become available, or the waiting room is full, the message is dropped and you get the log line. RViz, slam_toolbox and Nav2 costmaps all receive scans through this filter.

Here is a real line from ros2/ros2#1653:

[INFO] [1741356033.165430673] [rviz]: Message Filter dropping message: frame 'sualan36/odom' at time 3.960 for reason '...'

It contains two times, and they come from different clocks:

  • at time 3.960 is the dropped message’s header.stamp, printed to three decimals by MessageFilter::signalFailure (message_filter.hpp L704-L717).
  • The bracketed number is when the line was printed. rcutils takes it from rcutils_system_time_now(), so it is always wall-clock time, whatever the node’s use_sim_time is (rcutils logging.c L1200-L1205).

The tf time is not in the log at all. If you subtract at time from the bracketed value, you get a gap of billions of seconds in every simulation, even when everything is configured correctly. You have to get the tf side of the subtraction from somewhere else, as shown further down.

Why mixed clocks are billions of seconds apart

System time counts seconds since 1970-01-01 UTC, so in 2026 it is roughly 1.79 billion. Simulation time is whatever a simulator or ros2 bag play publishes on /clock, and it usually starts near zero. The ROS time a node gets from now() follows one of the two. According to the ROS 2 Clock and Time design article, a node with use_sim_time off uses system time. A node with it on uses the last /clock value it received, and returns 0 until it has received one. The design article treats that 0 as “uninitialized”.

The part that trips people up is that use_sim_time is not a global switch. The Jazzy tutorial puts it plainly: “Every node has the parameter use_sim_time” (Understanding parameters). Start the simulator, pass use_sim_time:=true to RViz only, and your laser driver or robot_state_publisher can keep stamping messages with system time.

tf2 stores transforms as a buffer along the time axis and answers “what was this transform at time T?” (About tf2). The default buffer length is 10 seconds (buffer_core.hpp L74). A scan stamped on the other clock is about 1.79 billion seconds away from anything in that 10-second window, so no amount of waiting will produce a transform for it.

Five clock combinations against a real tf2 buffer

Everything ran in one process. A clock_src node publishes /clock as “120 s + elapsed time” every 10 ms, and the same timer decides when tf (50 Hz) and scans (20 Hz) are sent. Each publishing node stamps its own messages with its own get_clock().now(). For each case, a fresh laser node and a fresh tf node are created with a different use_sim_time combination. The tf node publishes a dynamic odom→base_link and a static base_link→laser. The receiving consumer plays the role of RViz inside a simulation: use_sim_time=True and a tf2_ros.Buffer with a 10 s cache. For the “stamp 0” case, the laser node’s /clock subscription is remapped to a topic nobody publishes, so it behaves like a laser node that hasn’t received /clock yet.

The drop decision is not made by the C++ MessageFilter. It comes from a simplified Python port of the filter’s branching. Whether a transform is available, and the error string, come from the real tf2 buffer. The core of that judge:

    def add(self, frame, stamp):
        if self._can(frame, stamp):
            self.passed += 1
            return
        try:
            latest = sec(self.buffer.get_latest_common_time(self.target, frame))
        except Exception:
            latest = 0.0
        if latest != 0.0 and sec(stamp) + CACHE_SEC < latest:
            self.dropped_immediate += 1
            return
        self.queue.append((frame, stamp))
        if len(self.queue) > QUEUE:
            self.queue.pop(0)
            self.dropped_queue_full += 1

Each scan was judged twice at the same time: once against target odom, whose path includes the dynamic transform, and once against target base_link, whose path is only the static transform. The full script, plan and raw results are in the reproduction folder (experiment.py, results.json).

Environment: image ros:jazzy-ros-base (ros@sha256:066420e07f60aa18262f2479981def87ebcfcec42eefb0c0c57c4a46098348ca), ROS 2 Jazzy, Python 3.12.3, rclpy 7.1.12-1noble.20260902.053513, RMW rmw_fastrtps_cpp (default), no network, 1 CPU, 1 GiB. Five runs of the same script, all with exit code 0, each taking 14.56 to 14.6 s. Settings: /clock starts at 120.0 s, tf cache 10.0 s, judge queue size 5, measurement window 2.0 s per case.

Predictions (from the plan, written before the runs): tf latest stamp of 125.25 s and an assumed system time of 1790000000 s give a laser − tf difference of +0.25 s when both clocks match, +1789999874.75 s (about +1.79×109) when only the laser uses system time, −1789999874.5 s when only tf uses system time, and −125.25 s for a laser stamp of 0. Expected outcomes were: wait briefly then pass, queue-full drops, immediate drops, and no drops, respectively.

Case (laser / tf clock) Predicted laser − tf Measured laser − tf (median, across 5 runs) Target odom (dynamic path) Target base_link (static only)
/clock / /clock +0.25 s scale 0.0047 to 0.005 s 40 of 40 passed, 20 of them after waiting 40 passed immediately
system / system small (stamps themselves near 1.79×109) 0.005 to 0.0051 s 40 of 40 passed, all 40 after waiting 40 passed immediately
system / /clock +1789999874.75 s +1791021145.3394 (run 1) to +1791021203.6683 (run 5) 0 passed, 35 queue-full drops, 5 still pending at window end (run 3: 35 scans, 30 drops, 5 pending) all passed
/clock / system −1789999874.5 s −1791021145.3294 (run 1) to −1791021203.6582 (run 5) 0 passed, 40 immediate drops 40 passed immediately
stamp 0 / /clock −125.25 s −131.5831 to −131.563 s 40 passed immediately; a lookup at time 0 returned a transform stamped 130.5931, equal to the latest tf stamp at that moment (run 1) 40 passed immediately

Per-scan differences in the two same-clock cases ranged from 0.0 s to 0.0118 s. In every run, the first tf2 error recorded for the same-clock cases and for the system / /clock case was “extrapolation into the future”. For the /clock / system case it was “extrapolation into the past”.

Log bracket check: a use_sim_time=True node printed an INFO line in the drop-log format after receiving /clock. In run 1, at time was 120.0 and the bracket was 1791021265.1012058. Across the five runs, the bracket minus time.time() taken just before logging was 0.0165 to 0.0194 s, always inside the before/after time.time() window of 0.0166 to 0.0195 s.

Raw output lines from run 1:

{"kind": "log_bracket", "child_exit": 0, "bracket_time": 1791021265.1012058, "at_time": 120.0, "bracket_minus_at_time": 1791021145.101, "bracket_minus_system_time_s": 0.0194, "system_time_window_s": 0.0195}
{"kind": "case", "case": "same_sim", "laser_use_sim_time": true, "tf_use_sim_time": true, "laser_clock_blocked": false, "laser_clock_now_s": 120.913, "tf_clock_now_s": 120.913, "scans": 40, "first_scan_stamp_s": 120.943, "tf_latest_at_first_scan_s": 120.933, "diff_laser_minus_tf_median_s": 0.005, "diff_min_s": 0.0, "diff_max_s": 0.0118, "judges": {"target_odom_dynamic": {"passed": 40, "passed_after_wait": 20, "drop_immediate": 0, "drop_queue_full": 0, "pending": 0, "first_tf2_error": "Lookup would require extrapolation into the future.  Requested time 120.943139 but the latest data is at time 120.933150, when looking up transform from frame [same_sim/l"}, "target_base_link_static_only": {"passed": 40, "passed_after_wait": 0, "drop_immediate": 0, "drop_queue_full": 0, "pending": 0, "first_tf2_error": null}}}
{"kind": "case", "case": "laser_system_tf_sim", "laser_use_sim_time": false, "tf_use_sim_time": true, "laser_clock_blocked": false, "laser_clock_now_s": 1791021271.088, "tf_clock_now_s": 125.763, "scans": 40, "first_scan_stamp_s": 1791021271.128, "tf_latest_at_first_scan_s": 125.793, "diff_laser_minus_tf_median_s": 1791021145.3394, "diff_min_s": 1791021145.3344, "diff_max_s": 1791021145.3445, "judges": {"target_odom_dynamic": {"passed": 0, "passed_after_wait": 0, "drop_immediate": 0, "drop_queue_full": 35, "pending": 5, "first_tf2_error": "Lookup would require extrapolation into the future.  Requested time 1791021271.127658 but the latest data is at time 125.793160, when looking up transform from frame [las"}, "target_base_link_static_only": {"passed": 40, "passed_after_wait": 0, "drop_immediate": 0, "drop_queue_full": 0, "pending": 0, "first_tf2_error": null}}}
{"kind": "case", "case": "laser_sim_tf_system", "laser_use_sim_time": true, "tf_use_sim_time": false, "laser_clock_blocked": false, "laser_clock_now_s": 128.183, "tf_clock_now_s": 1791021273.508, "scans": 40, "first_scan_stamp_s": 128.193, "tf_latest_at_first_scan_s": 1791021273.527, "diff_laser_minus_tf_median_s": -1791021145.3294, "diff_min_s": -1791021145.3345, "diff_max_s": -1791021145.3244, "judges": {"target_odom_dynamic": {"passed": 0, "passed_after_wait": 0, "drop_immediate": 40, "drop_queue_full": 0, "pending": 0, "first_tf2_error": "Lookup would require extrapolation into the past.  Requested time 128.193093 but the earliest data is at time 1791021273.107409, when looking up transform from frame [las"}, "target_base_link_static_only": {"passed": 40, "passed_after_wait": 0, "drop_immediate": 0, "drop_queue_full": 0, "pending": 0, "first_tf2_error": null}}}
{"kind": "case", "case": "laser_no_clock_yet", "laser_use_sim_time": true, "tf_use_sim_time": true, "laser_clock_blocked": true, "laser_clock_now_s": 0.0, "tf_clock_now_s": 130.593, "scans": 40, "first_scan_stamp_s": 0.0, "tf_latest_at_first_scan_s": 130.593, "diff_laser_minus_tf_median_s": -131.5632, "diff_min_s": -132.5331, "diff_max_s": -130.5931, "judges": {"target_odom_dynamic": {"passed": 40, "passed_after_wait": 0, "drop_immediate": 0, "drop_queue_full": 0, "pending": 0, "first_tf2_error": null}, "target_base_link_static_only": {"passed": 40, "passed_after_wait": 0, "drop_immediate": 0, "drop_queue_full": 0, "pending": 0, "first_tf2_error": null}}, "stamp_zero_lookup": {"lookup_at_0_returned_stamp": 130.5931, "tf_latest_at_that_moment": 130.5931}}

How the measurements compare with the predictions. The absolute values differ, as expected: simulated time started at 120 s rather than the 125.25 s in the worked example, and system time was the real clock rather than an assumed round number. The mixed-clock differences also got larger with each run. That fits the setup: sim time restarted at 120 s every run while the system clock kept moving forward. What matched in all five runs was the sign and the scale: hundredths of a second when the clocks agree, about 1.79 billion seconds when they don’t. The bracket check confirms the source reading: even in a sim-time node, the bracketed log time is wall-clock time.

The sign decides how the scan gets dropped

Positive, billions of seconds: the laser node is on system time. The scan is stamped far in the future compared with the tf buffer, so tf2 answers “extrapolation into the future”. For a message filter, a future stamp is normal (tf might catch up), so the scan waits in the queue. A tf stream that follows /clock never reaches 1.79 billion, so scans just pile up until the oldest one is pushed out. In the geometry2 Jazzy source, MessageFilter‘s default buffer_timeout is duration::max(), so there is effectively no timeout (L166-L171). When the queue overflows, the message is dropped with 'discarding message because the queue is full' (L412-L424).

Negative, billions of seconds: the tf publisher is on system time. The scan is older than everything in the buffer, so tf2 answers “extrapolation into the past”. If the requested time plus the cache length is still earlier than the newest data, waiting cannot help, and the request is rejected immediately. In the runs, every scan on the dynamic path was dropped without ever entering the queue. In the source, addTransformableRequest returns “never transformable” under that condition (buffer_core.cpp L1326-L1335). The buffer then sets an exception (buffer.cpp L228-L239), and the filter logs it as reason OutTheBack: 'the timestamp on the message is earlier than all the data in the transform cache' (L551-L557, reason strings at L80-L117).

Those two reason strings come from reading the source, not from the experiment. The Python judge doesn’t print them, and I didn’t watch the C++ filter print them. One more caution from the source: the same catch (...) also turns timeout exceptions into OutTheBack. If the consuming node passes a finite buffer_timeout, a scan stamped in the future can time out and still be logged as “earlier than all the data” (buffer.cpp L288-L294). So rely on the sign of the subtraction, not on the wording of the reason.

The “extrapolation into the future” errors in the same-clock cases are the filter doing what it was built for. The scan was stamped a few milliseconds after the newest tf, and it passed as soon as the next tf arrived. Why about half the sim-time scans waited and all the system-time scans waited is my reading of the script, not something it measured. Sim time changes once per 10 ms tick, so a scan sent on the same tick as a tf gets an identical stamp and passes immediately. With system time, the scan is always stamped a hair after the tf. Either way, the error text matched the broken case. Only the size of the gap told them apart.

Two cases that stay silent but are still wrong

A laser stamp of 0 is not dropped. My first plan listed “laser node hasn’t received /clock yet” as a cause of the drop log. The tf2 source disagrees, and so did the runs. When the requested time is 0, tf2 swaps in the latest common time (buffer_core.cpp L345-L351). That is why these scans passed, even though their difference from tf was far outside the 10 s cache. The transform they got was the latest one, not the one from the moment the scan was taken. The log stays quiet, but on a moving robot the scan can end up drawn in the wrong place. To check, look for zeros in ros2 topic echo /scan --field header.stamp.

There is one exception, which I found in the source and did not reproduce. If the consuming node sets a tolerance with setTolerance(), the filter makes a second request at “stamp + tolerance” (L332-L336, L397-L401). That time is no longer 0, so the message can be dropped and logged as at time 0.000.

A static-only path never drops for timing reasons. Against target base_link, where the only hop is the static base_link→laser, every scan passed, including both mixed-clock cases. Static transforms have no history. StaticCache ignores the requested time (static_cache.cpp L37-L43) and reports its latest time as 0 (L73-L76). A clock mismatch only shows up as drops when the path includes a dynamic transform such as odom→base_link. One likely symptom, which I inferred and did not test in RViz: RViz is quiet with Fixed Frame set to base_link, then floods with drop messages when you switch it to odom or map. It also means the tf stamp you subtract must come from a dynamic transform on the path, not a static one.

Getting the two numbers on your own system

You need the scan’s stamp (the at time value, or header.stamp on the topic) and the latest stamp of a dynamic transform on the filter’s path. These are standard ROS 2 CLI commands. I didn’t run them in the container experiment, so no sample output is shown:

# One laser stamp (--field and --once exist in humble and jazzy ros2topic echo)
ros2 topic echo /scan --field header.stamp --once

# Latest time of a dynamic transform on the path (look at 'At time sec.nanosec')
ros2 run tf2_ros tf2_echo odom base_link

# Compare the clock setting of every involved node: laser driver, tf publishers, RViz/slam_toolbox
ros2 param get /<node_name> use_sim_time

Read tf2_echo output carefully. It joins the sec and nanosec integers with a dot and does not zero-pad nanosec (tf2_echo.cpp L198-L199). With sec=125 and nanosec=5000000 it prints 125.5000000, but the real value is 125.005 s. Check that the fractional part has nine digits, or read sec and nanosec separately from ros2 topic echo /tf.

Then classify the difference (laser − tf):

  • Small (scan or tf period scale): not a clock problem. If the drops continue, check whether the tf tree is connected and whether the scan’s frame_id is a frame that actually exists in it. The answers to the Stack Exchange question and to ros2/rviz#1615 pointed at the tf tree too.
  • Positive, billions of seconds: the laser driver has use_sim_time off. Expect discarding message because the queue is full.
  • Negative, billions of seconds: a tf publisher (robot_state_publisher, your odometry node) has use_sim_time off. On the immediate-rejection path, expect earlier than all the data in the transform cache.
  • Laser stamp exactly 0: the laser node hasn’t received /clock. Suspect wrong pairing with the latest tf rather than drops.
  • Both on system time, but seconds to hours apart: on real robots where the lidar runs on one computer (say, a Raspberry Pi) and tf comes from another, the two system clocks may not be synchronized. In turtlebot4#611 the maintainer suspected clock differences between the Pi, the Create 3 and the remote PC and recommended configuring chrony/NTP. My experiment ran on one machine and could not reproduce this.

You’ll sometimes see a 1-second threshold suggested. It is not an official rule. The boundary that matters in the source is the cache length, 10 s by default. A mixed-clock gap is more than eight orders of magnitude larger than that. So bigger queues or a longer tf cache are not a fix here: no realistic cache covers 1.79 billion seconds. Fix the clocks first, then decide whether queue or timeout settings still need tuning.

On real hardware, two cautions. First, turning on use_sim_time on a robot with no simulator or bag publishing /clock freezes ROS time at 0. Leave it off on real hardware, and in simulation or bag replay give every involved node the same value. Second, while scans are being dropped they don’t reach SLAM or the costmap, so obstacle information may not be updated. Diagnose with the robot stationary. If it has to move, keep it slow and within reach of the emergency stop. This is general operating advice, not a procedure I validated on a specific robot.

Two practice logs

1. The drop log says at time 2936.389 for reason 'the timestamp on the message is earlier than all the data in the transform cache', and tf2_echo odom base_link shows times around 1659319692. Which node do you check first?

Answer: laser − tf is negative and billions of seconds. The laser follows /clock, the tf publisher uses system time. Check the tf publisher’s use_sim_time first. This has the same shape as the /clock / system case above.

2. The laser and tf stamps are both around 1761521468 and differ by 0.1 s, yet discarding message because the queue is full keeps appearing. Is it the clock?

Answer: No. Both are system-time values and the gap is small, so the clocks agree. A large stamp on its own is not an error. Check that laser exists in the tf tree and that there is a path to the target frame. ros2/rviz#1615 has logs with numbers in the same range, but this check does not prove what caused that particular report.

What this experiment does not show

  • The judge is a simplified port of MessageFilter‘s branching, not the C++ filter itself. Tolerance, finite buffer_timeout and multi-threaded callbacks were not reproduced.
  • The queue size of 5 was my choice. I did not check the queue sizes or timeouts that RViz, slam_toolbox or Nav2 costmaps actually use, so drop and pending counts only apply to this setup. The reason strings come from the source, not from observed C++ output.
  • No Gazebo, RViz, slam_toolbox or physical lidar was involved. All nodes ran in one process on one machine, so network latency and clock drift between computers are out of scope.
  • A Foxy-era report (slam_toolbox#491) shows the reason 'Unknown'. I did not check that version’s code path.
  • The public reports linked here show what the log looks like in practice. The subtraction check is not used to decide what caused any of them.

Within those limits, the subtraction is a good first step. If the gap is billions of seconds, start by aligning use_sim_time on every node. If it’s small, leave the clocks alone and look at the tf tree and frame names. If nothing is logged but scans appear in the wrong place, check whether the laser stamp is 0.

Sources (checked 2026-10-03)