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 <phil_adams@us.ibm.com>

Author: padamstx

.secrets.baseline

@@ -3,7 +3,7 @@
     "files": "package-lock.json|^.secrets.baseline$",
     "lines": null
   },
-  "generated_at": "2024-01-24T22:23:01Z",
+  "generated_at": "2024-09-03T23:09:01Z",
   "plugins_used": [
     {
       "name": "AWSKeyDetector"
@@ -130,7 +130,7 @@
         "hashed_secret": "ffac6ba71b03ca5f5012197511d76fbcfcf62fbf",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 36,
+        "line_number": 38,
         "type": "Secret Keyword",
         "verified_result": null
       }
@@ -140,7 +140,7 @@
         "hashed_secret": "360c23c1ac7d9d6dad1d0710606b0df9de6e1a18",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 65,
+        "line_number": 63,
         "type": "Secret Keyword",
         "verified_result": null
       }
@@ -150,15 +150,15 @@
         "hashed_secret": "789cbe0407840b1c2041cb33452ff60f19bf58cc",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 60,
+        "line_number": 61,
         "type": "Secret Keyword",
         "verified_result": null
       },
       {
         "hashed_secret": "2207d3f3ac68743290fe4affc71c10bec4962232",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 61,
+        "line_number": 62,
         "type": "Secret Keyword",
         "verified_result": null
       }
@@ -168,7 +168,7 @@
         "hashed_secret": "ca3f35fa1a5cb92b242c2b42d6d902d43b4816f0",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 58,
+        "line_number": 59,
         "type": "Secret Keyword",
         "verified_result": null
       }
@@ -178,7 +178,7 @@
         "hashed_secret": "2207d3f3ac68743290fe4affc71c10bec4962232",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 58,
+        "line_number": 59,
         "type": "Secret Keyword",
         "verified_result": null
       }
@@ -388,7 +388,7 @@
       }
     ]
   },
