Skip to content

Commit

Permalink
Refactor logging for test framework registry (keycloak#35447)
Browse files Browse the repository at this point in the history
Signed-off-by: stianst <[email protected]>
  • Loading branch information
stianst authored Dec 3, 2024
1 parent 7a35d49 commit e995601
Show file tree
Hide file tree
Showing 2 changed files with 161 additions and 59 deletions.
Original file line number Diff line number Diff line change
@@ -1,6 +1,5 @@
package org.keycloak.test.framework.injection;

import org.jboss.logging.Logger;
import org.junit.jupiter.api.extension.ExtensionContext;
import org.keycloak.test.framework.TestFrameworkExtension;
import org.keycloak.test.framework.config.Config;
Expand All @@ -22,7 +21,7 @@
@SuppressWarnings({"rawtypes", "unchecked"})
public class Registry implements ExtensionContext.Store.CloseableResource {

private static final Logger LOGGER = Logger.getLogger(Registry.class);
private RegistryLogger logger;

private ExtensionContext currentContext;
private final List<Supplier<?, ?>> suppliers = new LinkedList<>();
Expand Down Expand Up @@ -75,11 +74,7 @@ private <T> T getDeployedDependency(Class<T> typeClass, String ref, InstanceCont
if (dependency != null) {
dependency.registerDependency(dependent);

if (LOGGER.isDebugEnabled()) {
LOGGER.debugv("Injecting existing dependency {0} into {1}",
dependency.getSupplier().getClass().getSimpleName(),
dependent.getSupplier().getClass().getSimpleName());
}
logger.logDependencyInjection(dependent, dependency, RegistryLogger.InjectionType.EXISTING);

return (T) dependency.getValue();
}
Expand All @@ -96,11 +91,7 @@ private <T> T getRequestedDependency(Class<T> typeClass, String ref, InstanceCon

requestedInstances.remove(requestedDependency);

if (LOGGER.isDebugEnabled()) {
LOGGER.debugv("Injecting requested dependency {0} into {1}",
dependency.getSupplier().getClass().getSimpleName(),
dependent.getSupplier().getClass().getSimpleName());
}
logger.logDependencyInjection(dependent, dependency, RegistryLogger.InjectionType.REQUESTED);

return (T) dependency.getValue();
}
Expand All @@ -120,11 +111,7 @@ private <T> T getUnConfiguredDependency(Class<T> typeClass, String ref, Instance

deployedInstances.add(dependency);

if (LOGGER.isDebugEnabled()) {
LOGGER.debugv("Injecting un-configured dependency {0} into {1}",
dependency.getSupplier().getClass().getSimpleName(),
dependent.getSupplier().getClass().getSimpleName());
}
logger.logDependencyInjection(dependent, dependency, RegistryLogger.InjectionType.UN_CONFIGURED);

return (T) dependency.getValue();
}
Expand Down Expand Up @@ -153,10 +140,7 @@ private void findRequestedInstances(Object testInstance) {
}
}

if (LOGGER.isDebugEnabled()) {
LOGGER.debugv("Requested suppliers: {0}",
requestedInstances.stream().map(r -> r.getSupplier().getClass().getSimpleName()).collect(Collectors.joining(", ")));
}
logger.logRequestedInstances(requestedInstances);
}

private void matchDeployedInstancesWithRequestedInstances() {
Expand All @@ -166,18 +150,10 @@ private void matchDeployedInstancesWithRequestedInstances() {
InstanceContext deployedInstance = getDeployedInstance(requestedInstance);
if (deployedInstance != null) {
if (requestedInstance.getLifeCycle().equals(deployedInstance.getLifeCycle()) && deployedInstance.getSupplier().compatible(deployedInstance, requestedInstance)) {
if (LOGGER.isDebugEnabled()) {
LOGGER.debugv("Reusing compatible: {0}",
deployedInstance.getSupplier().getClass().getSimpleName());
}

logger.logReusingCompatibleInstance(deployedInstance);
itr.remove();
} else {
if (LOGGER.isDebugEnabled()) {
LOGGER.debugv("Destroying non-compatible: {0}",
deployedInstance.getSupplier().getClass().getSimpleName());
}

logger.logDestroyIncompatible(deployedInstance);
destroy(deployedInstance);
}
}
Expand All @@ -194,10 +170,7 @@ private void deployRequestedInstances() {
instance.setValue(requestedInstance.getSupplier().getValue(instance));
deployedInstances.add(instance);

if (LOGGER.isDebugEnabled()) {
LOGGER.debugv("Created instance: {0}",
requestedInstance.getSupplier().getClass().getSimpleName());
}
logger.logCreatedInstance(requestedInstance, instance);
}
}
}
Expand All @@ -218,31 +191,31 @@ private void injectFields(Object testInstance) {
}

public void afterAll() {
LOGGER.debug("Closing instances with class lifecycle");
logger.logAfterAll();
List<InstanceContext<?, ?>> destroy = deployedInstances.stream().filter(i -> i.getLifeCycle().equals(LifeCycle.CLASS)).toList();
destroy.forEach(this::destroy);
}

public void afterEach() {
LOGGER.debug("Closing instances with method lifecycle");
logger.logAfterEach();
List<InstanceContext<?, ?>> destroy = deployedInstances.stream().filter(i -> i.getLifeCycle().equals(LifeCycle.METHOD)).toList();
destroy.forEach(this::destroy);

List<InstanceContext<?, ?>> cleanup = deployedInstances.stream().filter(i -> i.getValue() instanceof ManagedTestResource).toList();
for (InstanceContext<?, ?> c : cleanup) {
ManagedTestResource managedTestResource = (ManagedTestResource) c.getValue();
if (managedTestResource.isDirty()) {
LOGGER.debugv("Destroying dirty instance {0}", c.getValue());
logger.logDestroyDirty(c);
destroy(c);
} else {
LOGGER.debugv("Cleanup instance {0}", c.getValue());
logger.logCleanup(c);
managedTestResource.runCleanup();
}
}
}

public void close() {
LOGGER.debug("Closing all instances");
logger.logClose();
List<InstanceContext<?, ?>> destroy = deployedInstances.stream().sorted(InstanceContextComparator.INSTANCE.reversed()).toList();
destroy.forEach(this::destroy);
}
Expand Down Expand Up @@ -283,10 +256,7 @@ private void destroy(InstanceContext instanceContext) {
dependencies.forEach(this::destroy);
instanceContext.getSupplier().close(instanceContext);

if (LOGGER.isDebugEnabled()) {
LOGGER.debugv("Closed instance: {0}",
instanceContext.getSupplier().getClass().getSimpleName());
}
logger.logDestroy(instanceContext);
}
}

