KEYCLOAK-9113 Add support for inspecting log messages for uncaught errors

services/src/main/java/org/keycloak/services/error/KeycloakErrorHandler.java

@@ -41,6 +41,8 @@ public class KeycloakErrorHandler implements ExceptionMapper<Throwable> {
 
     private static final Pattern realmNamePattern = Pattern.compile(".*/realms/([^/]+).*");
 
+    public static final String UNCAUGHT_SERVER_ERROR_TEXT = "Uncaught server error";
+
     @Context
     private KeycloakSession session;
 
@@ -58,7 +60,7 @@ public class KeycloakErrorHandler implements ExceptionMapper<Throwable> {
         int statusCode = getStatusCode(throwable);
 
         if (statusCode >= 500 && statusCode <= 599) {
-            logger.error("Uncaught server error", throwable);
+            logger.error(UNCAUGHT_SERVER_ERROR_TEXT, throwable);
         }
 
         if (!MediaTypeMatcher.isHtmlRequest(headers)) {

testsuite/integration-arquillian/tests/base/src/main/java/org/keycloak/testsuite/arquillian/AuthServerTestEnricher.java

@@ -36,6 +36,8 @@ import org.jboss.arquillian.test.spi.event.suite.BeforeSuite;
 import org.jboss.logging.Logger;
 import org.keycloak.admin.client.Keycloak;
 import org.keycloak.representations.idm.RealmRepresentation;
+import org.keycloak.services.error.KeycloakErrorHandler;
+import org.keycloak.testsuite.arquillian.annotation.UncaughtServerErrorExpected;
 import org.keycloak.testsuite.client.KeycloakTestingClient;
 import org.keycloak.testsuite.util.LogChecker;
 import org.keycloak.testsuite.util.OAuthClient;
@@ -44,6 +46,7 @@ import org.wildfly.extras.creaper.commands.undertow.RemoveUndertowListener;
 import org.wildfly.extras.creaper.commands.undertow.SslVerifyClient;
 import org.wildfly.extras.creaper.commands.undertow.UndertowListenerType;
 import org.wildfly.extras.creaper.core.CommandFailedException;
+import org.keycloak.testsuite.util.TextFileChecker;
 import org.wildfly.extras.creaper.core.ManagementClient;
 import org.wildfly.extras.creaper.core.online.CliException;
 import org.wildfly.extras.creaper.core.online.OnlineManagementClient;
@@ -58,11 +61,18 @@ import java.net.MalformedURLException;
 import java.net.URL;
 import java.util.List;
 import java.util.Objects;
+import java.util.Optional;
 import java.util.Set;
 
 import java.util.concurrent.TimeoutException;
+import java.util.regex.Matcher;
+import java.util.regex.Pattern;
 import java.util.stream.Collectors;
+import java.util.stream.Stream;
 import javax.ws.rs.NotFoundException;
+import org.jboss.arquillian.test.spi.event.suite.After;
+import org.jboss.arquillian.test.spi.event.suite.Before;
+import org.junit.Assert;
 
 /**
  *
@@ -321,14 +331,36 @@ public class AuthServerTestEnricher {
         startContainerEvent.fire(new StartContainer(suiteContext.getAuthServerInfo().getArquillianContainer()));
     }
 
-    public void checkServerLogs(@Observes(precedence = -1) BeforeSuite event) throws IOException, InterruptedException {
+    private static final Pattern RECOGNIZED_ERRORS = Pattern.compile("ERROR|SEVERE|Exception ");
-        boolean checkLog = Boolean.parseBoolean(System.getProperty("auth.server.log.check", "true"));
+    private static final Pattern IGNORED = Pattern.compile("Jetty ALPN support not found|org.keycloak.events");
-        if (checkLog && suiteContext.getAuthServerInfo().isJBossBased()) {
+
-            String jbossHomePath = suiteContext.getAuthServerInfo().getProperties().get("jbossHome");
+    private static final boolean isRecognizedErrorLog(String logText) {
-            LogChecker.checkJBossServerLog(jbossHomePath);
+        //There is expected string "Exception" in server log: Adding provider
+        //singleton org.keycloak.services.resources.ModelExceptionMapper
+        return RECOGNIZED_ERRORS.matcher(logText).find() && ! IGNORED.matcher(logText).find();
+    }
+
+    private static final void failOnRecognizedErrorInLog(Stream<String> logStream) {
+        Optional<String> anyRecognizedError = logStream.filter(AuthServerTestEnricher::isRecognizedErrorLog).findAny();
+        if (anyRecognizedError.isPresent()) {
+            throw new RuntimeException(String.format("Server log file contains ERROR: '%s'", anyRecognizedError.get()));
         }
     }
 
+    public void checkServerLogs(@Observes(precedence = -1) BeforeSuite event) throws IOException, InterruptedException {
+        if (! suiteContext.getAuthServerInfo().isJBossBased()) {
+            suiteContext.setServerLogChecker(new TextFileChecker());    // checks nothing
+            return;
+        }
+
+        boolean checkLog = Boolean.parseBoolean(System.getProperty("auth.server.log.check", "true"));
+        String jbossHomePath = suiteContext.getAuthServerInfo().getProperties().get("jbossHome");
+        if (checkLog) {
+            LogChecker.getJBossServerLogsChecker(true, jbossHomePath).checkFiles(AuthServerTestEnricher::failOnRecognizedErrorInLog);
+        }
+        suiteContext.setServerLogChecker(LogChecker.getJBossServerLogsChecker(false, jbossHomePath));
+    }
+
     public void initializeTestContext(@Observes(precedence = 2) BeforeClass event) {
         TestContext testContext = new TestContext(suiteContext, event.getTestClass().getJavaClass());
         testContextProducer.set(testContext);
@@ -390,6 +422,31 @@ public class AuthServerTestEnricher {
         oAuthClientProducer.set(oAuthClient);
     }
 
+    public void beforeTest(@Observes(precedence = 100) Before event) throws IOException {
+        suiteContext.getServerLogChecker().updateLastCheckedPositionsOfAllFilesToEndOfFile();
+    }
+
+    private static final Pattern UNEXPECTED_UNCAUGHT_ERROR = Pattern.compile(
+      KeycloakErrorHandler.class.getSimpleName()
+        + ".*"
+        + Pattern.quote(KeycloakErrorHandler.UNCAUGHT_SERVER_ERROR_TEXT)
+        + "[\\s:]*(.*)$"
+    );
+
+    private void checkForNoUnexpectedUncaughtError(Stream<String> logStream) {
+        Optional<Matcher> anyUncaughtError = logStream.map(UNEXPECTED_UNCAUGHT_ERROR::matcher).filter(Matcher::find).findAny();
+        if (anyUncaughtError.isPresent()) {
+            Matcher m = anyUncaughtError.get();
+            Assert.fail("Uncaught server error detected: " + m.group(1));
+        }
+    }
+
+    public void afterTest(@Observes(precedence = -1) After event) throws IOException {
+        if (event.getTestMethod().getAnnotation(UncaughtServerErrorExpected.class) == null) {
+            suiteContext.getServerLogChecker().checkFiles(this::checkForNoUnexpectedUncaughtError);
+        }
+    }
+
     public void afterClass(@Observes(precedence = 2) AfterClass event) {
         //check if a test accidentally left the auth-server not running
         ContainerController controller = containerConroller.get();

testsuite/integration-arquillian/tests/base/src/main/java/org/keycloak/testsuite/arquillian/SuiteContext.java

@@ -24,6 +24,7 @@ import java.util.Set;
 
 import org.keycloak.testsuite.arquillian.migration.MigrationContext;
 
+import org.keycloak.testsuite.util.TextFileChecker;
 import java.util.LinkedList;
 import static org.keycloak.testsuite.util.MailServerConfiguration.FROM;
 import static org.keycloak.testsuite.util.MailServerConfiguration.HOST;
@@ -48,6 +49,8 @@ public final class SuiteContext {
     private boolean adminPasswordUpdated;
     private final Map<String, String> smtpServer = new HashMap<>();
 
+    private TextFileChecker serverLogChecker;
+
     /**
      * True if the testsuite is running in the adapter backward compatibility testing mode,
      * i.e. if the tests are running against newer auth server
@@ -62,6 +65,14 @@ public final class SuiteContext {
         smtpServer.put("port", PORT);
     }
 
+    public TextFileChecker getServerLogChecker() {
+        return this.serverLogChecker;
+    }
+
+    public void setServerLogChecker(TextFileChecker serverLogChecker) {
+        this.serverLogChecker = serverLogChecker;
+    }
+
     public boolean isAdminPasswordUpdated() {
         return adminPasswordUpdated;
     }

testsuite/integration-arquillian/tests/base/src/main/java/org/keycloak/testsuite/arquillian/annotation/UncaughtServerErrorExpected.java

@@ -0,0 +1,34 @@
+/*
+ * Copyright 2018 Red Hat, Inc. and/or its affiliates
+ * and other contributors as indicated by the @author tags.
+ * 
+ * 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
+ * 
+ * http://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 org.keycloak.testsuite.arquillian.annotation;
+
+import java.lang.annotation.Documented;
+import java.lang.annotation.ElementType;
+import java.lang.annotation.Retention;
+import java.lang.annotation.Target;
+import static java.lang.annotation.RetentionPolicy.RUNTIME;
+
+/**
+ * This annotation is for test methods that expect server to throw an uncaught server error
+ * @author hmlnarik
+ */
+@Documented
+@Retention(RUNTIME)
+@Target({ElementType.METHOD})
+public @interface UncaughtServerErrorExpected {
+
+}

testsuite/integration-arquillian/tests/base/src/main/java/org/keycloak/testsuite/util/LogChecker.java

@@ -16,57 +16,38 @@
  */
 package org.keycloak.testsuite.util;
 
-import org.apache.commons.io.FileUtils;
-import org.jboss.logging.Logger;
-
 import java.io.File;
 import java.io.IOException;
+import java.nio.file.Path;
+import java.util.Arrays;
 
 /**
  *
- * @author vramik
+ * @author hmlnarik
- * @author tkyjovsk
  */
 public class LogChecker {
 
-    private static final Logger log = Logger.getLogger(LogChecker.class);
+    public static String[] getJBossServerLogFiles(String jbossHome) {
-
-    private static final String[] IGNORED = new String[] { ".*Jetty ALPN support not found.*", ".*org.keycloak.events.*" };
-
-    public static void checkServerLog(File logFile) throws IOException {
-        log.info(String.format("Checking server log: '%s'", logFile.getAbsolutePath()));
-        String[] logContent = FileUtils.readFileToString(logFile, "UTF-8").split("\n");
-
-        for (String logText : logContent) {
-            boolean containsError = logText.contains("ERROR") || logText.contains("SEVERE") || logText.contains("Exception ");
-            //There is expected string "Exception" in server log: Adding provider
-            //singleton org.keycloak.services.resources.ModelExceptionMapper
-            if (containsError) {
-                boolean ignore = false;
-                for (String i : IGNORED) {
-                    if (logText.matches(i)) {
-                        ignore = true;
-                        break;
-                    }
-                }
-                if (!ignore) {
-                    throw new RuntimeException(String.format("Server log file contains ERROR: '%s'", logText));
-                }
-            }
-        }
-
-    }
-
-    public static void checkJBossServerLog(String jbossHome) throws IOException {
         boolean domain = System.getProperty("auth.server.config.property.name", "standalone").contains("domain");
         if (domain) {
-            checkServerLog(new File(jbossHome + "/domain/log/process-controller.log"));
+            return new String[] {
-            checkServerLog(new File(jbossHome + "/domain/log/host-controller.log"));
+              jbossHome + "/domain/log/process-controller.log",
-            checkServerLog(new File(jbossHome + "/domain/servers/load-balancer/log/server.log"));
+              jbossHome + "/domain/log/host-controller.log",
-            checkServerLog(new File(jbossHome + "/domain/servers/server-one/log/server.log"));
+              jbossHome + "/domain/servers/load-balancer/log/server.log",
+              jbossHome + "/domain/servers/server-one/log/server.log"
+            };
         } else {
-            checkServerLog(new File(jbossHome + "/standalone/log/server.log"));
+            return new String[] {
+                jbossHome + "/standalone/log/server.log"
+            };
         }
     }
 
+    public static TextFileChecker getJBossServerLogsChecker(boolean verbose, String jbossHome) throws IOException {
+        String[] pathsToCheck = getJBossServerLogFiles(jbossHome);
+        Path[] pathsArray = Arrays.stream(pathsToCheck).map(File::new).map(File::toPath).toArray(Path[]::new);
+
+        return new TextFileChecker(verbose, pathsArray);
+    }
+
 }

testsuite/integration-arquillian/tests/base/src/main/java/org/keycloak/testsuite/util/TextFileChecker.java

@@ -0,0 +1,85 @@
+/*
+ * Copyright 2018 Red Hat, Inc. and/or its affiliates
+ * and other contributors as indicated by the @author tags.
+ * 
+ * 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
+ * 
+ * http://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 org.keycloak.testsuite.util;
+
+import java.io.BufferedReader;
+import java.io.IOException;
+import java.io.InputStream;
+import java.io.InputStreamReader;
+import java.nio.file.Files;
+import java.nio.file.Path;
+import java.util.HashMap;
+import java.util.Map;
+import java.util.function.Consumer;
+import java.util.stream.Stream;
+import org.jboss.logging.Logger;
+import org.jboss.logging.Logger.Level;
+
+/**
+ *
+ * @author hmlnarik
+ */
+public class TextFileChecker {
+
+    private static final Logger log = Logger.getLogger(TextFileChecker.class);
+
+    private final Map<Path, Long> lastCheckedPositions = new HashMap<>();
+
+    private final Path[] paths;
+
+    private final boolean verbose;
+
+    public TextFileChecker(boolean verbose, Path... paths) {
+        this.verbose = verbose;
+        this.paths = paths;
+    }
+
+    public TextFileChecker(Path... paths) {
+        this(false, paths);
+    }
+
+    private void updateLastCheckedPositionsOfAllFilesToEndOfFile(Path path) throws IOException {
+        if (Files.exists(path)) {
+            lastCheckedPositions.put(path, Files.size(path));
+        } else {
+            lastCheckedPositions.remove(path);
+        }
+    }
+
+    public void checkFiles(Consumer<Stream<String>> lineChecker) throws IOException {
+        for (Path path : paths) {
+            log.logf(verbose ? Level.INFO : Level.DEBUG, "Checking server log: '%s'", path.toAbsolutePath());
+
+            if (! Files.exists(path)) {
+                continue;
+            }
+
+            try (InputStream in = Files.newInputStream(path)) {
+                Long lastCheckedPosition = lastCheckedPositions.computeIfAbsent(path, p -> 0L);
+                in.skip(lastCheckedPosition);
+                BufferedReader b = new BufferedReader(new InputStreamReader(in));
+                lineChecker.accept(b.lines());
+            }
+        }
+    }
+
+    public void updateLastCheckedPositionsOfAllFilesToEndOfFile() throws IOException {
+        for (Path path : paths) {
+            updateLastCheckedPositionsOfAllFilesToEndOfFile(path);
+        }
+    }
+}

testsuite/integration-arquillian/tests/base/src/test/java/org/keycloak/testsuite/error/UncaughtErrorPageTest.java

@@ -7,6 +7,7 @@ import org.keycloak.admin.client.resource.RealmResource;
 import org.keycloak.common.util.StreamUtil;
 import org.keycloak.representations.idm.RealmRepresentation;
 import org.keycloak.testsuite.AbstractKeycloakTest;
+import org.keycloak.testsuite.arquillian.annotation.UncaughtServerErrorExpected;
 import org.keycloak.testsuite.pages.ErrorPage;
 
 import javax.ws.rs.core.Response;
@@ -49,6 +50,7 @@ public class UncaughtErrorPageTest extends AbstractKeycloakTest {
     }
 
     @Test
+    @UncaughtServerErrorExpected
     public void uncaughtErrorJson() throws IOException {
         Response response = testingClient.testing().uncaughtError();
         assertEquals(500, response.getStatus());
@@ -60,6 +62,7 @@ public class UncaughtErrorPageTest extends AbstractKeycloakTest {
     }
 
     @Test
+    @UncaughtServerErrorExpected
     public void uncaughtError() throws MalformedURLException {
         URI uri = suiteContext.getAuthServerInfo().getUriBuilder().path("/auth/realms/master/testing/uncaught-error").build();
         driver.navigate().to(uri.toURL());

testsuite/integration-arquillian/tests/base/src/test/java/org/keycloak/testsuite/util/TextFileCheckerTest.java

@@ -0,0 +1,96 @@
+/*
+ * Copyright 2018 Red Hat, Inc. and/or its affiliates
+ * and other contributors as indicated by the @author tags.
+ * 
+ * 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
+ * 
+ * http://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 org.keycloak.testsuite.util;
+
+import java.io.File;
+import java.io.FileWriter;
+import java.io.IOException;
+import java.util.Collection;
+import java.util.LinkedList;
+import java.util.List;
+import java.util.function.Consumer;
+import java.util.stream.Stream;
+import org.hamcrest.Matchers;
+import org.junit.After;
+import org.junit.Assert;
+import org.junit.Before;
+import org.junit.Test;
+
+/**
+ *
+ * @author hmlnarik
+ */
+public class TextFileCheckerTest {
+
+    private TextFileChecker tfc;
+    private File tempFile;
+
+    private Consumer<Stream<String>> collector(Collection<String> target) {
+        return (Stream<String> s) -> s.forEachOrdered(target::add);
+    }
+
+    @Before
+    public void before() throws IOException {
+        tempFile = File.createTempFile("TextFileCheckerTest-", ".tmp");
+        tfc = new TextFileChecker(tempFile.toPath());
+    }
+
+    @After
+    public void after() throws IOException {
+        tempFile.delete();
+    }
+
+    @Test
+    public void testFileChecker() throws Exception {
+        try (FileWriter fw = new FileWriter(tempFile)) {
+            assertCheckedOutputIs();
+
+            fw.write("Hello, Dolly\n");
+            fw.flush();
+            assertCheckedOutputIs("Hello, Dolly");
+
+            fw.write("Well, hello, Dolly\n");
+            fw.flush();
+            assertCheckedOutputIs("Hello, Dolly", "Well, hello, Dolly");
+
+            fw.write("It's so nice to have you back where you belong\n");
+            fw.write("You're lookin' swell, Dolly\n");
+            fw.flush();
+            assertCheckedOutputIs("Hello, Dolly", "Well, hello, Dolly", "It's so nice to have you back where you belong", "You're lookin' swell, Dolly");
+
+            tfc.updateLastCheckedPositionsOfAllFilesToEndOfFile();
+
+            fw.write("I can tell, Dolly\n");
+            fw.write("You're still glowin', you're still crowin'\n");
+            fw.flush();
+            assertCheckedOutputIs("I can tell, Dolly", "You're still glowin', you're still crowin'");
+
+            tfc.updateLastCheckedPositionsOfAllFilesToEndOfFile();
+            assertCheckedOutputIs();
+        }
+    }
+
+    public void assertCheckedOutputIs(String... expectedOutput) throws IOException {
+        List<String> target = new LinkedList<>();
+        tfc.checkFiles(collector(target));
+        Assert.assertThat(target,
+          expectedOutput == null || expectedOutput.length == 0
+            ? Matchers.empty()
+            : Matchers.contains(expectedOutput));
+    }
+
+}