Add basic logging support

.gitignore

@@ -10,4 +10,5 @@ output
 test_mock.nf
 /.nf-test/
 site
-/tests
+/tests
+/.nf-test.log

example/hello.nf.test.snap

@@ -0,0 +1,34 @@
+{
+    "hello world example should start 4 processes": {
+        "content": [
+            {
+                "stderr": [
+
+                ],
+                "errorReport": "",
+                "exitStatus": 0,
+                "failed": false,
+                "stdout": [
+                    "WARN: Task runtime metrics are not reported when using macOS without a container engine",
+                    "Hola world!",
+                    "",
+                    "Ciao world!",
+                    "",
+                    "Hello world!",
+                    "",
+                    "Bonjour world!",
+                    ""
+                ],
+                "errorMessage": "",
+                "trace": {
+                    "tasksFailed": 0,
+                    "tasksCount": 4,
+                    "tasksSucceeded": 4
+                },
+                "name": "workflow",
+                "success": true
+            }
+        ],
+        "timestamp": "2023-09-03T11:00:53.244626"
+    }
+}

pom.xml

@@ -91,6 +91,26 @@
 			<version>1.3</version>
 		</dependency>
 
+		<!-- https://mvnrepository.com/artifact/org.slf4j/slf4j-api -->
+		<dependency>
+		    <groupId>org.slf4j</groupId>
+		    <artifactId>slf4j-api</artifactId>
+		    <version>2.0.7</version>
+		</dependency>
+
+		<!-- https://mvnrepository.com/artifact/ch.qos.logback/logback-classic -->
+		<dependency>
+		    <groupId>ch.qos.logback</groupId>
+		    <artifactId>logback-classic</artifactId>
+		    <version>1.4.11</version>
+		</dependency>
+
+		<!-- https://mvnrepository.com/artifact/ch.qos.logback/logback-core -->
+		<dependency>
+		    <groupId>ch.qos.logback</groupId>
+		    <artifactId>logback-core</artifactId>
+		    <version>1.4.11</version>
+		</dependency>
 
 	</dependencies>
 

src/main/java/com/askimed/nf/test/App.java

@@ -7,9 +7,8 @@
 import com.askimed.nf.test.commands.RunTestsCommand;
 import com.askimed.nf.test.commands.UpdatePluginsCommand;
 import com.askimed.nf.test.commands.VersionCommand;
-import com.askimed.nf.test.util.AnsiText;
-import com.askimed.nf.test.util.Emoji;
 
+import ch.qos.logback.classic.Level;
 import picocli.CommandLine;
 import picocli.CommandLine.Command;
 
