Skip to content

Commit e59dad2

Browse files
zoewanggzoewangg
committed
Improve logging for debuggability.
1 parent 587e080 commit e59dad2

File tree

23 files changed

+138
-206
lines changed

23 files changed

+138
-206
lines changed

‎.changes/next-release/feature-AWSSDKforJavav2-0aac933.json

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,5 @@
1+
{
2+
"category": "AWS SDK for Java v2",
3+
"type": "feature",
4+
"description": "Improve logging for debuggability. see `SdkStandardLogger`."
5+
}

‎core/auth/pom.xml

Lines changed: 0 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -47,10 +47,6 @@
4747
<artifactId>http-client-spi</artifactId>
4848
<version>${awsjavasdk.version}</version>
4949
</dependency>
50-
<dependency>
51-
<groupId>org.slf4j</groupId>
52-
<artifactId>slf4j-api</artifactId>
53-
</dependency>
5450
<dependency>
5551
<groupId>com.fasterxml.jackson.core</groupId>
5652
<artifactId>jackson-databind</artifactId>

‎core/auth/src/main/java/software/amazon/awssdk/auth/credentials/AwsCredentialsProviderChain.java

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -20,11 +20,10 @@
2020
import java.util.Collection;
2121
import java.util.Collections;
2222
import java.util.List;
23-
import org.slf4j.Logger;
24-
import org.slf4j.LoggerFactory;
2523
import software.amazon.awssdk.annotations.SdkPublicApi;
2624
import software.amazon.awssdk.core.exception.SdkClientException;
2725
import software.amazon.awssdk.utils.IoUtils;
26+
import software.amazon.awssdk.utils.Logger;
2827
import software.amazon.awssdk.utils.SdkAutoCloseable;
2928
import software.amazon.awssdk.utils.ToString;
3029
import software.amazon.awssdk.utils.Validate;
@@ -46,7 +45,7 @@
4645
*/
4746
@SdkPublicApi
4847
public final class AwsCredentialsProviderChain implements AwsCredentialsProvider, SdkAutoCloseable {
49-
private static final Logger log = LoggerFactory.getLogger(AwsCredentialsProviderChain.class);
48+
private static final Logger log = Logger.loggerFor(AwsCredentialsProviderChain.class);
5049

5150
private final List<AwsCredentialsProvider> credentialsProviders;
5251

@@ -91,14 +90,15 @@ public AwsCredentials resolveCredentials() {
9190
try {
9291
AwsCredentials credentials = provider.resolveCredentials();
9392

94-
log.debug("Loading credentials from {}", provider.toString());
93+
log.debug(() -> "Loading credentials from " + provider);
9594

9695
lastUsedProvider = provider;
9796
return credentials;
9897
} catch (RuntimeException e) {
9998
// Ignore any exceptions and move onto the next provider
10099
String message = provider + ": " + e.getMessage();
101-
log.debug("Unable to load credentials from " + message, e);
100+
log.debug(() -> "Unable to load credentials from " + message , e);
101+
102102
if (exceptionMessages == null) {
103103
exceptionMessages = new ArrayList<>();
104104
}

‎core/auth/src/main/java/software/amazon/awssdk/auth/signer/internal/AbstractAws4Signer.java

Lines changed: 19 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -27,8 +27,6 @@
2727
import java.util.List;
2828
import java.util.Map;
2929
import java.util.concurrent.TimeUnit;
30-
import org.slf4j.Logger;
31-
import org.slf4j.LoggerFactory;
3230
import software.amazon.awssdk.annotations.SdkInternalApi;
3331
import software.amazon.awssdk.auth.credentials.AwsCredentials;
3432
import software.amazon.awssdk.auth.credentials.AwsSessionCredentials;
@@ -40,6 +38,7 @@
4038
import software.amazon.awssdk.core.signer.Presigner;
4139
import software.amazon.awssdk.http.SdkHttpFullRequest;
4240
import software.amazon.awssdk.utils.BinaryUtils;
41+
import software.amazon.awssdk.utils.Logger;
4342
import software.amazon.awssdk.utils.http.SdkHttpUtils;
4443

4544
/**
@@ -53,7 +52,7 @@ public abstract class AbstractAws4Signer<T extends Aws4SignerParams, U extends A
5352

5453
public static final String EMPTY_STRING_SHA256_HEX = BinaryUtils.toHex(hash(""));
5554

56-
private static final Logger LOG = LoggerFactory.getLogger(Aws4Signer.class);
55+
private static final Logger LOG = Logger.loggerFor(Aws4Signer.class);
5756
private static final int SIGNER_CACHE_MAX_SIZE = 300;
5857
private static final FifoCache<SignerKey> SIGNER_CACHE =
5958
new FifoCache<>(SIGNER_CACHE_MAX_SIZE);
@@ -176,23 +175,21 @@ protected abstract void processRequestPayload(SdkHttpFullRequest.Builder mutable
176175
private String createCanonicalRequest(SdkHttpFullRequest.Builder request,
177176
String contentSha256,
178177
boolean doubleUrlEncode) {
179-
final String canonicalRequest = request.method().toString() +
180-
SignerConstant.LINE_SEPARATOR +
181-
// This would optionally double url-encode the resource path
182-
getCanonicalizedResourcePath(request.encodedPath(), doubleUrlEncode) +
183-
SignerConstant.LINE_SEPARATOR +
184-
getCanonicalizedQueryString(request.rawQueryParameters()) +
185-
SignerConstant.LINE_SEPARATOR +
186-
getCanonicalizedHeaderString(request.headers()) +
187-
SignerConstant.LINE_SEPARATOR +
188-
getSignedHeadersString(request.headers()) +
189-
SignerConstant.LINE_SEPARATOR +
190-
contentSha256;
191-
192-
if (LOG.isDebugEnabled()) {
193-
LOG.debug("AWS4 Canonical Request: '\"" + canonicalRequest + "\"");
194-
}
195178

179+
String canonicalRequest = request.method().toString() +
180+
SignerConstant.LINE_SEPARATOR +
181+
// This would optionally double url-encode the resource path
182+
getCanonicalizedResourcePath(request.encodedPath(), doubleUrlEncode) +
183+
SignerConstant.LINE_SEPARATOR +
184+
getCanonicalizedQueryString(request.rawQueryParameters()) +
185+
SignerConstant.LINE_SEPARATOR +
186+
getCanonicalizedHeaderString(request.headers()) +
187+
SignerConstant.LINE_SEPARATOR +
188+
getSignedHeadersString(request.headers()) +
189+
SignerConstant.LINE_SEPARATOR +
190+
contentSha256;
191+
192+
LOG.trace(() -> "AWS4 Canonical Request: " + canonicalRequest);
196193
return canonicalRequest;
197194
}
198195

@@ -212,10 +209,7 @@ private String createStringToSign(String canonicalRequest,
212209
SignerConstant.LINE_SEPARATOR +
213210
BinaryUtils.toHex(hash(canonicalRequest));
214211

215-
if (LOG.isDebugEnabled()) {
216-
LOG.debug("AWS4 String to Sign: '\"" + stringToSign + "\"");
217-
}
218-
212+
LOG.debug(() -> "AWS4 String to sign: " + stringToSign);
219213
return stringToSign;
220214
}
221215

@@ -237,10 +231,8 @@ private byte[] deriveSigningKey(AwsCredentials credentials,
237231
return signerKey.getSigningKey();
238232
}
239233

240-
if (LOG.isDebugEnabled()) {
241-
LOG.debug("Generating a new signing key as the signing key not available in the cache for the date "
242-
+ TimeUnit.DAYS.toMillis(daysSinceEpochSigningDate));
243-
}
234+
LOG.trace(() -> "Generating a new signing key as the signing key not available in the cache for the date: " +
235+
TimeUnit.DAYS.toMillis(daysSinceEpochSigningDate));
244236
byte[] signingKey = newSigningKey(credentials,
245237
signerRequestParams.getFormattedSigningDate(),
246238
signerRequestParams.getRegionName(),

‎core/auth/src/main/java/software/amazon/awssdk/auth/signer/internal/AwsChunkedEncodingInputStream.java

Lines changed: 11 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -24,13 +24,12 @@
2424
import java.util.Arrays;
2525
import javax.crypto.Mac;
2626
import javax.crypto.spec.SecretKeySpec;
27-
import org.slf4j.Logger;
28-
import org.slf4j.LoggerFactory;
2927
import software.amazon.awssdk.annotations.SdkInternalApi;
3028
import software.amazon.awssdk.auth.signer.AwsS3V4Signer;
3129
import software.amazon.awssdk.core.exception.SdkClientException;
3230
import software.amazon.awssdk.core.io.SdkInputStream;
3331
import software.amazon.awssdk.utils.BinaryUtils;
32+
import software.amazon.awssdk.utils.Logger;
3433

3534
/**
3635
* A wrapper class of InputStream that implements chunked-encoding.
@@ -46,7 +45,7 @@ public final class AwsChunkedEncodingInputStream extends SdkInputStream {
4645
private static final String CHUNK_SIGNATURE_HEADER = ";chunk-signature=";
4746
private static final int SIGNATURE_LENGTH = 64;
4847
private static final byte[] FINAL_CHUNK = new byte[0];
49-
private static final Logger log = LoggerFactory.getLogger(AwsChunkedEncodingInputStream.class);
48+
private static final Logger log = Logger.loggerFor(AwsChunkedEncodingInputStream.class);
5049

5150
private InputStream is = null;
5251
private final int maxBufferSize;
@@ -140,9 +139,7 @@ public int read() throws IOException {
140139
byte[] tmp = new byte[1];
141140
int count = read(tmp, 0, 1);
142141
if (count != -1) {
143-
if (log.isDebugEnabled()) {
144-
log.debug("One byte read from the stream.");
145-
}
142+
log.debug(() -> "One byte read from the stream.");
146143
int unsignedByte = (int) tmp[0] & 0xFF;
147144
return unsignedByte;
148145
} else {
@@ -172,9 +169,7 @@ public int read(byte[] b, int off, int len) throws IOException {
172169
int count = currentChunkIterator.read(b, off, len);
173170
if (count > 0) {
174171
isAtStart = false;
175-
if (log.isTraceEnabled()) {
176-
log.trace(count + " byte read from the stream.");
177-
}
172+
log.trace(() -> count + " byte read from the stream.");
178173
}
179174
return count;
180175
}
@@ -215,16 +210,12 @@ public void mark(int readlimit) {
215210
throw new UnsupportedOperationException("Chunk-encoded stream only supports mark() at the start of the stream.");
216211
}
217212
if (is.markSupported()) {
218-
if (log.isDebugEnabled()) {
219-
log.debug("AwsChunkedEncodingInputStream marked at the start of the stream "
220-
+ "(will directly mark the wrapped stream since it's mark-supported).");
221-
}
213+
log.debug(() -> "AwsChunkedEncodingInputStream marked at the start of the stream "
214+
+ "(will directly mark the wrapped stream since it's mark-supported).");
222215
is.mark(readlimit);
223216
} else {
224-
if (log.isDebugEnabled()) {
225-
log.debug("AwsChunkedEncodingInputStream marked at the start of the stream "
226-
+ "(initializing the buffer since the wrapped stream is not mark-supported).");
227-
}
217+
log.debug(() -> "AwsChunkedEncodingInputStream marked at the start of the stream "
218+
+ "(initializing the buffer since the wrapped stream is not mark-supported).");
228219
decodedStreamBuffer = new DecodedStreamBuffer(maxBufferSize);
229220
}
230221
}
@@ -242,15 +233,11 @@ public void reset() throws IOException {
242233
// Reset the wrapped stream if it is mark-supported,
243234
// otherwise use our buffered data.
244235
if (is.markSupported()) {
245-
if (log.isDebugEnabled()) {
246-
log.debug("AwsChunkedEncodingInputStream reset "
247-
+ "(will reset the wrapped stream because it is mark-supported).");
248-
}
236+
log.debug(() -> "AwsChunkedEncodingInputStream reset "
237+
+ "(will reset the wrapped stream because it is mark-supported).");
249238
is.reset();
250239
} else {
251-
if (log.isDebugEnabled()) {
252-
log.debug("AwsChunkedEncodingInputStream reset (will use the buffer of the decoded stream).");
253-
}
240+
log.debug(() -> "AwsChunkedEncodingInputStream reset (will use the buffer of the decoded stream).");
254241
if (null == decodedStreamBuffer) {
255242
throw new IOException("Cannot reset the stream because the mark is not set.");
256243
}

‎core/auth/src/main/java/software/amazon/awssdk/auth/signer/internal/DecodedStreamBuffer.java

Lines changed: 8 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -15,14 +15,13 @@
1515

1616
package software.amazon.awssdk.auth.signer.internal;
1717

18-
import org.slf4j.Logger;
19-
import org.slf4j.LoggerFactory;
2018
import software.amazon.awssdk.annotations.SdkInternalApi;
2119
import software.amazon.awssdk.core.exception.SdkClientException;
20+
import software.amazon.awssdk.utils.Logger;
2221

2322
@SdkInternalApi
2423
class DecodedStreamBuffer {
25-
private static final Logger log = LoggerFactory.getLogger(DecodedStreamBuffer.class);
24+
private static final Logger log = Logger.loggerFor(DecodedStreamBuffer.class);
2625

2726
private byte[] bufferArray;
2827
private int maxBufferSize;
@@ -38,11 +37,9 @@ class DecodedStreamBuffer {
3837
public void buffer(byte read) {
3938
pos = -1;
4039
if (byteBuffered >= maxBufferSize) {
41-
if (log.isDebugEnabled()) {
42-
log.debug("Buffer size " + maxBufferSize
43-
+ " has been exceeded and the input stream "
44-
+ "will not be repeatable. Freeing buffer memory");
45-
}
40+
log.debug(() -> "Buffer size " + maxBufferSize
41+
+ " has been exceeded and the input stream "
42+
+ "will not be repeatable. Freeing buffer memory");
4643
bufferSizeOverflow = true;
4744
} else {
4845
bufferArray[byteBuffered++] = read;
@@ -52,11 +49,9 @@ public void buffer(byte read) {
5249
public void buffer(byte[] src, int srcPos, int length) {
5350
pos = -1;
5451
if (byteBuffered + length > maxBufferSize) {
55-
if (log.isDebugEnabled()) {
56-
log.debug("Buffer size " + maxBufferSize
57-
+ " has been exceeded and the input stream "
58-
+ "will not be repeatable. Freeing buffer memory");
59-
}
52+
log.debug(() -> "Buffer size " + maxBufferSize
53+
+ " has been exceeded and the input stream "
54+
+ "will not be repeatable. Freeing buffer memory");
6055
bufferSizeOverflow = true;
6156
} else {
6257
System.arraycopy(src, srcPos, bufferArray, byteBuffered, length);

‎core/sdk-core/src/main/java/software/amazon/awssdk/core/SdkStandardLogger.java

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -30,5 +30,11 @@ public final class SdkStandardLogger {
3030
*/
3131
public static final Logger REQUEST_LOGGER = Logger.loggerFor("software.amazon.awssdk.request");
3232

33+
/**
34+
* Logger used for the purpose of logging the request id extracted either from the
35+
* http response header or from the response body.
36+
*/
37+
public static final Logger REQUEST_ID_LOGGER = Logger.loggerFor("software.amazon.awssdk.requestId");
38+
3339
private SdkStandardLogger() {}
3440
}

‎core/sdk-core/src/main/java/software/amazon/awssdk/core/http/JsonResponseHandler.java

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@
1919
import com.fasterxml.jackson.core.JsonParser;
2020
import java.io.IOException;
2121
import java.util.Map;
22+
import java.util.Optional;
2223
import software.amazon.awssdk.annotations.ReviewBeforeRelease;
2324
import software.amazon.awssdk.annotations.SdkProtectedApi;
2425
import software.amazon.awssdk.core.SdkStandardLogger;
@@ -88,6 +89,9 @@ public JsonResponseHandler(Unmarshaller<T, JsonUnmarshallerContext> responseUnma
8889
*/
8990
public T handle(HttpResponse response, ExecutionAttributes executionAttributes) throws Exception {
9091
SdkStandardLogger.REQUEST_LOGGER.trace(() -> "Parsing service response JSON.");
92+
SdkStandardLogger.REQUEST_ID_LOGGER.debug(() -> X_AMZN_REQUEST_ID_HEADER + " : " +
93+
Optional.ofNullable(response.getHeader(X_AMZN_REQUEST_ID_HEADER))
94+
.orElse("not available"));
9195

9296
JsonParser jsonParser = null;
9397

‎core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/StreamManagingStage.java

Lines changed: 4 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -22,8 +22,6 @@
2222
import java.io.IOException;
2323
import java.io.InputStream;
2424
import java.util.Optional;
25-
import org.slf4j.Logger;
26-
import org.slf4j.LoggerFactory;
2725
import software.amazon.awssdk.annotations.SdkInternalApi;
2826
import software.amazon.awssdk.core.internal.Response;
2927
import software.amazon.awssdk.core.internal.http.pipeline.RequestPipeline;
@@ -32,6 +30,7 @@
3230
import software.amazon.awssdk.core.io.ResettableInputStream;
3331
import software.amazon.awssdk.core.io.SdkBufferedInputStream;
3432
import software.amazon.awssdk.http.SdkHttpFullRequest;
33+
import software.amazon.awssdk.utils.Logger;
3534

3635
/**
3736
* Instruments the request input stream for both retry purposes (to allow for mark/reset) and progress reporting. Handles
@@ -42,7 +41,7 @@
4241
@SdkInternalApi
4342
public final class StreamManagingStage<OutputT> implements RequestPipeline<SdkHttpFullRequest, Response<OutputT>> {
4443

45-
private static final Logger log = LoggerFactory.getLogger(StreamManagingStage.class);
44+
private static final Logger log = Logger.loggerFor(StreamManagingStage.class);
4645

4746
private final RequestPipeline<SdkHttpFullRequest, Response<OutputT>> wrapped;
4847

@@ -58,7 +57,7 @@ public Response<OutputT> execute(SdkHttpFullRequest request, RequestExecutionCon
5857
context);
5958
} finally {
6059
// Always close so any progress tracking would get the final events propagated.
61-
toBeClosed.ifPresent(i -> closeQuietly(i, log));
60+
toBeClosed.ifPresent(i -> closeQuietly(i, log.logger()));
6261
}
6362
}
6463

@@ -97,9 +96,7 @@ private InputStream makeResettable(InputStream content) {
9796
// ResettableInputStream supports mark-and-reset without memory buffering
9897
return new ResettableInputStream((FileInputStream) content);
9998
} catch (IOException e) {
100-
if (log.isDebugEnabled()) {
101-
log.debug("For the record; ignore otherwise", e);
102-
}
99+
log.debug(() -> "For the record; ignore otherwise", e);
103100
}
104101
}
105102
return content;

‎core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/pipeline/stages/AsyncRetryableStage.java

Lines changed: 2 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -142,10 +142,8 @@ private void executeRetry(CompletableFuture<Response<OutputT>> future) {
142142
final int retriesAttempted = requestCount - 2;
143143
Duration delay = retryHandler.computeDelayBeforeNextRetry();
144144

145-
if (log.isDebugEnabled()) {
146-
log.debug("Retryable error detected, will retry in " + delay + "ms, attempt number: " +
147-
retriesAttempted);
148-
}
145+
SdkStandardLogger.REQUEST_LOGGER.debug(() -> "Retryable error detected, will retry in " + delay.toMillis() + "ms,"
146+
+ " attempt number " + retriesAttempted);
149147
retrySubmitter.schedule(() -> {
150148
execute(future);
151149
return null;

‎core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/pipeline/stages/HandleResponseStage.java

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -83,10 +83,10 @@ private Response<OutputT> handleResponse(HttpResponse httpResponse,
8383
* @throws IOException If any problems were encountered reading the response contents from
8484
* the HTTP method object.
8585
*/
86-
@SuppressWarnings("deprecation")
8786
private OutputT handleSuccessResponse(HttpResponse httpResponse, RequestExecutionContext context)
8887
throws IOException, InterruptedException {
8988
try {
89+
SdkStandardLogger.REQUEST_LOGGER.debug(() -> "Received successful response: " + httpResponse.getStatusCode());
9090
return successResponseHandler.handle(httpResponse, context.executionAttributes());
9191
} catch (IOException | InterruptedException | RetryableException e) {
9292
throw e;
@@ -138,5 +138,4 @@ private void closeInputStreamIfNeeded(HttpResponse httpResponse,
138138
.ifPresent(s -> IoUtils.closeQuietly(s, log));
139139
}
140140
}
141-
142141
}

0 commit comments

Comments
 (0)