Skip to content

Commit 6100e24

Browse files
padamstxpadamstx
authored
fix(logging): improve java core's debug logging (#226)
This commit adds some debug logging in various components and adds a custom interceptor that performs http message logging while redacting secrets in the debug messages. Signed-off-by: Phil Adams <[email protected]>
1 parent f2ed2b1 commit 6100e24

40 files changed

+778
-234
lines changed

‎.secrets.baseline

+8-8
Original file line numberDiff line numberDiff line change
@@ -3,7 +3,7 @@
33
"files": "package-lock.json|^.secrets.baseline$",
44
"lines": null
55
},
6-
"generated_at": "2024-01-24T22:23:01Z",
6+
"generated_at": "2024-09-03T23:09:01Z",
77
"plugins_used": [
88
{
99
"name": "AWSKeyDetector"
@@ -130,7 +130,7 @@
130130
"hashed_secret": "ffac6ba71b03ca5f5012197511d76fbcfcf62fbf",
131131
"is_secret": false,
132132
"is_verified": false,
133-
"line_number": 36,
133+
"line_number": 38,
134134
"type": "Secret Keyword",
135135
"verified_result": null
136136
}
@@ -140,7 +140,7 @@
140140
"hashed_secret": "360c23c1ac7d9d6dad1d0710606b0df9de6e1a18",
141141
"is_secret": false,
142142
"is_verified": false,
143-
"line_number": 65,
143+
"line_number": 63,
144144
"type": "Secret Keyword",
145145
"verified_result": null
146146
}
@@ -150,15 +150,15 @@
150150
"hashed_secret": "789cbe0407840b1c2041cb33452ff60f19bf58cc",
151151
"is_secret": false,
152152
"is_verified": false,
153-
"line_number": 60,
153+
"line_number": 61,
154154
"type": "Secret Keyword",
155155
"verified_result": null
156156
},
157157
{
158158
"hashed_secret": "2207d3f3ac68743290fe4affc71c10bec4962232",
159159
"is_secret": false,
160160
"is_verified": false,
161-
"line_number": 61,
161+
"line_number": 62,
162162
"type": "Secret Keyword",
163163
"verified_result": null
164164
}
@@ -168,7 +168,7 @@
168168
"hashed_secret": "ca3f35fa1a5cb92b242c2b42d6d902d43b4816f0",
169169
"is_secret": false,
170170
"is_verified": false,
171-
"line_number": 58,
171+
"line_number": 59,
172172
"type": "Secret Keyword",
173173
"verified_result": null
174174
}
@@ -178,7 +178,7 @@
178178
"hashed_secret": "2207d3f3ac68743290fe4affc71c10bec4962232",
179179
"is_secret": false,
180180
"is_verified": false,
181-
"line_number": 58,
181+
"line_number": 59,
182182
"type": "Secret Keyword",
183183
"verified_result": null
184184
}
@@ -388,7 +388,7 @@
388388
}
389389
]
390390
},
391-
"version": "0.13.1+ibm.61.dss",
391+
"version": "0.13.1+ibm.62.dss",
392392
"word_list": {
393393
"file": null,
394394
"hash": null

‎README.md

+42
Original file line numberDiff line numberDiff line change
@@ -47,6 +47,48 @@ The java-sdk-core project supports the following types of authentication:
4747

4848
For more information about the various authentication types and how to use them with your services, click [here](Authentication.md).
4949

50+
## Logging
51+
This project uses the [java.util.logging](https://docs.oracle.com/en/java/javase/11/core/java-logging-overview.html)
52+
framework for logging errors, warnings, informational and debug messages. The output is controlled by configuring the desired
53+
logging level (SEVERE, WARNING, INFO, FINE, etc.) for various loggers.
54+
55+
Each class within the project creates its own logger which is named after the class (e.g. `com.ibm.cloud.sdk.core.service.BaseService`).
56+
The logger names form a hierarchy that mirrors the package/class hierarchy. A logging level can be configured for an individual logger
57+
or for a group of loggers by leveraging the package name hierarchy.
58+
59+
You can configure the logging framework programmatically by using the [java.util.logging API](https://docs.oracle.com/javase/8/docs/api/java/util/logging/package-summary.html) to create and configure
60+
loggers, handlers and formatters. Please consult the logging framework documentation for more details on this.
61+
62+
You can also configure the framework by defining the desired configuration in a file, then
63+
supplying the name of the file to the logging framework when you run your application.
64+
Included with this project are two files which serve as examples of how to configure the logging framework:
65+
* `logging.properties`: this file contains the default configuration which will display messages that are logged at
66+
level INFO and above (e.g. INFO, WARNING, SEVERE) on the console
67+
* `debug-logging.properties`: this file contains a sample configuration that will set the logging level to FINE for all
68+
Java SDK core loggers and INFO for all other loggers
69+
70+
To cause the logging framework to use a particular configuration file when running your java application, specify the
71+
name of the configuration file with the `java.util.logging.config.file` system property, like this:
72+
```
73+
java -jar myapp.jar -Djava.util.logging.config.file=debug-logging.properties mypackage.MyMainClass
74+
```
75+
76+
For more details regarding the `java.util.logging` API and configuration, please consult the appropriate
77+
`java.util.logging` documentation.
78+
79+
### HTTP message logging
80+
One particular logging-related subject worth mentioning is the logging of HTTP request and response
81+
messages as they flow back and forth between the client and server.
82+
This can be very useful in diagnosing problems or simply verifying that the application is working as intended
83+
(we all know that sometimes "working as intended" is not necessarily aligned with "working as implemented" :) ).
84+
85+
The easiest way to enable HTTP message logging in the Java SDK core library is to simply configure
86+
logging level FINE (or FINER or FINEST) for the `com.ibm.cloud.sdk.core.service.BaseService` logger.
87+
This has the side-effect of causing an interceptor to be registered with the underlying `okhttp3` HTTP transport layer which performs
88+
logging of HTTP request and response messages. Note that the `debug-logging.properties` file contains a configuration that will
89+
include HTTP message logging.
90+
91+
5092
## Issues
5193

5294
If you encounter an issue with this project, you are welcome to submit a [bug report](https://github.com/IBM/java-sdk-core/issues).

‎debug-logging.properties

+28
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,28 @@
1+
#
2+
# Copyright 2024 IBM Corporation.
3+
# SPDX-License-Identifier: Apache2.0
4+
#
5+
6+
# This file contains a java.util.logging configuration that enables debug
7+
# logging (level = FINE) in the Java SDK core library.
8+
#
9+
# To use this file, you can add the "-Djava.util.logging.config.file=logging.properties"
10+
# option to your java command line.
11+
# For more information on java.util.logging, please see:
12+
# https://docs.oracle.com/en/java/javase/11/core/java-logging-overview.html
13+
14+
# Enable output to the console
15+
handlers=java.util.logging.ConsoleHandler
16+
17+
# Limit which messages are displayed on the console
18+
java.util.logging.ConsoleHandler.level=FINE
19+
20+
# Configure a one-line message format using SimpleFormatter
21+
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
22+
java.util.logging.SimpleFormatter.format=%1$tF %1$tT.%1$tL [%4$s] %5$s%6$s%n
23+
24+
# Set global log level to INFO
25+
.level=INFO
26+
27+
# Set Java SDK core log level to FINE
28+
com.ibm.cloud.sdk.core.level=FINE

‎logging.properties

+27-2
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,29 @@
1+
#
2+
# Copyright 2024 IBM Corporation.
3+
# SPDX-License-Identifier: Apache2.0
4+
#
5+
6+
# This file contains a default java.util.logging configuration
7+
# for the Java SDK core library. This file can be used as an
8+
# example for configurating Java core logging to suit your own requirements.
9+
#
10+
# To use this file, you can add the "-Djava.util.logging.config.file=logging.properties"
11+
# option to your java command line.
12+
# For more information on java.util.logging, please see:
13+
# https://docs.oracle.com/en/java/javase/11/core/java-logging-overview.html
14+
15+
# Enable output to the console
116
handlers=java.util.logging.ConsoleHandler
17+
18+
# Limit which messages are displayed on the console
19+
java.util.logging.ConsoleHandler.level=INFO
20+
21+
# Configure a one-line message format using SimpleFormatter
22+
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
23+
java.util.logging.SimpleFormatter.format=%1$tF %1$tT.%1$tL [%4$s] %5$s%6$s%n
24+
25+
# Set global log level to INFO
226
.level=INFO
3-
java.util.logging.ConsoleHandler.level=FINEST
4-
com.ibm.cloud.sdk.core.util.level=FINEST
27+
28+
# Set Java SDK core log level to INFO
29+
com.ibm.cloud.sdk.core.level=INFO

‎src/main/java/com/ibm/cloud/sdk/core/http/DefaultRetryStrategy.java

+2-2
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
/**
2-
* (C) Copyright IBM Corp. 2022. All Rights Reserved.
2+
* (C) Copyright IBM Corp. 2022, 2024. All Rights Reserved.
33
*
44
* Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with
55
* the License. You may obtain a copy of the License at
@@ -22,7 +22,7 @@
2222
public class DefaultRetryStrategy implements IRetryStrategy {
2323

2424
@Override
25-
public RetryInterceptor createRetryInterceptor(int maxRetries, int maxRetryInterval, Authenticator authenticator) {
25+
public IRetryInterceptor createRetryInterceptor(int maxRetries, int maxRetryInterval, Authenticator authenticator) {
2626
return new RetryInterceptor(maxRetries, maxRetryInterval, authenticator);
2727
}
2828
}

‎src/main/java/com/ibm/cloud/sdk/core/http/HttpClientSingleton.java

+35-41
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
/**
2-
* (C) Copyright IBM Corp. 2015, 2022.
2+
* (C) Copyright IBM Corp. 2015, 2024.
33
*
44
* Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with
55
* the License. You may obtain a copy of the License at
@@ -13,25 +13,6 @@
1313

1414
package com.ibm.cloud.sdk.core.http;
1515

16-
import com.ibm.cloud.sdk.core.http.HttpConfigOptions.LoggingLevel;
17-
import com.ibm.cloud.sdk.core.http.gzip.GzipRequestInterceptor;
18-
import com.ibm.cloud.sdk.core.service.security.DelegatingSSLSocketFactory;
19-
import okhttp3.Authenticator;
20-
import okhttp3.ConnectionSpec;
21-
import okhttp3.Interceptor;
22-
import okhttp3.OkHttpClient;
23-
import okhttp3.OkHttpClient.Builder;
24-
import okhttp3.TlsVersion;
25-
import okhttp3.logging.HttpLoggingInterceptor;
26-
27-
import javax.net.ssl.HostnameVerifier;
28-
import javax.net.ssl.SSLContext;
29-
import javax.net.ssl.SSLSession;
30-
import javax.net.ssl.SSLSocket;
31-
import javax.net.ssl.SSLSocketFactory;
32-
import javax.net.ssl.TrustManager;
33-
import javax.net.ssl.TrustManagerFactory;
34-
import javax.net.ssl.X509TrustManager;
3516
import java.io.IOException;
3617
import java.net.CookieManager;
3718
import java.net.CookiePolicy;
@@ -41,14 +22,34 @@
4122
import java.security.KeyStoreException;
4223
import java.security.NoSuchAlgorithmException;
4324
import java.security.cert.CertificateException;
44-
import java.util.Arrays;
4525
import java.util.ArrayList;
26+
import java.util.Arrays;
4627
import java.util.Iterator;
4728
import java.util.List;
4829
import java.util.concurrent.TimeUnit;
4930
import java.util.logging.Level;
5031
import java.util.logging.Logger;
5132

33+
import javax.net.ssl.HostnameVerifier;
34+
import javax.net.ssl.SSLContext;
35+
import javax.net.ssl.SSLSession;
36+
import javax.net.ssl.SSLSocket;
37+
import javax.net.ssl.SSLSocketFactory;
38+
import javax.net.ssl.TrustManager;
39+
import javax.net.ssl.TrustManagerFactory;
40+
import javax.net.ssl.X509TrustManager;
41+
42+
import com.ibm.cloud.sdk.core.http.HttpConfigOptions.LoggingLevel;
43+
import com.ibm.cloud.sdk.core.http.gzip.GzipRequestInterceptor;
44+
import com.ibm.cloud.sdk.core.service.security.DelegatingSSLSocketFactory;
45+
46+
import okhttp3.Authenticator;
47+
import okhttp3.ConnectionSpec;
48+
import okhttp3.Interceptor;
49+
import okhttp3.OkHttpClient;
50+
import okhttp3.OkHttpClient.Builder;
51+
import okhttp3.TlsVersion;
52+
5253
/**
5354
* This class encapsulate the {@link OkHttpClient} instance in a singleton pattern. OkHttp performs best when you create
5455
* a single OkHttpClient instance and reuse it for all of your HTTP calls. This is because each client holds its own
@@ -98,14 +99,14 @@ public java.security.cert.X509Certificate[] getAcceptedIssuers() {
9899

99100
private static final class FilteredSSLSocketFactory extends DelegatingSSLSocketFactory {
100101

101-
// Get the TLS verson names from the MODERN_TLS connection spec
102+
// Get the TLS version names from the MODERN_TLS connection spec
102103
private static final List<String> MODERN_TLS_NAMES = new ArrayList<>();
103104

104105
static {
105106
for (TlsVersion tlsVersion : ConnectionSpec.MODERN_TLS.tlsVersions()) {
106107
MODERN_TLS_NAMES.add(tlsVersion.javaName());
107108
}
108-
LOG.log(Level.FINEST, "Modern TLS names {0}", MODERN_TLS_NAMES);
109+
LOG.log(Level.FINEST, "Modern TLS names: {0}", MODERN_TLS_NAMES);
109110
}
110111

111112
private FilteredSSLSocketFactory(SSLSocketFactory delegate) {
@@ -116,12 +117,12 @@ private FilteredSSLSocketFactory(SSLSocketFactory delegate) {
116117
protected SSLSocket configureSocket(SSLSocket socket) throws IOException {
117118
// Find the TLS protocols supported by this socket
118119
List<String> supportedTlsNames = Arrays.asList(socket.getSupportedProtocols());
119-
LOG.log(Level.FINEST, "Socket supported protocols {0}", supportedTlsNames);
120+
LOG.log(Level.FINEST, "Socket supported TLS protocols: {0}", supportedTlsNames);
120121
// Get the union of MODERN_TLS_NAMES and the socket's supported protocols
121122
List<String> protocolsToEnable = new ArrayList<>();
122123
protocolsToEnable.addAll(supportedTlsNames);
123124
protocolsToEnable.retainAll(MODERN_TLS_NAMES);
124-
LOG.log(Level.FINEST, "Filtered protocols to enable {0}", protocolsToEnable);
125+
LOG.log(Level.FINEST, "Filtered TLS protocols to enable: {0}", protocolsToEnable);
125126
socket.setEnabledProtocols(protocolsToEnable.toArray(new String[]{}));
126127
return socket;
127128
}
@@ -132,7 +133,7 @@ protected SSLSocket configureSocket(SSLSocket socket) throws IOException {
132133
*
133134
* @return single instance of HttpClientSingleton
134135
*/
135-
public static HttpClientSingleton getInstance() {
136+
public static synchronized HttpClientSingleton getInstance() {
136137
if (instance == null) {
137138
instance = new HttpClientSingleton();
138139
}
@@ -200,7 +201,6 @@ private OkHttpClient configureHttpClient() {
200201
private void addCookieJar(final OkHttpClient.Builder builder) {
201202
final CookieManager cookieManager = new CookieManager();
202203
cookieManager.setCookiePolicy(CookiePolicy.ACCEPT_ALL);
203-
204204
builder.cookieJar(new ServiceCookieJar(cookieManager));
205205
}
206206

@@ -268,36 +268,32 @@ private OkHttpClient setProxyAuthenticator(OkHttpClient client, Authenticator pr
268268
private OkHttpClient setLoggingLevel(OkHttpClient client, LoggingLevel loggingLevel) {
269269
// First check to see if the client already has the http logging interceptor registered.
270270
// If not, then we'll register a new instance of one.
271-
HttpLoggingInterceptor loggingInterceptor = null;
271+
HttpLogger loggingInterceptor = null;
272272
for (Interceptor i : client.networkInterceptors()) {
273-
if (i instanceof HttpLoggingInterceptor) {
274-
loggingInterceptor = (HttpLoggingInterceptor) i;
273+
if (i instanceof HttpLogger) {
274+
loggingInterceptor = (HttpLogger) i;
275275
}
276276
}
277277

278278
OkHttpClient updatedClient = client;
279279
if (loggingInterceptor == null) {
280-
loggingInterceptor = new HttpLoggingInterceptor();
281-
loggingInterceptor.redactHeader(HttpHeaders.AUTHORIZATION);
282-
loggingInterceptor.redactHeader(HttpHeaders.WWW_AUTHENTICATE);
283-
loggingInterceptor.redactHeader("Proxy-Authenticate");
284-
loggingInterceptor.redactHeader("Proxy-Authorization");
280+
loggingInterceptor = new HttpLogger();
285281
OkHttpClient.Builder builder = client.newBuilder().addNetworkInterceptor(loggingInterceptor);
286282
updatedClient = builder.build();
287283
}
288284

289285
switch (loggingLevel) {
290286
case BODY:
291-
loggingInterceptor.setLevel(HttpLoggingInterceptor.Level.BODY);
287+
loggingInterceptor.setLevel(HttpLogger.Level.BODY);
292288
break;
293289
case HEADERS:
294-
loggingInterceptor.setLevel(HttpLoggingInterceptor.Level.HEADERS);
290+
loggingInterceptor.setLevel(HttpLogger.Level.HEADERS);
295291
break;
296292
case BASIC:
297-
loggingInterceptor.setLevel(HttpLoggingInterceptor.Level.BASIC);
293+
loggingInterceptor.setLevel(HttpLogger.Level.BASIC);
298294
break;
299295
default:
300-
loggingInterceptor.setLevel(HttpLoggingInterceptor.Level.NONE);
296+
loggingInterceptor.setLevel(HttpLogger.Level.NONE);
301297
}
302298

303299
return updatedClient;
@@ -352,7 +348,6 @@ private OkHttpClient reconfigureClientInterceptors(OkHttpClient client, String i
352348
for (Iterator<Interceptor> iter = builder.interceptors().iterator(); iter.hasNext(); ) {
353349
Interceptor element = iter.next();
354350
if (interceptorToRemove.equals(element.getClass().getSimpleName())) {
355-
LOG.log(Level.FINE, "Removing interceptor " + element.getClass().getName() + " from http client instance.");
356351
iter.remove();
357352
}
358353
}
@@ -377,7 +372,6 @@ private OkHttpClient reconfigureClientInterceptors(OkHttpClient client,
377372
for (Iterator<Interceptor> iter = builder.interceptors().iterator(); iter.hasNext(); ) {
378373
Interceptor element = iter.next();
379374
if (interfaceToRemove.isAssignableFrom(element.getClass())) {
380-
LOG.log(Level.FINE, "Removing interceptor " + element.getClass().getName() + " from http client instance.");
381375
iter.remove();
382376
}
383377
}

0 commit comments

Comments
 (0)