Add identity information to perftest related log

ngrinder-controller/src/main/java/org/ngrinder/agent/service/AgentService.java

@@ -40,6 +40,7 @@
 import org.ngrinder.infra.hazelcast.topic.subscriber.TopicSubscriber;
 import org.ngrinder.infra.schedule.ScheduledTaskService;
 import org.ngrinder.model.AgentInfo;
+import org.ngrinder.model.PerfTest;
 import org.ngrinder.model.User;
 import org.ngrinder.monitor.controller.model.SystemDataModel;
 import org.ngrinder.perftest.service.AgentManager;
@@ -74,6 +75,7 @@
 import static org.ngrinder.common.constant.ControllerConstants.PROP_CONTROLLER_ENABLE_AGENT_AUTO_APPROVAL;
 import static org.ngrinder.common.util.CollectionUtils.newHashMap;
 import static org.ngrinder.common.util.ExceptionUtils.processException;
+import static org.ngrinder.common.util.LoggingUtils.format;
 import static org.ngrinder.common.util.TypeConvertUtils.cast;
 
 /**
@@ -337,13 +339,14 @@ private boolean isCommonAgent(AgentInfo agentInfo) {
 	/**
 	 * Assign the agents on the given console.
 	 *
-	 * @param user              user
-	 * @param singleConsole     {@link SingleConsole} to which agents will be assigned
+	 * @param perfTest          current performance test.
+	 * @param singleConsole     {@link SingleConsole} to which agents will be assigned.
 	 * @param grinderProperties {@link GrinderProperties} to be distributed.
 	 * @param agentCount        the count of agents.
 	 */
