Rationalize logging subsystem #400

basil · 2023-01-13T22:33:29Z

Problem

This component used Logback for logging, which is not wrong but just different from the rest of the Jenkins ecosystem, which uses JUL. Additionally, it used a mix of log statements and System.out or System.err for logging. Finally, many of the log statements were overly noisy or contained grammatical erors.

Solution

Get rid of Logback and use the standard JUL logging backend for printing logs. Convert all System.out or System.err statements to use logging APIs. Remove noisy logs and clean up grammatical errors.

Implementation

First I got rid of Logback. Then I added a new logging.properties file that references our project-wide standard SupportLogFormatter to format log files. For production this is enabled by a static initializer in PluginCompatTesterCli (I tried to find a way to add a MANIFEST.MF entry to do this, but there was none). For tests this is enabled by adding -Djava.util.logging.config.class=org.jenkins.tools.test.logging.LoggingConfiguration in the Surefire configuration.

Testing done

Tested in context in jenkinsci/bom.

basil · 2023-01-14T16:09:17Z

logback.xml

@@ -1,13 +0,0 @@
-<?xml version="1.0" encoding="UTF-8"?>


With the removal of Logback this is no longer needed and has therefore been deleted.

basil · 2023-01-14T16:09:29Z

pom.xml

@@ -26,8 +26,8 @@
  <properties>
    <changelist>999999-SNAPSHOT</changelist>
    <gitHubRepo>jenkinsci/plugin-compat-tester</gitHubRepo>
-    <logbackVersion>1.4.5</logbackVersion>


With the removal of Logback this is no longer needed and has therefore been deleted.

basil · 2023-01-14T16:10:38Z

pom.xml

    <maven.scm.providers.version>1.6</maven.scm.providers.version>
+    <slf4j.version>2.0.6</slf4j.version>


Since we now need to define this version for both slf4j-api and slf4j-jdk14, extracting it to a property to eliminate duplication. This matches what we do in Jenkins core.

basil · 2023-01-14T16:10:47Z

pom.xml

@@ -46,27 +46,12 @@
      <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
-        <version>2.0.6</version>
+        <version>${slf4j.version}</version>


Consuming the new property in the original consumer. It will also be consumed later on in a new consumer (slf4j-jdk14).

basil · 2023-01-14T16:11:21Z

pom.xml

-    <dependency>
-      <groupId>ch.qos.logback</groupId>
-      <artifactId>logback-access</artifactId>
-      <version>${logbackVersion}</version>
-    </dependency>
-    <dependency>
-      <groupId>ch.qos.logback</groupId>
-      <artifactId>logback-classic</artifactId>
-      <version>${logbackVersion}</version>
-    </dependency>
-    <dependency>
-      <groupId>ch.qos.logback</groupId>
-      <artifactId>logback-core</artifactId>
-      <version>${logbackVersion}</version>
-    </dependency>


With the removal of Logback this is no longer needed and has therefore been deleted.

basil · 2023-01-14T16:27:18Z

src/main/java/org/jenkins/tools/test/model/PluginRemoting.java

-                                "Will try to ignore it (FTR https://issues.jenkins-ci.org/browse/JENKINS-55169). " +
-                                "hpiRemoteUrl={1}, pomFile={2}",
-                        new Object[] {artifactId, hpiRemoteUrl, pomFile});
+                LOGGER.log(Level.FINE, "No parent POM for {0}", artifactId);


Also downgrading this to fine: this is a common scenario, so no need to scare the user with a warning.

basil · 2023-01-14T16:28:16Z

src/main/java/org/jenkins/tools/test/model/hook/PluginCompatTesterHooks.java