@@ -20,8 +19,18 @@ public class App {
 
 	public static final String VERSION = "0.7.3";
 
-	public int run(String[] args) {
+	public static final String PACKAGE =  "com.askimed.nf.test";
+
+	public static final String LOG_FILENAME = ".nf-test.log";
+
+	public static final Level LOG_LEVEL = Level.DEBUG;
+
+	public static String[] args;
 
+	public int run(String[] args) {
+
+		App.args = args;
+
 		CommandLine commandLine = new CommandLine(new App());
 		commandLine.addSubcommand("clean", new CleanCommand());
 		commandLine.addSubcommand("init", new InitCommand());

src/main/java/com/askimed/nf/test/commands/AbstractCommand.java

@@ -1,10 +1,15 @@
 package com.askimed.nf.test.commands;
 
+import java.util.Arrays;
 import java.util.concurrent.Callable;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
 import com.askimed.nf.test.App;
 import com.askimed.nf.test.util.AnsiText;
 import com.askimed.nf.test.util.Emoji;
+import com.askimed.nf.test.util.LoggerUtil;
 
 import picocli.CommandLine.Option;
 import picocli.CommandLine.Help.Visibility;
@@ -15,9 +20,20 @@ public abstract class AbstractCommand implements Callable<Integer> {
 			"--silent" }, description = "Hide header and program version", required = false, showDefaultValue = Visibility.ALWAYS)
 	private boolean silent = false;
 
+	@Option(names = {
+			"--log" }, description = "Filename for log file", required = false, showDefaultValue = Visibility.ALWAYS)
+	private String logFilename = App.LOG_FILENAME;
+
+	private static Logger log = LoggerFactory.getLogger(App.class);
+
 	@Override
 	public Integer call() throws Exception {
 
+		LoggerUtil.init(App.PACKAGE, logFilename, App.LOG_LEVEL);
+
+		log.info(App.NAME + " " + App.VERSION);
+		log.info("Arguments: " + Arrays.toString(App.args));
+
 		if (!silent) {
 			printHeader();
 		}

src/main/java/com/askimed/nf/test/commands/RunTestsCommand.java

@@ -10,6 +10,10 @@
 import java.util.Vector;
 import java.util.function.Consumer;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+import com.askimed.nf.test.App;
 import com.askimed.nf.test.config.Config;
 import com.askimed.nf.test.core.AnsiTestExecutionListener;
 import com.askimed.nf.test.core.GroupTestExecutionListener;
@@ -72,6 +76,8 @@ public class RunTestsCommand extends AbstractCommand {
 			"--tag" }, split = ",", description = "Execute only tests with this tag", required = false, showDefaultValue = Visibility.ALWAYS)
 	private List<String> tags = new Vector<String>();
 
+	private static Logger log = LoggerFactory.getLogger(RunTestsCommand.class);
+
 	@Override
 	public Integer execute() throws Exception {
 
@@ -110,13 +116,15 @@ public Integer execute() throws Exception {
 				} else {
 					TestSuiteBuilder.setConfig(null);
 					System.out.println(AnsiColors.yellow("Warning: This pipeline has no nf-test config file."));
+					log.warn("No nf-test config file found.");
 				}
 
 				scripts = pathsToScripts(testPaths);
 
 			} catch (Exception e) {
 
 				System.out.println(AnsiColors.red("Error: Syntax errors in nf-test config file: " + e));
+				log.error("Parsing config file failed", e);
 				if (debug) {
 					e.printStackTrace();
 				}
@@ -127,7 +135,10 @@ public Integer execute() throws Exception {
 			if (scripts.size() == 0) {
 				System.out.println(AnsiColors
 						.red("Error: No tests or test directories containing scripts that end with *.test provided."));
+				log.error("No tests ot directories found containing test files.");
 				return 2;
+			} else {
+				log.info("Detected {} test files.", scripts.size());
 			}
 
 			loadPlugins(manager, plugins);
@@ -171,6 +182,7 @@ public Integer execute() throws Exception {
 		} catch (Throwable e) {
 
 			System.out.println(AnsiColors.red("Error: " + e));
+			log.error("Running tests failed.", e);
 
 			if (debug) {
 				e.printStackTrace();

src/main/java/com/askimed/nf/test/core/AbstractTest.java

@@ -254,5 +254,10 @@ public void setUpdateSnapshot(boolean updateSnapshot) {
 	public boolean isUpdateSnapshot() {
 		return updateSnapshot;
 	}
+
+	@Override
+	public String toString() {
+		return getHash().substring(0, 8) + ": " + getName();
+	}
 
 }

src/main/java/com/askimed/nf/test/core/AbstractTestSuite.java

@@ -230,6 +230,11 @@ protected String makeAbsolute(String path) {
 	protected boolean isRelative(String path) {
 		return path.startsWith("../") || path.startsWith("./");
 	}
+
+	@Override
+	public String toString() {
+		return name;
+	}
 
 	class NamedClosure {
 		public String name;

src/main/java/com/askimed/nf/test/core/TestExecutionEngine.java

@@ -6,13 +6,17 @@
 import java.util.Set;
 import java.util.Vector;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
 import com.askimed.nf.test.lang.TestSuiteBuilder;
 import com.askimed.nf.test.lang.extensions.SnapshotFile;
 import com.askimed.nf.test.plugins.PluginManager;
 import com.askimed.nf.test.util.AnsiColors;
 import com.askimed.nf.test.util.AnsiText;
 import com.askimed.nf.test.util.FileUtil;
 import com.askimed.nf.test.util.OutputFormat;
+import com.github.javaparser.utils.Log;
 
 import groovy.json.JsonOutput;
 
@@ -42,6 +46,8 @@ public class TestExecutionEngine {
 
 	private TagQuery tagQuery = new TagQuery();
 
+	private static Logger log = LoggerFactory.getLogger(TestExecutionEngine.class);
+
 	public void setScripts(List<File> scripts) {
 		this.scripts = scripts;
 	}
@@ -157,8 +163,13 @@ public int execute() throws Throwable {
 
 		listener.setDebug(debug);
 
+		int totalTests = 0;
+		int failedTests = 0;
+
+		log.info("Started test plan");
+
 		listener.testPlanExecutionStarted();
-
+		
 		boolean failed = false;
 		for (ITestSuite testSuite : testSuits) {
 
@@ -170,14 +181,21 @@ public int execute() throws Throwable {
 			if (configFile != null) {
 				testSuite.setGlobalConfigFile(configFile);
 			}
+
+			log.info("Running testsuite '{}' from file '{}'.", testSuite, testSuite.getFilename());
 
 			listener.testSuiteExecutionStarted(testSuite);
 
 			for (ITest test : testSuite.getTests()) {
 				if (test.isSkipped()) {
+					log.info("Test '{}' skipped.", test);				
 					listener.executionSkipped(test, "");
 					continue;
 				}
+
+				log.info("Run test '{}'. type: {}", test, test.getClass().getName());
+				totalTests++;
+
 				listener.executionStarted(test);
 				TestExecutionResult result = new TestExecutionResult(test);
 				test.setWithTrace(withTrace);
@@ -200,26 +218,37 @@ public int execute() throws Throwable {
 					result.setErrorReport(test.getErrorReport());
 					failed = true;
 					testSuite.setFailedTests(true);
+					failedTests++;
 
 				}
 				test.cleanup();
 				result.setEndTime(System.currentTimeMillis());
+
+				log.info("Test '{}' finished. status: {}", result.getTest(), result.getStatus(), result.getThrowable());
+
 				listener.executionFinished(test, result);
 
 			}
-
+			
 			// Remove obsolete snapshots when no test was skipped and no test failed.
 			if (cleanSnapshot && !testSuite.hasSkippedTests() && !testSuite.hasFailedTests()
 					&& testSuite.hasSnapshotLoaded()) {
+				log.info("Clean up obsolete snapshots");
 				SnapshotFile snapshot = testSuite.getSnapshot();
 				snapshot.removeObsoleteSnapshots();
 				snapshot.save();
 			}
 
+			log.info("Testsuite '{}' finished. snapshot file: {}, skipped tests: {}, failed tests: {}",
+					testSuite, testSuite.hasSnapshotLoaded(), testSuite.hasSkippedTests(), testSuite.hasFailedTests());
+
+
 			listener.testSuiteExecutionFinished(testSuite);
 
 		}
 
+		log.info("Executed {} tests. {} tests failed. Done!", totalTests, failedTests);
+
 		listener.testPlanExecutionFinished();
 
 		return (failed) ? 1 : 0;

src/main/java/com/askimed/nf/test/lang/extensions/Snapshot.java

@@ -2,6 +2,9 @@
 
 import java.io.IOException;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
 import com.askimed.nf.test.core.ITest;
 
 public class Snapshot {
@@ -12,6 +15,8 @@ public class Snapshot {
 
 	private SnapshotFile file;
 
+	private static Logger log = LoggerFactory.getLogger(Snapshot.class);
+
 	public Snapshot(Object actual, ITest test) {
 		this.actual = actual;
 		this.file = test.getTestSuite().getSnapshot();
@@ -24,23 +29,28 @@ public boolean match() throws IOException {
 
 	public boolean match(String id) throws IOException {
 		SnapshotFileItem expected = file.getSnapshot(id);
-		//new snapshot --> create snapshot
+		// new snapshot --> create snapshot
 		if (expected == null) {
+			log.debug("Snapshot '{}' not found.", id);
 			file.createSnapshot(id, actual);
 			file.save();
 			return true;
 		}
 
 		try {
-			//compare actual snapshot with expected
-			return new SnapshotFileItem(actual).equals(expected);
+			// compare actual snapshot with expected
+			boolean match = new SnapshotFileItem(actual).equals(expected);
+			log.debug("Snapshots '{}' match.", id);
+			return match;
 		} catch (Exception e) {
-			// test failes and flag set --> update snapshot
+			// test fails and flag set --> update snapshot
 			if (test.isUpdateSnapshot()) {
+				log.debug("Snapshots '{}' do not match. Update snapshots flag set.", id);
 				file.updateSnapshot(id, actual);
 				file.save();
 				return true;
 			} else {
+				log.debug("Snapshots '{}' do not match.", id);
 				throw e;
 			}
 		}