-	public synchronized void runAgent(User user, final SingleConsole singleConsole,
+	public synchronized void runAgent(PerfTest perfTest, final SingleConsole singleConsole,
 									  final GrinderProperties grinderProperties, final Integer agentCount) {
+		User user = perfTest.getCreatedBy();
 		final Set<AgentInfo> allFreeAgents = getAllAttachedFreeApprovedAgentsForUser(user.getUserId());
 		final Set<AgentInfo> necessaryAgents = selectAgent(user, allFreeAgents, agentCount);
 
@@ -359,9 +362,9 @@ public synchronized void runAgent(User user, final SingleConsole singleConsole,
 
 		hazelcastService.put(DIST_MAP_NAME_RECENTLY_USED_AGENTS, user.getUserId(), necessaryAgents);
 
-		LOGGER.info("{} agents are starting for user {}", agentCount, user.getUserId());
+		LOGGER.info(format(perfTest, "{} agents are starting.", agentCount));
 		for (AgentInfo agentInfo : necessaryAgents) {
-			LOGGER.info("- Agent {}", agentInfo.getName());
+			LOGGER.info(format(perfTest, "- Agent {}", agentInfo.getName()));
 		}
 		agentManager.runAgent(singleConsole, grinderProperties, necessaryAgents);
 	}

ngrinder-controller/src/main/java/org/ngrinder/common/util/LoggingUtils.java

@@ -0,0 +1,39 @@
+/*
+ * Copyright (c) 2012-present NAVER Corp.
+ *
+ * This file is part of The nGrinder software distribution. Refer to
+ * the file LICENSE which is part of The nGrinder distribution for
+ * licensing details. The nGrinder distribution is available on the
+ * Internet at https://naver.github.io/ngrinder
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.ngrinder.common.util;
+
+import org.ngrinder.model.PerfTest;
+
+import static org.ngrinder.common.util.NoOp.noOp;
+import static org.slf4j.helpers.MessageFormatter.arrayFormat;
+
+public class LoggingUtils {
+
+	public static String format(PerfTest perfTest, String format, Object... params) {
+		String prefix = "";
+		try {
+			prefix = String.format("[%d][%s] ", perfTest.getId(), perfTest.getCreatedBy().getUserId());
+		} catch (RuntimeException e) {
+			noOp();
+		}
+		return arrayFormat(prefix + format, params).getMessage();
+	}
+}

ngrinder-controller/src/main/java/org/ngrinder/infra/webhook/plugin/NGrinderWebhookPlugin.java

@@ -30,6 +30,7 @@
 import org.ngrinder.model.PerfTest;
 import org.ngrinder.service.IPerfTestService;
 
+import static org.ngrinder.common.util.LoggingUtils.format;
 import static org.ngrinder.infra.webhook.model.Event.FINISH;
 import static org.ngrinder.infra.webhook.model.Event.START;
 
@@ -52,7 +53,7 @@ public void start(PerfTest perfTest, IPerfTestService perfTestService, String ve
 		try {
 			sendWebhookRequest(perfTest, START);
 		} catch (RuntimeException e) {
-			log.error("[{}] An exception occurred while sending the webhook start request.", perfTest.getId(), e);
+			log.error(format(perfTest, "An exception occurred while sending the webhook start request."), e);
 		}
 	}
 
@@ -61,7 +62,7 @@ public void finish(PerfTest perfTest, String stopReason, IPerfTestService perfTe
 		try {
 			sendWebhookRequest(perfTest, FINISH);
 		} catch (RuntimeException e) {
-			log.error("[{}] An exception occurred while sending the webhook finish request.", perfTest.getId(), e);
+			log.error(format(perfTest, "An exception occurred while sending the webhook finish request."), e);
 		}
 	}
 

ngrinder-controller/src/main/java/org/ngrinder/perftest/service/PerfTestRunnable.java

@@ -64,6 +64,7 @@
 import static org.ngrinder.common.constant.CacheConstants.DIST_MAP_NAME_SAMPLING;
 import static org.ngrinder.common.constant.ClusterConstants.PROP_CLUSTER_SAFE_DIST;
 import static org.ngrinder.common.util.AccessUtils.getSafe;
+import static org.ngrinder.common.util.LoggingUtils.format;
 import static org.ngrinder.common.util.TypeConvertUtils.cast;
 import static org.ngrinder.model.Status.*;
 
@@ -213,17 +214,19 @@ public void doTest(final PerfTest perfTest) {
 			singleConsole.setReportPath(perfTestService.getReportFileDirectory(perfTest));
 			runTestOn(perfTest, grinderProperties, checkCancellation(singleConsole));
 		} catch (PerfTestPrepareException ex) {
+			LOG.error(format(perfTest, "Error while preparing a test : {} ", ex.getMessage()));
 			perfTestService.markProgressAndStatusAndFinishTimeAndStatistics(perfTest, Status.STOP_BY_ERROR,
 				ex.getMessage());
 		} catch (SingleConsoleCancellationException ex) {
 			// In case of error, mark the occurs error on perftest.
+			LOG.error(format(perfTest, "Error while preparing a single console : {} ", ex.getMessage()));
 			doCancel(perfTest, singleConsole);
 			notifyFinish(perfTest, StopReason.CANCEL_BY_USER);
-		} catch (Exception e) {
+		} catch (Exception ex) {
 			// In case of error, mark the occurs error on perftest.
-			LOG.error("Error while executing test: {} - {} ", perfTest.getTestIdentifier(), e.getMessage());
-			LOG.debug("Stack Trace is : ", e);
-			doTerminate(perfTest, singleConsole, e.getMessage());
+			LOG.error(format(perfTest, "Error while executing a test: {}", ex.getMessage()));
+			LOG.debug("Stack Trace is : ", ex);
+			doTerminate(perfTest, singleConsole, ex.getMessage());
 			notifyFinish(perfTest, StopReason.ERROR_WHILE_PREPARE);
 		}
 	}
@@ -273,6 +276,7 @@ private void prepareFileDistribution(PerfTest perfTest, SingleConsole singleCons
 		Set<String> distFilesDigest = getFilesDigest(distDir, distFiles);
 
 		singleConsole.sendDistFilesDigestToAgents(distFilesDigest);
+		LOG.info(format(perfTest, "Send digest of distribution files to agent for refresh agent's cache directory."));
 		deleteCachedDistFiles(distDir, distFiles, distFilesDigest, singleConsole.getAgentCachedDistFilesDigestList());
 	}
 
@@ -372,7 +376,7 @@ void startAgentsOn(PerfTest perfTest, GrinderProperties grinderProperties, Singl
 		int agentCount = perfTest.getAgentCount();
 		perfTestService.markStatusAndProgress(perfTest, START_AGENTS, getSafe(agentCount)
 				+ " agents are starting.");
-		agentService.runAgent(perfTest.getCreatedBy(), singleConsole, grinderProperties, getSafe(agentCount));
+		agentService.runAgent(perfTest, singleConsole, grinderProperties, getSafe(agentCount));
 		singleConsole.waitUntilAgentPrepared(agentCount);
 		perfTestService.markStatusAndProgress(perfTest, START_AGENTS_FINISHED, getSafe(agentCount)
 				+ " agents are ready.");
@@ -401,7 +405,7 @@ public void readyToStop(StopReason stopReason) {
 				PerfTest fetchedPerftest = perfTestService.getOne(perfTest.getId());
 				if (fetchedPerftest.getStatus().isStoppable()) {
 					perfTestService.markAbnormalTermination(perfTest, stopReason);
-					LOG.error("Abnormal test {} due to {}", perfTest.getId(), stopReason.name());
+					LOG.error(format(perfTest, "Abnormal test due to {}", stopReason.name()));
 				}
 			}
 		});
@@ -411,6 +415,7 @@ public void readyToStop(StopReason stopReason) {
 		addSamplingListeners(perfTest, singleConsole);
 		perfTestService.markStatusAndProgress(perfTest, TESTING, "The test is started.");
 		singleConsole.startSampling();
+		LOG.info(format(perfTest, "Sampling is started"));
 	}
 
 	protected void addSamplingListeners(final PerfTest perfTest, final SingleConsole singleConsole) {
@@ -470,17 +475,17 @@ protected void doFinish(boolean initial) {
 
 	void doFinish() {
 		for (PerfTest each : perfTestService.getAllAbnormalTesting()) {
-			LOG.info("Terminate {}", each.getId());
 			SingleConsole consoleUsingPort = consoleManager.getConsoleUsingPort(each.getPort());
 			doTerminate(each, consoleUsingPort);
+			LOG.info(format(each, "Abnormal test is terminated.", each.getId()));
 			cleanUp(each);
 			notifyFinish(each, StopReason.TOO_MANY_ERRORS);
 		}
 
 		for (PerfTest each : perfTestService.getAllStopRequested()) {
-			LOG.info("Stop test {}", each.getId());
 			SingleConsole consoleUsingPort = consoleManager.getConsoleUsingPort(each.getPort());
 			doCancel(each, consoleUsingPort);
+			LOG.info(format(each, "Test is Stopped."));
 			cleanUp(each);
 			notifyFinish(each, StopReason.CANCEL_BY_USER);
 		}
@@ -489,6 +494,7 @@ void doFinish() {
 			SingleConsole consoleUsingPort = consoleManager.getConsoleUsingPort(each.getPort());
 			if (isTestFinishCandidate(each, consoleUsingPort)) {
 				doNormalFinish(each, consoleUsingPort);
+				LOG.info(format(each, "Test is finished.", each.getId()));
 				cleanUp(each);
 				notifyFinish(each, StopReason.NORMAL);
 			}
@@ -517,24 +523,20 @@ private boolean isTestFinishCandidate(PerfTest perfTest, SingleConsole singleCon
 		// Give 5 seconds to be finished
 		if (perfTest.isThresholdDuration()
 				&& singleConsoleInUse.isCurrentRunningTimeOverDuration(perfTest.getDuration())) {
-			LOG.debug(
-					"Test {} is ready to finish. Current : {}, Planned : {}",
-				perfTest.getTestIdentifier(), singleConsoleInUse.getCurrentRunningTime(),
-				perfTest.getDuration());
+			LOG.debug(format(perfTest,
+					"Test is ready to finish. Current : {}, Planned : {}",
+				singleConsoleInUse.getCurrentRunningTime(), perfTest.getDuration()));
 			return true;
 		} else if (perfTest.isThresholdRunCount()
 				&& singleConsoleInUse.getCurrentExecutionCount() >= perfTest.getTotalRunCount()) {
-			LOG.debug("Test {} is ready to finish. Current : {}, Planned : {}",
-				perfTest.getTestIdentifier(), singleConsoleInUse.getCurrentExecutionCount(),
-				perfTest.getTotalRunCount());
+			LOG.debug(format(perfTest, "Test is ready to finish. Current : {}, Planned : {}",
+				singleConsoleInUse.getCurrentExecutionCount(), perfTest.getTotalRunCount()));
 			return true;
 		} else if (singleConsoleInUse instanceof NullSingleConsole) {
-			LOG.debug("Test {} is ready to finish. Current : {}, Planned : {}",
-				perfTest.getTestIdentifier(), singleConsoleInUse.getCurrentExecutionCount(),
-				perfTest.getTotalRunCount());
+			LOG.debug(format(perfTest, "Test is ready to finish. Current : {}, Planned : {}",
+				singleConsoleInUse.getCurrentExecutionCount(), perfTest.getTotalRunCount()));
 			return true;
 		}
-
 		return false;
 	}
 
@@ -546,14 +548,15 @@ private boolean isTestFinishCandidate(PerfTest perfTest, SingleConsole singleCon
 	 *                           {@link PerfTest}
 	 */
 	public void doCancel(PerfTest perfTest, SingleConsole singleConsoleInUse) {
-		LOG.info("Cancel test {} by user request.", perfTest.getId());
+		LOG.info(format(perfTest, "Cancel test."));
 		singleConsoleInUse.unregisterSampling();
+		LOG.info(format(perfTest, "Sampling is stopped"));
 		try {
 			perfTestService.markProgressAndStatusAndFinishTimeAndStatistics(perfTest, CANCELED,
 					"Stop requested by user");
 		} catch (Exception e) {
-			LOG.error("Error while canceling test {} : {}", perfTest.getId(), e.getMessage());
-			LOG.debug("Details : ", e);
+			LOG.error(format(perfTest,"Error while canceling test : {}", e.getMessage()));
+			LOG.debug(format(perfTest, "Details : "), e);
 		}
 		consoleManager.returnBackConsole(perfTest.getTestIdentifier(), singleConsoleInUse);
 	}
@@ -573,6 +576,7 @@ public void doTerminate(PerfTest perfTest, SingleConsole singleConsoleInUse) {
 	public void doTerminate(PerfTest perfTest, SingleConsole singleConsoleInUse, String errorMessage) {
 		if (singleConsoleInUse != null) {
 			singleConsoleInUse.unregisterSampling();
+			LOG.info(format(perfTest, "Sampling is stopped"));
 		}
 		String progressMessage = "Stopped by error";
 
@@ -584,8 +588,8 @@ public void doTerminate(PerfTest perfTest, SingleConsole singleConsoleInUse, Str
 			perfTestService.markProgressAndStatusAndFinishTimeAndStatistics(perfTest,
 				Status.STOP_BY_ERROR, progressMessage);
 		} catch (Exception e) {
-			LOG.error("Error while terminating {} : {}", perfTest.getTestIdentifier(), e.getMessage());
-			LOG.debug("Details : ", e);
+			LOG.error(format(perfTest, "Error while terminating : {}", e.getMessage()));
+			LOG.debug(format(perfTest, "Details : "), e);
 		}
 		consoleManager.returnBackConsole(perfTest.getTestIdentifier(), singleConsoleInUse);
 	}
@@ -598,9 +602,9 @@ public void doTerminate(PerfTest perfTest, SingleConsole singleConsoleInUse, Str
 	 *                           {@link PerfTest}
 	 */
 	public void doNormalFinish(PerfTest perfTest, SingleConsole singleConsoleInUse) {
-		LOG.debug("PerfTest {} status - currentRunningTime {} ", perfTest.getId(),
-				singleConsoleInUse.getCurrentRunningTime());
+		LOG.debug(format(perfTest, "PerfTest status - currentRunningTime {} ", singleConsoleInUse.getCurrentRunningTime()));
 		singleConsoleInUse.unregisterSampling();
+		LOG.info(format(perfTest, "Sampling is stopped"));
 		try {
 			// stop target host monitor
 			if (perfTestService.hasTooManyError(perfTest)) {
@@ -615,8 +619,8 @@ public void doNormalFinish(PerfTest perfTest, SingleConsole singleConsoleInUse)
 			}
 		} catch (Exception e) {
 			perfTestService.markStatusAndProgress(perfTest, Status.STOP_BY_ERROR, e.getMessage());
-			LOG.error("Error while finishing {} : {}", perfTest.getTestIdentifier(), e.getMessage());
-			LOG.debug("Details : ", e);
+			LOG.error(format(perfTest, "Error while finishing : {}", e.getMessage()));
+			LOG.debug(format(perfTest, "Details : "), e);
 		}
 		consoleManager.returnBackConsole(perfTest.getTestIdentifier(), singleConsoleInUse);
 	}

ngrinder-controller/src/main/java/org/ngrinder/perftest/service/PerfTestService.java

@@ -85,6 +85,7 @@
 import static org.ngrinder.common.util.AopUtils.proxy;
 import static org.ngrinder.common.util.CollectionUtils.*;
 import static org.ngrinder.common.util.ExceptionUtils.processException;
+import static org.ngrinder.common.util.LoggingUtils.format;
 import static org.ngrinder.common.util.NoOp.noOp;
 import static org.ngrinder.common.util.Preconditions.checkNotEmpty;
 import static org.ngrinder.common.util.Preconditions.checkNotNull;
@@ -626,7 +627,7 @@ public GrinderProperties getGrinderProperties(PerfTest perfTest, ScriptHandler s
 					grinderProperties.setProperty(GRINDER_PROP_JVM_ARGUMENTS, property);
 				}
 			}
-			LOGGER.info("Grinder Properties : {} ", grinderProperties);
+			LOGGER.info(format(perfTest, "Grinder Properties : {} ", grinderProperties));
 			return grinderProperties;
 		} catch (Exception e) {
 			throw processException("error while prepare grinder property for " + perfTest.getTestName(), e);
@@ -666,12 +667,12 @@ public ScriptHandler prepareDistribution(PerfTest perfTest) throws IOException {
 
 		// Get all files in the script path.
 		ScriptHandler handler = scriptHandlerFactory.getHandler(scriptEntry);
-		LOGGER.info("Script type is '{}'.", handler.getKey());
+		LOGGER.info(format(perfTest, "Script type is '{}'.", handler.getKey()));
 
 		ProcessingResultPrintStream processingResult = new ProcessingResultPrintStream(new ByteArrayOutputStream());
-		handler.prepareDist(perfTest.getId(), user, scriptEntry, perfTestDistDirectory, config.getControllerProperties(),
+		handler.prepareDist(perfTest, user, scriptEntry, perfTestDistDirectory, config.getControllerProperties(),
 				processingResult);
-		LOGGER.info("File write is completed in {}", perfTestDistDirectory);
+		LOGGER.info(format(perfTest, "File write is completed in {}", perfTestDistDirectory));
 		if (!processingResult.isSuccess()) {
 			File logDir = new File(getLogFileDirectory(perfTest), "distribution_log.txt");
 			try {
@@ -983,7 +984,7 @@ public void updatePerfTestAfterTestFinish(PerfTest perfTest) {
 		Map<String, Object> result = consoleManager.getConsoleUsingPort(perfTest.getPort()).getStatisticsData();
 		@SuppressWarnings("unchecked")
 		Map<String, Object> totalStatistics = MapUtils.getMap(result, "totalStatistics", MapUtils.EMPTY_MAP);
-		LOGGER.info("Total Statistics for test {}  is {}", perfTest.getId(), totalStatistics);
+		LOGGER.info(format(perfTest, "Total Statistics is {}", totalStatistics));
 		perfTest.setTps(parseDoubleWithSafety(totalStatistics, "TPS", 0D));
 		perfTest.setMeanTestTime(parseDoubleWithSafety(totalStatistics, "Mean_Test_Time_(ms)", 0D));
 		perfTest.setPeakTps(parseDoubleWithSafety(totalStatistics, "Peak_TPS", 0D));

ngrinder-controller/src/main/java/org/ngrinder/perftest/service/samplinglistener/MonitorCollectorPlugin.java

@@ -1,4 +1,4 @@
-/* 
+/*
  * Licensed under the Apache License, Version 2.0 (the "License");
  *  you may not use this file except in compliance with the License.
  *  You may obtain a copy of the License at
@@ -9,7 +9,7 @@
  * distributed under the License is distributed on an "AS IS" BASIS,
  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  * See the License for the specific language governing permissions and
- * limitations under the License. 
+ * limitations under the License.
  */
 package org.ngrinder.perftest.service.samplinglistener;
 
@@ -40,6 +40,7 @@
 
 import static org.apache.commons.io.IOUtils.closeQuietly;
 import static org.ngrinder.common.util.CollectionUtils.newHashMap;
+import static org.ngrinder.common.util.LoggingUtils.format;
 
 /**
  * Monitor data collector plugin.
@@ -82,7 +83,7 @@ public void startSampling(final ISingleConsole singleConsole, PerfTest perfTest,
 			scheduledTaskService.runAsync(new Runnable() {
 				@Override
 				public void run() {
-					LOGGER.info("Start JVM monitoring for IP:{}", target);
+					LOGGER.info(format(perfTest, "Start JVM monitoring for IP:{}", target));
 					MonitorClientService client = new MonitorClientService(target, MonitorCollectorPlugin.this.port);
 					client.init();
 					if (client.isConnected()) {
@@ -100,7 +101,7 @@ public void run() {
 							bw.flush();
 							clientMap.put(client, bw);
 						} catch (IOException e) {
-							LOGGER.error("Error to write to file:{}, Error:{}", dataFile.getPath(), e.getMessage());
+							LOGGER.error(format(perfTest, "Error to write to file: {}, Error: {}", dataFile.getPath(), e.getMessage()));
 						}
 					}
 				}
@@ -122,7 +123,7 @@ public void sampling(ISingleConsole singleConsole, PerfTest perfTest, IPerfTestS
 				bw.write(currentInfo.toRecordString());
 				bw.newLine();
 			} catch (IOException e) {
-				LOGGER.error("Error while saving file :" + e.getMessage());
+				LOGGER.error(format(perfTest, "Error while saving file: {}", e.getMessage()));
 			}
 		}
 	}