Sink all Async-Jobs logging to same debug.log

Error events are _replicated_ to error.log

Main incentive is to have all JobWorker, ResourceCommand
and MsoResultHandlerService logging the job life-cycle on
same page.

Issue-ID: VID-253
Change-Id: I862b408d71767ca3d5e6da3071bbae751261587e
Signed-off-by: Ittay Stern <ittay.stern@att.com>

12 files changed, 43 insertions, 25 deletions

diff --git a/vid-app-common/src/main/java/org/onap/vid/job/command/MacroServiceCommand.kt b/vid-app-common/src/main/java/org/onap/vid/job/command/MacroServiceCommand.kt
index 8ce73d713..2fdd19100 100644
--- a/vid-app-common/src/main/java/org/onap/vid/job/command/MacroServiceCommand.kt
+++ b/vid-app-common/src/main/java/org/onap/vid/job/command/MacroServiceCommand.kt
@@ -62,13 +62,13 @@ class MacroServiceCommand @Autowired constructor(
 
         //Aai return bad response while checking names uniqueness
         catch (exception : ExceptionWithRequestInfo) {
-            Logger.error("Failed to check name uniqueness in AAI. VID will try again later", exception)
+            Logger.error(EELFLoggerDelegate.errorLogger, "Failed to check name uniqueness in AAI. VID will try again later", exception)
             throw TryAgainException(exception);
         }
 
         //Vid reached to max retries while trying to find unique name in AAI
         catch (exception : MaxRetriesException) {
-            Logger.error("Failed to find unused name in AAI", exception)
+            Logger.error(EELFLoggerDelegate.errorLogger, "Failed to find unused name in AAI", exception)
             throw AbortingException(exception);
         }
     }
diff --git a/vid-app-common/src/main/java/org/onap/vid/job/command/MsoRequestBuilder.kt b/vid-app-common/src/main/java/org/onap/vid/job/command/MsoRequestBuilder.kt
index c392d0758..e46a24f78 100644
--- a/vid-app-common/src/main/java/org/onap/vid/job/command/MsoRequestBuilder.kt
+++ b/vid-app-common/src/main/java/org/onap/vid/job/command/MsoRequestBuilder.kt
@@ -209,7 +209,7 @@ class MsoRequestBuilder
         try {
             asyncInstantiationBL.updateServiceInfo(jobId) { x -> x.serviceInstanceName = serviceInstanceName }
         } catch (e: Exception) {
-            LOGGER.error("Failed updating service name {} in serviceInfo", serviceInstanceName, e)
+            LOGGER.error(EELFLoggerDelegate.errorLogger, "Failed updating service name {} in serviceInfo", serviceInstanceName, e)
         }
 
         return serviceInstanceName
