Add sanity caching and retry controls

pom.xml

@@ -697,6 +697,10 @@
                   <useSystemClassLoader>false</useSystemClassLoader>
                   <excludesFile>src/test/resources/slow-or-flaky-tests.txt</excludesFile>
                   <argLine>@{jacoco.surefire.argLine} ${surefire.argLine} -Dtest.github.connector=httpclient</argLine>
+                  <!-- Run some test passes with trace logging turned on -->
+                  <systemPropertyVariables>
+                    <java.util.logging.config.file>src/test/resources/test-trace-logging.properties</java.util.logging.config.file>
+                  </systemPropertyVariables>
                 </configuration>
               </execution>
               <execution>
@@ -710,6 +714,10 @@
                   <useSystemClassLoader>false</useSystemClassLoader>
                   <excludesFile>src/test/resources/slow-or-flaky-tests.txt</excludesFile>
                   <argLine>@{jacoco.surefire.argLine} ${surefire.argLine} -Dtest.github.connector=urlconnection</argLine>
+                  <!-- Run some test passes with trace logging turned on -->
+                  <systemPropertyVariables>
+                    <java.util.logging.config.file>src/test/resources/test-trace-logging.properties</java.util.logging.config.file>
+                  </systemPropertyVariables>
                 </configuration>
               </execution>
               <execution>
@@ -721,11 +729,25 @@
                 <configuration>
                   <classesDirectory>${project.basedir}/target/github-api-${project.version}.jar</classesDirectory>
                   <rerunFailingTestsCount>2</rerunFailingTestsCount>
-                  <!-- There are some tests that take longer or are a little
-                    flaky. Run them here. -->
                   <includesFile>src/test/resources/slow-or-flaky-tests.txt</includesFile>
                 </configuration>
               </execution>
+              <execution>
+                <id>slow-or-flaky-test-tracing</id>
+                <phase>integration-test</phase>
+                <goals>
+                  <goal>test</goal>
+                </goals>
+                <configuration>
+                  <classesDirectory>${project.basedir}/target/github-api-${project.version}.jar</classesDirectory>
+                  <rerunFailingTestsCount>2</rerunFailingTestsCount>
+                  <includesFile>src/test/resources/slow-or-flaky-tests.txt</includesFile>
+                  <!-- Run some test passes with trace logging turned on -->
+                  <systemPropertyVariables>
+                    <java.util.logging.config.file>src/test/resources/test-trace-logging.properties</java.util.logging.config.file>
+                  </systemPropertyVariables>
+                </configuration>
+              </execution>
               <execution>
                 <!-- Verify that JWT suite 0.11.x still works -->
                 <id>jwt0.11.x-test</id>

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

