Message retrieval leads to retries and failure

[rkischuk]

We have a production app which has Call Log and Read Messages permissions. For many messages, we are able to retrieve the message details. For some, however, we get a retry followed by a failure.

Such as this message: https://platform.ringcentral.com/restapi/v1.0/account/346124008/extension/346247008/message-store/748682490016

      message_uri = "https://platform.ringcentral.com/restapi/v1.0/account/346124008/extension/346247008/message-store/748682490016"
      response = client.http.get do |req|
        req.url lead.message_uri
      end

Then, I get the following perplexing series of messages:

W, [2017-06-12T09:48:34.397029 #25438]  WARN -- : You have been rate limited. Retrying in 60 seconds...
W, [2017-06-12T09:48:35.397205 #25438]  WARN -- : 60...
W, [2017-06-12T09:48:40.398032 #25438]  WARN -- : 55...
W, [2017-06-12T09:48:45.398863 #25438]  WARN -- : 50...
W, [2017-06-12T09:48:50.399689 #25438]  WARN -- : 45...
W, [2017-06-12T09:48:55.400518 #25438]  WARN -- : 40...
W, [2017-06-12T09:49:00.401316 #25438]  WARN -- : 35...
W, [2017-06-12T09:49:05.402063 #25438]  WARN -- : 30...
W, [2017-06-12T09:49:10.402881 #25438]  WARN -- : 25...
W, [2017-06-12T09:49:15.403729 #25438]  WARN -- : 20...
W, [2017-06-12T09:49:20.404500 #25438]  WARN -- : 15...
W, [2017-06-12T09:49:25.405330 #25438]  WARN -- : 10...
W, [2017-06-12T09:49:30.406249 #25438]  WARN -- : 5...
W, [2017-06-12T09:49:34.407022 #25438]  WARN -- : Retrying...
 => #<Faraday::Response:0x007f1ef4b29a48 @on_complete_callbacks=[], @env=#<Faraday::Env @method=:get @body={"errorCode"=>"CMN-301", "message"=>"Request rate exceeded", "errors"=>[{"errorCode"=>"CMN-301", "message"=>"Request rate exceeded"}]} @url=#<URI::HTTPS https://platform.ringcentral.com/restapi/v1.0/account/346124008/extension/346247008/message-store/748682490016> @request=#<Faraday::RequestOptions (empty)> @request_headers={"User-Agent"=>"ringcentral-sdk-ruby/2.1.0 ruby/2.3.1 x86_64-linux", "RC-User-Agent"=>"ringcentral-sdk-ruby/2.1.0 ruby/2.3.1 x86_64-linux", "SDK-User-Agent"=>"ringcentral-sdk-ruby/2.1.0 ruby/2.3.1 x86_64-linux", "Authorization"=>"Bearer U0pDMDFQMDdQQVMwMHxBQUNVT1lPZGVaaFZ1ek1yNWp4YkdrTmhiWVRlR3kxbDVtTTh2TWJWTUNkelRKdHhRVjE2VWNzRnpNVGlBN1RfdUhaNF9QWWRPMEVYNEhPV3FzbEwwTUtuMFBGMUVfcGdXQ3pFSkNZMWxXNnVxamVYbXlNT1RibFU2R21FWE1EcVBPd3dEY3NJUXNrNHFvLWlCTnp2aVZCdjVRRVlGOGg0VWRyekVBVlhXSWkzV2h4THVQZW9wZmFieG9oT28yUDdGY3N8SkRpS0dBfE9GNFlRX1dwZE1SNHoyVno2UXZ0WFE"} @ssl=#<Faraday::SSLOptions verify=true> @response=#<Faraday::Response:0x007f1ef4b29a48 ...> @response_headers={"server"=>"nginx/1.10.2", "date"=>"Mon, 12 Jun 2017 09:49:56 GMT", "content-type"=>"application/json", "content-length"=>"161", "connection"=>"close", "x-rate-limit-group"=>"light", "x-rate-limit-limit"=>"50", "x-rate-limit-remaining"=>"50", "x-rate-limit-window"=>"60", "retry-after"=>"60", "www-authenticate"=>"Bearer realm=\"RingCentral REST API\", error=\"CMN-301\", error_description=\"Request rate exceeded\"", "content-language"=>"en", "routingkey"=>"SJC01P07", "rcrequestid"=>"7db9fc62-4f54-11e7-94f2-005056af6d4e"} @status=429 @reason_phrase="Too Many Requests">>

How have we possibly been "rate limited" or submitted "Too Many Requests", when we have x-rate-limit-remaining of 50?

[rkischuk]

@grokify Do you need anything else from me to substantiate this issue?

[grokify]

API Response: Formatted and Explained

Here is an excerpt from your API response dump along with it formatted with line wrap for easier scanning.

From looking at the response in more detail, it seems like it has the following properties:

"x-rate-limit-group"=>"light",
"x-rate-limit-limit"=>"50",
"x-rate-limit-remaining"=>"50",
"x-rate-limit-window"=>"60",
"retry-after"=>"60", [...]
@status=429,
@reason_phrase="Too Many Requests"

When you are rate limited and receive a 429 status code with a Retry-After time, you have been penalized and the Retry-After time overrules the X-Rate-Limit-Remaining value.

Since you are throttled again after waiting the 60 second penalty time, there may be something else going on. The log entries you see are from the SDK's automatic rate limit handling feature. If you are just using one client, typically waiting the Retry-After time will allow you to make successful calls. One potential issue is that the rate limit are for the composite key of app and user (app key + username/extension). If you have multiple clients sharing the app and user credentials, then they will share/split the rate limit, described more below

Below, I've standard text to highlight the x-rate-limit-remaining, @status and @reason_phrase properties. The others are due to @ mentions.

---

#<Faraday::Response:0x007f1ef4b29a48 @on_complete_callbacks=[], @env=#<Faraday::Env @method=:get @Body={"errorCode"=>"CMN-301", "message"=>"Request rate exceeded", "errors"=>[{"errorCode"=>"CMN-301", "message"=>"Request rate exceeded"}]} @url=#<URI::HTTPS https://platform.ringcentral.com/restapi/v1.0/account/346124008/extension/346247008/message-store/748682490016> @request=#<Faraday::RequestOptions (empty)> @request_headers={"User-Agent"=>"ringcentral-sdk-ruby/2.1.0 ruby/2.3.1 x86_64-linux", "RC-User-Agent"=>"ringcentral-sdk-ruby/2.1.0 ruby/2.3.1 x86_64-linux", "SDK-User-Agent"=>"ringcentral-sdk-ruby/2.1.0 ruby/2.3.1 x86_64-linux", "Authorization"=>"Bearer REDACTED_ACCESS_TOKEN"} @ssl=#<Faraday::SSLOptions verify=true> @response=#<Faraday::Response:0x007f1ef4b29a48 ...> @response_headers={"server"=>"nginx/1.10.2", "date"=>"Mon, 12 Jun 2017 09:49:56 GMT", "content-type"=>"application/json", "content-length"=>"161", "connection"=>"close", "x-rate-limit-group"=>"light", "x-rate-limit-limit"=>"50", "x-rate-limit-remaining"=>"50", "x-rate-limit-window"=>"60", "retry-after"=>"60", "www-authenticate"=>"Bearer realm="RingCentral REST API", error="CMN-301", error_description="Request rate exceeded"", "content-language"=>"en", "routingkey"=>"SJC01P07", "rcrequestid"=>"7db9fc62-4f54-11e7-94f2-005056af6d4e"} @status=429 @reason_phrase="Too Many Requests">>

---

SDK Auto-Retry Feature Description

The reason you are seeing those log entries is due to the SDK's auto-retry feature.

The SDK's auto-retry feature is so that you don't have to handle the 429 throttling yourself. Normally if you receive a 429 error with a Retry-After header, you will need to write code to wait amount of time before resuming calls. With this feature, the SDK will automatically wait for you. It is supposed to be an optional feature enabled by setting config.retry = true but I just noticed that it seems this setting is always on now so I created issue #69 to resolve this. I'll also look to add logging of the HTTP status encountered that triggered the retry.

If your client is making one set of synchronous API calls, after waiting the time specified in the Retry-After header, it should make successful API calls again and not be throttled with a 429 status response. In this case, some other program may be using the same app/user credential pair to make API calls as described below.

Verification Script and Output

To verify the behavior, I created the following sample script which ran as expected with the output below. The output below retries quicker because this test app has a very limited rate limit plan for testing purposes.

Sample Script: retry.rb

#!ruby

require 'ringcentral_sdk'
require 'pp'

client = RingCentralSdk::REST::Client.new do |config|
  config.load_env = true
end

def get_one_message_url(client)
  res = client.http.get 'account/~/extension/~/message-store?dateFrom=2015-01-01T00:00:00Z'
  return res.body['records'][0]['uri']
end

def get_messages_repeat(client, url)
  while true
    res = client.http.get url
    puts res.status
  end
end

url = get_one_message_url client

get_messages_repeat client, url

Output:

 $ ruby retry.rb
 200
 200 
 200 
 200 
 W, [2017-07-14T01:04:24.770517 #37866]  WARN -- : You have been rate limited. Retrying in 10 seconds...
 W, [2017-07-14T01:04:25.775837 #37866]  WARN -- : 10...
 W, [2017-07-14T01:04:30.792809 #37866]  WARN -- : 5...
 W, [2017-07-14T01:04:34.807407 #37866]  WARN -- : Retrying...
 200 
 200 
 200 
 W, [2017-07-14T01:04:38.894751 #37866]  WARN -- : You have been rate limited. Retrying in 10 seconds...
 W, [2017-07-14T01:04:39.897062 #37866]  WARN -- : 10...
 W, [2017-07-14T01:04:44.910473 #37866]  WARN -- : 5...
 W, [2017-07-14T01:04:48.919197 #37866]  WARN -- : Retrying...
 200
 200
 W, [2017-07-14T01:04:50.873054 #37866]  WARN -- : You have been rate limited. Retrying in 10 seconds...
 W, [2017-07-14T01:04:51.877520 #37866]  WARN -- : 10...
 W, [2017-07-14T01:04:56.891078 #37866]  WARN -- : 5...
 W, [2017-07-14T01:05:00.906421 #37866]  WARN -- : Retrying...
 200
 200
 W, [2017-07-14T01:05:02.843016 #37866]  WARN -- : You have been rate limited. Retrying in 10 seconds...
 W, [2017-07-14T01:05:03.845219 #37866]  WARN -- : 10...
 ^C

Multiple Clients Sharing Rate Limit Scenario

If you are being throttled immediately, one cause for this may be if the app and user credentials are being used in multiple clients. The RingCentral API rate limits are for the composite key consisting of app and user credentails (app key + username/extension). If multiple clients share the app and user credentials, they will share/split the rate limit. In this scenario if one app is already throttled, a second app will be throttled as well.

To resolve this scenario, ask why you have different clients sharing the same app and user credentials.

• If the apps are performing different tasks, consider creating a different app and using different app credentials (app key and app secret)
• If the apps are performing the same task, consider having one app and asking Dev Support to increase the Rate Limit Plan for your app

[grokify]

Closing this issue since this was transferred to a support case and it looks like the issue is multiple clients using the same app and user credentials. Feel free to ask other questions or reopen case here if there are more questions.