Skip to content

Commit

Permalink
KEYCLOAK-9113 Add support for inspecting log messages for uncaught er…
Browse files Browse the repository at this point in the history
…rors
  • Loading branch information
hmlnarik committed Feb 13, 2019
1 parent 46c00f3 commit 37e6b6f
Show file tree
Hide file tree
Showing 8 changed files with 312 additions and 43 deletions.
Expand Up @@ -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;

Expand All @@ -58,7 +60,7 @@ public Response toResponse(Throwable 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)) {
Expand Down
Expand Up @@ -36,6 +36,8 @@
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;
Expand All @@ -44,6 +46,7 @@
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;
Expand All @@ -58,11 +61,18 @@
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;

/**
*
Expand Down Expand Up @@ -321,12 +331,34 @@ public void startAuthContainer(@Observes(precedence = 0) StartSuiteContainers ev
startContainerEvent.fire(new StartContainer(suiteContext.getAuthServerInfo().getArquillianContainer()));
}

private static final Pattern RECOGNIZED_ERRORS = Pattern.compile("ERROR|SEVERE|Exception ");
private static final Pattern IGNORED = Pattern.compile("Jetty ALPN support not found|org.keycloak.events");

private static final boolean isRecognizedErrorLog(String logText) {
//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"));
if (checkLog && suiteContext.getAuthServerInfo().isJBossBased()) {
String jbossHomePath = suiteContext.getAuthServerInfo().getProperties().get("jbossHome");
LogChecker.checkJBossServerLog(jbossHomePath);
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) {
Expand Down Expand Up @@ -390,6 +422,31 @@ public void initializeOAuthClient(@Observes(precedence = 4) BeforeClass event) {
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();
Expand Down
Expand Up @@ -24,6 +24,7 @@

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;
Expand All @@ -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
Expand All @@ -62,6 +65,14 @@ public SuiteContext(Set<ContainerInfo> arquillianContainers) {
smtpServer.put("port", PORT);
}

public TextFileChecker getServerLogChecker() {
return this.serverLogChecker;
}

public void setServerLogChecker(TextFileChecker serverLogChecker) {
this.serverLogChecker = serverLogChecker;
}

public boolean isAdminPasswordUpdated() {
return adminPasswordUpdated;
}
Expand Down
@@ -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 {

}
Expand Up @@ -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 tkyjovsk
* @author hmlnarik
*/
public class LogChecker {

private static final Logger log = Logger.getLogger(LogChecker.class);

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 {
public static String[] getJBossServerLogFiles(String jbossHome) {
boolean domain = System.getProperty("auth.server.config.property.name", "standalone").contains("domain");
if (domain) {
checkServerLog(new File(jbossHome + "/domain/log/process-controller.log"));
checkServerLog(new File(jbossHome + "/domain/log/host-controller.log"));
checkServerLog(new File(jbossHome + "/domain/servers/load-balancer/log/server.log"));
checkServerLog(new File(jbossHome + "/domain/servers/server-one/log/server.log"));
return new String[] {
jbossHome + "/domain/log/process-controller.log",
jbossHome + "/domain/log/host-controller.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);
}

}
@@ -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);
}
}
}
Expand Up @@ -7,6 +7,7 @@
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;
Expand Down Expand Up @@ -49,6 +50,7 @@ public void invalidRealmResource() throws MalformedURLException {
}

@Test
@UncaughtServerErrorExpected
public void uncaughtErrorJson() throws IOException {
Response response = testingClient.testing().uncaughtError();
assertEquals(500, response.getStatus());
Expand All @@ -60,6 +62,7 @@ public void uncaughtErrorJson() throws IOException {
}

@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());
Expand Down

0 comments on commit 37e6b6f

Please sign in to comment.