TS-44797 Added more debug logs in impacted test engine

.github/pull_request_template.md

@@ -1,7 +1,7 @@
 Addresses issue [TS-XXXXX](https://cqse.atlassian.net/browse/TS-XXXXX)
 
 - [ ] Changes are tested adequately
-- [ ] Agent's README.md updated in case of user-visible changes
+- [ ] Teamscale documentation updated in case of user-visible changes
 - [ ] CHANGELOG.md updated
 - [ ] Present new features in [N&N](https://cqse.atlassian.net/l/cp/KHSr81m1)
 - [ ] [TGA Tutorial](https://docs.teamscale.com/tutorial/setting-up-tga-java) updated

CHANGELOG.md

@@ -5,8 +5,9 @@ We use [semantic versioning](http://semver.org/):
 - PATCH version when you make backwards compatible bug fixes.
 
 # Next version
-
 - _agent_: improved logging when multiple agents are attached
+- [feature] _teamscale-gradle-plugin_: Added `debugLogging` option to enable debug logging for the java profiler and the impacted test engine
+- [feature] _teamscale-maven-plugin_: Enhanced `debugLogging` option to also enable debug logging for the impacted test engine
 
 # 36.1.0
 - [feature] _impacted-test-engine_: Added support for JUnit 5.13 and 6.0

agent/src/main/java/com/teamscale/jacoco/agent/testimpact/TestwiseCoverageResource.java

@@ -1,7 +1,12 @@
 package com.teamscale.jacoco.agent.testimpact;
 
-import java.io.IOException;
-import java.util.List;
+import com.teamscale.client.ClusteredTestDetails;
+import com.teamscale.client.PrioritizableTestCluster;
+import com.teamscale.jacoco.agent.JacocoRuntimeController;
+import com.teamscale.jacoco.agent.ResourceBase;
+import com.teamscale.report.testwise.jacoco.cache.CoverageGenerationException;
+import com.teamscale.report.testwise.model.TestExecution;
+import com.teamscale.report.testwise.model.TestInfo;
 
 import javax.ws.rs.DefaultValue;
 import javax.ws.rs.GET;
@@ -12,14 +17,8 @@
 import javax.ws.rs.QueryParam;
 import javax.ws.rs.core.MediaType;
 import javax.ws.rs.core.Response;
-
-import com.teamscale.client.ClusteredTestDetails;
-import com.teamscale.client.PrioritizableTestCluster;
-import com.teamscale.jacoco.agent.JacocoRuntimeController;
-import com.teamscale.jacoco.agent.ResourceBase;
-import com.teamscale.report.testwise.jacoco.cache.CoverageGenerationException;
-import com.teamscale.report.testwise.model.TestExecution;
-import com.teamscale.report.testwise.model.TestInfo;
+import java.io.IOException;
+import java.util.List;
 
 /**
  * The resource of the Jersey + Jetty http server holding all the endpoints specific for the
@@ -57,7 +56,7 @@ public Response handleTestStart(@PathParam(TEST_ID_PARAMETER) String testId) {
 			handleBadRequest("Test name is missing!");
 		}
 
-		logger.debug("Start test " + testId);
+		logger.debug("Start test {}", testId);
 
 		testwiseCoverageAgent.testEventHandler.testStart(testId);
 		return Response.noContent().build();
@@ -68,12 +67,12 @@ public Response handleTestStart(@PathParam(TEST_ID_PARAMETER) String testId) {
 	@Produces(MediaType.APPLICATION_JSON)
 	@Path("/test/end/{" + TEST_ID_PARAMETER + "}")
 	public TestInfo handleTestEnd(@PathParam(TEST_ID_PARAMETER) String testId,
-								  TestExecution testExecution) throws JacocoRuntimeController.DumpException, CoverageGenerationException {
+			TestExecution testExecution) throws JacocoRuntimeController.DumpException, CoverageGenerationException {
 		if (testId == null || testId.isEmpty()) {
 			handleBadRequest("Test name is missing!");
 		}
 
-		logger.debug("End test " + testId);
+		logger.debug("End test {}", testId);
 
 		return testwiseCoverageAgent.testEventHandler.testEnd(testId,
 				testExecution);

impacted-test-engine/src/main/kotlin/com/teamscale/test_impacted/commons/LoggerUtils.kt

@@ -24,9 +24,42 @@ object LoggerUtils {
 			override fun format(lr: LogRecord) =
 				String.format("[%1\$s] %2\$s%n", lr.level.localizedName, lr.message)
 		}
+		handler.level = Level.WARNING
 		MAIN_LOGGER.addHandler(handler)
 	}
 
+	/**
+	 * Configures file-based logging for the impacted test engine with the specified log level.
+	 *
+	 * @param logLevel The minimum log level that will be written to the log file.
+	 * @param logFilePath The filesystem path where the log file will be written. If null, no file logging is configured.
+	 */
+	fun configureFileLogging(logLevel: Level, logFilePath: String?) {
+		if (logFilePath == null) return
+		try {
+			val fileHandler = FileHandler(logFilePath, true)
+			fileHandler.level = logLevel
+			fileHandler.formatter = object : SimpleFormatter() {
+				@Synchronized
+				override fun format(lr: LogRecord) =
+					String.format(
+						"%1\$tF %1\$tT [%2\$s] %3\$s: %4\$s%n",
+						lr.millis,
+						lr.level.localizedName,
+						lr.loggerName,
+						lr.message
+					)
+			}
+			MAIN_LOGGER.addHandler(fileHandler)
+			MAIN_LOGGER.level = logLevel
+		} catch (e: IOException) {
+			val logger = createLogger()
+			logger.warning(
+				"Cannot create log file at $logFilePath specified via teamscale.test.impacted.logFilePath: ${e.message}"
+			)
+		}
+	}
+
 	/**
 	 * Normally, the java util logging framework picks up the config file specified via the system property
 	 * {@value #JAVA_UTIL_LOGGING_CONFIG_FILE_SYSTEM_PROPERTY}. For some reason, this does not work here, so we need to

impacted-test-engine/src/main/kotlin/com/teamscale/test_impacted/engine/ImpactedTestEngine.kt

@@ -1,5 +1,6 @@
 package com.teamscale.test_impacted.engine
 
+import com.teamscale.test_impacted.commons.LoggerUtils
 import com.teamscale.test_impacted.commons.LoggerUtils.createLogger
 import com.teamscale.test_impacted.engine.options.TestEngineOptionUtils
 import org.junit.platform.engine.*
@@ -18,11 +19,13 @@ class ImpactedTestEngine : TestEngine {
 	): TestDescriptor {
 		val engineOptions = TestEngineOptionUtils
 			.getEngineOptions(discoveryRequest.configurationParameters)
+		LoggerUtils.configureFileLogging(engineOptions.logLevel, engineOptions.logFilePath)
 		if (!engineOptions.enabled) {
+			LOG.fine { "Impacted test engine is disabled." }
 			return EngineDescriptor(uniqueId, ENGINE_NAME)
 		}
 		val configuration = engineOptions.testEngineConfiguration
-		val engine = InternalImpactedTestEngine(configuration, engineOptions.partition)
+		val engine = InternalImpactedTestEngine(configuration)
 
 		// Re-initialize the configuration for this discovery (and optional following execution).
 		internalImpactedTestEngine = engine

impacted-test-engine/src/main/kotlin/com/teamscale/test_impacted/engine/InternalImpactedTestEngine.kt

@@ -21,11 +21,9 @@ import org.junit.platform.engine.support.descriptor.EngineDescriptor
  * @constructor Initializes the test engine with the given configuration and partition.
  * @param configuration The configuration object that provides dependencies such as test engine registry,
  * test sorter, and test data writer.
- * @param partition The partition identifier used to divide tests and manage their execution.
  */
 internal class InternalImpactedTestEngine(
 	configuration: ImpactedTestEngineConfiguration,
-	private val partition: String?
 ) {
 	private val testEngineRegistry = configuration.testEngineRegistry
 	private val testSorter = configuration.testSorter

impacted-test-engine/src/main/kotlin/com/teamscale/test_impacted/engine/TestEngineRegistry.kt

@@ -1,5 +1,6 @@
 package com.teamscale.test_impacted.engine
 
+import com.teamscale.test_impacted.commons.LoggerUtils.createLogger
 import org.junit.platform.commons.util.ClassLoaderUtils
 import org.junit.platform.engine.TestEngine
 import java.util.*
@@ -17,18 +18,26 @@ open class TestEngineRegistry(
 	excludedTestEngineIds: Set<String>
 ) : Iterable<TestEngine> {
 	private val testEnginesById: Map<String, TestEngine>
+	private val logger = createLogger()
 
 	init {
 		var otherTestEngines = loadOtherTestEngines(excludedTestEngineIds)
 
+		logger.fine("Loaded ${otherTestEngines.size} test engines after excluding: $excludedTestEngineIds")
+		logger.fine("Found test engines: ${otherTestEngines.map { it.id }}")
+
 		// If there are no test engines set we don't need to filter but simply use all other test engines.
 		if (includedTestEngineIds.isNotEmpty()) {
+			logger.fine("Filtering by included test engine IDs: $includedTestEngineIds")
+			val beforeFilterCount = otherTestEngines.size
 			otherTestEngines = otherTestEngines.filter { testEngine ->
 				includedTestEngineIds.contains(testEngine.id)
 			}
+			logger.fine("Filtered from $beforeFilterCount to ${otherTestEngines.size} test engines")
 		}
 
 		testEnginesById = otherTestEngines.associateBy { it.id }
+		logger.fine("Final test engines to be used: ${testEnginesById.keys}")
 	}
 
 	/**

impacted-test-engine/src/main/kotlin/com/teamscale/test_impacted/engine/executor/TeamscaleAgentNotifier.kt

@@ -24,19 +24,22 @@
 
 	/** Reports the start of a test to the Teamscale JaCoCo agent.  */
 	open fun startTest(testUniformPath: String) {
+		LOG.fine { "Starting test notification for: $testUniformPath" }
 		try {
 			testwiseCoverageAgentApis.forEach { apiService ->
 				apiService.testStarted(testUniformPath.encodeUrl()).execute()
 			}
+			LOG.fine { "Successfully notified test start for: $testUniformPath" }
 		} catch (e: IOException) {
 			LOG.log(
 				Level.SEVERE, e
 			) { "Error while calling service api." }
 		}
 	}
 
 	/** Reports the end of a test to the Teamscale JaCoCo agent.  */
 	open fun endTest(testUniformPath: String, testExecution: TestExecution?) {
+		LOG.fine { "Ending test notification for: $testUniformPath (execution: ${testExecution != null})" }
 		try {
 			testwiseCoverageAgentApis.forEach { apiService ->
 				val url = testUniformPath.encodeUrl()
@@ -46,6 +49,7 @@
 					apiService.testFinished(url, testExecution).execute()
 				}
 			}
+			LOG.fine { "Successfully notified test end for: $testUniformPath" }
 		} catch (e: IOException) {
 			LOG.log(
 				Level.SEVERE, e
@@ -55,14 +59,16 @@
 
 	/** Reports the end of the test run to the Teamscale JaCoCo agent.  */
 	open fun testRunEnded() {
+		LOG.fine { "Notifying test run ended (partial: $partial)" }
 		try {
 			testwiseCoverageAgentApis.forEach { apiService ->
 				apiService.testRunFinished(partial).execute()
 			}
+			LOG.fine { "Successfully notified test run ended" }
 		} catch (e: IOException) {
 			LOG.log(
 				Level.SEVERE, e
 			) { "Error contacting test wise coverage agent." }
 		}
 	}
 }

impacted-test-engine/src/main/kotlin/com/teamscale/test_impacted/engine/options/TestEngineOptionUtils.kt

@@ -3,6 +3,7 @@ package com.teamscale.test_impacted.engine.options
 import com.teamscale.client.CommitDescriptor
 import org.junit.platform.engine.ConfigurationParameters
 import java.util.*
+import java.util.logging.Level
 
 /**
  * Utility object for creating and retrieving `TestEngineOptions` based on
@@ -40,10 +41,22 @@ object TestEngineOptionUtils {
 			testCoverageAgentUrls = propertyReader.getStringList("agentsUrls"),
 			includedTestEngineIds = propertyReader.getStringList("includedEngines").toSet(),
 			excludedTestEngineIds = propertyReader.getStringList("excludedEngines").toSet(),
-			reportDirectoryPath = propertyReader.getString("reportDirectory")
+			reportDirectoryPath = propertyReader.getString("reportDirectory"),
+			logLevel = determineLogLevel(propertyReader.getString("logLevel")),
+			logFilePath = propertyReader.getString("logFilePath"),
 		)
 	}
 
+	private fun determineLogLevel(logLevelString: String?): Level {
+		return when (logLevelString?.uppercase()) {
+			"DEBUG" -> Level.FINE
+			"INFO" -> Level.INFO
+			"WARN" -> Level.WARNING
+			"ERROR" -> Level.SEVERE
+			else -> Level.INFO
+		}
+	}
+
 	private fun PrefixingPropertyReader.createServerOptions() =
 		ServerOptions(
 			getString("server.url") ?: throw AssertionError("server url is required"),

impacted-test-engine/src/main/kotlin/com/teamscale/test_impacted/engine/options/TestEngineOptions.kt

@@ -12,6 +12,7 @@ import com.teamscale.test_impacted.engine.executor.TeamscaleAgentNotifier
 import com.teamscale.tia.client.ITestwiseCoverageAgentApi
 import okhttp3.HttpUrl.Companion.toHttpUrlOrNull
 import java.io.File
+import java.util.logging.Level
 import kotlin.io.path.createDirectories
 
 /**
@@ -37,6 +38,9 @@ import kotlin.io.path.createDirectories
  * @property excludedTestEngineIds A set of test engine IDs to explicitly exclude from the test run.
  * @param reportDirectoryPath The filesystem path where test reports will be saved. Must be writable during initialization.
  * @param testCoverageAgentUrls A list of URLs pointing to test-wise coverage agents used during test execution.
+ * @property logLevel The log level for the impacted test engine. Defaults to INFO.
+ * @property logFilePath The filesystem path where the impacted test engine log file will be written.
+ *                       If null, no file logging is configured.
  */
 class TestEngineOptions(
 	val enabled: Boolean,
@@ -54,7 +58,9 @@ class TestEngineOptions(
 	private val includedTestEngineIds: Set<String> = emptySet(),
 	private val excludedTestEngineIds: Set<String> = emptySet(),
 	reportDirectoryPath: String? = null,
-	testCoverageAgentUrls: List<String> = emptyList()
+	testCoverageAgentUrls: List<String> = emptyList(),
+	val logLevel: Level = Level.INFO,
+	val logFilePath: String? = null,
 ) {
 
 	private var reportDirectory = reportDirectoryPath?.let { File(it) }

impacted-test-engine/src/test/kotlin/com/teamscale/test_impacted/engine/ImpactedTestEngineTestBase.kt

@@ -74,8 +74,7 @@ abstract class ImpactedTestEngineTestBase {
 				testDataWriter, testEngineRegistry,
 				ImpactedTestsSorter(impactedTestsProvider),
 				teamscaleAgentNotifier
-			),
-			impactedTestsProvider.partition
+			)
 		)
 	}
 }

system-tests/gradle-multi-module/gradle-project/buildSrc/src/main/kotlin/com.example.java-convention.gradle.kts

@@ -68,6 +68,7 @@ val systemTest by tasks.registering(Test::class) {
 	configure<TeamscaleTaskExtension> {
 		collectTestwiseCoverage = true
 		runImpacted = System.getProperty("impacted") != null
+		debugLogging = System.getProperty("debugLogging")?.toBoolean() ?: false
 		partition = "System Tests"
 	}
 	testClassesDirs = files(test.map { it.sources.output.classesDirs })

system-tests/gradle-multi-module/gradle-project/gradle/gradle-daemon-jvm.properties

@@ -0,0 +1 @@
+toolchainVersion=21

system-tests/gradle-multi-module/src/test/kotlin/com/teamscale/tia/TestwiseCoverageGradleSystemTest.kt

@@ -8,6 +8,7 @@ import org.assertj.core.api.Assertions.assertThat
 import org.junit.jupiter.api.AfterEach
 import org.junit.jupiter.api.BeforeEach
 import org.junit.jupiter.api.Test
+import java.io.File
 
 /**
  * Runs tests in all submodules and expects the results of both in the upload.
@@ -64,7 +65,8 @@ class TestwiseCoverageGradleSystemTest {
 	@Test
 	@Throws(Exception::class)
 	fun testGradleAggregatedCompactCoverageUploadWithoutJVMTestSuite() {
-		runGradle("gradle-project", "clean", "unitTest", "teamscaleUnitTestReportUpload")
+		val result = runGradle("gradle-project", "clean", "unitTest", "teamscaleUnitTestReportUpload")
+		assertThat(result.isSuccess).isTrue()
 
 		val session = teamscaleMockServer.getOnlySession("Unit Tests")
 		assertThat(session.getReports()).hasSize(3)
@@ -83,7 +85,8 @@ class TestwiseCoverageGradleSystemTest {
 	@Test
 	@Throws(Exception::class)
 	fun testGradleAggregatedCompactCoverageUploadWithJVMTestSuite() {
-		runGradle("gradle-project", "clean", "teamscaleTestReportUpload")
+		val result = runGradle("gradle-project", "clean", "teamscaleTestReportUpload")
+		assertThat(result.isSuccess).isTrue()
 
 		val session = teamscaleMockServer.getOnlySession("Default Tests")
 		assertThat(session.getReports()).hasSize(3)
@@ -95,4 +98,16 @@ class TestwiseCoverageGradleSystemTest {
 		assertThat(compactReport.coverage.first().fullyCoveredLines).containsExactly(7, 8, 9)
 		assertThat(compactReport.coverage.last().fullyCoveredLines).containsExactly(3, 6, 16)
 	}
+
+	@Test
+	@Throws(Exception::class)
+	fun testDebugLogging() {
+		val result = runGradle("gradle-project", "clean", "systemTest", "-DdebugLogging=true", "-Dimpacted")
+		assertThat(result.isSuccess).isTrue()
+
+		assertThat(File("gradle-project/app/build/jacoco/systemTest/logs/teamscale-jacoco-agent.log")).content()
+			.contains("DEBUG com.teamscale.jacoco.agent.Agent - No explicit teamscale.properties file given.")
+		assertThat(File("gradle-project/app/build/jacoco/systemTest/engine.log")).content()
+			.contains("[FINE] com.teamscale.test_impacted.engine.TestEngineRegistry: Found test engines: [junit-jupiter]")
+	}
 }

system-tests/tia-maven/src/test/kotlin/com/teamscale/tia/TiaMavenSystemTest.kt

@@ -104,6 +104,17 @@ class TiaMavenSystemTest {
 		assertThat(teamscaleMockServer.baselines).containsOnly("null, master:1234")
 	}
 
+	@Test
+	@Throws(IOException::class)
+	fun testDebugLogging() {
+		runMavenTests("maven-project", "-DdebugLogging=true", "-Dtia")
+
+		assertThat(File("maven-project/sub-project-A/target/tia/agent.log")).content()
+			.contains("DEBUG com.teamscale.jacoco.agent.Agent - No explicit teamscale.properties file given.");
+		assertThat(File("maven-project/sub-project-A/target/tia/engine.log")).content()
+			.contains("[FINE] com.teamscale.test_impacted.engine.TestEngineRegistry: Found test engines: [junit-jupiter]")
+	}
+
 	/**
 	 * Starts a maven process with the reuseForks flag set to "false". Checks if the coverage can be converted to a
 	 * testwise coverage report afterward.

teamscale-gradle-plugin/src/main/kotlin/com/teamscale/TestImpactConfigurationAction.kt

@@ -92,6 +92,11 @@ class TestImpactConfigurationAction(
 		writeProperty("runAllTests", extension.runAllTests.get())
 		writeProperty("includeAddedTests", extension.includeAddedTests.get())
 		writeProperty("includeFailedAndSkipped", extension.includeFailedAndSkipped.get())
+
+		if (extension.debugLogging.getOrElse(false)) {
+			writeProperty("logFilePath", extension.agent.destination.asFile.get().resolve("engine.log").absolutePath)
+			writeProperty("logLevel", "DEBUG")
+		}
 	}
 }