-  "version": "0.13.1+ibm.61.dss",
+  "version": "0.13.1+ibm.62.dss",
   "word_list": {
     "file": null,
     "hash": null

README.md

@@ -47,6 +47,48 @@ The java-sdk-core project supports the following types of authentication:
 
 For more information about the various authentication types and how to use them with your services, click [here](Authentication.md).
 
+## Logging
+This project uses the [java.util.logging](https://docs.oracle.com/en/java/javase/11/core/java-logging-overview.html)
+framework for logging errors, warnings, informational and debug messages.  The output is controlled by configuring the desired
+logging level (SEVERE, WARNING, INFO, FINE, etc.) for various loggers.
+
+Each class within the project creates its own logger which is named after the class (e.g. `com.ibm.cloud.sdk.core.service.BaseService`).
+The logger names form a hierarchy that mirrors the package/class hierarchy.  A logging level can be configured for an individual logger
+or for a group of loggers by leveraging the package name hierarchy.
+
+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
+loggers, handlers and formatters. Please consult the logging framework documentation for more details on this.
+
+You can also configure the framework by defining the desired configuration in a file, then
+supplying the name of the file to the logging framework when you run your application.
+Included with this project are two files which serve as examples of how to configure the logging framework:
+* `logging.properties`: this file contains the default configuration which will display messages that are logged at
+level INFO and above (e.g. INFO, WARNING, SEVERE) on the console
+* `debug-logging.properties`: this file contains a sample configuration that will set the logging level to FINE for all
+Java SDK core loggers and INFO for all other loggers
+
+To cause the logging framework to use a particular configuration file when running your java application, specify the
+name of the configuration file with the `java.util.logging.config.file` system property, like this:
+```
+    java -jar myapp.jar -Djava.util.logging.config.file=debug-logging.properties mypackage.MyMainClass
+```
+
+For more details regarding the `java.util.logging` API and configuration, please consult the appropriate
+`java.util.logging` documentation.
+
+### HTTP message logging
+One particular logging-related subject worth mentioning is the logging of HTTP request and response
+messages as they flow back and forth between the client and server.
+This can be very useful in diagnosing problems or simply verifying that the application is working as intended
+(we all know that sometimes "working as intended" is not necessarily aligned with "working as implemented" :) ).
+
+The easiest way to enable HTTP message logging in the Java SDK core library is to simply configure
+logging level FINE (or FINER or FINEST) for the `com.ibm.cloud.sdk.core.service.BaseService` logger.
+This has the side-effect of causing an interceptor to be registered with the underlying `okhttp3` HTTP transport layer which performs
+logging of HTTP request and response messages.  Note that the `debug-logging.properties` file contains a configuration that will
+include HTTP message logging.
+
+
 ## Issues
 
 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

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

logging.properties

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

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

@@ -1,5 +1,5 @@
 /**
- * (C) Copyright IBM Corp. 2022.  All Rights Reserved.
+ * (C) Copyright IBM Corp. 2022, 2024.  All Rights Reserved.
  *
  * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with
  * the License. You may obtain a copy of the License at
@@ -22,7 +22,7 @@
 public class DefaultRetryStrategy implements IRetryStrategy {
 
   @Override
-  public RetryInterceptor createRetryInterceptor(int maxRetries, int maxRetryInterval, Authenticator authenticator) {
+  public IRetryInterceptor createRetryInterceptor(int maxRetries, int maxRetryInterval, Authenticator authenticator) {
     return new RetryInterceptor(maxRetries, maxRetryInterval, authenticator);
   }
 }

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

@@ -1,5 +1,5 @@
 /**
- * (C) Copyright IBM Corp. 2015, 2022.
+ * (C) Copyright IBM Corp. 2015, 2024.
  *
  * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with
  * the License. You may obtain a copy of the License at
@@ -13,25 +13,6 @@
 
 package com.ibm.cloud.sdk.core.http;
 
-import com.ibm.cloud.sdk.core.http.HttpConfigOptions.LoggingLevel;
-import com.ibm.cloud.sdk.core.http.gzip.GzipRequestInterceptor;
-import com.ibm.cloud.sdk.core.service.security.DelegatingSSLSocketFactory;
-import okhttp3.Authenticator;
-import okhttp3.ConnectionSpec;
-import okhttp3.Interceptor;
-import okhttp3.OkHttpClient;
-import okhttp3.OkHttpClient.Builder;
-import okhttp3.TlsVersion;
-import okhttp3.logging.HttpLoggingInterceptor;
-
-import javax.net.ssl.HostnameVerifier;
-import javax.net.ssl.SSLContext;
-import javax.net.ssl.SSLSession;
-import javax.net.ssl.SSLSocket;
-import javax.net.ssl.SSLSocketFactory;
-import javax.net.ssl.TrustManager;
-import javax.net.ssl.TrustManagerFactory;
-import javax.net.ssl.X509TrustManager;
 import java.io.IOException;
 import java.net.CookieManager;
 import java.net.CookiePolicy;
@@ -41,14 +22,34 @@
 import java.security.KeyStoreException;
 import java.security.NoSuchAlgorithmException;
 import java.security.cert.CertificateException;
-import java.util.Arrays;
 import java.util.ArrayList;
+import java.util.Arrays;
 import java.util.Iterator;
 import java.util.List;
 import java.util.concurrent.TimeUnit;
 import java.util.logging.Level;
 import java.util.logging.Logger;
 
+import javax.net.ssl.HostnameVerifier;
+import javax.net.ssl.SSLContext;
+import javax.net.ssl.SSLSession;
+import javax.net.ssl.SSLSocket;
+import javax.net.ssl.SSLSocketFactory;
+import javax.net.ssl.TrustManager;
+import javax.net.ssl.TrustManagerFactory;
+import javax.net.ssl.X509TrustManager;
+
+import com.ibm.cloud.sdk.core.http.HttpConfigOptions.LoggingLevel;
+import com.ibm.cloud.sdk.core.http.gzip.GzipRequestInterceptor;
+import com.ibm.cloud.sdk.core.service.security.DelegatingSSLSocketFactory;
+
+import okhttp3.Authenticator;
+import okhttp3.ConnectionSpec;
+import okhttp3.Interceptor;
+import okhttp3.OkHttpClient;
+import okhttp3.OkHttpClient.Builder;
+import okhttp3.TlsVersion;
+
 /**
  * This class encapsulate the {@link OkHttpClient} instance in a singleton pattern. OkHttp performs best when you create
  * 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() {
 
   private static final class FilteredSSLSocketFactory extends DelegatingSSLSocketFactory {
 
-      // Get the TLS verson names from the MODERN_TLS connection spec
+      // Get the TLS version names from the MODERN_TLS connection spec
       private static final List<String> MODERN_TLS_NAMES = new ArrayList<>();
 
       static {
         for (TlsVersion tlsVersion : ConnectionSpec.MODERN_TLS.tlsVersions()) {
           MODERN_TLS_NAMES.add(tlsVersion.javaName());
         }
-        LOG.log(Level.FINEST, "Modern TLS names {0}", MODERN_TLS_NAMES);
+        LOG.log(Level.FINEST, "Modern TLS names: {0}", MODERN_TLS_NAMES);
       }
 
       private FilteredSSLSocketFactory(SSLSocketFactory delegate) {
@@ -116,12 +117,12 @@ private FilteredSSLSocketFactory(SSLSocketFactory delegate) {
       protected SSLSocket configureSocket(SSLSocket socket) throws IOException {
         // Find the TLS protocols supported by this socket
         List<String> supportedTlsNames = Arrays.asList(socket.getSupportedProtocols());
-        LOG.log(Level.FINEST, "Socket supported protocols {0}", supportedTlsNames);
+        LOG.log(Level.FINEST, "Socket supported TLS protocols: {0}", supportedTlsNames);
         // Get the union of MODERN_TLS_NAMES and the socket's supported protocols
         List<String> protocolsToEnable = new ArrayList<>();
         protocolsToEnable.addAll(supportedTlsNames);
         protocolsToEnable.retainAll(MODERN_TLS_NAMES);
-        LOG.log(Level.FINEST, "Filtered protocols to enable {0}", protocolsToEnable);
+        LOG.log(Level.FINEST, "Filtered TLS protocols to enable: {0}", protocolsToEnable);
         socket.setEnabledProtocols(protocolsToEnable.toArray(new String[]{}));
         return socket;
       }
@@ -132,7 +133,7 @@ protected SSLSocket configureSocket(SSLSocket socket) throws IOException {
    *
    * @return single instance of HttpClientSingleton
    */
-  public static HttpClientSingleton getInstance() {
+  public static synchronized HttpClientSingleton getInstance() {
     if (instance == null) {
       instance = new HttpClientSingleton();
     }
@@ -200,7 +201,6 @@ private OkHttpClient configureHttpClient() {
   private void addCookieJar(final OkHttpClient.Builder builder) {
     final CookieManager cookieManager = new CookieManager();
     cookieManager.setCookiePolicy(CookiePolicy.ACCEPT_ALL);
-
     builder.cookieJar(new ServiceCookieJar(cookieManager));
   }
 
@@ -268,36 +268,32 @@ private OkHttpClient setProxyAuthenticator(OkHttpClient client, Authenticator pr
   private OkHttpClient setLoggingLevel(OkHttpClient client, LoggingLevel loggingLevel) {
     // First check to see if the client already has the http logging interceptor registered.
     // If not, then we'll register a new instance of one.
-    HttpLoggingInterceptor loggingInterceptor = null;
+    HttpLogger loggingInterceptor = null;
     for (Interceptor i : client.networkInterceptors()) {
-      if (i instanceof HttpLoggingInterceptor) {
-        loggingInterceptor = (HttpLoggingInterceptor) i;
+      if (i instanceof HttpLogger) {
+        loggingInterceptor = (HttpLogger) i;
       }
     }
 
     OkHttpClient updatedClient = client;
     if (loggingInterceptor == null) {
-      loggingInterceptor = new HttpLoggingInterceptor();
-      loggingInterceptor.redactHeader(HttpHeaders.AUTHORIZATION);
-      loggingInterceptor.redactHeader(HttpHeaders.WWW_AUTHENTICATE);
-      loggingInterceptor.redactHeader("Proxy-Authenticate");
-      loggingInterceptor.redactHeader("Proxy-Authorization");
+      loggingInterceptor = new HttpLogger();
       OkHttpClient.Builder builder = client.newBuilder().addNetworkInterceptor(loggingInterceptor);
       updatedClient = builder.build();
     }
 
     switch (loggingLevel) {
       case BODY:
-        loggingInterceptor.setLevel(HttpLoggingInterceptor.Level.BODY);
+        loggingInterceptor.setLevel(HttpLogger.Level.BODY);
         break;
       case HEADERS:
-        loggingInterceptor.setLevel(HttpLoggingInterceptor.Level.HEADERS);
+        loggingInterceptor.setLevel(HttpLogger.Level.HEADERS);
         break;
       case BASIC:
-        loggingInterceptor.setLevel(HttpLoggingInterceptor.Level.BASIC);
+        loggingInterceptor.setLevel(HttpLogger.Level.BASIC);
         break;
       default:
-        loggingInterceptor.setLevel(HttpLoggingInterceptor.Level.NONE);
+        loggingInterceptor.setLevel(HttpLogger.Level.NONE);
     }
 
     return updatedClient;
@@ -352,7 +348,6 @@ private OkHttpClient reconfigureClientInterceptors(OkHttpClient client, String i
       for (Iterator<Interceptor> iter = builder.interceptors().iterator(); iter.hasNext(); ) {
         Interceptor element = iter.next();
         if (interceptorToRemove.equals(element.getClass().getSimpleName())) {
-          LOG.log(Level.FINE, "Removing interceptor " + element.getClass().getName() + " from http client instance.");
           iter.remove();
         }
       }
@@ -377,7 +372,6 @@ private OkHttpClient reconfigureClientInterceptors(OkHttpClient client,
       for (Iterator<Interceptor> iter = builder.interceptors().iterator(); iter.hasNext(); ) {
         Interceptor element = iter.next();
         if (interfaceToRemove.isAssignableFrom(element.getClass())) {
-          LOG.log(Level.FINE, "Removing interceptor " + element.getClass().getName() + " from http client instance.");
           iter.remove();
         }
       }