Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: add client logging with slf4j #1586

Open
wants to merge 25 commits into
base: main
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from 10 commits
Commits
Show all changes
25 commits
Select commit Hold shift + click to select a range
c38282b
add slf4j and other test dep. add logging utils. add logging to req/r…
zhumin8 Dec 5, 2024
3f30267
remove JUL wrapper as fallback condition. Other test setups.
zhumin8 Dec 5, 2024
35d9a75
remove unused LoggingInterceptor.
zhumin8 Dec 5, 2024
a63d6fe
revert unintential change to test. add comments.
zhumin8 Dec 5, 2024
83329e7
remove public from LoggingUtils.
zhumin8 Dec 5, 2024
6a5d3d3
downgrade logback and remove unused.
zhumin8 Dec 5, 2024
930d0aa
put logging inside try-catch block to avoid crashing for logging errors.
zhumin8 Dec 5, 2024
44f3de8
simplify logic for getLogger. remove unused argLine for maven-surefir…
zhumin8 Dec 5, 2024
598d5b9
logging util class refactor.
zhumin8 Dec 5, 2024
445fe08
fix test setup timing issue.
zhumin8 Dec 5, 2024
a7f5a5e
add tests. feedback. minor cleanups.
zhumin8 Dec 7, 2024
8bc1ae7
TestAppender change to per test. add LoggingTest.
zhumin8 Dec 7, 2024
bde6ede
update messages.
zhumin8 Dec 9, 2024
7c89c3f
test setup - try use env for all test in ci.
zhumin8 Dec 10, 2024
6da450d
add env set to sonar test.
zhumin8 Dec 10, 2024
9e20be9
duplicate fields to log in message. add tests.
zhumin8 Dec 10, 2024
db99e70
add tests.
zhumin8 Dec 10, 2024
68307fc
minor cleanup and comment.
zhumin8 Dec 10, 2024
4202902
fix add env to sonar ci.
zhumin8 Dec 10, 2024
cfbe873
add log env to integration in build.sh
zhumin8 Dec 10, 2024
858b725
deps: add gson explicitly. move gson and slf4j-api version to parent …
zhumin8 Dec 10, 2024
fb8889a
deps: explicitly declare org.hamcrest:hamcrest-core:test
zhumin8 Dec 10, 2024
15d3016
update logging messages to rm 'auth'.
zhumin8 Dec 10, 2024
c2a8d76
make sensitive key comparison case insensitive.
zhumin8 Dec 11, 2024
6485526
extract env var name.
zhumin8 Dec 11, 2024
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -92,6 +92,8 @@ public class ComputeEngineCredentials extends GoogleCredentials
static final Duration COMPUTE_REFRESH_MARGIN = Duration.ofMinutes(3).plusSeconds(45);

private static final Logger LOGGER = Logger.getLogger(ComputeEngineCredentials.class.getName());
private static final org.slf4j.Logger SLF4JLOGGER =
LoggingConfigs.getLogger(ComputeEngineCredentials.class);
lqiu96 marked this conversation as resolved.
Show resolved Hide resolved

static final String DEFAULT_METADATA_SERVER_URL = "http://metadata.google.internal";

Expand Down Expand Up @@ -296,11 +298,14 @@ public AccessToken refreshAccessToken() throws IOException {
throw new IOException("Empty content from metadata token server request.");
}
GenericData responseData = response.parseAs(GenericData.class);
LoggingUtils.logGenericData(
responseData, SLF4JLOGGER, "Auth response from refresh access token payload.");
String accessToken =
OAuth2Utils.validateString(responseData, "access_token", PARSE_ERROR_PREFIX);
int expiresInSeconds =
OAuth2Utils.validateInt32(responseData, "expires_in", PARSE_ERROR_PREFIX);
long expiresAtMilliseconds = clock.currentTimeMillis() + expiresInSeconds * 1000;

return new AccessToken(accessToken, new Date(expiresAtMilliseconds));
}

