Receiving before sending???

edit

I am a ROS noobie, so bare with me.

I've just implemented the "talker.py" and "listener.py" example in the very helpful ROS tutorial pages.

Out of curiosity, I modified my listener.py such that it calls rospy.get_time() as the first step of the callback() function. Then it calculates the difference between this timestamp and the one sent by the talker (now - received time) as a rudimentary way to estimate the time-lag of sending/receiving a message. I then log both this instantaneous difference, the average of the last 100 such measurements and their standard deviation.

Here is a snippet of the resulting output:

[INFO] [WallTime: 1455490866.482270] /listener_10101_1455490785467Time diff: 0.00205, avg(100): 0.00116 +/- 0.00029 
[INFO] [WallTime: 1455490866.581423] /listener_10101_1455490785467Time diff: 0.00113, avg(100): 0.00116 +/- 0.00029 
[INFO] [WallTime: 1455490866.681358] /listener_10101_1455490785467Time diff: 0.00111, avg(100): 0.00116 +/- 0.00029 
[INFO] [WallTime: 1455490866.781439] /listener_10101_1455490785467Time diff: 0.00117, avg(100): 0.00116 +/- 0.00029 
[INFO] [WallTime: 1455490866.881240] /listener_10101_1455490785467Time diff: 0.00104, avg(100): 0.00116 +/- 0.00029 
[INFO] [WallTime: 1455490866.981350] /listener_10101_1455490785467Time diff: 0.00102, avg(100): 0.00116 +/- 0.00029

I've found that over time the values are occasionally < 0 (see the transition in the second line below), indicating the the time stamp on receipt of the message is BEFORE the time stamp sent by the talker. That is the message is received before it was sent!!! (What???)

[INFO] [WallTime: 1455490892.081103] /listener_10101_1455490785467Time diff: 0.00089, avg(100): 0.00105 +/- 0.00015 
[INFO] [WallTime: 1455490892.181117] /listener_10101_1455490785467Time diff: 0.00091, avg(100): 0.00105 +/- 0.00015 
[INFO] [WallTime: 1455490898.958321] /listener_10101_1455490785467Time diff: -0.00189, avg(100): 0.00102 +/- 0.00033 
[INFO] [WallTime: 1455490898.959107] /listener_10101_1455490785467Time diff: -0.00100, avg(100): 0.00100 +/- 0.00039 
[INFO] [WallTime: 1455490892.376509] /listener_10101_1455490785467Time diff: -0.00369, avg(100): 0.00096 +/- 0.00061 
[INFO] [WallTime: 1455490892.477625] /listener_10101_1455490785467Time diff: -0.00259, avg(100): 0.00092 +/- 0.00070

I would be thrilled if anyone could help me understand either what conceptual error I am making here or how this is possible?

EDIT: Here is the important part of the code (the callback() function). (sorry for the mess in the comments below)

import numpy as np

valuelist = []

def callback(data, vals = valuelist):
    now = rospy.get_time()
    sentval = data.data.split()
    dt = now - float(sentval[2])
    if vals.__len__() < 100:
        vals.insert(0,dt)
    else:
        vals.pop()
        vals.insert(0,dt)

    valsnp = np.array(vals)
    rospy.loginfo(rospy.get_caller_id() + 'Time diff: %0.5f, avg(%3d): %0.5f +/- %0.5f ' % (dt, valsnp.size, valsnp.mean(),valsnp.std()) )

EDIT2: The talker code (talker.py)

import rospy
from std_msgs.msg import String

def talker():
    pub = rospy.Publisher('chatter', String, queue_size=10)
    rospy.init_node('talker', anonymous=True)
    rate = rospy.Rate(10) # 10hz
    while not rospy.is_shutdown():
        hello_str = "hello world %s" % rospy.get_time()
        pub.publish(hello_str)
        rospy.loginfo(hello_str)
        rate.sleep()

if __name__ == '__main__':
    try:
        talker()
    except rospy.ROSInterruptException:
        pass

Thanks in advance, Val