diff --git a/vid-app-common/src/main/java/org/onap/vid/job/command/MsoResultHandlerService.kt b/vid-app-common/src/main/java/org/onap/vid/job/command/MsoResultHandlerService.kt
index 50eada64f..e60919a34 100644
--- a/vid-app-common/src/main/java/org/onap/vid/job/command/MsoResultHandlerService.kt
+++ b/vid-app-common/src/main/java/org/onap/vid/job/command/MsoResultHandlerService.kt
@@ -68,11 +68,11 @@ class MsoResultHandlerService
     fun handleResponse(sharedData: JobSharedData, msoResponse: RestObject<RequestReferencesContainer>, actionDescription: String): MsoResult {
         return if (msoResponse.statusCode in 200..399) {
             val msoResourceIds = MsoResourceIds(msoResponse.get().requestReferences.requestId, msoResponse.get().requestReferences.instanceId)
-            LOGGER.debug("Successfully sent $actionDescription. Request id: ${msoResourceIds.requestId}")
+            LOGGER.debug(EELFLoggerDelegate.debugLogger, "Successfully sent $actionDescription. Request id: ${msoResourceIds.requestId}")
             asyncInstantiationBL.addResourceInfo(sharedData, Job.JobStatus.IN_PROGRESS, msoResourceIds.instanceId)
             MsoResult(Job.JobStatus.COMPLETED_WITH_NO_ACTION, msoResourceIds)
         } else {
-            LOGGER.debug("Failed to $actionDescription. Details: ${msoResponse.raw}")
+            LOGGER.debug(EELFLoggerDelegate.debugLogger, "Failed to $actionDescription. Details: ${msoResponse.raw}")
             asyncInstantiationBL.addFailedResourceInfo(sharedData, msoResponse)
             MsoResult(Job.JobStatus.FAILED)
         }
diff --git a/vid-app-common/src/main/java/org/onap/vid/job/command/ResourceCommand.kt b/vid-app-common/src/main/java/org/onap/vid/job/command/ResourceCommand.kt
index 97c9f99ce..4477a9f24 100644
--- a/vid-app-common/src/main/java/org/onap/vid/job/command/ResourceCommand.kt
+++ b/vid-app-common/src/main/java/org/onap/vid/job/command/ResourceCommand.kt
@@ -112,7 +112,7 @@ abstract class ResourceCommand(
         jobStatus = comulateStatusAndUpdatePropertyIfFinal(jobStatus)
 
         try {
-            Logger.debug("job: ${this.javaClass.simpleName} ${sharedData.jobUuid} $actionPhase ${getActionType()} $internalState $jobStatus $childJobs")
+            Logger.debug(EELFLoggerDelegate.debugLogger, "job: ${this.javaClass.simpleName} ${sharedData.jobUuid} $actionPhase ${getActionType()} $internalState $jobStatus $childJobs")
         } catch (e:Exception) { /* do nothing. Just failed to log...*/}
 
         if (shallStopJob(jobStatus)) {
@@ -121,7 +121,7 @@ abstract class ResourceCommand(
         }
 
         val (nextActionPhase, nextInternalState) = calcNextInternalState(jobStatus, internalState, actionPhase)
-        Logger.debug("next state for job ${sharedData.jobUuid} is $nextInternalState")
+        Logger.debug(EELFLoggerDelegate.debugLogger, "next state for job ${sharedData.jobUuid} is $nextInternalState")
         actionPhase = nextActionPhase
         internalState = nextInternalState
 
@@ -131,7 +131,7 @@ abstract class ResourceCommand(
         }
 
         jobStatus = getExternalInProgressStatus()
-        Logger.debug("next status for job ${sharedData.jobUuid} is $jobStatus")
+        Logger.debug(EELFLoggerDelegate.debugLogger, "next status for job ${sharedData.jobUuid} is $jobStatus")
 //        if (internalState.immediate) return call() //shortcut instead of execute another command
         return NextCommand(jobStatus, this)
     }
@@ -153,7 +153,7 @@ abstract class ResourceCommand(
             JobStatus.IN_PROGRESS
         }
         catch (exception: AbortingException) {
-            Logger.error("caught AbortingException. Set job status to FAILED")
+            Logger.error(EELFLoggerDelegate.errorLogger, "caught AbortingException. Set job status to FAILED")
             JobStatus.FAILED;
         }
     }
diff --git a/vid-app-common/src/main/java/org/onap/vid/job/command/RootServiceCommand.kt b/vid-app-common/src/main/java/org/onap/vid/job/command/RootServiceCommand.kt
index c4680b2bd..875de66d6 100644
--- a/vid-app-common/src/main/java/org/onap/vid/job/command/RootServiceCommand.kt
+++ b/vid-app-common/src/main/java/org/onap/vid/job/command/RootServiceCommand.kt
@@ -71,13 +71,13 @@ abstract class RootServiceCommand @Autowired constructor(
         try {
             val requests = auditService.retrieveRequestsFromMsoByServiceIdAndRequestTypeAndScope(serviceInstanceId, requestType, scope)
             if (requests.isEmpty() || requests[0].requestId == null) {
-                LOGGER.error("Failed to retrieve requestId with type: $type, scope: $scope for service instanceId $serviceInstanceId ")
+                LOGGER.error(EELFLoggerDelegate.errorLogger, "Failed to retrieve requestId with type: $type, scope: $scope for service instanceId $serviceInstanceId ")
                 return Job.JobStatus.FAILED
             }
             val createMyselfCommand = planResumeMyselfRestCall(requests[0].requestId, sharedData.userId)
             return executeAndHandleMsoInstanceRequest(createMyselfCommand)
         } catch (exception: Exception) {
-            LOGGER.error("Failed to resume instanceId $serviceInstanceId ", exception)
+            LOGGER.error(EELFLoggerDelegate.errorLogger, "Failed to resume instanceId $serviceInstanceId ", exception)
             return Job.JobStatus.FAILED
         }
     }
diff --git a/vid-app-common/src/main/java/org/onap/vid/job/command/VfmoduleCommand.kt b/vid-app-common/src/main/java/org/onap/vid/job/command/VfmoduleCommand.kt
index 6c499079f..731625c53 100644
--- a/vid-app-common/src/main/java/org/onap/vid/job/command/VfmoduleCommand.kt
+++ b/vid-app-common/src/main/java/org/onap/vid/job/command/VfmoduleCommand.kt
@@ -193,7 +193,7 @@ class VfmoduleCommand @Autowired constructor(
             val replaceMyselfCommand = planReplaceMyselfRestCall(commandParentData)
             return executeAndHandleMsoInstanceRequest(replaceMyselfCommand)
         } catch (exception: Exception) {
-            LOGGER.error("Failed to replace instanceId ${getRequest().instanceId} ", exception)
+            LOGGER.error(EELFLoggerDelegate.errorLogger, "Failed to replace instanceId ${getRequest().instanceId} ", exception)
             return Job.JobStatus.FAILED
         }
     }