@@ -103,19 +107,18 @@ private Map<String, Object> runHooks(String stage, Map<String, Object> elements)
        // Modifications build on each other, pertinent checks should be handled in the hook
        for(PluginCompatTesterHook hook : beforeHooks) {
            try {
-                System.out.println("Processing " + hook.getClass().getName());


This was printing a message for every hook, even hooks that we weren't executing. I think it makes more sense not to spam the user with hooks that are not running. This PR rather only prints INFO-level logs for hooks that actually do run.

basil · 2023-01-14T16:28:35Z

src/main/java/org/jenkins/tools/test/model/hook/PluginCompatTesterHooks.java

                if(!excludeHooks.contains(hook.getClass().getName()) && hook.check(elements)) {
+                    LOGGER.log(Level.INFO, "Running hook: {0}", hook.getClass().getName());


Print the "running hook" message only for hooks that are actually running.

basil · 2023-01-14T16:28:56Z

src/main/java/org/jenkins/tools/test/model/hook/PluginCompatTesterHooks.java

                    elements = hook.action(elements);
                    hook.validate(elements);
                } else {
-                    System.out.println("Hook not triggered.  Continuing.");
+                    LOGGER.log(Level.FINE, "Skipping hook: {0}", hook.getClass().getName());


We still print a message for skipped hooks but leave it to FINE level since this should typically only be relevant when debugging something while developing a hooks-related change.

basil · 2023-01-14T16:30:17Z

src/main/java/org/jenkins/tools/test/model/hook/PluginCompatTesterHooks.java

@@ -179,7 +182,7 @@ private Map<String, Queue<PluginCompatTesterHook>> findHooks(String stage) {
            // Ignore abstract hooks
            if (!Modifier.isAbstract(c.getModifiers())) {
                try {
-                    System.out.println("Hook: " + c.getName());
+                    LOGGER.log(Level.FINE, "Loading hook: {0}", c.getName());


Similarly, this was creating a lot of log noise, one statement for each hook, even if the hook never got executed. Lowering this to FINE level since the typical user shouldn't care about hooks that aren't running; rather, this is relevant when debugging something while developing a hooks-related change.

src/main/java/org/jenkins/tools/test/maven/ExternalMavenRunner.java

src/main/java/org/jenkins/tools/test/model/MavenPom.java

pom.xml

….java Co-authored-by: James Nord <jtnord@users.noreply.github.com>

Co-authored-by: James Nord <jtnord@users.noreply.github.com>

…8670fa437150c50b75d380fb25052319e774#r1072679293

basil · 2023-01-17T19:20:05Z

All feedback addressed from my perspective

jtnord · 2023-01-18T13:41:26Z

downstream closed source build is passing - this is good to merge from my perspective.

basil added the work-in-progress label Jan 13, 2023

Rationalize logging subsystem

b334867

basil force-pushed the logging branch from b5bfb5b to b334867 Compare January 14, 2023 00:13

basil added a commit to basil/bom that referenced this pull request Jan 14, 2023

Test jenkinsci/plugin-compat-tester#400

730604a

basil added internal and removed work-in-progress labels Jan 14, 2023

basil marked this pull request as ready for review January 14, 2023 16:08

basil requested a review from a team as a code owner January 14, 2023 16:08

basil requested a review from jtnord January 14, 2023 16:08

basil commented Jan 14, 2023

View reviewed changes

basil mentioned this pull request Jan 14, 2023

Clean up hooks #403

Merged

jtnord reviewed Jan 17, 2023

View reviewed changes

basil and others added 4 commits January 17, 2023 11:12

Update src/main/java/org/jenkins/tools/test/maven/ExternalMavenRunner…

a2b849a

….java Co-authored-by: James Nord <jtnord@users.noreply.github.com>

Update src/main/java/org/jenkins/tools/test/maven/ExternalMavenRunner…

f6dc795

….java Co-authored-by: James Nord <jtnord@users.noreply.github.com>

Update src/main/java/org/jenkins/tools/test/model/MavenPom.java

5596f1d

Co-authored-by: James Nord <jtnord@users.noreply.github.com>

https://github.com/jenkinsci/plugin-compat-tester/pull/400/files/b334…

1b7dd8d

…8670fa437150c50b75d380fb25052319e774#r1072679293

jtnord self-requested a review January 18, 2023 13:35

jtnord approved these changes Jan 18, 2023

View reviewed changes

basil added 2 commits January 18, 2023 06:43

Merge remote-tracking branch 'origin/master' into logging

a8b1208

Fix indentation

4a3add8

basil merged commit 076df70 into master Jan 18, 2023

basil deleted the logging branch January 18, 2023 15:25

jtnord mentioned this pull request Jan 18, 2023

Remove usage of Maven SCM API #404

Merged

basil mentioned this pull request Jan 18, 2023

Upgrade PCT to latest jenkinsci/bom#1683

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Rationalize logging subsystem #400

Rationalize logging subsystem #400

basil commented Jan 13, 2023 •

edited

basil Jan 14, 2023

basil Jan 14, 2023

basil Jan 14, 2023

basil Jan 14, 2023

basil Jan 14, 2023

basil Jan 14, 2023

basil Jan 14, 2023

basil Jan 14, 2023

basil Jan 14, 2023

basil Jan 14, 2023

basil commented Jan 17, 2023

jtnord commented Jan 18, 2023

		<maven.scm.providers.version>1.6</maven.scm.providers.version>
		<slf4j.version>2.0.6</slf4j.version>

		if(!excludeHooks.contains(hook.getClass().getName()) && hook.check(elements)) {
		LOGGER.log(Level.INFO, "Running hook: {0}", hook.getClass().getName());

Rationalize logging subsystem #400

Rationalize logging subsystem #400

Conversation

basil commented Jan 13, 2023 • edited

Problem

Solution

Implementation

Testing done

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

basil commented Jan 17, 2023

jtnord commented Jan 18, 2023

basil commented Jan 13, 2023 •

edited