Annotate gets a start_time before the end_time

[mateusduboli]

Hello,

I'm using the client.annotate method annotate the beginning and end of a method call.

The problem I'm having is that, when the process takes too little time to complete, less then a second to be more precise, the Librato API responds with a 400 error saying that start_time is greater then end_time. Here is an example response:

#<struct Faraday::Env method=:put, body="{\"errors\":{\"params\":{\"start_time\":[\"must be before end_time\"]}}}", url=#<URI::HTTPS:0x00000001351910 URL:https://metrics-api.librato.com/v1/annotations/system.timed_action/68919280>, request=#<Faraday::RequestOptions timeout=30, open_timeout=20>, request_headers={"User-Agent"=>"librato-metrics/1.5.0 (ruby; 2.0.0p384; x86_64-linux-gnu) direct-faraday/0.9.1", "Content-Type"=>"application/json", "Authorization"=>"xxxxxxxxx"}, ssl=#<Faraday::SSLOptions verify=true>, parallel_manager=nil, params=nil, response=nil, response_headers={"content-type"=>"application/json;charset=utf-8", "date"=>"Mon, 01 Jun 2015 18:11:13 GMT", "server"=>"nginx", "status"=>"400 Bad Request", "content-length"=>"64", "connection"=>"Close"}, status=400>

//Extracted body
{ 
  "errors": {
    "params": {
      "start_time": [ 
        "must be before end_time"
      ]
    }
  }
}"

Sample call:

client = Librato::Metrics.Client.new('me@here.world', 'MUCH_SECRET_SUCH_KEY') 
client.annotate('system.timed_action', 'sample time action') do
  # do stuff...
end

[nextmat]

@mateusduboli - sorry for the slow response, that definitely looks like a bug.

@mheffner - do you know offhand if we would raise this when start time and end time are equivalent and/or if that state is allowable? If not we should probably just not submit end_time if they are the same here?

[mheffner]

@nextmat I don't see any reason why our API couldn't allow start_time=end_time. I've opened a ticket for our API.

[mheffner]

So I just added a test for this and we do accept start_time=end_time. Can we determine whether this is actually sending a start_time > end_time? Is there a scenario where that could happen?

[mateusduboli]

@mheffner Try to annotate a event that lasts less then a second, I placed a sleep 1 in my code and it stopped to return the error.

[nextmat]

I did a bit of digging into this and the only thing I can figure is a time mismatch between your servers and ours, where your servers are running ahead.

With the block form it looks like by default the start_time is unspecified which means it will resolve to our clock time and the end_time is specifically submitted based on your clock. If your machine is running a second or more ahead of us this could result in an end_time earlier than the start_time.

In looking at the code it looks like we could probably simplify things a little by always sending client time which would fix this if that was the issue. You may also want to check that your time services are running properly.

[nextmat]

I have a possible fix for this in #109, would you mind using that branch and seeing if that fixes the issue for you? I have been unable to reproduce it myself but I think there is a pretty good chance that is the problem.

[mateusduboli]

@nextmat will do

[nextmat]

@mateusduboli just checking back to see if this resolved your problem?

[mateusduboli]

@nextmat sorry, I've still hadn't had the time to do the test, I'll do it the first thing tomorrow :smile:

[mateusduboli]

@nextmat Did it! I couldn't reproduce the problem anymore.

[nextmat]

Awesome. Released in v1.5.1