From 0ae03081d904f42fbb851ab781e2d3f4b9ceb3d2 Mon Sep 17 00:00:00 2001 From: Martin Kouba Date: Thu, 11 Aug 2022 16:42:20 +0200 Subject: [PATCH] ArC - add debug logging for the request context manipulation - activation, deactivation and destruction --- docs/src/main/asciidoc/cdi-reference.adoc | 12 +++++++ .../io/quarkus/arc/impl/RequestContext.java | 35 +++++++++++++++++-- 2 files changed, 44 insertions(+), 3 deletions(-) diff --git a/docs/src/main/asciidoc/cdi-reference.adoc b/docs/src/main/asciidoc/cdi-reference.adoc index 05e17ed224ce8..b98af78afd3b7 100644 --- a/docs/src/main/asciidoc/cdi-reference.adoc +++ b/docs/src/main/asciidoc/cdi-reference.adoc @@ -354,6 +354,18 @@ The request context is destroyed: NOTE: An event with qualifier `@Initialized(RequestScoped.class)` is fired when the request context is initialized for an observer notification. Moreover, the events with qualifiers `@BeforeDestroyed(RequestScoped.class)` and `@Destroyed(RequestScoped.class)` are fired when the request context is destroyed. +==== How to Enable Trace Logging for Request Context Activation + +You can set the `TRACE` level for the logger `io.quarkus.arc.requestContext` and try to analyze the log output afterwards. + +.`application.properties` Example +[source,properties] +---- +quarkus.log.category."io.quarkus.arc.requestContext".min-level=TRACE <1> +quarkus.log.category."io.quarkus.arc.requestContext".level=TRACE +---- +<1> You also need to adjust the minimum log level for the relevant category. + === Qualified Injected Fields In CDI, if you declare a field injection point you need to use `@Inject` and optionally a set of qualifiers. diff --git a/independent-projects/arc/runtime/src/main/java/io/quarkus/arc/impl/RequestContext.java b/independent-projects/arc/runtime/src/main/java/io/quarkus/arc/impl/RequestContext.java index c7b3e07684739..30fbc2a361f8b 100644 --- a/independent-projects/arc/runtime/src/main/java/io/quarkus/arc/impl/RequestContext.java +++ b/independent-projects/arc/runtime/src/main/java/io/quarkus/arc/impl/RequestContext.java @@ -31,7 +31,7 @@ */ class RequestContext implements ManagedContext { - private static final Logger LOGGER = Logger.getLogger(RequestContext.class.getPackage().getName()); + private static final Logger LOG = Logger.getLogger("io.quarkus.arc.requestContext"); private final CurrentContext currentContext; @@ -39,11 +39,15 @@ class RequestContext implements ManagedContext { private final LazyValue> beforeDestroyedNotifier; private final LazyValue> destroyedNotifier; + private final boolean traceEnabled; + public RequestContext(CurrentContext currentContext) { this.currentContext = currentContext; this.initializedNotifier = new LazyValue<>(RequestContext::createInitializedNotifier); this.beforeDestroyedNotifier = new LazyValue<>(RequestContext::createBeforeDestroyedNotifier); this.destroyedNotifier = new LazyValue<>(RequestContext::createDestroyedNotifier); + // we do not need to check the effective log level + this.traceEnabled = LOG.isTraceEnabled(); } @Override @@ -122,6 +126,15 @@ public void destroy(Contextual contextual) { @Override public void activate(ContextState initialState) { + if (traceEnabled) { + String stack = Arrays.stream(Thread.currentThread().getStackTrace()) + .skip(2) + .limit(7) + .map(se -> "\n\t" + se.toString()) + .collect(Collectors.joining()); + LOG.tracef("Activate %s %s\n\t...", + initialState != null ? Integer.toHexString(initialState.hashCode()) : "new", stack); + } if (initialState == null) { currentContext.set(new RequestContextState(new ConcurrentHashMap<>())); // Fire an event with qualifier @Initialized(RequestScoped.class) if there are any observers for it @@ -151,6 +164,14 @@ public ContextState getStateIfActive() { @Override public void deactivate() { + if (traceEnabled) { + String stack = Arrays.stream(Thread.currentThread().getStackTrace()) + .skip(2) + .limit(7) + .map(se -> "\n\t" + se.toString()) + .collect(Collectors.joining()); + LOG.tracef("Deactivate%s\n\t...", stack); + } currentContext.remove(); } @@ -161,6 +182,14 @@ public void destroy() { @Override public void destroy(ContextState state) { + if (traceEnabled) { + String stack = Arrays.stream(Thread.currentThread().getStackTrace()) + .skip(2) + .limit(7) + .map(se -> "\n\t" + se.toString()) + .collect(Collectors.joining()); + LOG.tracef("Destroy %s%s\n\t...", state != null ? Integer.toHexString(state.hashCode()) : "", stack); + } if (state == null) { // nothing to destroy return; @@ -174,7 +203,7 @@ public void destroy(ContextState state) { try { fireIfNotEmpty(beforeDestroyedNotifier); } catch (Exception e) { - LOGGER.warn("An error occurred during delivery of the @BeforeDestroyed(RequestScoped.class) event", e); + LOG.warn("An error occurred during delivery of the @BeforeDestroyed(RequestScoped.class) event", e); } //Performance: avoid an iterator on the map elements map.forEach(this::destroyContextElement); @@ -182,7 +211,7 @@ public void destroy(ContextState state) { try { fireIfNotEmpty(destroyedNotifier); } catch (Exception e) { - LOGGER.warn("An error occurred during delivery of the @Destroyed(RequestScoped.class) event", e); + LOG.warn("An error occurred during delivery of the @Destroyed(RequestScoped.class) event", e); } map.clear(); }