Expand Down Expand Up @@ -361,7 +366,9 @@ private HttpResponse getMetadataResponse(
request.setThrowExceptionOnExecuteError(false);
HttpResponse response;
try {
LoggingUtils.logRequest(request, SLF4JLOGGER, "auth get metadata sending request.");
response = request.execute();
LoggingUtils.logResponse(response, SLF4JLOGGER, "auth get metadata received response.");
lqiu96 marked this conversation as resolved.
Show resolved Hide resolved
} catch (UnknownHostException exception) {
throw new IOException(
"ComputeEngineCredentials cannot find the metadata server. This is"
Expand Down Expand Up @@ -461,7 +468,10 @@ private static boolean pingComputeEngineMetadata(
request,
MetricsUtils.getGoogleCredentialsMetricsHeader(
RequestType.METADATA_SERVER_PING, CredentialTypeForMetrics.DO_NOT_SEND));

LoggingUtils.logRequest(request, SLF4JLOGGER, "auth pin MDS.");
HttpResponse response = request.execute();
LoggingUtils.logResponse(response, SLF4JLOGGER, "auth received response from MDS.");
lqiu96 marked this conversation as resolved.
Show resolved Hide resolved
try {
// Internet providers can return a generic response to all requests, so it is necessary
// to check that metadata header is present also.
Expand Down Expand Up @@ -633,6 +643,8 @@ private String getDefaultServiceAccount() throws IOException {
throw new IOException("Empty content from metadata token server request.");
}
GenericData responseData = response.parseAs(GenericData.class);
LoggingUtils.logGenericData(
responseData, SLF4JLOGGER, "Auth get default service account payload.");
Map<String, Object> defaultAccount =
OAuth2Utils.validateMap(responseData, "default", PARSE_ERROR_ACCOUNT);
return OAuth2Utils.validateString(defaultAccount, "email", PARSE_ERROR_ACCOUNT);
Expand Down
9 changes: 9 additions & 0 deletions oauth2_http/java/com/google/auth/oauth2/IamUtils.java
Original file line number Diff line number Diff line change
Expand Up @@ -56,6 +56,7 @@
import java.util.HashSet;
import java.util.Map;
import java.util.Set;
import org.slf4j.Logger;

/**
* This internal class provides shared utilities for interacting with the IAM API for common
Expand All @@ -68,6 +69,7 @@ class IamUtils {
"https://iamcredentials.googleapis.com/v1/projects/-/serviceAccounts/%s:generateIdToken";
private static final String PARSE_ERROR_MESSAGE = "Error parsing error message response. ";
private static final String PARSE_ERROR_SIGNATURE = "Error parsing signature response. ";
private static final Logger LOGGER = LoggingConfigs.getLogger(IamUtils.class);

// Following guidance for IAM retries:
// https://cloud.google.com/iam/docs/retry-strategy#errors-to-retry
Expand Down Expand Up @@ -142,7 +144,9 @@ private static String getSignature(
IamUtils.IAM_RETRYABLE_STATUS_CODES.contains(response.getStatusCode())));
request.setIOExceptionHandler(new HttpBackOffIOExceptionHandler(backoff));

LoggingUtils.logRequest(request, LOGGER, "auth sending request to get signature.");
HttpResponse response = request.execute();
LoggingUtils.logResponse(response, LOGGER, "auth received response for signature.");
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: Could the message to be more descriptive? i.e. Signature to sign the blob or something that better describes this

int statusCode = response.getStatusCode();
if (statusCode >= 400 && statusCode < HttpStatusCodes.STATUS_CODE_SERVER_ERROR) {
GenericData responseError = response.parseAs(GenericData.class);
Expand All @@ -169,6 +173,7 @@ private static String getSignature(
}

GenericData responseData = response.parseAs(GenericData.class);
LoggingUtils.logGenericData(responseData, LOGGER, "Auth response payload.");
lqiu96 marked this conversation as resolved.
Show resolved Hide resolved
return OAuth2Utils.validateString(responseData, "signedBlob", PARSE_ERROR_SIGNATURE);
}

Expand Down Expand Up @@ -220,7 +225,10 @@ static IdToken getIdToken(
MetricsUtils.getGoogleCredentialsMetricsHeader(
RequestType.ID_TOKEN_REQUEST, credentialTypeForMetrics));

LoggingUtils.logRequest(request, LOGGER, "auth sending request to get id token.");
HttpResponse response = request.execute();

LoggingUtils.logResponse(response, LOGGER, "auth received response for id token.");
int statusCode = response.getStatusCode();
if (statusCode >= 400 && statusCode < HttpStatusCodes.STATUS_CODE_SERVER_ERROR) {
GenericData responseError = response.parseAs(GenericData.class);
Expand All @@ -245,6 +253,7 @@ static IdToken getIdToken(
}

GenericJson responseData = response.parseAs(GenericJson.class);
LoggingUtils.logGenericData(responseData, LOGGER, "response data payload.");
String rawToken = OAuth2Utils.validateString(responseData, "token", PARSE_ERROR_MESSAGE);
return IdToken.create(rawToken);
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -65,6 +65,7 @@
import java.util.List;
import java.util.Map;
import java.util.Objects;
import org.slf4j.Logger;

/**
* ImpersonatedCredentials allowing credentials issued to a user or service account to impersonate
Expand Down Expand Up @@ -110,6 +111,7 @@ public class ImpersonatedCredentials extends GoogleCredentials
private int lifetime;
private String iamEndpointOverride;
private final String transportFactoryClassName;
private static final Logger LOGGER = LoggingConfigs.getLogger(ImpersonatedCredentials.class);

private transient HttpTransportFactory transportFactory;

Expand Down Expand Up @@ -546,12 +548,15 @@ public AccessToken refreshAccessToken() throws IOException {

HttpResponse response = null;
try {
LoggingUtils.logRequest(request, LOGGER, "auth sending refresh access token request.");
response = request.execute();
LoggingUtils.logResponse(response, LOGGER, "auth received response.");
} catch (IOException e) {
throw new IOException("Error requesting access token", e);
}

GenericData responseData = response.parseAs(GenericData.class);
LoggingUtils.logGenericData(responseData, LOGGER, "Auth response payload.");
response.disconnect();

String accessToken =
Expand Down
50 changes: 50 additions & 0 deletions oauth2_http/java/com/google/auth/oauth2/LoggingConfigs.java
Original file line number Diff line number Diff line change
@@ -0,0 +1,50 @@
package com.google.auth.oauth2;

import org.slf4j.ILoggerFactory;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

class LoggingConfigs {

private static EnvironmentProvider environmentProvider = SystemEnvironmentProvider.getInstance();
private static final Logger NO_OP_LOGGER = org.slf4j.helpers.NOPLogger.NOP_LOGGER;
private static boolean loggingEnabled = isLoggingEnabled();
// expose this setter only for testing purposes
static void setEnvironmentProvider(EnvironmentProvider provider) {
environmentProvider = provider;
// Recalculate LOGGING_ENABLED after setting the new provider
loggingEnabled = isLoggingEnabled();
}
lqiu96 marked this conversation as resolved.
Show resolved Hide resolved

private LoggingConfigs() {}

static Logger getLogger(Class<?> clazz) {
return getLogger(clazz, new DefaultLoggerFactoryProvider());
}

// constructor with LoggerFactoryProvider to make testing easier
static Logger getLogger(Class<?> clazz, LoggerFactoryProvider factoryProvider) {
if (loggingEnabled) {
return factoryProvider.getLoggerFactory().getLogger(clazz.getName());
} else {
// use SLF4j's NOP logger regardless of bindings
return NO_OP_LOGGER;
}
lqiu96 marked this conversation as resolved.
Show resolved Hide resolved
}

static boolean isLoggingEnabled() {
String enableLogging = environmentProvider.getEnv("GOOGLE_SDK_JAVA_LOGGING");
lqiu96 marked this conversation as resolved.
Show resolved Hide resolved
return "true".equalsIgnoreCase(enableLogging);
}

interface LoggerFactoryProvider {
ILoggerFactory getLoggerFactory();
}

static class DefaultLoggerFactoryProvider implements LoggerFactoryProvider {
@Override
public ILoggerFactory getLoggerFactory() {
return LoggerFactory.getILoggerFactory();
}
}
}
155 changes: 155 additions & 0 deletions oauth2_http/java/com/google/auth/oauth2/LoggingUtils.java
Original file line number Diff line number Diff line change
@@ -0,0 +1,155 @@
package com.google.auth.oauth2;

import com.google.api.client.http.HttpRequest;
import com.google.api.client.http.HttpResponse;
import com.google.api.client.http.UrlEncodedContent;
import com.google.api.client.util.GenericData;
import java.nio.charset.StandardCharsets;
import java.security.MessageDigest;
import java.security.NoSuchAlgorithmException;
import java.util.HashMap;
import java.util.Map;
import org.slf4j.Logger;
import org.slf4j.MDC;

class LoggingUtils {

private LoggingUtils() {}

static void logWithMDC(
Logger logger, org.slf4j.event.Level level, Map<String, String> contextMap, String message) {
contextMap.forEach(MDC::put);
switch (level) {
case TRACE:
logger.trace(message);
break;
case DEBUG:
logger.debug(message);
break;
case INFO:
logger.info(message);
break;
case WARN:
logger.warn(message);
break;
case ERROR:
logger.error(message);
break;
default:
logger.info(message);
// Default to INFO level
}
MDC.clear();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why does this need to be cleared?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

MDC carries contextual information in log messages. It is tied to thread, and is safer to clear it to avoid it be carried over to other log entries.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I see. Can you add that as a comment? Or a link to a guide that tells us clear it so future readers?

}

static void logRequest(HttpRequest request, Logger logger, String message) {
if (logger.isInfoEnabled()) {
try {
Map<String, String> loggingDataMap = new HashMap<>();
loggingDataMap.put("request.method", request.getRequestMethod());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it would be good to duplicate information like request.method and request.url in message instead of always relying on MDC, as we discussed yesterday. It would be great if we can make this change in this release. However, if not, it should not be a blocker either, as adding these info later is not a breaking change.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's already done. (9e20be9)
It is verified in LoggingTest (here you can see the message is parsed then verified. The test is not extensive in verifying information. )

loggingDataMap.put("request.url", request.getUrl().toString());

Map<String, Object> headers = new HashMap<>();
request
.getHeaders()
.forEach(
(key, val) -> {
if ("authorization".equals(key)) {
lqiu96 marked this conversation as resolved.
Show resolved Hide resolved
String hashedVal = calculateSHA256Hash(String.valueOf(val));
headers.put(key, hashedVal);
} else {
headers.put(key, val);
}
});
loggingDataMap.put("request.headers", headers.toString());

if (request.getContent() != null && logger.isDebugEnabled()) {
// are payload always GenericData? If so, can parse and store in json
GenericData data = (GenericData) ((UrlEncodedContent) request.getContent()).getData();

Map<String, String> contextMap = parseGenericData(data);
loggingDataMap.put("request.payload", contextMap.toString());

logWithMDC(logger, org.slf4j.event.Level.DEBUG, loggingDataMap, message);
} else {

logWithMDC(logger, org.slf4j.event.Level.INFO, loggingDataMap, message);
}
} catch (Exception e) {
logger.error("Error logging request: ", e);
}
}
}

static void logResponse(HttpResponse response, Logger logger, String message) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In general, I think we should not try to call these methods if logging is not enabled due to performance concerns, similar to the comment in sdk-platform-java.

if (logger.isInfoEnabled()) {
try {
Map<String, String> responseLogDataMap = new HashMap<>();
responseLogDataMap.put("response.status", String.valueOf(response.getStatusCode()));
responseLogDataMap.put("response.status.message", response.getStatusMessage());

Map<String, Object> headers = new HashMap<>();
response.getHeaders().forEach((key, val) -> headers.put(key, val));
responseLogDataMap.put("response.headers", headers.toString());
logWithMDC(logger, org.slf4j.event.Level.INFO, responseLogDataMap, message);
} catch (Exception e) {

logger.error("Error logging response: ", e);
}
}
}

static void logGenericData(GenericData genericData, Logger logger, String message) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: Can we change this to be something like logResponsePayload and parseResponsePayload so it's clearer as to what it's doing?

if (logger.isDebugEnabled()) {
lqiu96 marked this conversation as resolved.
Show resolved Hide resolved
try {

Map<String, String> contextMap = parseGenericData(genericData);
logWithMDC(logger, org.slf4j.event.Level.DEBUG, contextMap, message);
} catch (Exception e) {
logger.error("Error logging GenericData: ", e);
}
}
}

private static Map<String, String> parseGenericData(GenericData genericData) {
lqiu96 marked this conversation as resolved.
Show resolved Hide resolved
Map<String, String> contextMap = new HashMap<>();
genericData.forEach(
(key, val) -> {
if ("token".equals(key)
|| "assertion".equals(key)
|| "access_token".equals(key)
|| "client_secret".equals(key)
|| "refresh_token".equals(key)) {
lqiu96 marked this conversation as resolved.
Show resolved Hide resolved
String secretString = String.valueOf(val);
String hashedVal = calculateSHA256Hash(secretString);
contextMap.put(key, hashedVal);
} else {
contextMap.put(key, val.toString());
}
});
return contextMap;
}

private static String calculateSHA256Hash(String data) {
try {
MessageDigest digest = MessageDigest.getInstance("SHA-256");
byte[] inputBytes = data.getBytes(StandardCharsets.UTF_8);
byte[] hashBytes = digest.digest(inputBytes);
return bytesToHex(hashBytes);
} catch (NoSuchAlgorithmException e) {
return "Error calculating SHA-256 hash."; // do not fail for logging failures
}
}

private static String bytesToHex(byte[] hash) {
StringBuilder hexString = new StringBuilder(2 * hash.length);
for (byte b : hash) {
String hex = Integer.toHexString(0xff & b);
if (hex.length() == 1) {
hexString.append('0');
}
hexString.append(hex);
}
return hexString.toString();
}
}
Loading
Loading