Improve wait handing in abuse retry (#1971)

* Do not assume server time is in sync with local machine time

* Add test to maintain 100% coverage

src/main/java/org/kohsuke/github/GHRateLimit.java

@@ -494,7 +494,7 @@ && getRemaining() <= other.getRemaining())) {
                 return this;
             } else if (!(other instanceof UnknownLimitRecord)) {
                 // If the above is not the case that means other has a later reset
-                // or the same resent and fewer requests remaining.
+                // or the same reset and fewer requests remaining.
                 // If the other record is not an unknown record, the other is more recent
                 return other;
             } else if (this.isExpired() && !other.isExpired()) {

src/main/java/org/kohsuke/github/GitHubAbuseLimitHandler.java

@@ -4,6 +4,7 @@
 
 import java.io.IOException;
 import java.io.InterruptedIOException;
+import java.time.Duration;
 import java.time.ZonedDateTime;
 import java.time.format.DateTimeFormatter;
 import java.time.temporal.ChronoUnit;
@@ -23,6 +24,11 @@
  */
 public abstract class GitHubAbuseLimitHandler extends GitHubConnectorResponseErrorHandler {
 
+    /**
+     * On a wait, even if the response suggests a very short wait, wait for a minimum duration.
+     */
+    private static final int MINIMUM_ABUSE_RETRY_MILLIS = 1000;
+
     /**
      * Create default GitHubAbuseLimitHandler instance
      */
@@ -143,7 +149,7 @@ public void onError(GitHubConnectorResponse connectorResponse) throws IOExceptio
     };
 
     // If "Retry-After" missing, wait for unambiguously over one minute per GitHub guidance
-    static long DEFAULT_WAIT_MILLIS = 61 * 1000;
+    static long DEFAULT_WAIT_MILLIS = Duration.ofSeconds(61).toMillis();
 
     /*
      * Exposed for testability. Given an http response, find the retry-after header field and parse it as either a
@@ -156,11 +162,23 @@ static long parseWaitTime(GitHubConnectorResponse connectorResponse) {
         }
 
         try {
-            return Math.max(1000, Long.parseLong(v) * 1000);
+            return Math.max(MINIMUM_ABUSE_RETRY_MILLIS, Duration.ofSeconds(Long.parseLong(v)).toMillis());
         } catch (NumberFormatException nfe) {
             // The retry-after header could be a number in seconds, or an http-date
+            // We know it was a date if we got a number format exception :)
+
+            // Don't use ZonedDateTime.now(), because the local and remote server times may not be in sync
+            // Instead, we can take advantage of the Date field in the response to see what time the remote server
+            // thinks it is
+            String dateField = connectorResponse.header("Date");
+            ZonedDateTime now;
+            if (dateField != null) {
+                now = ZonedDateTime.parse(dateField, DateTimeFormatter.RFC_1123_DATE_TIME);
+            } else {
+                now = ZonedDateTime.now();
+            }
             ZonedDateTime zdt = ZonedDateTime.parse(v, DateTimeFormatter.RFC_1123_DATE_TIME);
-            return ChronoUnit.MILLIS.between(ZonedDateTime.now(), zdt);
+            return Math.max(MINIMUM_ABUSE_RETRY_MILLIS, ChronoUnit.MILLIS.between(now, zdt));
         }
     }
 

src/test/java/org/kohsuke/github/AbuseLimitHandlerTest.java

@@ -481,9 +481,46 @@ public void onError(@NotNull GitHubConnectorResponse connectorResponse) throws I
                                 "You have exceeded a secondary rate limit. Please wait a few minutes before you try again");
 
                         long waitTime = parseWaitTime(connectorResponse);
-                        // The exact value here will depend on when the test is run
                         assertThat(waitTime, Matchers.lessThan(GitHubAbuseLimitHandler.DEFAULT_WAIT_MILLIS));
-                        assertThat(waitTime, Matchers.greaterThan(3 * 1000l));
+                        assertThat(waitTime, equalTo(8 * 1000l));
+
+                        GitHubAbuseLimitHandler.WAIT.onError(connectorResponse);
+                    }
+                })
+                .build();
+
+        gitHub.getMyself();
+        assertThat(mockGitHub.getRequestCount(), equalTo(1));
+
+        getTempRepository();
+        assertThat(mockGitHub.getRequestCount(), equalTo(3));
+    }
+
+    /**
+     * Tests the behavior of the GitHub API client when the abuse limit handler with a date retry, when the response is
+     * missing the main "date" header.
+     *
+     * @throws Exception
+     *             if any error occurs during the test execution.
+     */
+    @Test
+    public void testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After_Missing_Date_Header()
+            throws Exception {
+        // Customized response that templates the date to keep things working
+        snapshotNotAllowed();
+        gitHub = getGitHubBuilder().withEndpoint(mockGitHub.apiServer().baseUrl())
+                .withAbuseLimitHandler(new GitHubAbuseLimitHandler() {
+                    /**
+                     * Overriding method because the actual method will wait for one minute causing slowness in unit
+                     * tests
+                     */
+                    @Override
+                    public void onError(@NotNull GitHubConnectorResponse connectorResponse) throws IOException {
+                        long waitTime = parseWaitTime(connectorResponse);
+
+                        // This will now use system time, so might not be exactly 8s
+                        assertThat(waitTime, Matchers.greaterThan((8 - 1) * 1000l));
+                        assertThat(waitTime, Matchers.lessThan((8 + 1) * 1000l));
 
                         GitHubAbuseLimitHandler.WAIT.onError(connectorResponse);
                     }

src/test/resources/org/kohsuke/github/AbuseLimitHandlerTest/wiremock/testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After_Missing_Date_Header/__files/1-user.json

@@ -0,0 +1,45 @@
+{
+  "login": "bitwiseman",
+  "id": 1958953,
+  "node_id": "MDQ6VXNlcjE5NTg5NTM=",
+  "avatar_url": "https://avatars3.githubusercontent.com/u/1958953?v=4",
+  "gravatar_id": "",
+  "url": "https://api.github.com/users/bitwiseman",
+  "html_url": "https://github.com/bitwiseman",
+  "followers_url": "https://api.github.com/users/bitwiseman/followers",
+  "following_url": "https://api.github.com/users/bitwiseman/following{/other_user}",
+  "gists_url": "https://api.github.com/users/bitwiseman/gists{/gist_id}",
+  "starred_url": "https://api.github.com/users/bitwiseman/starred{/owner}{/repo}",
+  "subscriptions_url": "https://api.github.com/users/bitwiseman/subscriptions",
+  "organizations_url": "https://api.github.com/users/bitwiseman/orgs",
+  "repos_url": "https://api.github.com/users/bitwiseman/repos",
+  "events_url": "https://api.github.com/users/bitwiseman/events{/privacy}",
+  "received_events_url": "https://api.github.com/users/bitwiseman/received_events",
+  "type": "User",
+  "site_admin": false,
+  "name": "Liam Newman",
+  "company": "Cloudbees, Inc.",
+  "blog": "",
+  "location": "Seattle, WA, USA",
+  "email": "[email protected]",
+  "hireable": null,
+  "bio": "https://twitter.com/bitwiseman",
+  "public_repos": 181,
+  "public_gists": 7,
+  "followers": 146,
+  "following": 9,
+  "created_at": "2012-07-11T20:38:33Z",
+  "updated_at": "2020-02-06T17:29:39Z",
+  "private_gists": 8,
+  "total_private_repos": 10,
+  "owned_private_repos": 0,
+  "disk_usage": 33697,
+  "collaborators": 0,
+  "two_factor_authentication": true,
+  "plan": {
+    "name": "free",
+    "space": 976562499,
+    "collaborators": 0,
+    "private_repos": 10000
+  }
+}

src/test/resources/org/kohsuke/github/AbuseLimitHandlerTest/wiremock/testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After_Missing_Date_Header/__files/3-r_h_t_fail.json

@@ -0,0 +1,126 @@
+{
+  "id": 238757196,
+  "node_id": "MDEwOlJlcG9zaXRvcnkyMzg3NTcxOTY=",
+  "name": "temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After",
+  "full_name": "hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After",
+  "private": false,
+  "owner": {
+    "login": "hub4j-test-org",
+    "id": 7544739,
+    "node_id": "MDEyOk9yZ2FuaXphdGlvbjc1NDQ3Mzk=",
+    "avatar_url": "https://avatars3.githubusercontent.com/u/7544739?v=4",
+    "gravatar_id": "",
+    "url": "https://api.github.com/users/hub4j-test-org",
+    "html_url": "https://github.com/hub4j-test-org",
+    "followers_url": "https://api.github.com/users/hub4j-test-org/followers",
+    "following_url": "https://api.github.com/users/hub4j-test-org/following{/other_user}",
+    "gists_url": "https://api.github.com/users/hub4j-test-org/gists{/gist_id}",
+    "starred_url": "https://api.github.com/users/hub4j-test-org/starred{/owner}{/repo}",
+    "subscriptions_url": "https://api.github.com/users/hub4j-test-org/subscriptions",
+    "organizations_url": "https://api.github.com/users/hub4j-test-org/orgs",
+    "repos_url": "https://api.github.com/users/hub4j-test-org/repos",
+    "events_url": "https://api.github.com/users/hub4j-test-org/events{/privacy}",
+    "received_events_url": "https://api.github.com/users/hub4j-test-org/received_events",
+    "type": "Organization",
+    "site_admin": false
+  },
+  "html_url": "https://github.com/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After",
+  "description": "A test repository for testing the github-api project: temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After",
+  "fork": false,
+  "url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After",
+  "forks_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/forks",
+  "keys_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/keys{/key_id}",
+  "collaborators_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/collaborators{/collaborator}",
+  "teams_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/teams",
+  "hooks_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/hooks",
+  "issue_events_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/issues/events{/number}",
+  "events_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/events",
+  "assignees_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/assignees{/user}",
+  "branches_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/branches{/branch}",
+  "tags_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/tags",
+  "blobs_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/git/blobs{/sha}",
+  "git_tags_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/git/tags{/sha}",
+  "git_refs_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/git/refs{/sha}",
+  "trees_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/git/trees{/sha}",
+  "statuses_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/statuses/{sha}",
+  "languages_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/languages",
+  "stargazers_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/stargazers",
+  "contributors_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/contributors",
+  "subscribers_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/subscribers",
+  "subscription_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/subscription",
+  "commits_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/commits{/sha}",
+  "git_commits_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/git/commits{/sha}",
+  "comments_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/comments{/number}",
+  "issue_comment_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/issues/comments{/number}",
+  "contents_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/contents/{+path}",
+  "compare_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/compare/{base}...{head}",
+  "merges_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/merges",
+  "archive_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/{archive_format}{/ref}",
+  "downloads_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/downloads",
+  "issues_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/issues{/number}",
+  "pulls_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/pulls{/number}",
+  "milestones_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/milestones{/number}",
+  "notifications_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/notifications{?since,all,participating}",
+  "labels_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/labels{/name}",
+  "releases_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/releases{/id}",
+  "deployments_url": "https://api.github.com/repos/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After/deployments",
+  "created_at": "2020-02-06T18:33:39Z",
+  "updated_at": "2020-02-06T18:33:43Z",
+  "pushed_at": "2020-02-06T18:33:41Z",
+  "git_url": "git://github.com/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After.git",
+  "ssh_url": "[email protected]:hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After.git",
+  "clone_url": "https://github.com/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After.git",
+  "svn_url": "https://github.com/hub4j-test-org/temp-testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After",
+  "homepage": "http://github-api.kohsuke.org/",
+  "size": 0,
+  "stargazers_count": 0,
+  "watchers_count": 0,
+  "language": null,
+  "has_issues": true,
+  "has_projects": true,
+  "has_downloads": true,
+  "has_wiki": true,
+  "has_pages": false,
+  "forks_count": 0,
+  "mirror_url": null,
+  "archived": false,
+  "disabled": false,
+  "open_issues_count": 0,
+  "license": null,
+  "forks": 0,
+  "open_issues": 0,
+  "watchers": 0,
+  "default_branch": "main",
+  "permissions": {
+    "admin": true,
+    "push": true,
+    "pull": true
+  },
+  "temp_clone_token": "",
+  "allow_squash_merge": true,
+  "allow_merge_commit": true,
+  "allow_rebase_merge": true,
+  "delete_branch_on_merge": false,
+  "organization": {
+    "login": "hub4j-test-org",
+    "id": 7544739,
+    "node_id": "MDEyOk9yZ2FuaXphdGlvbjc1NDQ3Mzk=",
+    "avatar_url": "https://avatars3.githubusercontent.com/u/7544739?v=4",
+    "gravatar_id": "",
+    "url": "https://api.github.com/users/hub4j-test-org",
+    "html_url": "https://github.com/hub4j-test-org",
+    "followers_url": "https://api.github.com/users/hub4j-test-org/followers",
+    "following_url": "https://api.github.com/users/hub4j-test-org/following{/other_user}",
+    "gists_url": "https://api.github.com/users/hub4j-test-org/gists{/gist_id}",
+    "starred_url": "https://api.github.com/users/hub4j-test-org/starred{/owner}{/repo}",
+    "subscriptions_url": "https://api.github.com/users/hub4j-test-org/subscriptions",
+    "organizations_url": "https://api.github.com/users/hub4j-test-org/orgs",
+    "repos_url": "https://api.github.com/users/hub4j-test-org/repos",
+    "events_url": "https://api.github.com/users/hub4j-test-org/events{/privacy}",
+    "received_events_url": "https://api.github.com/users/hub4j-test-org/received_events",
+    "type": "Organization",
+    "site_admin": false
+  },
+  "network_count": 0,
+  "subscribers_count": 6
+}

src/test/resources/org/kohsuke/github/AbuseLimitHandlerTest/wiremock/testHandler_Wait_Secondary_Limits_Too_Many_Requests_Date_Retry_After_Missing_Date_Header/mappings/1-user.json

@@ -0,0 +1,47 @@
+{
+  "id": "a60baf84-5b5c-4f86-af3d-cab0d609c7b2",
+  "name": "user",
+  "request": {
+    "url": "/user",
+    "method": "GET",
+    "headers": {
+      "Accept": {
+        "equalTo": "application/vnd.github+json"
+      }
+    }
+  },
+  "response": {
+    "status": 200,
+    "bodyFileName": "1-user.json",
+    "headers": {
+      "Content-Type": "application/json; charset=utf-8",
+      "Server": "GitHub.com",
+      "Status": "200 OK",
+      "X-RateLimit-Limit": "5000",
+      "X-RateLimit-Remaining": "4930",
+      "X-RateLimit-Reset": "{{now offset='3 seconds' format='unix'}}",
+      "Cache-Control": "private, max-age=60, s-maxage=60",
+      "Vary": [
+        "Accept, Authorization, Cookie, X-GitHub-OTP",
+        "Accept-Encoding"
+      ],
+      "ETag": "W/\"1cb30f031c67c499473b3aad01c7f7a5\"",
+      "Last-Modified": "Thu, 06 Feb 2020 17:29:39 GMT",
+      "X-OAuth-Scopes": "admin:org, admin:org_hook, admin:public_key, admin:repo_hook, delete_repo, gist, notifications, repo, user, write:discussion",
+      "X-Accepted-OAuth-Scopes": "",
+      "X-GitHub-Media-Type": "unknown, github.v3",
+      "Access-Control-Expose-Headers": "ETag, Link, Location, Retry-After, X-GitHub-OTP, X-RateLimit-Limit, X-RateLimit-Remaining, X-RateLimit-Reset, X-OAuth-Scopes, X-Accepted-OAuth-Scopes, X-Poll-Interval, X-GitHub-Media-Type",
+      "Access-Control-Allow-Origin": "*",
+      "Strict-Transport-Security": "max-age=31536000; includeSubdomains; preload",
+      "X-Frame-Options": "deny",
+      "X-Content-Type-Options": "nosniff",
+      "X-XSS-Protection": "1; mode=block",
+      "Referrer-Policy": "origin-when-cross-origin, strict-origin-when-cross-origin",
+      "Content-Security-Policy": "default-src 'none'",
+      "X-GitHub-Request-Id": "CC37:2605:3F884:4E941:5E3C5BFC"
+    }
+  },
+  "uuid": "a60baf84-5b5c-4f86-af3d-cab0d609c7b2",
+  "persistent": true,
+  "insertionIndex": 1
+}