diff --git a/sdk/identity/azure-identity-extensions/src/main/java/com/azure/identity/extensions/implementation/credential/provider/DefaultTokenCredentialProvider.java b/sdk/identity/azure-identity-extensions/src/main/java/com/azure/identity/extensions/implementation/credential/provider/DefaultTokenCredentialProvider.java index 34831e5f5c2ef..4378c8ab8a94c 100644 --- a/sdk/identity/azure-identity-extensions/src/main/java/com/azure/identity/extensions/implementation/credential/provider/DefaultTokenCredentialProvider.java +++ b/sdk/identity/azure-identity-extensions/src/main/java/com/azure/identity/extensions/implementation/credential/provider/DefaultTokenCredentialProvider.java @@ -4,6 +4,8 @@ package com.azure.identity.extensions.implementation.credential.provider; import com.azure.core.credential.TokenCredential; +import com.azure.core.http.policy.HttpLogOptions; +import com.azure.core.util.HttpClientOptions; import com.azure.core.util.logging.ClientLogger; import com.azure.identity.ClientCertificateCredentialBuilder; import com.azure.identity.ClientSecretCredentialBuilder; @@ -107,9 +109,7 @@ && hasText(options.getPassword())) { LOGGER.verbose("Use the dac builder."); ExecutorService executorService = Executors.newFixedThreadPool(1, new ThreadFactory() { - private int count = 0; - @Override public Thread newThread(Runnable runnable) { return new Thread(runnable, "az-id-test-" + count++); @@ -120,7 +120,7 @@ public Thread newThread(Runnable runnable) { .authorityHost(authorityHost) .tenantId(tenantId) .managedIdentityClientId(clientId) - .executorService(executorService) + .executorService(executorService).enableAccountIdentifierLogging().addPolicy(new HttpDebugLoggingPolicy()) .build(); } diff --git a/sdk/identity/azure-identity-extensions/src/main/java/com/azure/identity/extensions/implementation/credential/provider/HttpDebugLoggingPolicy.java b/sdk/identity/azure-identity-extensions/src/main/java/com/azure/identity/extensions/implementation/credential/provider/HttpDebugLoggingPolicy.java new file mode 100644 index 0000000000000..76ebf78fbfac7 --- /dev/null +++ b/sdk/identity/azure-identity-extensions/src/main/java/com/azure/identity/extensions/implementation/credential/provider/HttpDebugLoggingPolicy.java @@ -0,0 +1,264 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +package com.azure.identity.extensions.implementation.credential.provider; + +import com.azure.core.http.ContentType; +import com.azure.core.http.HttpHeader; +import com.azure.core.http.HttpHeaders; +import com.azure.core.http.HttpPipelineCallContext; +import com.azure.core.http.HttpPipelineNextPolicy; +import com.azure.core.http.HttpRequest; +import com.azure.core.http.HttpResponse; +import com.azure.core.http.policy.HttpLoggingPolicy; +import com.azure.core.http.policy.HttpPipelinePolicy; +import com.azure.core.util.CoreUtils; +import com.fasterxml.jackson.databind.ObjectMapper; +import com.fasterxml.jackson.databind.SerializationFeature; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import reactor.core.publisher.Mono; + +import java.io.ByteArrayOutputStream; +import java.io.IOException; +import java.io.UnsupportedEncodingException; +import java.nio.ByteBuffer; +import java.nio.channels.Channels; +import java.nio.channels.WritableByteChannel; +import java.nio.charset.StandardCharsets; +import java.util.HashSet; +import java.util.Locale; +import java.util.Optional; +import java.util.Set; +import java.util.concurrent.TimeUnit; + +/** + * The pipeline policy that handles logging of HTTP requests and responses. + */ +public class HttpDebugLoggingPolicy implements HttpPipelinePolicy { + + private static final ObjectMapper PRETTY_PRINTER = new ObjectMapper().enable(SerializationFeature.INDENT_OUTPUT); + private static final String REDACTED_PLACEHOLDER = "REDACTED"; + private static final Set DISALLOWED_HEADER_NAMES = new HashSet<>(); + private static final boolean PRETTY_PRINT_BODY = true; + + /** + * Creates an HttpDebugLoggingPolicy with the given log configurations. + */ + public HttpDebugLoggingPolicy() { + DISALLOWED_HEADER_NAMES.add("authorization"); + } + + @Override + public Mono process(HttpPipelineCallContext context, HttpPipelineNextPolicy next) { + final Logger logger = LoggerFactory.getLogger((String) context.getData("caller-method").orElse("")); + final long startNs = System.nanoTime(); + + return logRequest(logger, context.getHttpRequest(), context.getData(HttpLoggingPolicy.RETRY_COUNT_CONTEXT)) + .then(next.process()) + .flatMap(response -> logResponse(logger, response, startNs)) + .doOnError(throwable -> logger.warn("<-- HTTP FAILED: ", throwable)); + } + + private Mono logRequest(final Logger logger, final HttpRequest request, + final Optional optionalRetryCount) { + if (!logger.isInfoEnabled()) { + return Mono.empty(); + } + + StringBuilder requestLogMessage = new StringBuilder(); + requestLogMessage.append("--> ") + .append(request.getHttpMethod()) + .append(" ") + .append(request.getUrl()) + .append(System.lineSeparator()); + + optionalRetryCount.ifPresent(o -> requestLogMessage.append("Try count: ") + .append(o) + .append(System.lineSeparator())); + + addHeadersToLogMessage(logger, request.getHeaders(), requestLogMessage); + + if (request.getBody() == null) { + requestLogMessage.append("(empty body)") + .append(System.lineSeparator()) + .append("--> END ") + .append(request.getHttpMethod()) + .append(System.lineSeparator()); + + return logAndReturn(logger, requestLogMessage, null); + } + + String contentType = request.getHeaders().getValue("Content-Type"); + long contentLength = getContentLength(logger, request.getHeaders()); + + if (shouldBodyBeLogged(contentType, contentLength)) { + ByteArrayOutputStream outputStream = new ByteArrayOutputStream((int) contentLength); + WritableByteChannel bodyContentChannel = Channels.newChannel(outputStream); + + // Add non-mutating operators to the data stream. + request.setBody( + request.getBody() + .flatMap(byteBuffer -> writeBufferToBodyStream(bodyContentChannel, byteBuffer)) + .doFinally(ignored -> { + requestLogMessage.append(contentLength) + .append("-byte body:") + .append(System.lineSeparator()) + .append(prettyPrintIfNeeded(logger, contentType, + convertStreamToString(outputStream, logger))) + .append(System.lineSeparator()) + .append("--> END ") + .append(request.getHttpMethod()) + .append(System.lineSeparator()); + + logger.info(requestLogMessage.toString()); + })); + + return Mono.empty(); + } else { + requestLogMessage.append(contentLength) + .append("-byte body: (content not logged)") + .append(System.lineSeparator()) + .append("--> END ") + .append(request.getHttpMethod()) + .append(System.lineSeparator()); + + return logAndReturn(logger, requestLogMessage, null); + } + } + + /* + * Logs thr HTTP response. + * + * @param logger Logger used to log the response. + * @param response HTTP response returned from Azure. + * @param startNs Nanosecond representation of when the request was sent. + * @return A Mono containing the HTTP response. + */ + private Mono logResponse(final Logger logger, final HttpResponse response, long startNs) { + if (!logger.isInfoEnabled()) { + return Mono.just(response); + } + + long tookMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNs); + + String contentLengthString = response.getHeaderValue("Content-Length"); + String bodySize = (CoreUtils.isNullOrEmpty(contentLengthString)) + ? "unknown-length body" + : contentLengthString + "-byte body"; + + StringBuilder responseLogMessage = new StringBuilder(); + responseLogMessage.append("<-- ") + .append(response.getStatusCode()) + .append(" ") + .append(response.getRequest().getUrl()) + .append(" (") + .append(tookMs) + .append(" ms, ") + .append(bodySize) + .append(")") + .append(System.lineSeparator()); + + addHeadersToLogMessage(logger, response.getHeaders(), responseLogMessage); + + String contentTypeHeader = response.getHeaderValue("Content-Type"); + long contentLength = getContentLength(logger, response.getHeaders()); + + if (shouldBodyBeLogged(contentTypeHeader, contentLength)) { + HttpResponse bufferedResponse = response.buffer(); + ByteArrayOutputStream outputStream = new ByteArrayOutputStream((int) contentLength); + WritableByteChannel bodyContentChannel = Channels.newChannel(outputStream); + return bufferedResponse.getBody() + .flatMap(byteBuffer -> writeBufferToBodyStream(bodyContentChannel, byteBuffer)) + .doFinally(ignored -> { + responseLogMessage.append("Response body:") + .append(System.lineSeparator()) + .append(prettyPrintIfNeeded(logger, contentTypeHeader, + convertStreamToString(outputStream, logger))) + .append(System.lineSeparator()) + .append("<-- END HTTP"); + + logger.info(responseLogMessage.toString()); + }).then(Mono.just(bufferedResponse)); + } else { + responseLogMessage.append("(body content not logged)") + .append(System.lineSeparator()) + .append("<-- END HTTP"); + + return logAndReturn(logger, responseLogMessage, response); + } + } + + private Mono logAndReturn(Logger logger, StringBuilder logMessageBuilder, T data) { + logger.info(logMessageBuilder.toString()); + return Mono.justOrEmpty(data); + } + + private void addHeadersToLogMessage(Logger logger, HttpHeaders headers, StringBuilder sb) { + for (HttpHeader header : headers) { + String headerName = header.getName(); + sb.append(headerName).append(":"); + if (!DISALLOWED_HEADER_NAMES.contains(headerName.toLowerCase(Locale.ROOT))) { + sb.append(header.getValue()); + } else { + sb.append(REDACTED_PLACEHOLDER); + } + sb.append(System.lineSeparator()); + } + } + + private String prettyPrintIfNeeded(Logger logger, String contentType, String body) { + String result = body; + if (PRETTY_PRINT_BODY && contentType != null + && (contentType.startsWith(ContentType.APPLICATION_JSON) || contentType.startsWith("text/json"))) { + try { + final Object deserialized = PRETTY_PRINTER.readTree(body); + result = PRETTY_PRINTER.writeValueAsString(deserialized); + } catch (Exception e) { + logger.warn("Failed to pretty print JSON: {}", e.getMessage()); + } + } + return result; + } + + private long getContentLength(Logger logger, HttpHeaders headers) { + long contentLength = 0; + + String contentLengthString = headers.getValue("Content-Length"); + if (CoreUtils.isNullOrEmpty(contentLengthString)) { + return contentLength; + } + + try { + contentLength = Long.parseLong(contentLengthString); + } catch (NumberFormatException | NullPointerException e) { + logger.warn("Could not parse the HTTP header content-length: '{}'.", + headers.getValue("content-length"), e); + } + + return contentLength; + } + + private boolean shouldBodyBeLogged(String contentTypeHeader, long contentLength) { + return !ContentType.APPLICATION_OCTET_STREAM.equalsIgnoreCase(contentTypeHeader) + && contentLength != 0; + } + + private static String convertStreamToString(ByteArrayOutputStream stream, Logger logger) { + try { + return stream.toString(StandardCharsets.UTF_8.name()); + } catch (UnsupportedEncodingException ex) { + logger.error(ex.toString()); + throw new RuntimeException(ex); + } + } + + private static Mono writeBufferToBodyStream(WritableByteChannel channel, ByteBuffer byteBuffer) { + try { + channel.write(byteBuffer.duplicate()); + return Mono.just(byteBuffer); + } catch (IOException ex) { + return Mono.error(ex); + } + } +} diff --git a/sdk/identity/azure-identity-extensions/src/main/java/com/azure/identity/extensions/implementation/template/AzureAuthenticationTemplate.java b/sdk/identity/azure-identity-extensions/src/main/java/com/azure/identity/extensions/implementation/template/AzureAuthenticationTemplate.java index ec6a4a1c993e1..489f6f5b7f008 100644 --- a/sdk/identity/azure-identity-extensions/src/main/java/com/azure/identity/extensions/implementation/template/AzureAuthenticationTemplate.java +++ b/sdk/identity/azure-identity-extensions/src/main/java/com/azure/identity/extensions/implementation/template/AzureAuthenticationTemplate.java @@ -126,7 +126,7 @@ TokenCredentialProvider getTokenCredentialProvider() { } Duration getBlockTimeout() { - return Duration.ofSeconds(30 * 4); + return Duration.ofSeconds(30 * 3); } AtomicBoolean getIsInitialized() { diff --git a/sdk/identity/azure-identity/pom.xml b/sdk/identity/azure-identity/pom.xml index 6d01a90111e55..30e72ac804678 100644 --- a/sdk/identity/azure-identity/pom.xml +++ b/sdk/identity/azure-identity/pom.xml @@ -6,7 +6,7 @@ com.azure azure-identity - 1.11.0-beta.1 + 1.10.0 Microsoft Azure client library for Identity This module contains client library for Microsoft Azure Identity. diff --git a/sdk/identity/azure-identity/src/main/java/com/azure/identity/implementation/IdentityClient.java b/sdk/identity/azure-identity/src/main/java/com/azure/identity/implementation/IdentityClient.java index 4a16b2a932931..2dc14f4eb2f39 100644 --- a/sdk/identity/azure-identity/src/main/java/com/azure/identity/implementation/IdentityClient.java +++ b/sdk/identity/azure-identity/src/main/java/com/azure/identity/implementation/IdentityClient.java @@ -953,9 +953,12 @@ private Mono authenticateToArcManagedIdentityEndpoint(String identi * @return a Publisher that emits an AccessToken */ public Mono authenticateWithExchangeToken(TokenRequestContext request) { - + LOGGER.verbose("wi check exec authenticateWithExchangeToken"); return clientAssertionAccessor.getValue() - .flatMap(assertionToken -> Mono.fromCallable(() -> authenticateWithExchangeTokenHelper(request, assertionToken))); + .flatMap(assertionToken -> Mono.fromCallable(() -> { + LOGGER.verbose("wi check exec from callable, assertionToken: " + assertionToken); + return authenticateWithExchangeTokenHelper(request, assertionToken); + })); } /** @@ -1289,14 +1292,17 @@ private boolean isADFSTenant() { Function> getWorkloadIdentityTokenProvider() { return appTokenProviderParameters -> { + LOGGER.verbose("wi check exec appTokenProvider"); TokenRequestContext trc = new TokenRequestContext() .setScopes(new ArrayList<>(appTokenProviderParameters.scopes)) .setClaims(appTokenProviderParameters.claims) .setTenantId(appTokenProviderParameters.tenantId); + LOGGER.verbose("wi check authenticateWithExchangeTokenSync"); Mono accessTokenAsync = authenticateWithExchangeToken(trc); - + LOGGER.verbose("wi check return mono token"); return accessTokenAsync.map(accessToken -> { + LOGGER.verbose("wi check access token returned: " + accessToken.getToken()); TokenProviderResult result = new TokenProviderResult(); result.setAccessToken(accessToken.getToken()); result.setTenantId(trc.getTenantId()); diff --git a/sdk/identity/azure-identity/src/main/java/com/azure/identity/implementation/IdentityClientBase.java b/sdk/identity/azure-identity/src/main/java/com/azure/identity/implementation/IdentityClientBase.java index 12f3430ddb4f7..40c1ac3c2c269 100644 --- a/sdk/identity/azure-identity/src/main/java/com/azure/identity/implementation/IdentityClientBase.java +++ b/sdk/identity/azure-identity/src/main/java/com/azure/identity/implementation/IdentityClientBase.java @@ -421,6 +421,7 @@ ConfidentialClientApplication getWorkloadIdentityConfidentialClient() { throw LOGGER.logExceptionAsWarning(new IllegalStateException(e)); } + LOGGER.log(LogLevel.VERBOSE, () -> "wi-check set appTokenProvider 1"); applicationBuilder.appTokenProvider(getWorkloadIdentityTokenProvider()); @@ -585,7 +586,7 @@ AccessToken getTokenFromAzureCLIAuthentication(StringBuilder azCommand) { } } - LOGGER.verbose("Azure CLI Authentication => A token response was received from Azure CLI, deserializing the" + log("Azure CLI Authentication => A token response was received from Azure CLI, deserializing the" + " response into an Access Token."); Map objectMap = SERIALIZER_ADAPTER.deserialize(processOutput, Map.class, SerializerEncoding.JSON); @@ -709,6 +710,9 @@ AccessToken getTokenFromAzureDeveloperCLIAuthentication(StringBuilder azdCommand } AccessToken authenticateWithExchangeTokenHelper(TokenRequestContext request, String assertionToken) throws IOException { + log("wi check start authenticateWithExchangeTokenHelper"); + log("wi check start authenticateWithExchangeTokenHelper params: " + tenantId); + String authorityUrl = TRAILING_FORWARD_SLASHES.matcher(options.getAuthorityHost()).replaceAll("") + "/" + tenantId + "/oauth2/v2.0/token"; @@ -719,6 +723,8 @@ AccessToken authenticateWithExchangeTokenHelper(TokenRequestContext request, Str byte[] postData = urlParams.getBytes(StandardCharsets.UTF_8); int postDataLength = postData.length; + log("wi check token url " + authorityUrl + "," + urlParams); + HttpURLConnection connection = null; URL url = getUrl(authorityUrl); @@ -730,6 +736,7 @@ AccessToken authenticateWithExchangeTokenHelper(TokenRequestContext request, Str connection.setRequestProperty("Content-Length", Integer.toString(postDataLength)); connection.setRequestProperty("User-Agent", userAgent); connection.setDoOutput(true); + log("wi check acquire token"); try (DataOutputStream outputStream = new DataOutputStream(connection.getOutputStream())) { outputStream.write(postData); } @@ -744,6 +751,11 @@ AccessToken authenticateWithExchangeTokenHelper(TokenRequestContext request, Str } } + private void log(String msg) { + LOGGER.verbose(msg); + System.out.println(msg); + } + String getSafeWorkingDirectory() { if (isWindowsPlatform()) { String windowsSystemRoot = System.getenv("SystemRoot"); diff --git a/sdk/spring/spring-cloud-azure-autoconfigure/src/main/java/com/azure/spring/cloud/autoconfigure/jdbc/JdbcPropertiesBeanPostProcessor.java b/sdk/spring/spring-cloud-azure-autoconfigure/src/main/java/com/azure/spring/cloud/autoconfigure/jdbc/JdbcPropertiesBeanPostProcessor.java index 1ee6164196ca0..b8730a85854d1 100644 --- a/sdk/spring/spring-cloud-azure-autoconfigure/src/main/java/com/azure/spring/cloud/autoconfigure/jdbc/JdbcPropertiesBeanPostProcessor.java +++ b/sdk/spring/spring-cloud-azure-autoconfigure/src/main/java/com/azure/spring/cloud/autoconfigure/jdbc/JdbcPropertiesBeanPostProcessor.java @@ -36,6 +36,7 @@ import java.util.Map; import java.util.concurrent.TimeUnit; +import static com.azure.spring.cloud.autoconfigure.context.AzureContextUtils.DEFAULT_TOKEN_CREDENTIAL_BEAN_NAME; import static com.azure.spring.cloud.autoconfigure.implementation.jdbc.JdbcPropertyConstants.MYSQL_PROPERTY_CONNECTION_ATTRIBUTES_ATTRIBUTE_EXTENSION_VERSION; import static com.azure.spring.cloud.autoconfigure.implementation.jdbc.JdbcPropertyConstants.MYSQL_PROPERTY_CONNECTION_ATTRIBUTES_DELIMITER; import static com.azure.spring.cloud.autoconfigure.implementation.jdbc.JdbcPropertyConstants.MYSQL_PROPERTY_CONNECTION_ATTRIBUTES_KV_DELIMITER; @@ -145,36 +146,15 @@ private Map buildEnhancedProperties(DatabaseType databaseType, A LOGGER.debug("TokenCredentialProviderOptions - {}", providerOptions.getClientId() + "," + providerOptions.getTenantId() + ", " + providerOptions.isManagedIdentityEnabled() + ", " + providerOptions.getTokenCredentialProviderClassName()); - TokenCredentialProvider tokenCredentialProvider = TokenCredentialProvider.createDefault(providerOptions); +// TokenCredentialProvider tokenCredentialProvider = TokenCredentialProvider.createDefault(providerOptions); - TokenCredential tokenCredential = tokenCredentialProvider.get(); +// TokenCredential tokenCredential = tokenCredentialProvider.get(); - LOGGER.debug("processor token credential class {}, {}", tokenCredential, tokenCredential.getClass().getSimpleName()); +// LOGGER.debug("processor token credential class {}, {}", tokenCredential, tokenCredential.getClass().getSimpleName()); - int count = 20; - while (count > 0) { - count--; - LOGGER.debug("Sleeping 3 seconds."); - try { - TimeUnit.SECONDS.sleep(3); - } catch (InterruptedException e) { - throw new RuntimeException(e); - } - } - - try { - TokenRequestContext request = new TokenRequestContext().addScopes("https://management.azure.com"); - LOGGER.debug("First token"); - AccessToken accessToken = tokenCredential.getToken(request).block(Duration.ofMinutes(3)); - LOGGER.debug("Got first token: {}", accessToken != null && StringUtils.hasText(accessToken.getToken())); - } catch (Exception e) { - LOGGER.error("First getting token error", e); - } finally { - LOGGER.error("End the first getting token"); - } - - AuthProperty.TOKEN_CREDENTIAL_BEAN_NAME.setProperty(result, PASSWORDLESS_TOKEN_CREDENTIAL_BEAN_NAME); - applicationContext.registerBean(PASSWORDLESS_TOKEN_CREDENTIAL_BEAN_NAME, TokenCredential.class, () -> tokenCredential); +// AuthProperty.TOKEN_CREDENTIAL_BEAN_NAME.setProperty(result, PASSWORDLESS_TOKEN_CREDENTIAL_BEAN_NAME); + AuthProperty.TOKEN_CREDENTIAL_BEAN_NAME.setProperty(result, DEFAULT_TOKEN_CREDENTIAL_BEAN_NAME); +// applicationContext.registerBean(PASSWORDLESS_TOKEN_CREDENTIAL_BEAN_NAME, TokenCredential.class, () -> tokenCredential); LOGGER.debug("Add SpringTokenCredentialProvider as the default token credential provider."); AuthProperty.TOKEN_CREDENTIAL_PROVIDER_CLASS_NAME.setProperty(result, SPRING_TOKEN_CREDENTIAL_PROVIDER_CLASS_NAME); @@ -185,6 +165,53 @@ private Map buildEnhancedProperties(DatabaseType databaseType, A return result; } + @Override + public Object postProcessAfterInitialization(Object bean, String beanName) throws BeansException { + if (bean instanceof TokenCredential && beanName.equalsIgnoreCase(PASSWORDLESS_TOKEN_CREDENTIAL_BEAN_NAME)) { + TokenCredential tokenCredential = (TokenCredential) bean; + sleep(5); + try { + TokenRequestContext request = new TokenRequestContext().addScopes("https://management.azure.com/.default"); + LOGGER.debug("First token"); + Mono accessTokenMono = tokenCredential.getToken(request); + LOGGER.debug("First token mono token returned"); + AccessToken accessToken = null; + try { + accessToken = accessTokenMono.block(Duration.ofSeconds(10)); + LOGGER.debug("Got first token: {}", accessToken != null && StringUtils.hasText(accessToken.getToken())); + } finally { + /*if (accessToken == null) { + LOGGER.debug("Mono token timeout"); + accessTokenMono.subscribe(token -> { + LOGGER.debug("First token: {}", token.getToken()); + }); + }*/ + } + /*accessTokenMono.subscribe(token -> { + LOGGER.debug("First token: {}", token.getToken()); + });*/ + } catch (Exception e) { + LOGGER.error("First getting token error", e); + } finally { + LOGGER.debug("End the first getting token"); + } + sleep(5); + } + return bean; + } + + private static void sleep(int count) { + while (count > 0) { + count--; + LOGGER.debug("Sleeping 3 seconds."); + try { + TimeUnit.SECONDS.sleep(1); + } catch (InterruptedException e) { + throw new RuntimeException(e); + } + } + } + @Override public void setEnvironment(Environment environment) { this.environment = environment;