8000 Log multi-line output of the managed Keycloak server as a single record by ahus1 · Pull Request #54830 · keycloak/keycloak · GitHub
[go: up one dir, main page]

Skip to content
Draft
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations 8000
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
< 10BC8 td class="blob-code blob-code-addition js-file-line"> }
Original file line number Diff line number Diff line change
Expand Up @@ -15,8 +15,6 @@
import java.util.List;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.TimeUnit;
import java.util.regex.Matcher;
import java.util.regex.Pattern;
import javax.net.ssl.HttpsURLConnection;
import javax.net.ssl.SSLContext;
import javax.net.ssl.SSLSocketFactory;
Expand All @@ -32,7 +30,9 @@
import org.keycloak.testframework.util.FileUtils;
import org.keycloak.testframework.util.ProcessUtils;
import org.keycloak.testframework.util.TmpDir;
import org.keycloak.util.JsonSerialization;

import com.fasterxml.jackson.databind.JsonNode;
import io.quarkus.fs.util.ZipUtils;
import org.jboss.logging.Logger;

Expand Down Expand Up @@ -156,6 +156,9 @@ private DistributionKeycloakServer.OutputHandler startKeycloak(List<String> args

ProcessBuilder pb = new ProcessBuilder(cmd);
pb.directory(new File(keycloakHomeDir, "bin"));
// The output handler requires ECS JSON records, so don't allow overriding these from the environment
pb.environment().put("KC_LOG_CONSOLE_OUTPUT", "json");
pb.environment().put("KC_LOG_CONSOLE_JSON_FORMAT", "ecs");

if (debug) {
pb.environment().put("DEBUG", "true");
Expand Down Expand Up @@ -358,8 +361,8 @@ private static File resolveKeycloakDist() {

private class OutputHandler implements Runnable {

private static final Pattern LOG_PATTERN = Pattern.compile("([^ ]*) ([^ ]*) ([A-Z]*)([ ]*)(.*)");
private static final Logger LOGGER = Logger.getLogger("managed.keycloak");
private static final String LOGGER_NAME = "managed.keycloak";
private static final Logger LOGGER = Logger.getLogger(LOGGER_NAME);

private boolean startedInPrinted = false;
private final Process process;
Expand All @@ -376,24 +379,12 @@ public void run() {
BufferedReader br = new BufferedReader(new InputStreamReader(is, StandardCharsets.UTF_8));
try {
for (String line = br.readLine(); process.isAlive() && line != null; line = br.readLine()) {
if (!startedInPrinted && line.matches(".*Keycloak.* started in.*")) {
startupLatch.countDown();
}

Matcher matcher = LOG_PATTERN.matcher(line);
if (matcher.matches()) {
String levelString = matcher.group(3);
String message = matcher.group(5);
if (levelString != null && message != null) {
for (Logger.Level l : Logger.Level.values()) {
if (l.name().equals(levelString)) {
LOGGER.log(l, message);
break;
}
}
}
if (line.startsWith("{")) {
logJson(line);
} else {
detectStartup(line);
LOGGER.info(line);
}
LOGGER.info(line);
}
} catch (IOException e) {
// Ignored
Expand All @@ -404,6 +395,51 @@ public void run() {
}
}

private void detectStartup(String text) {
if (!startedInPrinted && text.matches(".*Keycloak.* started in.*")) {
startupLatch.countDown();
}
}

// The server logs in JSON (ECS) format, so a record with a stack trace arrives as a single line.
private void logJson(String line) {
JsonNode node;
try {
node = JsonSerialization.mapper.readTree(line);
} catch (IOException e) {
detectStartup(line);
LOGGER.info(line);
return;
}

// JSON that is not a log record is forwarded unchanged
if (!node.hasNonNull("message")) {
LOGGER.info(line);
return;
}

String message = node.get("message").asText();
detectStartup(message);

JsonNode stackTrace = node.get("error.stack_trace");
if (stackTrace != null && !stackTrace.isNull()) {
message = message + "\n" + stackTrace.asText();

Logger.Level level = Logger.Level.INFO;
String levelString = node.path("log.level").asText("");
for (Logger.Level l : Logger.Level.values()) {
if (l.name().equals(levelString)) {
level = l;
break;
}
}
// Nested under the managed logger to keep its configured level, while preserving the original logger name
String loggerName = node.path("log.logger").asText("");
Logger logger = loggerName.isEmpty() ? LOGGER : Logger.getLogger(LOGGER_NAME + "." + loggerName);
logger.log(level, message);
}

public boolean waitForStarted() {
try {
startupLatch.await(startTimeout, TimeUnit.SECONDS);
Expand Down
3 changes: 1 addition & 2 deletions test-framework/docs/LOGGING.md
Original file line number Diff line number Diff line change
Expand Up @@ -49,8 +49,7 @@ Some useful categories include:
any issues with the test framework itself, or custom suppliers.
* `org.keycloak` - Logging from the Keycloak server. If you set this to `DEBUG` for example, but don't want debug from
the test framework, also explicitly set `org.keycloak.testframework` to for example `INFO`
* `managed.keycloak` - Log output from the managed Keycloak server if you are running the server in `distribution` mode
(which is the default)
* `managed.keycloak` - Log output from the managed Keycloak server if you are running the server in `distribution` mode (which is the default). The original logger name of each record is appended, for example `managed.keycloak.org.keycloak.services`.
* `managed.db` - Output from database containers are included in this category. Standard out is logged with `DEBUG`
level, while standard error is logged with `WARN` level
* `managed.infinispan` - Output from the external Infinispan container is included in this category. Standard out is
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,84 @@
package org.keycloak.testframework.tests;

import java.util.Arrays;
import java.util.concurrent.BlockingQueue;
import java.util.concurrent.LinkedBlockingQueue;
import java.util.concurrent.TimeUnit;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.LogRecord;

import org.keycloak.testframework.annotations.KeycloakIntegrationTest;
import org.keycloak.testframework.config.Config;
import org.keycloak.testframework.remote.runonserver.InjectRunOnServer;
import org.keycloak.testframework.remote.runonserver.RunOnServerClient;
import org.keycloak.testframework.server.KeycloakServer;

import org.junit.jupiter.api.Assertions;
import org.junit.jupiter.api.Assumptions;
import org.junit.jupiter.api.Test;

@KeycloakIntegrationTest
public class ManagedServerLogTest {

private static final String MARKER = "ManagedServerLogTest-marker";

@InjectRunOnServer
RunOnServerClient runOnServer;

@Test
public void multiLineRecordIsLoggedAsSingleRecordWithOriginalLevel() throws Exception {
Assumptions.assumeTrue(isDistributionSelected(), "Only applies to the distribution server");

BlockingQueue<LogRecord> records = new LinkedBlockingQueue<>();
Handler handler = new Handler() {
@Override
public void publish(LogRecord record) {
if (record.getMessage() != null && record.getMessage().contains(MARKER)) {
records.add(record);
}
}

@Override
public void flush() {
}

@Override
public void close() {
}
};

java.util.logging.Logger managedLogger = java.util.logging.Logger.getLogger("managed.keycloak");
managedLogger.addHandler(handler);
try {
runOnServer.run(session -> org.jboss.logging.Logger.getLogger("test.managed.log")
.error("ManagedServerLogTest-marker message", new RuntimeException("outer", new IllegalStateException("root cause"))));

LogRecord record = records.poll(30, TimeUnit.SECONDS);
Assertions.assertNotNull(record, "Record from managed server not received");
Assertions.assertEquals(Level.SEVERE, record.getLevel());
String message = record.getMessage();
Assertions.assertTrue(message.contains("java.lang.RuntimeException: outer"), message);
Assertions.assertTrue(message.contains("Caused by: java.lang.IllegalStateException: root cause"), message);
Assertions.assertTrue(message.contains("\n\tat "), message);
Assertions.assertNull(records.poll(1, TimeUnit.SECONDS), "Record should have been logged only once");
} finally {
managedLogger.removeHandler(handler);
}
}

// Distribution is the first registered server supplier, so it is the default unless filtered out
private static boolean isDistributionSelected() {
String selected = Config.getSelectedSupplier(KeycloakServer.class);
if (selected != null && !"distribution".equals(selected)) {
return false;
}
String included = Config.getIncludedSuppliers(KeycloakServer.class);
if (included != null && Arrays.stream(included.split(",")).noneMatch("distribution"::equals)) {
return false;
}
String excluded = Config.getExcludedSuppliers(KeycloakServer.class);
return excluded == null || Arrays.stream(excluded.split(",")).noneMatch("distribution"::equals);
}

}
Loading
0