diff --git a/vid-app-common/src/main/java/org/onap/vid/job/command/VnfCommand.kt b/vid-app-common/src/main/java/org/onap/vid/job/command/VnfCommand.kt
index 6f00f9ae6..48ff7b7ac 100644
--- a/vid-app-common/src/main/java/org/onap/vid/job/command/VnfCommand.kt
+++ b/vid-app-common/src/main/java/org/onap/vid/job/command/VnfCommand.kt
@@ -61,7 +61,7 @@ class VnfCommand @Autowired constructor(
             try {
                 childJobs = pushChildrenJobsToBroker(vfModules.filter { filterModuleByNeedToCreateBase(it) }, dataForChild, JobType.VolumeGroupInstantiation)
             } catch (e: AsdcCatalogException) {
-                LOGGER.error("Failed to retrieve service definitions from SDC, for VfModule is BaseModule.. Error: " + e.message , e)
+                LOGGER.error(EELFLoggerDelegate.errorLogger, "Failed to retrieve service definitions from SDC, for VfModule is BaseModule.. Error: " + e.message , e)
                 //return Job.JobStatus.FAILED
                 throw e;
             }
diff --git a/vid-app-common/src/main/java/org/onap/vid/job/impl/DeleteOldJobsSchedulerInitializer.java b/vid-app-common/src/main/java/org/onap/vid/job/impl/DeleteOldJobsSchedulerInitializer.java
index ad4b8c95a..114c20105 100644
--- a/vid-app-common/src/main/java/org/onap/vid/job/impl/DeleteOldJobsSchedulerInitializer.java
+++ b/vid-app-common/src/main/java/org/onap/vid/job/impl/DeleteOldJobsSchedulerInitializer.java
@@ -85,7 +85,7 @@ public class DeleteOldJobsSchedulerInitializer {
     Trigger createTrigger() {
         int minutes = new Random(System.nanoTime()).nextInt(59);
         int hours = 6;
-        logger.info("trigger for DeleteOldJobs is {}:{} ", hours, minutes);
+        logger.info(EELFLoggerDelegate.debugLogger, "trigger for DeleteOldJobs is {}:{} ", hours, minutes);
 
         return TriggerBuilder.newTrigger()
                 .withIdentity("DeleteOldJobsTrigger")
diff --git a/vid-app-common/src/main/java/org/onap/vid/job/impl/DeleteOldJobsWorker.java b/vid-app-common/src/main/java/org/onap/vid/job/impl/DeleteOldJobsWorker.java
index d60ddab8d..ba0a9981e 100644
--- a/vid-app-common/src/main/java/org/onap/vid/job/impl/DeleteOldJobsWorker.java
+++ b/vid-app-common/src/main/java/org/onap/vid/job/impl/DeleteOldJobsWorker.java
@@ -34,7 +34,7 @@ public class DeleteOldJobsWorker extends QuartzJobBean {
 
     @Override
     protected void executeInternal(JobExecutionContext context) {
-        LOGGER.info("delete old final jobs that has finished before {} seconds", secondsAgo);
+        LOGGER.info(EELFLoggerDelegate.debugLogger, "delete old final jobs that has finished before {} seconds", secondsAgo);
         jobsBrokerService.deleteOldFinalJobs(secondsAgo);
     }
 
diff --git a/vid-app-common/src/main/java/org/onap/vid/job/impl/JobWorker.java b/vid-app-common/src/main/java/org/onap/vid/job/impl/JobWorker.java
index 80d8cc53c..c629a665c 100644
--- a/vid-app-common/src/main/java/org/onap/vid/job/impl/JobWorker.java
+++ b/vid-app-common/src/main/java/org/onap/vid/job/impl/JobWorker.java
@@ -114,7 +114,7 @@ public class JobWorker extends QuartzJobBean {
             final JobCommand jobCommand = jobCommandFactory.toCommand(job);
             nextCommand = jobCommand.call();
         } catch (Exception e) {
-            LOGGER.error("error while executing job from queue: {}", e);
+            LOGGER.error(EELFLoggerDelegate.errorLogger, "error while executing job from queue: {}", e);
             nextCommand = new NextCommand(FAILED);
         }
 
diff --git a/vid-app-common/src/main/java/org/onap/vid/job/impl/JobsBrokerServiceInDatabaseImpl.java b/vid-app-common/src/main/java/org/onap/vid/job/impl/JobsBrokerServiceInDatabaseImpl.java
index 74a729494..51803891a 100644
--- a/vid-app-common/src/main/java/org/onap/vid/job/impl/JobsBrokerServiceInDatabaseImpl.java
+++ b/vid-app-common/src/main/java/org/onap/vid/job/impl/JobsBrokerServiceInDatabaseImpl.java
@@ -20,6 +20,21 @@
 
 package org.onap.vid.job.impl;
 
+import static org.onap.vid.job.Job.JobStatus.CREATING;
+import static org.onap.vid.job.Job.JobStatus.FINAL_STATUS;
+import static org.onap.vid.job.Job.JobStatus.IN_PROGRESS;
+import static org.onap.vid.job.Job.JobStatus.PENDING_RESOURCE;
+import static org.onap.vid.job.Job.JobStatus.RESOURCE_IN_PROGRESS;
+
+import java.sql.Timestamp;
+import java.time.LocalDateTime;
+import java.util.Collection;
+import java.util.Date;
+import java.util.List;
+import java.util.Optional;
+import java.util.UUID;
+import java.util.stream.Collectors;
+import javax.annotation.PostConstruct;
 import org.apache.commons.lang3.StringUtils;
 import org.hibernate.SessionFactory;
 import org.jetbrains.annotations.NotNull;
@@ -37,14 +52,6 @@ import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.beans.factory.annotation.Value;
 import org.springframework.stereotype.Service;
 
-import javax.annotation.PostConstruct;
-import java.sql.Timestamp;
-import java.time.LocalDateTime;
-import java.util.*;
-import java.util.stream.Collectors;
-
-import static org.onap.vid.job.Job.JobStatus.*;
-
 @Service
 public class JobsBrokerServiceInDatabaseImpl implements JobsBrokerService {
 
@@ -252,7 +259,10 @@ public class JobsBrokerServiceInDatabaseImpl implements JobsBrokerService {
         Integer age = jobDao.getAge();
         jobDao.setAge(age + 1);
 
-        logger.debug(EELFLoggerDelegate.debugLogger, "{}/{}", jobDao.getStatus(), jobDao.getType());
+        logger.debug(EELFLoggerDelegate.debugLogger, "pushing back jobDao {} of {}: {}/{}",
+            StringUtils.substring(String.valueOf(jobDao.getUuid()), 0, 8),
+            StringUtils.substring(String.valueOf(jobDao.getTemplateId()), 0, 8),
+            jobDao.getStatus(), jobDao.getType());
 
         dataAccessService.saveDomainObject(jobDao, DaoUtils.getPropsMap());
     }
diff --git a/vid-automation/TestNg-ApiTest.xml b/vid-automation/TestNg-ApiTest.xml
index 641f3eba6..e0ca82cb8 100644
--- a/vid-automation/TestNg-ApiTest.xml
+++ b/vid-automation/TestNg-ApiTest.xml
@@ -20,6 +20,10 @@
                             "underDevelopment"
                         };
 
+                        String [] testClassesToRunAlways = new String [] {
+                            "LoggerFormatTest"
+                        };
+
                         String [] classes1 = new String [] {
                             "AsyncInstantiationALaCarteApiTest"
                         };
@@ -34,6 +38,10 @@
 
                         if (methodClass.contains("org.onap.vid.api.Base")) return true;
 
+                        for (c: testClassesToRunAlways) {
+                            if (methodClass.endsWith(c)) return true; // repeat in any selectPart value
+                        }
+
                         for (c: classes1) {
                             if (methodClass.endsWith(c)) return selectPart==1;
                         }