use @Slf4j (+logback) for logging instead of System.out/err.println (#165)

Co-authored-by: Michael Hoennig <michael@hoennig.de>
Reviewed-on: https://dev.hostsharing.net/hostsharing/hs.hsadmin.ng/pulls/165
Reviewed-by: Marc Sandlus <marc.sandlus@hostsharing.net>

build.gradle

@@ -66,6 +66,7 @@ dependencies {
     implementation 'org.springframework.boot:spring-boot-starter-validation'
     implementation 'org.springframework.boot:spring-boot-starter-actuator'
     implementation 'org.springframework.boot:spring-boot-starter-security'
+    implementation 'org.springdoc:springdoc-openapi-starter-webmvc-ui:2.8.5'
     implementation 'com.github.gavlyukovskiy:datasource-proxy-spring-boot-starter:1.10.0'
     implementation 'org.postgresql:postgresql'
     implementation 'org.liquibase:liquibase-core'
@@ -76,7 +77,6 @@ dependencies {
     implementation 'net.java.dev.jna:jna:5.16.0'
     implementation 'org.modelmapper:modelmapper:3.2.2'
     implementation 'org.iban4j:iban4j:3.2.10-RELEASE'
-    implementation 'org.springdoc:springdoc-openapi-starter-webmvc-ui:2.8.5'
     implementation 'org.reflections:reflections:0.10.2'
 
     compileOnly 'org.projectlombok:lombok'

src/main/java/net/hostsharing/hsadminng/config/RealCasAuthenticator.java

@@ -2,6 +2,7 @@ package net.hostsharing.hsadminng.config;
 
 import io.micrometer.core.annotation.Timed;
 import lombok.SneakyThrows;
+import lombok.extern.slf4j.Slf4j;
 import org.springframework.beans.factory.annotation.Value;
 import org.springframework.security.authentication.BadCredentialsException;
 import org.springframework.util.LinkedMultiValueMap;
@@ -14,6 +15,8 @@ import javax.xml.parsers.DocumentBuilderFactory;
 import javax.xml.parsers.ParserConfigurationException;
 import java.io.IOException;
 
+// HOWTO add logger
+@Slf4j
 public class RealCasAuthenticator implements CasAuthenticator {
 
     @Value("${hsadminng.cas.server}")
@@ -32,7 +35,8 @@ public class RealCasAuthenticator implements CasAuthenticator {
                 ? fetchServiceTicket(ticket)
                 : ticket;
         final var userName = extractUserName(verifyServiceTicket(serviceTicket));
-        System.err.println("CAS-user: " + userName);
+        // HOWTO log some message for a certain log level (trace, debug, info, warn, error)
+        log.debug("CAS-user: {}", userName);
         return userName;
     }
 
@@ -65,9 +69,7 @@ public class RealCasAuthenticator implements CasAuthenticator {
     private String extractUserName(final Document verification) {
 
         if (verification.getElementsByTagName("cas:authenticationSuccess").getLength() == 0) {
-            System.err.println("CAS service ticket could not be validated");
+            throwBadCredentialsException("CAS service ticket could not be verified");
-            System.err.println(verification);
-            throwBadCredentialsException("CAS service ticket could not be validated");
         }
         return verification.getElementsByTagName("cas:user").item(0).getTextContent();
     }

src/main/java/net/hostsharing/hsadminng/errors/RestResponseEntityExceptionHandler.java

@@ -28,6 +28,7 @@ import java.util.regex.Pattern;
 import static net.hostsharing.hsadminng.errors.CustomErrorResponse.*;
 
 @ControllerAdvice
+// HOWTO handle exceptions to produce specific http error codes and sensible error messages
 public class RestResponseEntityExceptionHandler
         extends ResponseEntityExceptionHandler {
 

src/main/java/net/hostsharing/hsadminng/hash/HashGenerator.java

@@ -121,10 +121,4 @@ public final class HashGenerator {
         }
         return withSalt(stringBuilder.toString());
     }
-
-    public static void main(String[] args) {
-        System.out.println(
-            HashGenerator.using(Algorithm.LINUX_YESCRYPT).withRandomSalt().hash("my plaintext domain transfer passphrase")
-        );
-    }
 }

src/main/java/net/hostsharing/hsadminng/hs/hosting/asset/validators/Dns.java

@@ -125,10 +125,4 @@ public class Dns {
             return Result.fromException(exception);
         }
     }
-
-    public static void main(String[] args) {
-        final var result = new Dns("example.org").fetchRecordsOfType("TXT");
-        System.out.println(result);
-    }
-
 }

src/main/java/net/hostsharing/hsadminng/rbac/generator/RbacSpec.java

@@ -1261,16 +1261,12 @@ public class RbacSpec {
                         m -> isStatic(m.getModifiers()) && m.getName().equals("main")
                 )
                 .findFirst()
-                .orElse(null);
+                .orElseThrow(() -> new RuntimeException("no main method in: " + c.getName() + " => cannot generate RBAC rules"));
-        if (mainMethod != null) {
         try {
             mainMethod.invoke(null, new Object[] { null });
         } catch (IllegalAccessException | InvocationTargetException e) {
             throw new RuntimeException(e);
         }
-        } else {
-            System.err.println("WARNING: no main method in: " + c.getName() + " => no RBAC rules generated");
-        }
     }
 
     public static Set<Class<? extends BaseEntity>> findRbacEntityClasses(String packageName) {

src/main/java/net/hostsharing/hsadminng/rbac/generator/RbacViewMermaidFlowchartGenerator.java

@@ -202,6 +202,5 @@ public class RbacViewMermaidFlowchartGenerator {
                     .replace("%{flowchart}", flowchart.toString())
                     .replace("%{case}", forCase == null ? "" : " " + forCase),
                 StandardOpenOption.CREATE, StandardOpenOption.TRUNCATE_EXISTING);
-        System.out.println("Markdown-File: " + path.toAbsolutePath());
     }
 }

