[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

@@ -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>

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>

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) {
     }