confusing timestamp related error trace in server log

[Armando Migliaccio]

This has been observed in multi-node CI runs for Neutron:

[req-de4ba471-c1d7-49f4-860d-e717c611ebbd None None] Message received from the host: devstack-trusty-2-node-rax-iad-2588390-4019.slave.openstack.org during the registration of Open vSwitch agent has a timestamp: 2015-05-19T18:15:27Z. This differs from the current server timestamp: 2015-05-19T18:15:27Z by more than the threshold agent downtime: 75.

What's weird about this is that the two timestamps are the same when they shouldn't.

This is the logstash query:

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiZHVyaW5nIHRoZSByZWdpc3RyYXRpb24gb2YgT3BlbiB2U3dpdGNoIGFnZW50IGhhcyBhIHRpbWVzdGFtcFwiIiwiZmllbGRzIjpbXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiJhbGwiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxNDMyMDYxMTA1NDUxfQ==

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/186185

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/186185
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=2b7e6552e82f899a91ce3d6973d90778440fac8c
Submitter: Jenkins
Branch: master

commit 2b7e6552e82f899a91ce3d6973d90778440fac8c
Author: Kevin Benton <email address hidden>
Date: Wed May 27 14:52:06 2015 -0700

    Remove time formatting in agent clock error

    This removes time formatting that may be hiding timezone
    issues that are leading to a delta being calculated between
    the agent and the server even when it shows none. It also
    adds logging of the difference so we can see how far off it
    thinks they are.

    Example message:
    during the registration of Open vSwitch agent has a timestamp:
    2015-05-19T18:15:27Z. This differs from the current server
    timestamp: 2015-05-19T18:15:27Z by more than the threshold agent
    downtime: 75.

    Note that the timestamps are exactly the same after formatting.

    Change-Id: Ibfc30444b7a167fb18ae9051a775266236d4ecce
    Related-Bug: #1456760

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/186632

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/186632
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=a0c9745e90596d4a3207e844332e078ca7ecc5fa
Submitter: Jenkins
Branch: master

commit a0c9745e90596d4a3207e844332e078ca7ecc5fa
Author: Kevin Benton <email address hidden>
Date: Thu May 28 16:48:04 2015 -0700

    Use correct time delta function

    The .seconds attribute of a timedetla object cannot be taken in
    isolation because it can overflow into days. For example, a -1 second
    difference will become -1 day and 86399 seconds.

    This became a problem when the agent clock was slightly ahead of
    the server clock. When calling (server_time - agent_time).seconds
    in this scenario, it would go below 0 in the daily seconds and
    wraparound to 86399 seconds and -1 day.

    This patch corrects the issue by using a method in timeutils that
    ends up calling total_seconds(), which was designed for this usecase.
    It also restores the formatting that was removed in patch:
    Ibfc30444b7a167fb18ae9051a775266236d4ecce

    Closes-Bug: #1456760
    Change-Id: Ie90249ab68bb5f8d117872d52180c7087d8fac9b

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: feature/pecan
Review: https://review.openstack.org/196701

[OpenStack Infra (hudson-openstack)]

Change abandoned by Kyle Mestery (<email address hidden>) on branch: feature/pecan
Review: https://review.openstack.org/196701
Reason: This is lacking the functional fix [1], so I'll propose a new merge commit which includes that one.

[1] https://review.openstack.org/#/c/196711/

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: feature/pecan
Review: https://review.openstack.org/196920