src/main/java/net/hostsharing/hsadminng/rbac/generator/RbacViewPostgresGenerator.java

@@ -49,6 +49,5 @@ public class RbacViewPostgresGenerator {
                 toString(),
                 StandardOpenOption.CREATE,
                 StandardOpenOption.TRUNCATE_EXISTING);
-        System.out.println(outputPath.toAbsolutePath());
     }
 }

src/main/java/net/hostsharing/hsadminng/rbac/generator/RolesGrantsAndPermissionsGenerator.java

@@ -358,9 +358,6 @@ class RolesGrantsAndPermissionsGenerator {
     }
 
     private String roleRef(final PostgresTriggerReference rootRefVar, final RbacSpec.RbacRoleDefinition roleDef) {
-        if (roleDef == null) {
-            System.out.println("null");
-        }
         if (roleDef.getEntityAlias().isGlobal()) {
             return "rbac.global_ADMIN()";
         }

src/main/resources/application.yml

@@ -68,8 +68,10 @@ metrics:
                 server:
                     requests: true
 
+# HOWTO set logging-levels for certain Java packages (trace, debug, info, warn, error)
 logging:
     level:
-        org:
+        org.springframework.security: info
-            springframework:
+# HOWTO configure logging, e.g. logging to a separate file, see:
-                security: TRACE
+#   https://docs.spring.io/spring-boot/reference/features/logging.html
+

src/test/java/net/hostsharing/hsadminng/config/CasAuthenticationFilterIntegrationTest.java

@@ -1,11 +1,16 @@
 package net.hostsharing.hsadminng.config;
 
 import com.github.tomakehurst.wiremock.WireMockServer;
+import net.hostsharing.hsadminng.test.LogbackLogPattern;
 import org.junit.jupiter.api.Tag;
 import org.junit.jupiter.api.Test;
+import org.junit.jupiter.api.extension.ExtendWith;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.beans.factory.annotation.Value;
+import org.springframework.boot.logging.LogLevel;
 import org.springframework.boot.test.context.SpringBootTest;
+import org.springframework.boot.test.system.CapturedOutput;
+import org.springframework.boot.test.system.OutputCaptureExtension;
 import org.springframework.boot.test.web.client.TestRestTemplate;
 import org.springframework.http.HttpEntity;
 import org.springframework.http.HttpMethod;
@@ -13,15 +18,23 @@ import org.springframework.http.HttpStatus;
 import org.springframework.test.context.ActiveProfiles;
 import org.springframework.test.context.TestPropertySource;
 
+import static com.github.tomakehurst.wiremock.client.WireMock.aResponse;
+import static com.github.tomakehurst.wiremock.client.WireMock.get;
+import static com.github.tomakehurst.wiremock.client.WireMock.urlEqualTo;
 import static net.hostsharing.hsadminng.config.HttpHeadersBuilder.headers;
 import static org.apache.commons.lang3.RandomStringUtils.randomAlphanumeric;
 import static org.assertj.core.api.Assertions.assertThat;
-import static com.github.tomakehurst.wiremock.client.WireMock.*;
 
 @SpringBootTest(webEnvironment = SpringBootTest.WebEnvironment.RANDOM_PORT)
-@TestPropertySource(properties = {"server.port=0", "hsadminng.cas.server=http://localhost:8088"})
+@TestPropertySource(properties = {
+        "server.port=0",
+        "hsadminng.cas.server=http://localhost:8088",
+
+        "logging.level.root=DEBUG"
+})
 @ActiveProfiles({"wiremock", "realCasAuthenticator"}) // IMPORTANT: To test prod config, do NOT use test profile!
 @Tag("generalIntegrationTest")
+@ExtendWith(OutputCaptureExtension.class)
 class CasAuthenticationFilterIntegrationTest {
 
     @Value("${local.server.port}")
@@ -37,7 +50,7 @@ class CasAuthenticationFilterIntegrationTest {
     private WireMockServer wireMockServer;
 
     @Test
-    public void shouldAcceptRequestWithValidCasTicket() {
+    public void shouldAcceptRequestWithValidCasTicket(final CapturedOutput capturedOutput) {
         // given
         final var username = "test-user-" + randomAlphanumeric(4);
         wireMockServer.stubFor(get(urlEqualTo("/cas/p3/serviceValidate?service=" + serviceUrl + "&ticket=ST-valid"))
@@ -63,6 +76,9 @@ class CasAuthenticationFilterIntegrationTest {
         // then
         assertThat(result.getStatusCode()).isEqualTo(HttpStatus.OK);
         assertThat(result.getBody()).isEqualTo("pong " + username + "\n");
+        // HOWTO assert log messages
+        assertThat(capturedOutput.getOut()).containsPattern(
+                LogbackLogPattern.of(LogLevel.DEBUG, RealCasAuthenticator.class, "CAS-user: " + username));
     }
 
     @Test

src/test/java/net/hostsharing/hsadminng/errors/RestResponseEntityExceptionHandlerUnitTest.java

@@ -39,8 +39,8 @@ class RestResponseEntityExceptionHandlerUnitTest {
         final var errorResponse = exceptionHandler.handleConflict(givenException, givenWebRequest);
 
         // then
-        assertThat(errorResponse.getBody().getStatusCode()).isEqualTo(409);
+        assertThat(errorResponse.getBody()).extracting(CustomErrorResponse::getStatusCode).isEqualTo(409);
-        assertThat(errorResponse.getBody().getMessage()).isEqualTo("ERROR: [409] First Line");
+        assertThat(errorResponse.getBody()).extracting(CustomErrorResponse::getMessage).isEqualTo("ERROR: [409] First Line");
     }
 
     @Test

src/test/java/net/hostsharing/hsadminng/test/LogbackLogPattern.java

@@ -0,0 +1,21 @@
+package net.hostsharing.hsadminng.test;
+
+import ch.qos.logback.classic.pattern.TargetLengthBasedClassNameAbbreviator;
+import org.springframework.boot.logging.LogLevel;
+
+public class LogbackLogPattern {
+
+    private static final int LOGBACK_MAX_CLASSNAME_LENGTH = 36;
+
+    /**
+     * @return a regular expression for a log message
+     */
+    public static CharSequence of(
+            final LogLevel logLevel,
+            final Class<?> loggingClass,
+            final String message) {
+        final var abbreviator = new TargetLengthBasedClassNameAbbreviator(LOGBACK_MAX_CLASSNAME_LENGTH);
+        final var shortenedClassName = abbreviator.abbreviate(loggingClass.getName());
+        return logLevel + " [0-9]+ .* " + shortenedClassName +  " *: " + message;
+    }
+}