Expand Down Expand Up @@ -319,6 +289,8 @@ private void loadSuppliers() {
valueTypeAlias.addAll(extension.valueTypeAliases());
}

logger = new RegistryLogger(valueTypeAlias);

Set<Class> loadedValueTypes = new HashSet<>();
Set<Supplier> skippedSuppliers = new HashSet<>();

Expand All @@ -345,21 +317,7 @@ private void loadSuppliers() {
}
}

if (LOGGER.isDebugEnabled()) {
StringBuilder loaded = new StringBuilder();
loaded.append("Loaded suppliers:");
for (Supplier s : suppliers) {
loaded.append("\n - " + valueTypeAlias.getAlias(s.getValueType()) + " --> " + s.getAlias());
}
LOGGER.debug(loaded.toString());

StringBuilder skipped = new StringBuilder();
skipped.append("Skipped suppliers:");
for (Supplier s : skippedSuppliers) {
skipped.append("\n - " + valueTypeAlias.getAlias(s.getValueType()) + " --> " + s.getAlias());
}
LOGGER.debug(skipped.toString());
}
logger.logSuppliers(suppliers, skippedSuppliers);
}

private InstanceContext getDeployedInstance(Class typeClass, String ref) {
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,144 @@
package org.keycloak.test.framework.injection;

import org.jboss.logging.Logger;

import java.util.List;
import java.util.Set;
import java.util.stream.Collectors;

@SuppressWarnings("rawtypes")
class RegistryLogger {

private static final Logger LOGGER = Logger.getLogger(RegistryLogger.class);
private final ValueTypeAlias valueTypeAlias;

public RegistryLogger(ValueTypeAlias valueTypeAlias) {
this.valueTypeAlias = valueTypeAlias;
}

public void logDependencyInjection(InstanceContext<?, ?> dependent, InstanceContext<?, ?> dependency, InjectionType injectionType) {
if (LOGGER.isDebugEnabled()) {
LOGGER.debugv("Injecting {0} dependency {1}#{2,number,#} into {3}#{4,number,#}",
injectionType,
dependency.getSupplier().getClass().getSimpleName(),
dependency.getInstanceId(),
dependent.getSupplier().getClass().getSimpleName(),
dependent.getInstanceId());
}
}

public void logRequestedInstances(List<RequestedInstance<?, ?>> requestedInstances) {
if (LOGGER.isDebugEnabled()) {
LOGGER.debugv("Requested instances: {0}",
requestedInstances.stream().map(r -> r.getSupplier().getValueType().getSimpleName()).collect(Collectors.joining(", ")));
}
}

public void logReusingCompatibleInstance(InstanceContext instance) {
if (LOGGER.isDebugEnabled()) {
LOGGER.debugv("Reusing compatible: {0}#{1,number,#}",
instance.getSupplier().getClass().getSimpleName(),
instance.getInstanceId());
}
}

public void logDestroy(InstanceContext instance) {
if (LOGGER.isDebugEnabled()) {
LOGGER.debugv("Closed instance: {0}#{1,number,#}",
instance.getSupplier().getClass().getSimpleName(),
instance.getInstanceId());
}
}

public void logDestroyIncompatible(InstanceContext instance) {
if (LOGGER.isDebugEnabled()) {
LOGGER.debugv("Closing non-compatible instance: {0}#{1,number,#}",
instance.getSupplier().getClass().getSimpleName(),
instance.getInstanceId());
}
}

public void logDestroyDirty(InstanceContext instance) {
if (LOGGER.isDebugEnabled()) {
LOGGER.debugv("Closing dirty instance: {0}#{1,number,#}",
instance.getSupplier().getClass().getSimpleName(),
instance.getInstanceId());
}
}

public void logCleanup(InstanceContext instance) {
LOGGER.debugv("Cleanup instance {0}#{1,number,#}", instance.getValue(), instance.getInstanceId());
}

public void logCreatedInstance(RequestedInstance requestedInstance, InstanceContext instance) {
if (LOGGER.isDebugEnabled()) {
LOGGER.debugv("Created instance: {0}#{1,number,#}",
requestedInstance.getSupplier().getClass().getSimpleName(), instance.getInstanceId());
}
}

public void logAfterAll() {
LOGGER.debug("Closing instances with class lifecycle");
}

public void logAfterEach() {
LOGGER.debug("Closing instances with method lifecycle");
}

public void logClose() {
LOGGER.debug("Closing all instances");
}

public void logSuppliers(List<Supplier<?, ?>> suppliers, Set<Supplier> skippedSuppliers) {
if (LOGGER.isDebugEnabled()) {
StringBuilder sb = new StringBuilder();
sb.append("Loaded suppliers:");
for (Supplier s : suppliers) {
sb.append("\n - ");
appendSupplierInfo(s, sb);
}

sb.append("\nSkipped suppliers:");
for (Supplier s : skippedSuppliers) {
sb.append("\n - ");
appendSupplierInfo(s, sb);
}

LOGGER.debug(sb.toString());
}
}

private void appendSupplierInfo(Supplier s, StringBuilder sb) {
sb.append("supplierType=");
sb.append(s.getClass().getSimpleName());
sb.append(", valueType=");
sb.append(s.getValueType().getSimpleName());

String alias = valueTypeAlias.getAlias(s.getValueType());
if (!alias.equals(s.getValueType().getSimpleName())) {
sb.append(", alias=");
sb.append(alias);
}

}

public enum InjectionType {

EXISTING("existing"),
REQUESTED("requested"),
UN_CONFIGURED("un-configured");

private String stringRep;

InjectionType(String stringRep) {
this.stringRep = stringRep;
}


@Override
public String toString() {
return stringRep;
}
}

}

0 comments on commit e995601

Please sign in to comment.