Ensure that Each Step of Each Backend Process is Logged

12 files changed, 52 insertions, 18 deletions

diff --git a/src/main/java/at/gv/egiz/moazs/backend/DeliveryRequestBackend.java b/src/main/java/at/gv/egiz/moazs/backend/DeliveryRequestBackend.java
index 178e26c..c4207f0 100644
--- a/src/main/java/at/gv/egiz/moazs/backend/DeliveryRequestBackend.java
+++ b/src/main/java/at/gv/egiz/moazs/backend/DeliveryRequestBackend.java
@@ -37,6 +37,9 @@ public class DeliveryRequestBackend implements Consumer<String> {
             "DeliveryRequest for AppDeliveryID=%s is not in repository. " ;
     private static final String BINARY_RESPONSE_MISSING_ERROR_MSG =
             "Binary DeliveryRequestStatus for AppDeliveryID=%s is not in repository. " ;
+    private static final String BACKEND_ACCEPT_MSG =
+            "Backend accepts mzs:DeliveryRequest with AppDeliveryID={}.";
+
 
     private static final at.gv.zustellung.app2mzs.xsd.ObjectFactory mzsOF = new at.gv.zustellung.app2mzs.xsd.ObjectFactory();
     private static final at.gv.zustellung.msg.xsd.ObjectFactory msgOF = new at.gv.zustellung.msg.xsd.ObjectFactory();
@@ -79,12 +82,12 @@ public class DeliveryRequestBackend implements Consumer<String> {
     @Override
     public void accept(String appDeliveryID) {
 
+        log.info(BACKEND_ACCEPT_MSG, appDeliveryID);
         DeliveryRequestStatusType status = null;
         var fallbackAnswerBuilder = errorBuilder().withAppDeliveryID(appDeliveryID);
 
         try {
 
-            log.trace("Fetch mzs:DeliveryRequest wiht AppDeliveryID={} from repository.", appDeliveryID);
             var mzsRequest = repository.retrieveDeliveryRequest(appDeliveryID).orElseThrow(
                     () -> moaZSException(format(DELIVERY_REQUEST_MISSING_ERROR_MSG, appDeliveryID)));
             traceMzsRequest(mzsRequest);
diff --git a/src/main/java/at/gv/egiz/moazs/backend/ForwardResponseToServiceSink.java b/src/main/java/at/gv/egiz/moazs/backend/ForwardResponseToServiceSink.java
index 4b3c085..b64c186 100644
--- a/src/main/java/at/gv/egiz/moazs/backend/ForwardResponseToServiceSink.java
+++ b/src/main/java/at/gv/egiz/moazs/backend/ForwardResponseToServiceSink.java
@@ -6,6 +6,8 @@ import at.gv.egiz.moazs.scheme.Msg2MzsConverter;
 import at.gv.egiz.moazs.scheme.MsgResponse;
 import at.gv.zustellung.app2mzs.xsd.ClientType;
 import at.gv.zustellung.app2mzs.xsd.Mzs2AppPortType;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.stereotype.Component;
 
@@ -14,6 +16,8 @@ import java.util.concurrent.CompletableFuture;
 @Component
 public class ForwardResponseToServiceSink {
 
+    private static final Logger log = LoggerFactory.getLogger(ForwardResponseToServiceSink.class);
+
     private final ClientFactory factory;
     private final DeliveryRepository repository;
     private final Msg2MzsConverter converter;
@@ -26,6 +30,8 @@ public class ForwardResponseToServiceSink {
     }
 
     public CompletableFuture<Void> send(MsgResponse msgResponse, ClientType params) {
+        log.info("Forward msg:{} with AppDeliveryID={} to service at {}.",
+                msgResponse.getRootElementLocalPart(), msgResponse.getAppDeliveryID(), params.getURL());
         var binaryResponse = repository.retrieveBinaryResponse(msgResponse.getResponseID());
         Mzs2AppPortType client = factory.create(params, Mzs2AppPortType.class);
         return msgResponse.sendToMzsClient(converter, binaryResponse, client);
diff --git a/src/main/java/at/gv/egiz/moazs/backend/LogResponseSink.java b/src/main/java/at/gv/egiz/moazs/backend/LogResponseSink.java
index d419944..bf2e615 100644
--- a/src/main/java/at/gv/egiz/moazs/backend/LogResponseSink.java
+++ b/src/main/java/at/gv/egiz/moazs/backend/LogResponseSink.java
@@ -14,7 +14,6 @@ import static java.util.concurrent.CompletableFuture.completedFuture;
 public class LogResponseSink {
 
     private static final Logger log = LoggerFactory.getLogger(LogResponseSink.class);
-    private static final String LOG_LEVEL_WARN_MESSAGE = "Will not log response because INFO level is disabled.";
 
     private final Marshaller msgMarshaller;
 
@@ -35,7 +34,7 @@ public class LogResponseSink {
             builder.append(msgMarshaller.marshallXml(msgResponse.getResponseAsJAXBElement()));
             log.info(builder.toString());
         } else {
-            log.warn(LOG_LEVEL_WARN_MESSAGE);
+            log.warn("Will not log response because INFO level is disabled.");
         }
 
         return completedFuture(null);
diff --git a/src/main/java/at/gv/egiz/moazs/backend/MsgResponseBackend.java b/src/main/java/at/gv/egiz/moazs/backend/MsgResponseBackend.java
index df0f83e..844a559 100644
--- a/src/main/java/at/gv/egiz/moazs/backend/MsgResponseBackend.java
+++ b/src/main/java/at/gv/egiz/moazs/backend/MsgResponseBackend.java
@@ -51,6 +51,7 @@ public class MsgResponseBackend implements Consumer<String> {
      */
     @Override
     public void accept(String responseID) {
+        log.info("Backend accepts MsgResponse with responseID={}.", responseID);
         supplyAsync(() -> verifySignature(responseID))
                 .thenAcceptAsync(msgResponse -> applySinks(msgResponse))
                 .exceptionally(ex -> {
@@ -67,6 +68,10 @@ public class MsgResponseBackend implements Consumer<String> {
         try {
             var binaryResponse = repository.retrieveBinaryResponse(responseID).orElseThrow(
                     () -> moaZSException(BINARY_RESPONSE_MISSING_ERROR_MSG, MoaZSException.ERROR_MZS_BINARY_RESPONSE_MISSING));
+
+            log.info("Verify Signature of msg:{} with AppDeliveryID={}.",
+                    response.getRootElementLocalPart(), response.getAppDeliveryID());
+
             signatureVerifier.accept(binaryResponse);
             return response;
         } catch (MoaZSException ex) {
@@ -80,6 +85,7 @@ public class MsgResponseBackend implements Consumer<String> {
 
     private void applySinks(MsgResponse msgResponse) {
         var appDeliveryID = msgResponse.getAppDeliveryID();
+
         var request = repository.retrieveDeliveryRequest(appDeliveryID).orElseThrow(
                 ()-> moaZSException(format(REQUEST_MISSING_ERROR_MSG, appDeliveryID)));
 
diff --git a/src/main/java/at/gv/egiz/moazs/backend/MsgResponseSinkHub.java b/src/main/java/at/gv/egiz/moazs/backend/MsgResponseSinkHub.java
index 0df5c68..46b0101 100644
--- a/src/main/java/at/gv/egiz/moazs/backend/MsgResponseSinkHub.java
+++ b/src/main/java/at/gv/egiz/moazs/backend/MsgResponseSinkHub.java
@@ -2,6 +2,8 @@ package at.gv.egiz.moazs.backend;
 
 import at.gv.egiz.moazs.scheme.MsgResponse;
 import at.gv.zustellung.app2mzs.xsd.MsgResponseSinksType;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.stereotype.Component;
 
@@ -10,6 +12,8 @@ import static java.util.concurrent.CompletableFuture.supplyAsync;
 @Component
 public class MsgResponseSinkHub {
 
+    private static final Logger log = LoggerFactory.getLogger(MsgResponseSinkHub.class);
+
     private final SaveResponseToFileSink saveResponseSink;
     private final LogResponseSink logResponseSink;
     private final ForwardResponseToServiceSink forwardResponseSink;
@@ -27,6 +31,9 @@ public class MsgResponseSinkHub {
      */
     public void applySinks(MsgResponse msgResponse, MsgResponseSinksType sinkParams) {
 
+        log.info("Apply Sinks to msg:{} with appDeliveryID={}.",
+                msgResponse.getRootElementLocalPart(), msgResponse.getAppDeliveryID());
+
         if (sinkParams.getSaveResponseToFile().isActive()) {
             supplyAsync(() -> saveResponseSink.save(msgResponse, sinkParams.getSaveResponseToFile().getPath()));
         }
diff --git a/src/main/java/at/gv/egiz/moazs/backend/SaveResponseToFileSink.java b/src/main/java/at/gv/egiz/moazs/backend/SaveResponseToFileSink.java
index c58e1a5..38eef2e 100644
--- a/src/main/java/at/gv/egiz/moazs/backend/SaveResponseToFileSink.java
+++ b/src/main/java/at/gv/egiz/moazs/backend/SaveResponseToFileSink.java
@@ -48,6 +48,8 @@ public class SaveResponseToFileSink {
     public CompletableFuture<Void> save(MsgResponse response, String rootPath) {
 
         var responseID = response.getResponseID();
+        log.info("Save msg:{} with AppDeliveryID={}.",
+                response.getRootElementLocalPart(), response.getAppDeliveryID());
 
         var responsePath = generatePath(rootPath, responseID, "xml");
         var storeResponseToFileSystemFuture = supplyAsync(() -> msgMarshaller.marshallXml(response.getResponseAsJAXBElement()))
diff --git a/src/main/java/at/gv/egiz/moazs/client/ClientFactory.java b/src/main/java/at/gv/egiz/moazs/client/ClientFactory.java
index f173467..44da83a 100644
--- a/src/main/java/at/gv/egiz/moazs/client/ClientFactory.java
+++ b/src/main/java/at/gv/egiz/moazs/client/ClientFactory.java
@@ -65,6 +65,9 @@ public class ClientFactory {
     }
 
     private <T> T createClient(ClientType params, Class<T> clazz) {
+
+        log.info("Create client for service {}", params.getURL());
+
         var factory = new JaxWsClientFactoryBean();
         factory.setServiceClass(clazz);
         factory.setAddress(params.getURL());
diff --git a/src/main/java/at/gv/egiz/moazs/client/TnvzHelper.java b/src/main/java/at/gv/egiz/moazs/client/TnvzHelper.java
index a304bdf..1e84e43 100644
--- a/src/main/java/at/gv/egiz/moazs/client/TnvzHelper.java
+++ b/src/main/java/at/gv/egiz/moazs/client/TnvzHelper.java
@@ -9,6 +9,8 @@ import at.gv.zustellung.msg.xsd.persondata.ObjectFactory;
 import at.gv.zustellung.msg.xsd.persondata.PostalAddressType;
 import at.gv.zustellung.tnvz.xsd.*;
 import at.gv.zustellung.tnvz.xsd.QueryPersonRequest.QueryEntryList;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.stereotype.Component;
 
@@ -32,8 +34,7 @@ import static java.util.stream.Collectors.toSet;
 @Component
 public class TnvzHelper {
 
-    private final Mzs2MsgConverter converter;
-
+    private static final Logger log = LoggerFactory.getLogger(TnvzHelper.class);
     private static final ObjectFactory FACTORY = new at.gv.zustellung.msg.xsd.persondata.ObjectFactory();
     private static final String ENTRY_ID = "entry-id";
     private static final String RECEIVER_NOT_ADRESSABLE_ERROR_MSG = "Receiver is not addressable. Reason: %s";
@@ -41,6 +42,8 @@ public class TnvzHelper {
             "receiver only accepts attachments of type(s) %s.";
     private static final String MZS_NO_TNVZ_PERSON_QUERY_RESULTS_ERROR_MSG = "tnvz:QueryResultList was empty.";
 
+    private final Mzs2MsgConverter converter;
+
 
     @Autowired
     public TnvzHelper(Mzs2MsgConverter converter) {
@@ -59,6 +62,9 @@ public class TnvzHelper {
     public IdentificationType performQueryPersonRequest(DeliveryRequestType mzsRequest,
                                                         TNVZServicePort tvnzPort) {
 
+        log.info("Perform Query Person Request for mzs:DeliveryRequest with AppDeliveryID={}",
+                mzsRequest.getMetaData().getAppDeliveryID());
+
         var tvnzQuery = buildQuery(mzsRequest);
         var tvnzResponse = tvnzPort.queryPerson(tvnzQuery);
         verifyResponse(tvnzResponse);
diff --git a/src/main/java/at/gv/egiz/moazs/config/MoaSigConfig.java b/src/main/java/at/gv/egiz/moazs/config/MoaSigConfig.java
index c2f06c2..5615131 100644
--- a/src/main/java/at/gv/egiz/moazs/config/MoaSigConfig.java
+++ b/src/main/java/at/gv/egiz/moazs/config/MoaSigConfig.java
@@ -48,15 +48,15 @@ public class MoaSigConfig {
     }
 
     private void fallBackToSpringEnvForMoaSPSSConfigProperty() throws IOException {
-        log.info("value of spssConfigFilePath is {}", spssConfigFilePath);
+        log.debug("Value of spssConfigFilePath is {}", spssConfigFilePath);
 
         if(System.getProperty(MOA_SPSS_CONFIG_FILE_PROPERTY) == null) {
 
             var realFile = new File(fileUtils.determinePath(spssConfigFilePath));
-            log.info("spssConfigFilePath.getCanonicalPath(): ", realFile.getCanonicalPath());
+            log.debug("spssConfigFilePath.getCanonicalPath(): ", realFile.getCanonicalPath());
 
             if(realFile.exists() && realFile.canRead()) {
-                log.info(SET_PROPERTY_MSG_TEMPLATE, MOA_SPSS_CONFIG_FILE_PROPERTY, realFile.getCanonicalPath());
+                log.debug(SET_PROPERTY_MSG_TEMPLATE, MOA_SPSS_CONFIG_FILE_PROPERTY, realFile.getCanonicalPath());
                 System.getProperties().setProperty(MOA_SPSS_CONFIG_FILE_PROPERTY, realFile.getCanonicalPath());
             } else {
                 throw new FileNotFoundException("File '" + realFile.getCanonicalPath() + "' does not exist or is not readable.");
diff --git a/src/main/java/at/gv/egiz/moazs/preprocess/DeliveryRequestAugmenter.java b/src/main/java/at/gv/egiz/moazs/preprocess/DeliveryRequestAugmenter.java
index 240a677..4796844 100644
--- a/src/main/java/at/gv/egiz/moazs/preprocess/DeliveryRequestAugmenter.java
+++ b/src/main/java/at/gv/egiz/moazs/preprocess/DeliveryRequestAugmenter.java
@@ -51,15 +51,15 @@ public class DeliveryRequestAugmenter {
         var fallbackProfileId = determineProfileIdFrom(requestConfig);
         var fallbackConfig = configs.get(fallbackProfileId);
 
-        trace("request config", requestConfig);
-        trace("fallback config", fallbackConfig);
+        trace("Request config", requestConfig);
+        trace("Fallback config", fallbackConfig);
 
         var augmentedConfig = (requestConfig != null && fallbackConfig != null)
                 ? util.merge(requestConfig, fallbackConfig)
                 : coalesce(requestConfig, fallbackConfig)
                     .orElseThrow(()-> moaZSException(CONFIG_MISSING_ERROR_MSG));
 
-        trace("augmented config", augmentedConfig);
+        trace("Augmented config", augmentedConfig);
 
         validator.isConfigProfileComplete(augmentedConfig);
 
diff --git a/src/main/java/at/gv/egiz/moazs/repository/InMemoryDeliveryRepository.java b/src/main/java/at/gv/egiz/moazs/repository/InMemoryDeliveryRepository.java
index b8a6d78..23c534c 100644
--- a/src/main/java/at/gv/egiz/moazs/repository/InMemoryDeliveryRepository.java
+++ b/src/main/java/at/gv/egiz/moazs/repository/InMemoryDeliveryRepository.java
@@ -32,41 +32,42 @@ public class InMemoryDeliveryRepository implements DeliveryRepository {
         this.binaryResponseRepository = builder.build();
     }
 
+    //TODO: Handle all "key exists" cases!
     @Override
     public void store(DeliveryRequestType request) {
         var key = request.getMetaData().getAppDeliveryID();
-        log.trace("Store DeliveryRequest by key={}", key);
+        log.info("Store DeliveryRequest by key={}.", key);
         requestRepository.put(key, request);
     }
 
     @Override
     public Optional<DeliveryRequestType> retrieveDeliveryRequest(String appDeliveryID) {
-        log.trace("Retrieve DeliveryRequest by key={}", appDeliveryID);
+        log.info("Retrieve DeliveryRequest by key={}.", appDeliveryID);
         return ofNullable(requestRepository.getIfPresent(appDeliveryID));
     }
 
     @Override
     public void store(MsgResponse response) {
         String key = response.getResponseID();
-        log.trace("Store MsgResponse by key={}", key);
+        log.info("Store MsgResponse by key={}.", key);
         responseRepository.put(key, response);
     }
 
     @Override
     public Optional<MsgResponse> retrieveResponse(String responseID) {
-        log.trace("Retrieve MsgResponse by key={}", responseID);
+        log.info("Retrieve MsgResponse by key={}.", responseID);
         return ofNullable(responseRepository.getIfPresent(responseID));
     }
 
     @Override
     public void store(String responseID, byte[] data) {
-        log.trace("Store Binary MsgResponse by key={}", responseID);
+        log.info("Store Binary MsgResponse by key={}.", responseID);
         binaryResponseRepository.put(responseID, data);
     }
 
     @Override
     public Optional<byte[]> retrieveBinaryResponse(String responseID) {
-        log.trace("Retrieve Binary MsgResponse by key={}", responseID);
+        log.info("Retrieve Binary MsgResponse by key={}.", responseID);
         return ofNullable(binaryResponseRepository.getIfPresent(responseID));
     }
 
diff --git a/src/main/java/at/gv/egiz/moazs/scheme/MsgResponse.java b/src/main/java/at/gv/egiz/moazs/scheme/MsgResponse.java
index c4fd0b7..f105278 100644
--- a/src/main/java/at/gv/egiz/moazs/scheme/MsgResponse.java
+++ b/src/main/java/at/gv/egiz/moazs/scheme/MsgResponse.java
@@ -26,12 +26,13 @@ public abstract class MsgResponse <T> {
     public String getResponseID() {
         return id;
     }
+    public String getRootElementLocalPart() {return getResponseAsJAXBElement().getName().getLocalPart();}
 
+    public abstract DeliveryAnswerType getAnswer();
     public abstract T getResponse();
     public abstract JAXBElement<T> getResponseAsJAXBElement();
     public abstract String getAppDeliveryID();
     public abstract String getZSDeliveryID();
-    public abstract DeliveryAnswerType getAnswer();
 
     /**
      * Create an error response that is based on the current response.