Weird timings in stats in solar o report

[Jedrzej Nowak]

----
vagrant@solar-dev:/vagrant$ solar o report last

ssh_transport_node_node1.run -> SUCCESS
rsync_node_node1.run -> SUCCESS
transports_node_node1.run -> SUCCESS
node1.run -> INPROGRESS
rsync_node_node2.run -> SUCCESS
ssh_transport_node_node2.run -> SUCCESS
transports_node_node2.run -> INPROGRESS
node2.run -> PENDING
hosts_file_node_node2.run -> PENDING
hosts_file_node_node1.run -> PENDING
Total Delta: -2908862384.54
Total Time: 1454431197.38
---

---

ssh_transport_node_node1.run -> SUCCESS
rsync_node_node1.run -> SUCCESS
transports_node_node1.run -> SUCCESS
node1.run -> SUCCESS
rsync_node_node2.run -> SUCCESS
ssh_transport_node_node2.run -> SUCCESS
transports_node_node2.run -> SUCCESS
node2.run -> SUCCESS
hosts_file_node_node2.run -> INPROGRESS
hosts_file_node_node1.run -> INPROGRESS
Total Delta: -2908862385.56
Total Time: 8.16077613831
---

And finally after all succeeded:

---

ssh_transport_node_node1.run -> SUCCESS
rsync_node_node1.run -> SUCCESS
transports_node_node1.run -> SUCCESS
node1.run -> SUCCESS
rsync_node_node2.run -> SUCCESS
ssh_transport_node_node2.run -> SUCCESS
transports_node_node2.run -> SUCCESS
node2.run -> SUCCESS
hosts_file_node_node2.run -> SUCCESS
hosts_file_node_node1.run -> SUCCESS
Total Delta: 20.3823788166
Total Time: 11.2949230671
---

[Jedrzej Nowak (jnowak)]

I found also one like that:

---
ssh_transport_node_node1.run -> SUCCESS
rsync_node_node1.run -> SUCCESS
transports_node_node1.run -> SUCCESS
node1.run -> SUCCESS
rsync_node_node2.run -> SUCCESS
ssh_transport_node_node2.run -> SUCCESS
transports_node_node2.run -> SUCCESS
node2.run -> SUCCESS
hosts_file_node_node2.run -> INPROGRESS
hosts_file_node_node1.run -> SUCCESS
Total Delta: -1454431183.18
Total Time: 10.1105899811
---

[Jedrzej Nowak (jnowak)]

To reproduce:

1. Make deployment fail (at end preferably)
2. solar o restart last
3. solar o report last

First few reports will show negative time.

[Jedrzej Nowak (jnowak)]

A lot errors like that can be seen in our test examples.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/286040
Committed: https://git.openstack.org/cgit/openstack/solar/commit/?id=6f85c893b34fcd6f18dde2655226b3acd7f9ce3c
Submitter: Jenkins
Branch: master

commit 6f85c893b34fcd6f18dde2655226b3acd7f9ce3c
Author: Maciej Kwiek <email address hidden>
Date: Mon Feb 29 14:19:21 2016 +0100

    Timestamp comparison in calculating time fixed

    There were two issue here:
    * end_time was not assigned a new value when solar re-started tasks.
      It caused tasks to have start_time higher than end_time until it
      ended. It is fixed by setting end_time to 0 while starting task.
    * While calculating the delta and longest path time, we checked if
      end and start times were equal to 0 by strict comparison, which
      didn't work due to timestamps being floats.

    Change-Id: I00057ab2707338692f080ced4603ab7303b8c9e2
    Closes-bug: 1541022