@@ -70,6 +70,9 @@ public class GitHub {
     private final ConcurrentMap<String, GHUser> users;
     private final ConcurrentMap<String, GHOrganization> orgs;
 
+    @Nonnull
+    private final GitHubSanityCachedValue<GHMeta> sanityCachedMeta = new GitHubSanityCachedValue<>();
+
     /**
      * Creates a client API root object.
      *
@@ -1253,7 +1256,7 @@ public boolean isCredentialValid() {
      * @see <a href="https://developer.github.com/v3/meta/#meta">Get Meta</a>
      */
     public GHMeta getMeta() throws IOException {
-        return createRequest().withUrlPath("/meta").fetch(GHMeta.class);
+        return this.sanityCachedMeta.get(() -> createRequest().withUrlPath("/meta").fetch(GHMeta.class));
     }
 
     /**

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

@@ -16,6 +16,7 @@
 import java.time.format.DateTimeFormatter;
 import java.time.temporal.ChronoUnit;
 import java.util.*;
+import java.util.concurrent.ThreadLocalRandom;
 import java.util.concurrent.atomic.AtomicReference;
 import java.util.logging.Logger;
 
@@ -45,11 +46,15 @@
 class GitHubClient {
 
     /** The Constant CONNECTION_ERROR_RETRIES. */
-    static final int CONNECTION_ERROR_RETRIES = 2;
-    /**
-     * If timeout issues let's retry after milliseconds.
-     */
-    static final int retryTimeoutMillis = 100;
+    private static final int DEFAULT_CONNECTION_ERROR_RETRIES = 2;
+
+    /** The Constant DEFAULT_MINIMUM_RETRY_TIMEOUT_MILLIS. */
+    private static final int DEFAULT_MINIMUM_RETRY_MILLIS = 100;
+
+    /** The Constant DEFAULT_MAXIMUM_RETRY_TIMEOUT_MILLIS. */
+    private static final int DEFAULT_MAXIMUM_RETRY_MILLIS = DEFAULT_MINIMUM_RETRY_MILLIS;
+
+    private static final ThreadLocal<String> sendRequestTraceId = new ThreadLocal<>();
 
     // Cache of myself object.
     private final String apiUrl;
@@ -64,6 +69,12 @@ class GitHubClient {
     @Nonnull
     private final AtomicReference<GHRateLimit> rateLimit = new AtomicReference<>(GHRateLimit.DEFAULT);
 
+    @Nonnull
+    private final GitHubSanityCachedValue<GHRateLimit> sanityCachedRateLimit = new GitHubSanityCachedValue<>();
+
+    @Nonnull
+    private GitHubSanityCachedValue<Boolean> sanityCachedIsCredentialValid = new GitHubSanityCachedValue<>();
+
     private static final Logger LOGGER = Logger.getLogger(GitHubClient.class.getName());
 
     private static final ObjectMapper MAPPER = new ObjectMapper();
@@ -154,17 +165,22 @@ private <T> T fetch(Class<T> type, String urlPath) throws IOException {
      * @return the boolean
      */
     public boolean isCredentialValid() {
-        try {
-            // If 404, ratelimit returns a default value.
-            // This works as credential test because invalid credentials returns 401, not 404
-            getRateLimit();
-            return true;
-        } catch (IOException e) {
-            LOGGER.log(FINE,
-                    "Exception validating credentials on " + getApiUrl() + " with login '" + getLogin() + "' " + e,
-                    e);
-            return false;
-        }
+        return sanityCachedIsCredentialValid.get(() -> {
+            try {
+                // If 404, ratelimit returns a default value.
+                // This works as credential test because invalid credentials returns 401, not 404
+                getRateLimit();
+                return Boolean.TRUE;
+            } catch (IOException e) {
+                LOGGER.log(FINE,
+                        e,
+                        () -> String.format("(%s) Exception validating credentials on %s with login '%s'",
+                                sendRequestTraceId.get(),
+                                getApiUrl(),
+                                getLogin()));
+                return Boolean.FALSE;
+            }
+        });
     }
 
     /**
@@ -188,7 +204,7 @@ public HttpConnector getConnector() {
         }
 
         LOGGER.warning(
-                "HttpConnector and getConnector() are deprecated. " + "Please file an issue describing your use case.");
+                "HttpConnector and getConnector() are deprecated. Please file an issue describing your use case.");
         return (HttpConnector) connector;
     }
 
@@ -262,27 +278,35 @@ String getEncodedAuthorization() throws IOException {
      */
     @Nonnull
     GHRateLimit getRateLimit(@Nonnull RateLimitTarget rateLimitTarget) throws IOException {
-        GHRateLimit result;
-        try {
-            GitHubRequest request = GitHubRequest.newBuilder()
-                    .rateLimit(RateLimitTarget.NONE)
-                    .withApiUrl(getApiUrl())
-                    .withUrlPath("/rate_limit")
-                    .build();
-            result = this
-                    .sendRequest(request,
-                            (connectorResponse) -> GitHubResponse.parseBody(connectorResponse, JsonRateLimit.class))
-                    .body().resources;
-        } catch (FileNotFoundException e) {
-            // For some versions of GitHub Enterprise, the rate_limit endpoint returns a 404.
-            LOGGER.log(FINE, "/rate_limit returned 404 Not Found.");
-
-            // However some newer versions of GHE include rate limit header information
-            // If the header info is missing and the endpoint returns 404, fill the rate limit
-            // with unknown
-            result = GHRateLimit.fromRecord(GHRateLimit.UnknownLimitRecord.current(), rateLimitTarget);
-        }
-        return updateRateLimit(result);
+        // Even when explicitly asking for rate limit, restrict to sane query frequency
+        // return cached value if available
+        GHRateLimit output = sanityCachedRateLimit.get(
+                (currentValue) -> currentValue == null || currentValue.getRecord(rateLimitTarget).isExpired(),
+                () -> {
+                    GHRateLimit result;
+                    try {
+                        final GitHubRequest request = GitHubRequest.newBuilder()
+                                .rateLimit(RateLimitTarget.NONE)
+                                .withApiUrl(getApiUrl())
+                                .withUrlPath("/rate_limit")
+                                .build();
+                        result = this
+                                .sendRequest(request,
+                                        (connectorResponse) -> GitHubResponse.parseBody(connectorResponse,
+                                                JsonRateLimit.class))
+                                .body().resources;
+                    } catch (FileNotFoundException e) {
+                        // For some versions of GitHub Enterprise, the rate_limit endpoint returns a 404.
+                        LOGGER.log(FINE, "(%s) /rate_limit returned 404 Not Found.", sendRequestTraceId.get());
+
+                        // However some newer versions of GHE include rate limit header information
+                        // If the header info is missing and the endpoint returns 404, fill the rate limit
+                        // with unknown
+                        result = GHRateLimit.fromRecord(GHRateLimit.UnknownLimitRecord.current(), rateLimitTarget);
+                    }
+                    return result;
+                });
+        return updateRateLimit(output);
     }
 
     /**
@@ -421,7 +445,13 @@ public <T> GitHubResponse<T> sendRequest(@Nonnull GitHubRequest.Builder<?> build
     @Nonnull
     public <T> GitHubResponse<T> sendRequest(GitHubRequest request, @CheckForNull BodyHandler<T> handler)
             throws IOException {
-        int retries = CONNECTION_ERROR_RETRIES;
+        // WARNING: This is an unsupported environment variable.
+        // The GitHubClient class is internal and may change at any time.
+        int retryCount = Math.max(DEFAULT_CONNECTION_ERROR_RETRIES,
+                Integer.getInteger(GitHubClient.class.getName() + ".retryCount", DEFAULT_CONNECTION_ERROR_RETRIES));
+
+        int retries = retryCount;
+        sendRequestTraceId.set(Integer.toHexString(request.hashCode()));
         GitHubConnectorRequest connectorRequest = prepareConnectorRequest(request);
         do {
             GitHubConnectorResponse connectorResponse = null;
@@ -432,6 +462,7 @@ public <T> GitHubResponse<T> sendRequest(GitHubRequest request, @CheckForNull Bo
                 logResponse(connectorResponse);
                 noteRateLimit(request.rateLimitTarget(), connectorResponse);
                 detectKnownErrors(connectorResponse, request, handler != null);
+                logResponseBody(connectorResponse);
                 return createResponse(connectorResponse, handler);
             } catch (RetryRequestException e) {
                 // retry requested by requested by error handler (rate limit handler for example)
@@ -441,7 +472,7 @@ public <T> GitHubResponse<T> sendRequest(GitHubRequest request, @CheckForNull Bo
             } catch (SocketException | SocketTimeoutException | SSLHandshakeException e) {
                 // These transient errors thrown by HttpURLConnection
                 if (retries > 0) {
-                    logRetryConnectionError(e, request.url(), retries);
+                    logRetryConnectionError(e, connectorRequest.url(), retries);
                     continue;
                 }
                 throw interpretApiError(e, connectorRequest, connectorResponse);
@@ -537,22 +568,31 @@ private GitHubConnectorRequest prepareConnectorRequest(GitHubRequest request) th
 
     private void logRequest(@Nonnull final GitHubConnectorRequest request) {
         LOGGER.log(FINE,
-                () -> String.format("(%s) GitHub API request [%s]: %s",
-                        Integer.toHexString(request.hashCode()),
-                        (getLogin() == null ? "anonymous" : getLogin()),
-                        (request.method() + " " + request.url().toString())));
+                () -> String.format("(%s) GitHub API request: %s %s",
+                        sendRequestTraceId.get(),
+                        request.method(),
+                        request.url().toString()));
     }
 
     private void logResponse(@Nonnull final GitHubConnectorResponse response) {
-        LOGGER.log(FINE, () -> {
+        LOGGER.log(FINER, () -> {
+            return String.format("(%s) GitHub API response: %s",
+                    sendRequestTraceId.get(),
+                    response.request().url().toString(),
+                    response.statusCode());
+        });
+    }
+
+    private void logResponseBody(@Nonnull final GitHubConnectorResponse response) {
+        LOGGER.log(FINEST, () -> {
+            String body;
             try {
-                return String.format("(%s) GitHub API response [%s]: %s",
-                        Integer.toHexString(response.request().hashCode()),
-                        (getLogin() == null ? "anonymous" : getLogin()),
-                        (response.statusCode() + " " + GitHubResponse.getBodyAsString(response)));
-            } catch (IOException e) {
-                throw new RuntimeException(e);
+                body = GitHubResponse.getBodyAsString(response);
+            } catch (Throwable e) {
+                body = "Error reading response body";
             }
+            return String.format("(%s) GitHub API response body: %s", sendRequestTraceId.get(), body);
+
         });
     }
 
@@ -581,8 +621,9 @@ private static boolean shouldIgnoreBody(@Nonnull GitHubConnectorResponse connect
             // workflow run cancellation - See https://docs.github.com/en/rest/reference/actions#cancel-a-workflow-run
 
             LOGGER.log(FINE,
-                    "Received HTTP_ACCEPTED(202) from " + connectorResponse.request().url().toString()
-                            + " . Please try again in 5 seconds.");
+                    () -> String.format("(%s) Received HTTP_ACCEPTED(202) from %s. Please try again in 5 seconds.",
+                            sendRequestTraceId.get(),
+                            connectorResponse.request().url().toString()));
             return true;
         } else {
             return false;
@@ -632,11 +673,29 @@ private static IOException interpretApiError(IOException e,
 
     private static void logRetryConnectionError(IOException e, URL url, int retries) throws IOException {
         // There are a range of connection errors where we want to wait a moment and just automatically retry
+
+        // WARNING: These are unsupported environment variables.
+        // The GitHubClient class is internal and may change at any time.
+        int minRetryInterval = Math.max(DEFAULT_MINIMUM_RETRY_MILLIS,
+                Integer.getInteger(GitHubClient.class.getName() + ".minRetryInterval", DEFAULT_MINIMUM_RETRY_MILLIS));
+        int maxRetryInterval = Math.max(DEFAULT_MAXIMUM_RETRY_MILLIS,
+                Integer.getInteger(GitHubClient.class.getName() + ".maxRetryInterval", DEFAULT_MAXIMUM_RETRY_MILLIS));
+
+        long sleepTime = maxRetryInterval <= minRetryInterval
+                ? minRetryInterval
+                : ThreadLocalRandom.current().nextLong(minRetryInterval, maxRetryInterval);
+
         LOGGER.log(INFO,
-                e.getMessage() + " while connecting to " + url + ". Sleeping " + GitHubClient.retryTimeoutMillis
-                        + " milliseconds before retrying... ; will try " + retries + " more time(s)");
+                () -> String.format(
+                        "(%s) %s while connecting to %s: '%s'. Sleeping %d milliseconds before retrying (%d retries remaining)",
+                        sendRequestTraceId.get(),
+                        e.getClass().toString(),
+                        url.toString(),
+                        e.getMessage(),
+                        sleepTime,
+                        retries));
         try {
-            Thread.sleep(GitHubClient.retryTimeoutMillis);
+            Thread.sleep(sleepTime);
         } catch (InterruptedException ie) {
             throw (IOException) new InterruptedIOException().initCause(e);
         }
@@ -658,8 +717,10 @@ private void detectInvalidCached404Response(GitHubConnectorResponse connectorRes
                 && connectorResponse.header("ETag") != null
                 && !Objects.equals(connectorResponse.request().header("Cache-Control"), "no-cache")) {
             LOGGER.log(FINE,
-                    "Encountered GitHub invalid cached 404 from " + connectorResponse.request().url()
-                            + ". Retrying with \"Cache-Control\"=\"no-cache\"...");
+                    () -> String.format(
+                            "(%s) Encountered GitHub invalid cached 404 from %s. Retrying with \"Cache-Control\"=\"no-cache\"...",
+                            sendRequestTraceId.get(),
+                            connectorResponse.request().url()));
             // Setting "Cache-Control" to "no-cache" stops the cache from supplying
             // "If-Modified-Since" or "If-None-Match" values.
             // This makes GitHub give us current data (not incorrectly cached data)
@@ -677,7 +738,10 @@ private void noteRateLimit(@Nonnull RateLimitTarget rateLimitTarget,
             GHRateLimit.Record observed = new GHRateLimit.Record(limit, remaining, reset, connectorResponse);
             updateRateLimit(GHRateLimit.fromRecord(observed, rateLimitTarget));
         } catch (NumberFormatException e) {
-            LOGGER.log(FINEST, "Missing or malformed X-RateLimit header: ", e);
+            LOGGER.log(FINER,
+                    () -> String.format("(%s) Missing or malformed X-RateLimit header: %s",
+                            sendRequestTraceId.get(),
+                            e.getMessage()));
         }
     }