Merge pull request #648 from hapifhir/logging_interceptor

Adding changes for logging request and resp

RELEASE_NOTES.md

@@ -1 +1,2 @@
+* Updating client logger to log both req and resp
 * Refactoring of converter loader and misc packages. 

org.hl7.fhir.r4/src/main/java/org/hl7/fhir/r4/utils/client/FHIRToolingClient.java

@@ -276,15 +276,9 @@ public class FHIRToolingClient {
       URI url = resourceAddress.resolveOperationURLFromClass(resourceClass, name, ps);
       if (complex) {
         byte[] body = ByteUtils.resourceToByteArray(params, false, isJson(getPreferredResourceFormat()));
-        if (client.getLogger() != null) {
-          client.getLogger().logRequest("POST", url.toString(), null, body);
-        }
         result = client.issuePostRequest(url, body, getPreferredResourceFormat(), generateHeaders(),
             "POST " + resourceClass.getName() + "/$" + name, TIMEOUT_OPERATION_LONG);
       } else {
-        if (client.getLogger() != null) {
-          client.getLogger().logRequest("GET", url.toString(), null, null);
-        }
         result = client.issueGetResourceRequest(url, getPreferredResourceFormat(), generateHeaders(), "GET " + resourceClass.getName() + "/$" + name, TIMEOUT_OPERATION_LONG);
       }
       if (result.isUnsuccessfulRequest()) {

org.hl7.fhir.r4/src/main/java/org/hl7/fhir/r4/utils/client/network/Client.java

@@ -19,6 +19,7 @@ public class Client {
   public static final String DEFAULT_CHARSET = "UTF-8";
   private static final long DEFAULT_TIMEOUT = 5000;
   private ToolingClientLogger logger;
+  private FhirLoggingInterceptor fhirLoggingInterceptor;
   private int retryCount;
   private long timeout = DEFAULT_TIMEOUT;
 
@@ -28,6 +29,7 @@ public class Client {
 
   public void setLogger(ToolingClientLogger logger) {
     this.logger = logger;
+    this.fhirLoggingInterceptor = new FhirLoggingInterceptor(logger);
   }
 
   public int getRetryCount() {
@@ -167,7 +169,7 @@ public class Client {
                                                              int retryCount,
                                                              long timeout) throws IOException {
     return new FhirRequestBuilder(request)
-      .withLogger(logger)
+      .withLogger(fhirLoggingInterceptor)
       .withResourceFormat(resourceFormat)
       .withRetryCount(retryCount)
       .withMessage(message)
@@ -183,7 +185,7 @@ public class Client {
                                                                        int retryCount,
                                                                        long timeout) throws IOException {
     return new FhirRequestBuilder(request)
-      .withLogger(logger)
+      .withLogger(fhirLoggingInterceptor)
       .withResourceFormat(resourceFormat)
       .withRetryCount(retryCount)
       .withMessage(message)

org.hl7.fhir.r4/src/main/java/org/hl7/fhir/r4/utils/client/network/FhirLoggingInterceptor.java

@@ -0,0 +1,55 @@
+package org.hl7.fhir.r4.utils.client.network;
+
+import okhttp3.*;
+import org.hl7.fhir.utilities.ToolingClientLogger;
+import org.jetbrains.annotations.NotNull;
+
+import java.io.IOException;
+import java.util.ArrayList;
+import java.util.List;
+import java.util.Map;
+
+public class FhirLoggingInterceptor implements Interceptor {
+
+  private ToolingClientLogger logger;
+
+  public FhirLoggingInterceptor(ToolingClientLogger logger) {
+    this.logger = logger;
+  }
+
+  public FhirLoggingInterceptor setLogger(ToolingClientLogger logger) {
+    this.logger = logger;
+    return this;
+  }
+
+  @NotNull
+  @Override
+  public Response intercept(@NotNull Interceptor.Chain chain) throws IOException {
+    // Log Request
+    Request request = chain.request();
+    logger.logRequest(request.method(), request.url().toString(), new ArrayList<>(request.headers().names()),
+      request.body() != null ? request.body().toString().getBytes() : null);
+
+    // Log Response
+    Response response = null;
+    response = chain.proceed(chain.request());
+
+    MediaType contentType = null;
+    byte[] bodyBytes = null;
+    if (response.body() != null) {
+      contentType = response.body().contentType();
+      bodyBytes = response.body().bytes();
+    }
+
+    // Get Headers as List
+    List<String> headerList = new ArrayList<>();
+    Map<String, List<String>> headerMap = response.headers().toMultimap();
+    headerMap.keySet().forEach(key -> headerMap.get(key).forEach(value -> headerList.add(key + ":" + value)));
+
+    logger.logResponse(Integer.toString(response.code()), headerList, bodyBytes);
+
+    // Reading byte[] clears body. Need to recreate.
+    ResponseBody body = ResponseBody.create(bodyBytes, contentType);
+    return response.newBuilder().body(body).build();
+  }
+}

org.hl7.fhir.r4/src/main/java/org/hl7/fhir/r4/utils/client/network/FhirRequestBuilder.java

@@ -45,10 +45,11 @@ public class FhirRequestBuilder {
    * Time unit for {@link FhirRequestBuilder#timeout}.
    */
   private TimeUnit timeoutUnit = TimeUnit.MILLISECONDS;
+
   /**
-   * {@link ToolingClientLogger} for log output.
+   * {@link FhirLoggingInterceptor} for log output.
    */
-  private ToolingClientLogger logger = null;
+  private FhirLoggingInterceptor logger = null;
 
   public FhirRequestBuilder(Request.Builder httpRequest) {
     this.httpRequest = httpRequest;
@@ -160,7 +161,11 @@ public class FhirRequestBuilder {
         .build();
     };
 
-    return okHttpClient.newBuilder()
+    OkHttpClient.Builder builder = okHttpClient.newBuilder();
+    if (logger != null) builder.addInterceptor(logger);
+    builder.addInterceptor(new RetryInterceptor(retryCount));
+
+    return builder.connectTimeout(timeout, timeoutUnit)
       .addInterceptor(new RetryInterceptor(retryCount))
       .connectTimeout(timeout, timeoutUnit)
       .writeTimeout(timeout, timeoutUnit)
@@ -189,7 +194,7 @@ public class FhirRequestBuilder {
     return this;
   }
 
-  public FhirRequestBuilder withLogger(ToolingClientLogger logger) {
+  public FhirRequestBuilder withLogger(FhirLoggingInterceptor logger) {
     this.logger = logger;
     return this;
   }
@@ -228,7 +233,6 @@ public class FhirRequestBuilder {
     if (response.body() != null) {
       try {
         byte[] body = response.body().bytes();
-        log(response.code(), response.headers(), body);
         resource = (T) getParser(format).parse(body);
         if (resource instanceof OperationOutcome && hasError((OperationOutcome) resource)) {
           error = (OperationOutcome) resource;
@@ -255,7 +259,6 @@ public class FhirRequestBuilder {
     OperationOutcome error = null;
     try {
       byte[] body = response.body().bytes();
-      log(response.code(), response.headers(), body);
       String contentType = response.header("Content-Type");
       if (body != null) {
         if (contentType.contains(ResourceFormat.RESOURCE_XML.getHeader()) || contentType.contains("text/xml+fhir")) {
@@ -301,30 +304,4 @@ public class FhirRequestBuilder {
       throw new EFhirClientException("Invalid format: " + format);
     }
   }
-
-  /**
-   * Logs the given {@link Response}, using the current {@link ToolingClientLogger}. If the current
-   * {@link FhirRequestBuilder#logger} is null, no action is taken.
-   *
-   * @param responseCode    HTTP response code
-   * @param responseHeaders {@link Headers} from response
-   * @param responseBody    Byte array response
-   */
-  protected void log(int responseCode, Headers responseHeaders, byte[] responseBody) {
-    if (logger != null) {
-      List<String> headerList = new ArrayList<>(Collections.emptyList());
-      Map<String, List<String>> headerMap = responseHeaders.toMultimap();
-      headerMap.keySet().forEach(key -> headerMap.get(key).forEach(value -> headerList.add(key + ":" + value)));
-
-      try {
-        logger.logResponse(Integer.toString(responseCode), headerList, responseBody);
-      } catch (Exception e) {
-        System.out.println("Error parsing response body passed in to logger ->\n" + e.getLocalizedMessage());
-      }
-    }
-//    else { // TODO fix logs
-//      System.out.println("Call to log HTTP response with null ToolingClientLogger set... are you forgetting to " +
-//        "initialize your logger?");
-//    }
-  }
 }

org.hl7.fhir.r5/pom.xml

@@ -107,6 +107,12 @@
 			<version>4.9.0</version>
 			<optional>true</optional>
 		</dependency>
+		<dependency>
+			<groupId>com.squareup.okhttp3</groupId>
+			<artifactId>logging-interceptor</artifactId>
+			<version>4.9.0</version>
+			<optional>true</optional>
+		</dependency>
 
 		<!-- Test dependencies -->
 		<dependency>

org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/context/HTMLClientLogger.java

@@ -42,7 +42,7 @@ import org.hl7.fhir.utilities.Utilities;
 
 public class HTMLClientLogger extends BaseLogger implements ToolingClientLogger {
 
-  private static final boolean DEBUG = false;
+  private static final boolean DEBUG = true;
   
   private PrintStream file;
   

org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/utils/client/FHIRToolingClient.java

@@ -308,15 +308,9 @@ public class FHIRToolingClient {
       URI url = resourceAddress.resolveOperationURLFromClass(resourceClass, name, ps);
       if (complex) {
         byte[] body = ByteUtils.resourceToByteArray(params, false, isJson(getPreferredResourceFormat()));
-        if (client.getLogger() != null) {
-          client.getLogger().logRequest("POST", url.toString(), null, body);
-        }
         result = client.issuePostRequest(url, body, getPreferredResourceFormat(), generateHeaders(),
             "POST " + resourceClass.getName() + "/$" + name, TIMEOUT_OPERATION_LONG);
       } else {
-        if (client.getLogger() != null) {
-          client.getLogger().logRequest("GET", url.toString(), null, null);
-        }
         result = client.issueGetResourceRequest(url, getPreferredResourceFormat(), generateHeaders(), "GET " + resourceClass.getName() + "/$" + name, TIMEOUT_OPERATION_LONG);
       }
       if (result.isUnsuccessfulRequest()) {

org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/utils/client/network/Client.java

@@ -4,6 +4,7 @@ import okhttp3.Headers;
 import okhttp3.MediaType;
 import okhttp3.Request;
 import okhttp3.RequestBody;
+import okhttp3.logging.HttpLoggingInterceptor;
 import org.hl7.fhir.r5.model.Bundle;
 import org.hl7.fhir.r5.model.Resource;
 import org.hl7.fhir.r5.utils.client.EFhirClientException;
@@ -19,6 +20,7 @@ public class Client {
   public static final String DEFAULT_CHARSET = "UTF-8";
   private static final long DEFAULT_TIMEOUT = 5000;
   private ToolingClientLogger logger;
+  private FhirLoggingInterceptor fhirLoggingInterceptor;
   private int retryCount;
   private long timeout = DEFAULT_TIMEOUT;
 
@@ -28,6 +30,7 @@ public class Client {
 
   public void setLogger(ToolingClientLogger logger) {
     this.logger = logger;
+    this.fhirLoggingInterceptor = new FhirLoggingInterceptor(logger);
   }
 
   public int getRetryCount() {
@@ -168,7 +171,7 @@ public class Client {
                                                              int retryCount,
                                                              long timeout) throws IOException {
     return new FhirRequestBuilder(request)
-      .withLogger(logger)
+      .withLogger(fhirLoggingInterceptor)
       .withResourceFormat(resourceFormat)
       .withRetryCount(retryCount)
       .withMessage(message)
@@ -184,7 +187,7 @@ public class Client {
                                                                        int retryCount,
                                                                        long timeout) throws IOException {
     return new FhirRequestBuilder(request)
-      .withLogger(logger)
+      .withLogger(fhirLoggingInterceptor)
       .withResourceFormat(resourceFormat)
       .withRetryCount(retryCount)
       .withMessage(message)

org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/utils/client/network/FhirLoggingInterceptor.java

@@ -0,0 +1,55 @@
+package org.hl7.fhir.r5.utils.client.network;
+
+import okhttp3.*;
+import org.hl7.fhir.utilities.ToolingClientLogger;
+import org.jetbrains.annotations.NotNull;
+
+import java.io.IOException;
+import java.util.ArrayList;
+import java.util.List;
+import java.util.Map;
+
+public class FhirLoggingInterceptor implements Interceptor {
+
+  private ToolingClientLogger logger;
+
+  public FhirLoggingInterceptor(ToolingClientLogger logger) {
+    this.logger = logger;
+  }
+
+  public FhirLoggingInterceptor setLogger(ToolingClientLogger logger) {
+    this.logger = logger;
+    return this;
+  }
+
+  @NotNull
+  @Override
+  public Response intercept(@NotNull Interceptor.Chain chain) throws IOException {
+    // Log Request
+    Request request = chain.request();
+    logger.logRequest(request.method(), request.url().toString(), new ArrayList<>(request.headers().names()),
+      request.body() != null ? request.body().toString().getBytes() : null);
+
+    // Log Response
+    Response response = null;
+    response = chain.proceed(chain.request());
+
+    MediaType contentType = null;
+    byte[] bodyBytes = null;
+    if (response.body() != null) {
+      contentType = response.body().contentType();
+      bodyBytes = response.body().bytes();
+    }
+
+    // Get Headers as List
+    List<String> headerList = new ArrayList<>();
+    Map<String, List<String>> headerMap = response.headers().toMultimap();
+    headerMap.keySet().forEach(key -> headerMap.get(key).forEach(value -> headerList.add(key + ":" + value)));
+
+    logger.logResponse(Integer.toString(response.code()), headerList, bodyBytes);
+
+    // Reading byte[] clears body. Need to recreate.
+    ResponseBody body = ResponseBody.create(bodyBytes, contentType);
+    return response.newBuilder().body(body).build();
+  }
+}

org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/utils/client/network/FhirRequestBuilder.java

@@ -45,10 +45,11 @@ public class FhirRequestBuilder {
    * Time unit for {@link FhirRequestBuilder#timeout}.
    */
   private TimeUnit timeoutUnit = TimeUnit.MILLISECONDS;
+
   /**
-   * {@link ToolingClientLogger} for log output.
+   * {@link FhirLoggingInterceptor} for log output.
    */
-  private ToolingClientLogger logger = null;
+  private FhirLoggingInterceptor logger = null;
 
   public FhirRequestBuilder(Request.Builder httpRequest) {
     this.httpRequest = httpRequest;
@@ -160,9 +161,11 @@ public class FhirRequestBuilder {
         .build();
     };
 
-    return okHttpClient.newBuilder()
+    OkHttpClient.Builder builder = okHttpClient.newBuilder();
-      .addInterceptor(new RetryInterceptor(retryCount))
+    if (logger != null) builder.addInterceptor(logger);
-      .connectTimeout(timeout, timeoutUnit)
+    builder.addInterceptor(new RetryInterceptor(retryCount));
+
+    return builder.connectTimeout(timeout, timeoutUnit)
       .writeTimeout(timeout, timeoutUnit)
       .readTimeout(timeout, timeoutUnit)
       .proxyAuthenticator(proxyAuthenticator)
@@ -189,7 +192,7 @@ public class FhirRequestBuilder {
     return this;
   }
 
-  public FhirRequestBuilder withLogger(ToolingClientLogger logger) {
+  public FhirRequestBuilder withLogger(FhirLoggingInterceptor logger) {
     this.logger = logger;
     return this;
   }
@@ -228,7 +231,6 @@ public class FhirRequestBuilder {
     if (response.body() != null) {
       try {
         byte[] body = response.body().bytes();
-        log(response.code(), response.headers(), body);
         resource = (T) getParser(format).parse(body);
         if (resource instanceof OperationOutcome && hasError((OperationOutcome) resource)) {
           error = (OperationOutcome) resource;
@@ -255,7 +257,6 @@ public class FhirRequestBuilder {
     OperationOutcome error = null;
     try {
       byte[] body = response.body().bytes();
-      log(response.code(), response.headers(), body);
       String contentType = response.header("Content-Type");
       if (body != null) {
         if (contentType.contains(ResourceFormat.RESOURCE_XML.getHeader()) || contentType.contains("text/xml+fhir")) {
@@ -301,30 +302,4 @@ public class FhirRequestBuilder {
       throw new EFhirClientException("Invalid format: " + format);
     }
   }
-
-  /**
-   * Logs the given {@link Response}, using the current {@link ToolingClientLogger}. If the current
-   * {@link FhirRequestBuilder#logger} is null, no action is taken.
-   *
-   * @param responseCode    HTTP response code
-   * @param responseHeaders {@link Headers} from response
-   * @param responseBody    Byte array response
-   */
-  protected void log(int responseCode, Headers responseHeaders, byte[] responseBody) {
-    if (logger != null) {
-      List<String> headerList = new ArrayList<>(Collections.emptyList());
-      Map<String, List<String>> headerMap = responseHeaders.toMultimap();
-      headerMap.keySet().forEach(key -> headerMap.get(key).forEach(value -> headerList.add(key + ":" + value)));
-
-      try {
-        logger.logResponse(Integer.toString(responseCode), headerList, responseBody);
-      } catch (Exception e) {
-        System.out.println("Error parsing response body passed in to logger ->\n" + e.getLocalizedMessage());
-      }
-    }
-//    else { // TODO fix logs
-//      System.out.println("Call to log HTTP response with null ToolingClientLogger set... are you forgetting to " +
-//        "initialize your logger?");
-//    }
-  }
 }

org.hl7.fhir.r5/src/test/java/org/hl7/fhir/r5/utils/client/network/ClientTest.java

@@ -4,9 +4,11 @@ import okhttp3.HttpUrl;
 import okhttp3.mockwebserver.MockResponse;
 import okhttp3.mockwebserver.MockWebServer;
 import okhttp3.mockwebserver.RecordedRequest;
+import org.hl7.fhir.r5.context.HTMLClientLogger;
 import org.hl7.fhir.r5.formats.JsonParser;
 import org.hl7.fhir.r5.model.*;
 import org.junit.jupiter.api.*;
+import org.mockito.Mockito;
 
 import java.io.IOException;
 import java.net.URI;
@@ -143,4 +145,24 @@ class ClientTest {
     Assertions.assertArrayEquals(payload, recordedRequest.getBody().readByteArray(),
       "POST request payload does not match send data.");
   }
+
+  @Test
+  @DisplayName("Testing the logger works.")
+  void test_logger() throws IOException, URISyntaxException, InterruptedException {
+    byte[] payload = ByteUtils.resourceToByteArray(patient, true, false);
+    server.enqueue(
+      new MockResponse()
+        .setResponseCode(200)
+        .setBody(new String(payload))
+    );
+    HTMLClientLogger mockLogger = Mockito.mock(HTMLClientLogger.class);
+    client.setLogger(mockLogger);
+    client.issuePostRequest(new URI(serverUrl.toString()), payload,
+      "xml", null, TIMEOUT);
+    server.takeRequest();
+    Mockito.verify(mockLogger, Mockito.times(1))
+      .logRequest(Mockito.anyString(), Mockito.anyString(), Mockito.anyList(), Mockito.any());
+    Mockito.verify(mockLogger, Mockito.times(1))
+      .logResponse(Mockito.anyString(), Mockito.anyList(), Mockito.any());
+  }
 }

org.hl7.fhir.utilities/pom.xml

@@ -86,6 +86,12 @@
             <version>${validator_test_case_version}</version>
             <scope>test</scope>
         </dependency>
+        <dependency>
+            <groupId>com.squareup.okhttp3</groupId>
+            <artifactId>logging-interceptor</artifactId>
+            <version>4.9.0</version>
+            <scope>compile</scope>
+        </dependency>
     </dependencies>
 
     <build>

org.hl7.fhir.utilities/src/main/java/org/hl7/fhir/utilities/ToolingClientLogger.java

@@ -35,10 +35,9 @@ import java.util.List;
 
 public interface ToolingClientLogger {
 
-  public void logRequest(String method, String url, List<String> headers, byte[] body);
+  void logRequest(String method, String url, List<String> headers, byte[] body);
-  public void logResponse(String outcome, List<String> headers, byte[] body);
+  void logResponse(String outcome, List<String> headers, byte[] body);
-  public String getLastId();
+  String getLastId();
-  public void clearLastId();
+  void clearLastId();
-
 
 }