From: Ittay Stern Date: Tue, 3 Dec 2019 18:38:44 +0000 (+0200) Subject: Sink all Async-Jobs logging to same debug.log X-Git-Tag: 6.0.1~124 X-Git-Url: https://gerrit.onap.org/r/gitweb?a=commitdiff_plain;h=74f309f00ee86d768378573598cb9c338fffbd9f;p=vid.git 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 --- 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, 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; }