952264 - Store the timing of actions in slaveapi

Status: RESOLVED FIXED

(Release Engineering :: General, defect, P2)

Description

[Chris Cooper [:coop] (he/him)]

The reboot history in slave health is currently populated from kittenherder log data. In order to properly replace this, we need to start tracking the timing of actions requested via slaveapi.

Specifically, we should be tracking:
* time request was made
* action start time
* action end time

Probably best to store these in seconds since the epoch to make date math easier.

Comment 1

[Chris Cooper [:coop] (he/him)]

Turns out I need this before I can properly work on bug 914805.

Comment 2

[Chris Cooper [:coop] (he/him)]

bhearsum: did you see any gevent errors like the following when you were developing/testing?

https://coop.pastebin.mozilla.org/4330288

Wondering whether it's related to me working locally on a Mac instead of Linux...despite the individual steps failing, I do get a proper result at the end:

{
  "reboot": {
    "4470660944": {
      "finish_timestamp": 1392753174, 
      "request_timestamp": 1392753161, 
      "start_timestamp": 1392753168, 
      "state": 3, 
      "text": "Attempting SSH reboot...Failed.\nAttempting PDU reboot...Failed.\nSlave already has reboot bug (919801), nothing to do."
    }
  }
}

Should have a hacky patch ready for feedback soon.

Comment 3

[[e-mail] (:bhearsum)]

(In reply to Chris Cooper [:coop] from comment #2)
> Wondering whether it's related to me working locally on a Mac instead of
> Linux...despite the individual steps failing, I do get a proper result at
> the end:

Hrm. I certainly don't hit them now, but they seem vaguely familiar. Which version of gevent are you using?

> {
>   "reboot": {
>     "4470660944": {
>       "finish_timestamp": 1392753174, 
>       "request_timestamp": 1392753161, 
>       "start_timestamp": 1392753168, 
>       "state": 3, 
>       "text": "Attempting SSH reboot...Failed.\nAttempting PDU
> reboot...Failed.\nSlave already has reboot bug (919801), nothing to do."
>     }
>   }
> }
> 
> Should have a hacky patch ready for feedback soon.

Nice!

Comment 4

[Chris Cooper [:coop] (he/him)]

Attachment: [slaveapi] Add timestamps to events

Asking for feedback rather than review because I'm not sure whether there's a better approach.

Comment 5

[[e-mail] (:bhearsum)]

Comment on attachment 8384766 [details] [diff] [review]
[slaveapi] Add timestamps to events

Review of attachment 8384766 [details] [diff] [review]:
-----------------------------------------------------------------

This looks fine overall, but have you considered putting the timestamp generation in the Processor? I think one call to time.time() before action(), and one call afterwards would avoid the need for actions to know anything about timestamps.

Comment 6

[Chris Cooper [:coop] (he/him)]

Attachment: [slaveapi] Add timestamps to events, v2

(In reply to Ben Hearsum [:bhearsum] from comment #5)
> This looks fine overall, but have you considered putting the timestamp
> generation in the Processor? I think one call to time.time() before
> action(), and one call afterwards would avoid the need for actions to know
> anything about timestamps.

Good call, as much as I want to add timestamps by hand to every event going forward.

Comment 7

[[e-mail] (:bhearsum)]

Comment on attachment 8385656 [details] [diff] [review]
[slaveapi] Add timestamps to events, v2

Review of attachment 8385656 [details] [diff] [review]:
-----------------------------------------------------------------

Awesome!

Comment 8

[Chris Cooper [:coop] (he/him)]

Comment on attachment 8385656 [details] [diff] [review]
[slaveapi] Add timestamps to events, v2

http://hg.mozilla.org/build/slaveapi/rev/07ce0c06ba96

Comment 9

[Justin Wood (:Callek)]

I'm going to be deploying this today with slaveapi 1.0.16 in Bug 979553

Comment 10

[Chris Cooper [:coop] (he/him)]

If you look at https://secure.pub.build.mozilla.org/slaveapi/results right now, you'll notice that the request_timestamp corresponds to the server restart time rather than the time of the request as intended.

I don't think there's enough of a delta between start_timestamp and request_timestamp to warrant keeping both. I'll post a patch to remove request_timestamp.

Comment 11

[Chris Cooper [:coop] (he/him)]

Attachment: Remove request_timestamp

Comment 12

[Chris Cooper [:coop] (he/him)]

Attachment: Remove request_timestamp, v2

Small change from previous patch: we want to set the start_timestamp when we first set up the action message.

Comment 13

[Justin Wood (:Callek)]

(In reply to Chris Cooper [:coop] [away until April 3] from comment #8)
> Comment on attachment 8385656 [details] [diff] [review]
> [slaveapi] Add timestamps to events, v2
> 
> http://hg.mozilla.org/build/slaveapi/rev/07ce0c06ba96

Somehow we lost this patch in the hg (and git) repos, not sure how thats possible, since this cset existed in my local hg repo as well... (when I spun 1.0.16)

That said, the followup cset doesn't seem to apply right now

Comment 14

[Justin Wood (:Callek)]

pushed to git:

$ git push
Counting objects: 19, done.
Delta compression using up to 4 threads.
Compressing objects: 100% (10/10), done.
Writing objects: 100% (10/10), 1.31 KiB | 0 bytes/s, done.
Total 10 (delta 8), reused 0 (delta 0)
To ssh://[e-mail]/build/slaveapi.git
   ccce02a..ac585d5  master -> master

Justin@AQUARIUS /c/Sources/git/slaveapi
$ git log ccce02a..ac585d5
commit ac585d513bf9323a1ff649c113a43aac2eb9cb55
Author: Justin Wood <[e-mail]>
Date:   Tue Mar 25 23:05:47 2014 -0400

    Bug 952264 - Store the timing of actions in slaveapi. r=bhearsum

Comment 15

[Chris Cooper [:coop] (he/him)]

Comment on attachment 8387984 [details] [diff] [review]
Remove request_timestamp, v2

Don't need this patch any more. Request timestamps are working as intended now.