Skip to content

Commit

Permalink
Add sanity caching and retry controls (#1744)
Browse files Browse the repository at this point in the history 
* Add sanity caching and retry controls

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

Co-authored-by: Fabien Thouny <3714318+KeepItSimpleStupid@users.noreply.github.com>

* Allow dynamic tuning of retries at runtime

* Add trace id to sendRequest logs

* Add trace log testing configs

* Cleanup test and do not run trace logging on slow tests

* Tweak to get greater coverage

---------

Co-authored-by: Fabien Thouny <3714318+KeepItSimpleStupid@users.noreply.github.com>
  • Loading branch information
@bitwiseman @KeepItSimpleStupid
bitwiseman and KeepItSimpleStupid authored Nov 22, 2023
1 parent 2062439 commit b2b3e1c
Show file tree
Hide file tree
Showing 7 changed files with 251 additions and 86 deletions.
26 changes: 24 additions & 2 deletions pom.xml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand All @@ -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>
Expand All @@ -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>
Expand Down
5 changes: 4 additions & 1 deletion src/main/java/org/kohsuke/github/GitHub.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*
Expand Down Expand Up @@ -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));
}

/**
Expand Down
182 changes: 123 additions & 59 deletions src/main/java/org/kohsuke/github/GitHubClient.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand Down Expand Up @@ -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;
Expand All @@ -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();
Expand Down Expand Up @@ -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;
}
});
}

/**
Expand All @@ -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;
}

Expand Down Expand Up @@ -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);
}

/**
Expand Down Expand Up @@ -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;
Expand All @@ -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)
Expand All @@ -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);
Expand Down Expand Up @@ -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);

});
}

Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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);
}
Expand All @@ -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)
Expand All @@ -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()));
}
}

Expand Down
Loading

0 comments on commit b2b3e1c

Please sign in to comment.