Timestamps taken by rosbag play (and rqt_bag) and by rosbag.Bag's read_messages() differ

Question

There is something very strange happening with some rosbags I have. These rosbags contain messages of type sensor_msgs/Image among other topics.

So I do:

First scenario

On one terminal I run rostopic echo /the_image/header because I am not interested in the actual data, just the header info. In another terminal I run rosbag play --clock the_bag.bag

With this I get

seq: 7814
stamp: 
  secs: 1625151029
  nsecs: 882629359
frame_id: ''
---
seq: 7815
stamp: 
  secs: 1625151029
  nsecs: 934761166
frame_id: ''
---
seq: 7816
stamp: 
  secs: 1625151029
  nsecs: 986241550
frame_id: ''
---
seq: 7817
stamp: 
  secs: 1625151030
  nsecs:  82884301
frame_id: ''
---

Second Scenario I do the same as the previous scenario but instead of rosbag play I run rqt_bag the_bag.bag and once there I right click the message to publish them. With that I get similar values but (I have reported the problem before) the first messages are skipped. (this is not the problem of this question)

Third Scenario

Here comes the weird part. Instead of doing as above I have a python script that does

timestamps=[]
for topic, msg, t in  rosbag.Bag("the_bag.bag").read_messages():
    if topic == '/the_image':
        timestamps.append((image_idx, t))
with open("timestamps.txt",'w') as f:
    for idx, t in timestamps:
        f.write('{0},{1},{2}\n'.format(str(idx).zfill(8), t.secs, t.nsecs))

So as you can see I open the bag and get a list of timestamps and record it in a text file. Which gives:

00000000,1625151029,987577614
00000001,1625151030,33818541
00000002,1625151030,88932237
00000003,1625151030,170311084
00000004,1625151030,232427083
00000005,1625151030,279726253
00000006,1625151030,363255375
00000007,1625151030,463079346
00000008,1625151030,501315763
00000009,1625151030,566104245
00000010,1625151030,586694806

As you can see the values are totally different!!!

What could be happening here?

Answer 1

This is a known "issue" with rostopic echo and bag files. I put issue in quotes because it's not necessarily an issue, but just a product of how rostopic works. To spare the somewhat obscure details of the implementation, this problem essentially happens because rospy.rostime does not get initialized correctly when just playing a bag file and echoing that; even if you set /use_sim_time to true.

To give some clarity on what you're seeing, the timestamps coming off your Python script are correct and the rostopic ones are not. If you need the timestamps to be 100% correct with rostopic you can use the -b flag like: rostoic echo -b the_bag.bag /my_image_topic