diff --git a/pom.xml b/pom.xml index bd9bb94e04..a7bf493c16 100644 --- a/pom.xml +++ b/pom.xml @@ -697,6 +697,10 @@ false src/test/resources/slow-or-flaky-tests.txt @{jacoco.surefire.argLine} ${surefire.argLine} -Dtest.github.connector=httpclient + + + src/test/resources/test-trace-logging.properties + @@ -710,6 +714,10 @@ false src/test/resources/slow-or-flaky-tests.txt @{jacoco.surefire.argLine} ${surefire.argLine} -Dtest.github.connector=urlconnection + + + src/test/resources/test-trace-logging.properties + @@ -721,11 +729,25 @@ ${project.basedir}/target/github-api-${project.version}.jar 2 - src/test/resources/slow-or-flaky-tests.txt + + slow-or-flaky-test-tracing + integration-test + + test + + + ${project.basedir}/target/github-api-${project.version}.jar + 2 + src/test/resources/slow-or-flaky-tests.txt + + + src/test/resources/test-trace-logging.properties + + + jwt0.11.x-test diff --git a/src/main/java/org/kohsuke/github/GitHub.java b/src/main/java/org/kohsuke/github/GitHub.java index e0d01bcc6f..8bcd93b85f 100644 --- a/src/main/java/org/kohsuke/github/GitHub.java +++ b/src/main/java/org/kohsuke/github/GitHub.java @@ -70,6 +70,9 @@ public class GitHub { private final ConcurrentMap users; private final ConcurrentMap orgs; + @Nonnull + private final GitHubSanityCachedValue sanityCachedMeta = new GitHubSanityCachedValue<>(); + /** * Creates a client API root object. * @@ -1253,7 +1256,7 @@ public boolean isCredentialValid() { * @see Get Meta */ public GHMeta getMeta() throws IOException { - return createRequest().withUrlPath("/meta").fetch(GHMeta.class); + return this.sanityCachedMeta.get(() -> createRequest().withUrlPath("/meta").fetch(GHMeta.class)); } /** diff --git a/src/main/java/org/kohsuke/github/GitHubClient.java b/src/main/java/org/kohsuke/github/GitHubClient.java index cd18100d65..09160fc119 100644 --- a/src/main/java/org/kohsuke/github/GitHubClient.java +++ b/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 sendRequestTraceId = new ThreadLocal<>(); // Cache of myself object. private final String apiUrl; @@ -64,6 +69,12 @@ class GitHubClient { @Nonnull private final AtomicReference rateLimit = new AtomicReference<>(GHRateLimit.DEFAULT); + @Nonnull + private final GitHubSanityCachedValue sanityCachedRateLimit = new GitHubSanityCachedValue<>(); + + @Nonnull + private GitHubSanityCachedValue 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 fetch(Class 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 GitHubResponse sendRequest(@Nonnull GitHubRequest.Builder build @Nonnull public GitHubResponse sendRequest(GitHubRequest request, @CheckForNull BodyHandler 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 GitHubResponse 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 GitHubResponse 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())); } } diff --git a/src/main/java/org/kohsuke/github/GitHubSanityCachedValue.java b/src/main/java/org/kohsuke/github/GitHubSanityCachedValue.java new file mode 100644 index 0000000000..8b5de1874b --- /dev/null +++ b/src/main/java/org/kohsuke/github/GitHubSanityCachedValue.java @@ -0,0 +1,50 @@ +package org.kohsuke.github; + +import org.kohsuke.github.function.SupplierThrows; + +import java.time.Instant; +import java.util.function.Function; + +/** + * GitHubSanityCachedValue limits queries for a particular value to once per second. + */ +class GitHubSanityCachedValue { + + private final Object lock = new Object(); + private long lastQueriedAtEpochSeconds = 0; + private T lastResult = null; + + /** + * Gets the value from the cache or calls the supplier if the cache is empty or out of date. + * + * @param query + * a supplier the returns an updated value. Only called if the cache is empty or out of date. + * @return the value from the cache or the value returned from the supplier. + * @throws E + * the exception thrown by the supplier if it fails. + */ + T get(SupplierThrows query) throws E { + return get((value) -> Boolean.FALSE, query); + } + + /** + * Gets the value from the cache or calls the supplier if the cache is empty or out of date. + * + * @param isExpired + * a supplier that returns true if the cached value is no longer valid. + * @param query + * a supplier the returns an updated value. Only called if the cache is empty or out of date. + * @return the value from the cache or the value returned from the supplier. + * @throws E + * the exception thrown by the supplier if it fails. + */ + T get(Function isExpired, SupplierThrows query) throws E { + synchronized (lock) { + if (Instant.now().getEpochSecond() > lastQueriedAtEpochSeconds || isExpired.apply(lastResult)) { + lastResult = query.get(); + lastQueriedAtEpochSeconds = Instant.now().getEpochSecond(); + } + } + return lastResult; + } +} diff --git a/src/main/java/org/kohsuke/github/function/SupplierThrows.java b/src/main/java/org/kohsuke/github/function/SupplierThrows.java new file mode 100644 index 0000000000..ea906c61b3 --- /dev/null +++ b/src/main/java/org/kohsuke/github/function/SupplierThrows.java @@ -0,0 +1,21 @@ +package org.kohsuke.github.function; + +/** + * A functional interface, equivalent to {@link java.util.function.Supplier} but that allows throwing {@link Throwable} + * + * @param + * the type of output + * @param + * the type of error + */ +@FunctionalInterface +public interface SupplierThrows { + /** + * Get a value. + * + * @return the + * @throws E + * the exception that may be thrown + */ + T get() throws E; +} diff --git a/src/test/java/org/kohsuke/github/RequesterRetryTest.java b/src/test/java/org/kohsuke/github/RequesterRetryTest.java index 5a635c3a0f..7b88ce707f 100644 --- a/src/test/java/org/kohsuke/github/RequesterRetryTest.java +++ b/src/test/java/org/kohsuke/github/RequesterRetryTest.java @@ -178,8 +178,8 @@ public void testSocketConnectionAndRetry() throws Exception { } String capturedLog = getTestCapturedLog(); - assertThat(capturedLog.contains("will try 2 more time"), is(true)); - assertThat(capturedLog.contains("will try 1 more time"), is(true)); + assertThat(capturedLog, containsString("(2 retries remaining)")); + assertThat(capturedLog, containsString("(1 retries remaining)")); assertThat(this.mockGitHub.getRequestCount(), equalTo(baseRequestCount + 6)); } @@ -216,8 +216,8 @@ public void testSocketConnectionAndRetry_StatusCode() throws Exception { } String capturedLog = getTestCapturedLog(); - assertThat(capturedLog.contains("will try 2 more time"), is(true)); - assertThat(capturedLog.contains("will try 1 more time"), is(true)); + assertThat(capturedLog, containsString("(2 retries remaining)")); + assertThat(capturedLog, containsString("(1 retries remaining)")); assertThat(this.mockGitHub.getRequestCount(), equalTo(baseRequestCount + 6)); } @@ -275,8 +275,8 @@ public void testSocketConnectionAndRetry_Success() throws Exception { GHBranch branch = repo.getBranch("test/timeout"); assertThat(branch, notNullValue()); String capturedLog = getTestCapturedLog(); - assertThat(capturedLog.contains("will try 2 more time"), is(true)); - assertThat(capturedLog.contains("will try 1 more time"), is(true)); + assertThat(capturedLog, containsString("(2 retries remaining)")); + assertThat(capturedLog, containsString("(1 retries remaining)")); assertThat(this.mockGitHub.getRequestCount(), equalTo(baseRequestCount + 6)); } @@ -307,8 +307,7 @@ public void testResponseCodeFailureExceptions() throws Exception { assertThat(e.getCause(), instanceOf(IOException.class)); assertThat(e.getCause().getMessage(), is("Custom")); String capturedLog = getTestCapturedLog(); - assertThat(capturedLog.contains("will try 2 more time"), is(false)); - assertThat(capturedLog.contains("will try 1 more time"), is(false)); + assertThat(capturedLog, not(containsString("retries remaining"))); assertThat(this.mockGitHub.getRequestCount(), equalTo(baseRequestCount)); } @@ -328,8 +327,7 @@ public void testResponseCodeFailureExceptions() throws Exception { assertThat(e, instanceOf(FileNotFoundException.class)); assertThat(e.getMessage(), is("Custom")); String capturedLog = getTestCapturedLog(); - assertThat(capturedLog.contains("will try 2 more time"), is(false)); - assertThat(capturedLog.contains("will try 1 more time"), is(false)); + assertThat(capturedLog, not(containsString("retries remaining"))); assertThat(this.mockGitHub.getRequestCount(), equalTo(baseRequestCount)); } } @@ -360,8 +358,7 @@ public void testInputStreamFailureExceptions() throws Exception { assertThat(e.getCause(), instanceOf(IOException.class)); assertThat(e.getCause().getMessage(), is("Custom")); String capturedLog = getTestCapturedLog(); - assertThat(capturedLog.contains("will try 2 more time"), is(false)); - assertThat(capturedLog.contains("will try 1 more time"), is(false)); + assertThat(capturedLog, not(containsString("retries remaining"))); assertThat(this.mockGitHub.getRequestCount(), equalTo(baseRequestCount + 1)); } @@ -378,8 +375,7 @@ public void testInputStreamFailureExceptions() throws Exception { assertThat(e.getCause(), instanceOf(FileNotFoundException.class)); assertThat(e.getCause().getMessage(), containsString("hub4j-test-org-missing")); String capturedLog = getTestCapturedLog(); - assertThat(capturedLog.contains("will try 2 more time"), is(false)); - assertThat(capturedLog.contains("will try 1 more time"), is(false)); + assertThat(capturedLog, not(containsString("retries remaining"))); assertThat(this.mockGitHub.getRequestCount(), equalTo(baseRequestCount + 1)); } @@ -394,8 +390,7 @@ public void testInputStreamFailureExceptions() throws Exception { .fetchHttpStatusCode(), equalTo(404)); String capturedLog = getTestCapturedLog(); - assertThat(capturedLog.contains("will try 2 more time"), is(false)); - assertThat(capturedLog.contains("will try 1 more time"), is(false)); + assertThat(capturedLog, not(containsString("retries remaining"))); assertThat(this.mockGitHub.getRequestCount(), equalTo(baseRequestCount + 1)); } @@ -466,16 +461,16 @@ private void runConnectionExceptionTest(HttpConnector connector, int expectedReq baseRequestCount = this.mockGitHub.getRequestCount(); assertThat(this.gitHub.getOrganization(GITHUB_API_TEST_ORG), is(notNullValue())); String capturedLog = getTestCapturedLog(); - assertThat(capturedLog, containsString("will try 2 more time")); - assertThat(capturedLog, containsString("will try 1 more time")); + assertThat(capturedLog, containsString("(2 retries remaining)")); + assertThat(capturedLog, containsString("(1 retries remaining)")); assertThat(this.mockGitHub.getRequestCount(), equalTo(baseRequestCount + expectedRequestCount)); resetTestCapturedLog(); baseRequestCount = this.mockGitHub.getRequestCount(); this.gitHub.createRequest().withUrlPath("/orgs/" + GITHUB_API_TEST_ORG).send(); capturedLog = getTestCapturedLog(); - assertThat(capturedLog, containsString("will try 2 more time")); - assertThat(capturedLog, containsString("will try 1 more time")); + assertThat(capturedLog, containsString("(2 retries remaining)")); + assertThat(capturedLog, containsString("(1 retries remaining)")); assertThat(this.mockGitHub.getRequestCount(), equalTo(baseRequestCount + expectedRequestCount)); } @@ -492,13 +487,12 @@ private void runConnectionExceptionStatusCodeTest(HttpConnector connector, int e equalTo(200)); String capturedLog = getTestCapturedLog(); if (expectedRequestCount > 0) { - assertThat(capturedLog, containsString("will try 2 more time")); - assertThat(capturedLog, containsString("will try 1 more time")); + assertThat(capturedLog, containsString("(2 retries remaining)")); + assertThat(capturedLog, containsString("(1 retries remaining)")); assertThat(this.mockGitHub.getRequestCount(), equalTo(baseRequestCount + expectedRequestCount)); } else { // Success without retries - assertThat(capturedLog, not(containsString("will try 2 more time"))); - assertThat(capturedLog, not(containsString("will try 1 more time"))); + assertThat(capturedLog, not(containsString("retries remaining"))); assertThat(this.mockGitHub.getRequestCount(), equalTo(baseRequestCount + 1)); } } diff --git a/src/test/resources/test-trace-logging.properties b/src/test/resources/test-trace-logging.properties new file mode 100644 index 0000000000..8ce4376389 --- /dev/null +++ b/src/test/resources/test-trace-logging.properties @@ -0,0 +1,11 @@ +# Logs to console only +handlers=java.util.logging.FileHandler + +java.util.logging.FileHandler.pattern = target/surefire/test-trace-log%u-%g.txt +java.util.logging.FileHandler.level = FINEST +java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter + +# log level for package, this override global .level and handler level +# com.mkyong.level = WARNING +org.kohsuke.github.GitHubClient.level=FINEST +org.kohsuke.github.GitHub.level=FINEST \ No newline at end of file