Handle not initialized logger (#94)

* Added validations and waiting mechanism

* Added tests and replaced IllegalArgumentException with LogCaptorException

* Added another test

* Added another test

* Attempt to resolve security issue

* Attempt to resolve security hotspot

* Applied sonar recommendations

* Improved performance

src/main/java/nl/altindag/log/LogCaptor.java

@@ -23,9 +23,8 @@
 import nl.altindag.log.appender.InMemoryAppender;
 import nl.altindag.log.model.LogEvent;
 import nl.altindag.log.util.JavaUtilLoggingLoggerUtils;
+import nl.altindag.log.util.LogbackUtils;
 import nl.altindag.log.util.Mappers;
-import nl.altindag.log.util.ValidationUtils;
-import org.slf4j.LoggerFactory;
 
 import java.util.Arrays;
 import java.util.Collections;
@@ -54,10 +53,7 @@ public final class LogCaptor implements AutoCloseable {
     private final List<ILoggingEvent> eventsCollector = new CopyOnWriteArrayList<>();
 
     private LogCaptor(String loggerName) {
-        org.slf4j.Logger slf4jLogger = LoggerFactory.getLogger(loggerName);
-        ValidationUtils.requireLoggerOfType(slf4jLogger, ch.qos.logback.classic.Logger.class);
-
-        logger = (Logger) slf4jLogger;
+        logger = LogbackUtils.getLogger(loggerName);
         appender = new InMemoryAppender<>("log-captor", eventsCollector);
         appender.start();
         logger.addAppender(appender);

src/main/java/nl/altindag/log/exception/LogCaptorException.java

@@ -0,0 +1,27 @@
+/*
+ * Copyright 2019 Thunderberry.
+ *
+ * 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
+ *
+ *      https://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 nl.altindag.log.exception;
+
+public final class LogCaptorException extends RuntimeException {
+
+    public LogCaptorException(Throwable cause) {
+        super(cause);
+    }
+
+    public LogCaptorException(String message) {
+        super(message);
+    }
+}

src/main/java/nl/altindag/log/util/LogbackUtils.java

@@ -0,0 +1,91 @@
+/*
+ * Copyright 2019 Thunderberry.
+ *
+ * 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
+ *
+ *      https://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 nl.altindag.log.util;
+
+import nl.altindag.log.exception.LogCaptorException;
+import org.slf4j.LoggerFactory;
+import org.slf4j.helpers.SubstituteLogger;
+
+import java.util.Optional;
+import java.util.concurrent.TimeUnit;
+import java.util.function.IntSupplier;
+import java.util.regex.Pattern;
+
+/**
+ * <strong>NOTE:</strong>
+ * Please don't use this class directly as it is part of the internal API. Class name and methods can be changed any time.
+ *
+ * @author Hakan Altindag
+ */
+public final class LogbackUtils {
+
+    private static final int DEFAULT_POLL_COUNTER_LIMIT = 10;
+    private static final int DEFAULT_POLL_DELAY_MILLISECONDS = 100;
+    private static final Pattern IS_NUMBER_PATTERN = Pattern.compile("^\\d+$");
+
+    private static final IntSupplier POLL_COUNTER_LIMIT = () -> Optional.ofNullable(System.getProperty("logcaptor.poll-counter-limit"))
+            .map(String::trim)
+            .filter(value -> !value.isEmpty())
+            .filter(value -> IS_NUMBER_PATTERN.matcher(value).matches())
+            .map(Integer::parseInt)
+            .orElse(DEFAULT_POLL_COUNTER_LIMIT);
+    private static final IntSupplier POLL_DELAY_MILLISECONDS = () -> Optional.ofNullable(System.getProperty("logcaptor.poll-delay-milliseconds"))
+            .map(String::trim)
+            .filter(value -> !value.isEmpty())
+            .filter(value -> IS_NUMBER_PATTERN.matcher(value).matches())
+            .map(Integer::parseInt)
+            .orElse(DEFAULT_POLL_DELAY_MILLISECONDS);
+
+    private LogbackUtils() {}
+
+    public static ch.qos.logback.classic.Logger getLogger(String loggerName) {
+        org.slf4j.Logger slf4jLogger = getSlf4jLogger(loggerName);
+        ValidationUtils.requireLoggerOfType(slf4jLogger, ch.qos.logback.classic.Logger.class);
+        return (ch.qos.logback.classic.Logger) slf4jLogger;
+    }
+
+    /**
+     * Attempts to get the {@link org.slf4j.Logger}.
+     * It might occur the {@link LoggerFactory} returns a {@link SubstituteLogger}. In that
+     * case it will retry to get the correct logger within the given poll limit and poll delay.
+     * SLF4J will provide the {@link SubstituteLogger} temporally when the underlying logger is not ready yet.
+     * This will most likely happen when running the tests in parallel.
+     */
+    private static org.slf4j.Logger getSlf4jLogger(String loggerName) {
+        int retryCounter = 0;
+        org.slf4j.Logger slf4jLogger = LoggerFactory.getLogger(loggerName);
+
+        if (!(slf4jLogger instanceof SubstituteLogger)) {
+            return slf4jLogger;
+        }
+
+        int pollCounterLimit = POLL_COUNTER_LIMIT.getAsInt();
+        int pollDelayMilliseconds = POLL_DELAY_MILLISECONDS.getAsInt();
+
+        while (slf4jLogger instanceof SubstituteLogger && retryCounter++ < pollCounterLimit) {
+            try {
+                TimeUnit.MILLISECONDS.sleep(pollDelayMilliseconds);
+                slf4jLogger = LoggerFactory.getLogger(loggerName);
+            } catch (InterruptedException e) {
+                Thread.currentThread().interrupt();
+                throw new LogCaptorException(e);
+            }
+        }
+
+        return slf4jLogger;
+    }
+
+}

src/main/java/nl/altindag/log/util/ValidationUtils.java

@@ -15,6 +15,7 @@
  */
 package nl.altindag.log.util;
 
+import nl.altindag.log.exception.LogCaptorException;
 import org.slf4j.Logger;
 
 /**
@@ -31,11 +32,11 @@ public static <T extends Logger, U extends Logger> void requireLoggerOfType(T ac
         if (actualLogger == null || !requiredLogger.getCanonicalName().equals(actualLogger.getClass().getCanonicalName())) {
             String actualLoggerType = actualLogger != null ? actualLogger.getClass().getName() : "nothing";
 
-            throw new IllegalArgumentException(
+            throw new LogCaptorException(
                     String.format("SLF4J Logger implementation should be of the type [%s] but found [%s].", requiredLogger.getName(), actualLoggerType)
             );
         } else if (!(requiredLogger.isInstance(actualLogger))) {
-            throw new IllegalArgumentException(
+            throw new LogCaptorException(
                     String.format(
                             "Multiple classloaders are being used. The Logging API is created by the following classloader: [%s], " +
                             "while it should have been created by the following classloader: [%s].",

src/test/java/nl/altindag/log/LogCaptorShould.java

@@ -25,6 +25,7 @@
 import ch.qos.logback.core.spi.FilterReply;
 import nl.altindag.console.ConsoleCaptor;
 import nl.altindag.log.appender.InMemoryAppender;
+import nl.altindag.log.exception.LogCaptorException;
 import nl.altindag.log.model.LogEvent;
 import nl.altindag.log.service.LogMessage;
 import nl.altindag.log.service.Service;
@@ -437,7 +438,7 @@ void throwExceptionWhenLoggerImplementationIsNull() {
             loggerFactoryMockedStatic.when(() -> LoggerFactory.getLogger(anyString())).thenReturn(null);
 
             assertThatThrownBy(LogCaptor::forRoot)
-                    .isInstanceOf(IllegalArgumentException.class)
+                    .isInstanceOf(LogCaptorException.class)
                     .hasMessage("SLF4J Logger implementation should be of the type [ch.qos.logback.classic.Logger] but found [nothing].");
         }
     }
@@ -450,7 +451,7 @@ void throwExceptionWhenLoggerImplementationIsNotLogback() {
             loggerFactoryMockedStatic.when(() -> LoggerFactory.getLogger(anyString())).thenReturn(logger);
 
             assertThatThrownBy(LogCaptor::forRoot)
-                    .isInstanceOf(IllegalArgumentException.class)
+                    .isInstanceOf(LogCaptorException.class)
                     .hasMessage("SLF4J Logger implementation should be of the type [ch.qos.logback.classic.Logger] but found [org.slf4j.simple.SimpleLogger].");
         }
     }
@@ -469,7 +470,7 @@ void throwExceptionWhenLoggerImplementationIsFromAnotherClassloader() throws Inv
             loggerFactoryMockedStatic.when(() -> LoggerFactory.getLogger(anyString())).thenReturn(logger);
 
             assertThatThrownBy(LogCaptor::forRoot)
-                    .isInstanceOf(IllegalArgumentException.class)
+                    .isInstanceOf(LogCaptorException.class)
                     .hasMessage(String.format("Multiple classloaders are being used. The Logging API is created by the following classloader: [nl.altindag.log.LogCaptorShould$CustomClassLoader], " +
                             "while it should have been created by the following classloader: [%s].", this.getClass().getClassLoader().getClass().getName()
                     ));

src/test/java/nl/altindag/log/util/LogbackUtilsShould.java

@@ -0,0 +1,109 @@
+/*
+ * Copyright 2019 Thunderberry.
+ *
+ * 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
+ *
+ *      https://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 nl.altindag.log.util;
+
+import ch.qos.logback.classic.Logger;
+import nl.altindag.log.exception.LogCaptorException;
+import org.junit.jupiter.api.Test;
+import org.mockito.MockedStatic;
+import org.slf4j.LoggerFactory;
+import org.slf4j.helpers.SubstituteLogger;
+
+import static org.assertj.core.api.Assertions.assertThat;
+import static org.assertj.core.api.Assertions.assertThatThrownBy;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.mockStatic;
+import static org.mockito.Mockito.times;
+
+class LogbackUtilsShould {
+
+    @Test
+    void getLoggerEvenWhenItHasInitializedLogger() {
+        SubstituteLogger substituteLogger = mock(SubstituteLogger.class);
+        Logger logbackLogger = mock(Logger.class);
+
+        try (MockedStatic<LoggerFactory> mockedStatic = mockStatic(LoggerFactory.class)) {
+            mockedStatic.when(() -> LoggerFactory.getLogger("magic-logger"))
+                    .thenReturn(substituteLogger)
+                    .thenReturn(logbackLogger);
+
+            Logger logger = LogbackUtils.getLogger("magic-logger");
+            assertThat(logger).isEqualTo(logbackLogger);
+        }
+    }
+
+    @Test
+    void failToGetLoggerWhenTheUnderlyingLoggerIsNotInitializedYet() {
+        SubstituteLogger substituteLogger = mock(SubstituteLogger.class);
+        System.setProperty("logcaptor.poll-counter-limit", "1");
+
+        try (MockedStatic<LoggerFactory> mockedStatic = mockStatic(LoggerFactory.class)) {
+            mockedStatic.when(() -> LoggerFactory.getLogger("magic-logger"))
+                    .thenReturn(substituteLogger);
+
+            assertThatThrownBy(() -> LogbackUtils.getLogger("magic-logger"))
+                    .isInstanceOf(LogCaptorException.class)
+                    .hasMessage("SLF4J Logger implementation should be of the type [ch.qos.logback.classic.Logger] but found [org.slf4j.helpers.SubstituteLogger].");
+        } finally {
+            System.clearProperty("logcaptor.poll-counter-limit");
+        }
+    }
+
+    @Test
+    void failToGetLoggerWhenTheUnderlyingLoggerIsNotInitializedAndExceedsRetryMechanism() {
+        System.setProperty("logcaptor.poll-counter-limit", "5");
+        System.setProperty("logcaptor.poll-delay-milliseconds", "10");
+
+        SubstituteLogger substituteLogger = mock(SubstituteLogger.class);
+
+        try (MockedStatic<LoggerFactory> mockedStatic = mockStatic(LoggerFactory.class)) {
+            mockedStatic.when(() -> LoggerFactory.getLogger("magic-logger"))
+                    .thenReturn(substituteLogger);
+
+            assertThatThrownBy(() -> LogbackUtils.getLogger("magic-logger"))
+                    .isInstanceOf(LogCaptorException.class)
+                    .hasMessage("SLF4J Logger implementation should be of the type [ch.qos.logback.classic.Logger] but found [org.slf4j.helpers.SubstituteLogger].");
+
+            mockedStatic.verify(() -> LoggerFactory.getLogger("magic-logger"), times(6));
+        } finally {
+            System.clearProperty("logcaptor.poll-counter-limit");
+            System.clearProperty("logcaptor.poll-delay-milliseconds");
+        }
+    }
+
+    @Test
+    void useDefaultRetryMechanismWhenSystemPropertiesAreInvalid() {
+        System.setProperty("logcaptor.poll-counter-limit", "   ");
+        System.setProperty("logcaptor.poll-delay-milliseconds", "    ");
+
+        SubstituteLogger substituteLogger = mock(SubstituteLogger.class);
+
+        try (MockedStatic<LoggerFactory> mockedStatic = mockStatic(LoggerFactory.class)) {
+            mockedStatic.when(() -> LoggerFactory.getLogger("magic-logger"))
+                    .thenReturn(substituteLogger);
+
+            assertThatThrownBy(() -> LogbackUtils.getLogger("magic-logger"))
+                    .isInstanceOf(LogCaptorException.class)
+                    .hasMessage("SLF4J Logger implementation should be of the type [ch.qos.logback.classic.Logger] but found [org.slf4j.helpers.SubstituteLogger].");
+
+            mockedStatic.verify(() -> LoggerFactory.getLogger("magic-logger"), times(11));
+        } finally {
+            System.clearProperty("logcaptor.poll-counter-limit");
+            System.clearProperty("logcaptor.poll-delay-milliseconds");
+        }
+    }
+
+}