From 3aa417be4fa1bc04891c49b869b925e63a3d8f37 Mon Sep 17 00:00:00 2001
From: ebrahimiar <66822910+ebrahimiar@users.noreply.github.com>
Date: Mon, 1 Jul 2024 11:39:27 +0330
Subject: [PATCH] [feature] adding service call duration in log handler. (#5)

The format of request and response log has been changed to json.
Request log consists of "soap-request" field.
Successful response log consist of "soap-response" and "duration field."
Unsuccessful response log consist of "soap-fault" and "duration" field.
---
 pom.xml                                       |  5 +++
 tosan-soap-client/pom.xml                     |  4 ++
 .../tosan/client/soap/handler/LogHandler.java | 45 ++++++++++++++++---
 3 files changed, 48 insertions(+), 6 deletions(-)

diff --git a/pom.xml b/pom.xml
index 456a58b..d9dd284 100644
--- a/pom.xml
+++ b/pom.xml
@@ -75,6 +75,11 @@
                 <artifactId>jakarta.jws-api</artifactId>
                 <version>3.0.0</version>
             </dependency>
+            <dependency>
+                <groupId>com.fasterxml.jackson.core</groupId>
+                <artifactId>jackson-databind</artifactId>
+                <version>2.17.1</version>
+            </dependency>
             <dependency>
                 <groupId>com.sun.xml.ws</groupId>
                 <artifactId>jaxws-rt</artifactId>
diff --git a/tosan-soap-client/pom.xml b/tosan-soap-client/pom.xml
index 23af6a3..437585f 100644
--- a/tosan-soap-client/pom.xml
+++ b/tosan-soap-client/pom.xml
@@ -20,6 +20,10 @@
             <groupId>org.slf4j</groupId>
             <artifactId>jul-to-slf4j</artifactId>
         </dependency>
+        <dependency>
+            <groupId>com.fasterxml.jackson.core</groupId>
+            <artifactId>jackson-databind</artifactId>
+        </dependency>
         <dependency>
             <groupId>jakarta.xml.bind</groupId>
             <artifactId>jakarta.xml.bind-api</artifactId>
diff --git a/tosan-soap-client/src/main/java/com/tosan/client/soap/handler/LogHandler.java b/tosan-soap-client/src/main/java/com/tosan/client/soap/handler/LogHandler.java
index 9981998..00df9c7 100644
--- a/tosan-soap-client/src/main/java/com/tosan/client/soap/handler/LogHandler.java
+++ b/tosan-soap-client/src/main/java/com/tosan/client/soap/handler/LogHandler.java
@@ -1,5 +1,9 @@
 package com.tosan.client.soap.handler;
 
+import com.fasterxml.jackson.annotation.JsonInclude;
+import com.fasterxml.jackson.databind.DeserializationFeature;
+import com.fasterxml.jackson.databind.ObjectMapper;
+import com.fasterxml.jackson.databind.SerializationFeature;
 import jakarta.xml.soap.SOAPMessage;
 import jakarta.xml.ws.handler.MessageContext;
 import jakarta.xml.ws.handler.soap.SOAPHandler;
@@ -10,6 +14,8 @@
 import javax.xml.namespace.QName;
 import java.io.ByteArrayOutputStream;
 import java.io.OutputStream;
+import java.util.LinkedHashMap;
+import java.util.Map;
 import java.util.Set;
 
 /**
@@ -18,8 +24,16 @@
  */
 public class LogHandler implements SOAPHandler<SOAPMessageContext> {
     private static final Logger logger = LoggerFactory.getLogger(LogHandler.class);
+    private static final ObjectMapper mapper = new ObjectMapper();
     private Set<String> securedParameterNames;
+    ThreadLocal<Long> startTimeMillis = new ThreadLocal<>();
 
+    static {
+        mapper.enable(SerializationFeature.INDENT_OUTPUT)
+                .disable(SerializationFeature.FAIL_ON_EMPTY_BEANS)
+                .setSerializationInclusion(JsonInclude.Include.NON_NULL)
+                .configure(DeserializationFeature.FAIL_ON_UNKNOWN_PROPERTIES, false);
+    }
     public LogHandler() {
     }
 
@@ -31,33 +45,52 @@ public boolean handleMessage(SOAPMessageContext messageContext) {
         SOAPMessage msg = messageContext.getMessage();
         boolean request = (Boolean) messageContext.get(SOAPMessageContext.MESSAGE_OUTBOUND_PROPERTY);
         OutputStream logStream = new ByteArrayOutputStream();
+        Map<String, String> logParams = new LinkedHashMap<>();
         try {
+            msg.writeTo(logStream);
             if (request) {
-                logStream.write("Soap Request: ".getBytes());
+                logParams.put("soap-request", getBody(logStream));
+                startTimeMillis.set(System.currentTimeMillis());
             } else {
-                logStream.write("Soap Response: ".getBytes());
+                logParams.put("soap-response", getBody(logStream));
+                logParams.put("duration", getDurationLogMessage());
             }
-            msg.writeTo(logStream);
-            logger.info(LogEncryptor.encrypt(logStream.toString(), securedParameterNames));
+            logger.info(mapper.writeValueAsString(logParams));
         } catch (Exception e) {
             logger.info("Error in logger: ", e);
+        } finally {
+            if (!request) {
+                startTimeMillis.remove();
+            }
         }
         return true;
     }
 
+    private String getBody(OutputStream logStream) {
+        return LogEncryptor.encrypt(logStream.toString(), securedParameterNames);
+    }
+
     public boolean handleFault(SOAPMessageContext c) {
         SOAPMessage msg = c.getMessage();
         try {
             OutputStream logStream = new ByteArrayOutputStream();
-            logStream.write("Soap Fault Recognized: ".getBytes());
             msg.writeTo(logStream);
-            logger.info(logStream.toString());
+            Map<String, String> params = new LinkedHashMap<>();
+            params.put("soap-fault", getBody(logStream));
+            params.put("duration", getDurationLogMessage());
+            logger.info(mapper.writeValueAsString(params));
         } catch (Exception e) {
             logger.info("Error in logger: ", e);
+        } finally {
+            startTimeMillis.remove();
         }
         return true;
     }
 
+    private String getDurationLogMessage() {
+        return (System.currentTimeMillis() - startTimeMillis.get()) / 1000.0 + "s";
+    }
+
     public void close(MessageContext c) {
     }