Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

2214 - Add support for ScopedContext #2385

Closed
wants to merge 4 commits into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
@@ -0,0 +1,44 @@
/*
* Licensed to the Apache Software Foundation (ASF) under one or more
* contributor license agreements. See the NOTICE file distributed with
* this work for additional information regarding copyright ownership.
* The ASF licenses this file to you 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.apache.logging.log4j;

import static org.hamcrest.MatcherAssert.assertThat;
import static org.hamcrest.Matchers.equalTo;
import static org.hamcrest.Matchers.nullValue;

import org.junit.jupiter.api.Test;

public class ScopedContextTest {

@Test
public void testScope() {
ScopedContext.INITIAL_CONTEXT
.where("key1", "Log4j2")
.run(() -> assertThat(ScopedContext.get("key1"), equalTo("Log4j2")));
ScopedContext.INITIAL_CONTEXT.where("key1", "value1").run(() -> {
assertThat(ScopedContext.get("key1"), equalTo("value1"));
ScopedContext.current().get().where("key2", "value2").run(() -> {
assertThat(ScopedContext.get("key1"), equalTo("value1"));
assertThat(ScopedContext.get("key2"), equalTo("value2"));
});
ScopedContext.INITIAL_CONTEXT.where("key2", "value2").run(() -> {
assertThat(ScopedContext.get("key1"), nullValue());
assertThat(ScopedContext.get("key2"), equalTo("value2"));
});
});
}
}
264 changes: 264 additions & 0 deletions log4j-api/src/main/java/org/apache/logging/log4j/ScopedContext.java
Original file line number Diff line number Diff line change
@@ -0,0 +1,264 @@
/*
* Licensed to the Apache Software Foundation (ASF) under one or more
* contributor license agreements. See the NOTICE file distributed with
* this work for additional information regarding copyright ownership.
* The ASF licenses this file to you 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.apache.logging.log4j;

import java.util.Collections;
import java.util.HashMap;
import java.util.Map;
import java.util.Optional;
import java.util.concurrent.Callable;
import java.util.function.Supplier;
import org.apache.logging.log4j.internal.ScopedContextAnchor;

/**
* Context that can be used for data to be logged in a block of code.
*
* While this is influenced by ScopedValues from Java 21 it does not share the same API. While it can perform a
* similar function as a set of ScopedValues it is really meant to allow a block of code to include a set of keys and
* values in all the log events within that block. The underlying implementation must provide support for
* logging the ScopedContext for that to happen.
*
* The ScopedContext will not be bound to the current thread until either a run or call method is invoked. The
* contexts are nested so creating and running or calling via a second ScopedContext will result in the first
* ScopedContext being hidden until the call is returned. Thus the values from the first ScopedContext need to
* be added to the second to be included.
*
* @since 2.24.0
*/
public class ScopedContext {

public static final ScopedContext INITIAL_CONTEXT = new ScopedContext();

/**
* @hidden
* Returns an unmodifiable copy of the current ScopedContext Map. This method should
* only be used by implementations of Log4j API.
* @return the Map of Renderable objects.
*/
public static Map<String, Renderable> getContextMap() {
Optional<ScopedContext> context = ScopedContextAnchor.getContext();
if (context.isPresent()
&& context.get().contextMap != null
&& !context.get().contextMap.isEmpty()) {
return Collections.unmodifiableMap(context.get().contextMap);
}
return Collections.emptyMap();
}

/**
* Return the key from the current ScopedContext, if there is one and the key exists.
* @param key The key.
* @return The value of the key in the current ScopedContext.
*/
@SuppressWarnings("unchecked")
public static <T> T get(String key) {
Copy link
Contributor

@ppkarwasz ppkarwasz Mar 17, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I believe that ThreadContext and ScopedContext should be write-only.

The way I see it, these are logging-only services. The presence of get() methods allows user to use these services to store and retrieve their thread-dependent data, which is in my opinion and abuse of the API.

There are more proper ways to store data, e.g. in a servlet application the username should be stored in the ServletRequest attributes, not in ThreadContext.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I have to disagree with this but here we are just expressing our own opinions. Your example would require passing the ServletRequest through many methods that have no business knowing what a ServletRequest is or that they are even running in a servlet, but do need to know who the user is. For example, I have plenty of code that is shared between REST requests and Kafka consumers. It is obviously very late to suggest that the ThreadContext be write only. FWIW, the enhancement going into SLF4J does something sort of similar to this but instead of having the scoped context completely separate there you still do MDC.get to fetch attributes from the scoped context.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, I believe it is a matter of taste and commodity.

I am a little bit worried about users using ThreadContext for business-critical functionality, since a change of logging backend (e.g. from log4j-core to log4j-to-jul), might break that functionality. For example in #2374 I assumed that the ThreadContextMap implementation used by an implementation is strictly linked to the logger context implementation; since java.util.logging formatters don't support context data, log4j-to-jul might as well use no-op ThreadContextMap. Am I wrong?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree with @ppkarwasz's stance here.

Your example would require passing the ServletRequest through many methods that have no business knowing what a ServletRequest is or that they are even running in a servlet, but do need to know who the user is.

I understand the need, but using the logging framework to figure out who the session belongs to doesn't sound right to me. If a business logic needs to access the user and it is not available at that level, it should not blame the logging for this.

Optional<ScopedContext> context = ScopedContextAnchor.getContext();
if (context.isPresent()) {
Renderable renderable = context.get().contextMap.get(key);
if (renderable != null) {
return (T) renderable.getObject();
}
}
return null;
}

/**
* Returns an Optional holding the active ScopedContext.
* @return an Optional containing the active ScopedContext, if there is one.
*/
public static Optional<ScopedContext> current() {
return ScopedContextAnchor.getContext();
}

private final ScopedContext parent;
private final String key;
private final Renderable value;
private final Map<String, Renderable> contextMap;

private ScopedContext() {
this.parent = null;
this.key = null;
this.value = null;
this.contextMap = null;
}

private ScopedContext(Map<String, Renderable> map) {
this.parent = null;
this.key = null;
this.value = null;
this.contextMap = map;
}

private ScopedContext(ScopedContext parent, String key, Renderable value) {
this.parent = parent;
this.key = key;
this.value = value;
this.contextMap = null;
}

/**
* Adds a key/value pair to the ScopedContext being constructed.
* @param key the key to add.
* @param value the value associated with the key.
* @return the ScopedContext being constructed.
*/
public ScopedContext where(String key, Object value) {
return addObject(key, value);
}

/**
* Adds a key/value pair to the ScopedContext being constructed.
* @param key the key to add.
* @param supplier the function to generate the value.
* @return the ScopedContext being constructed.
*/
public ScopedContext where(String key, Supplier<Object> supplier) {
return addObject(key, supplier.get());
}

private ScopedContext addObject(String key, Object obj) {
if (obj != null) {
Renderable renderable = obj instanceof Renderable ? (Renderable) obj : new ObjectRenderable(obj);
return new ScopedContext(this, key, renderable);
}
return this;
}

/**
* Executes a code block that includes all the key/value pairs added to the ScopedContext.
* @param op the code block to execute.
*/
public void run(Runnable op) {
new ScopedContextRunner(this, op).run();
}

/**
* Executes a code block that includes all the key/value pairs added to the ScopedContext.
* @param op the code block to execute.
* @return the return value from the code block.
*/
public <R> R call(Callable<R> op) throws Exception {
return new ScopedContextCaller<R>(this, op).call();
}

private static class ScopedContextRunner implements Runnable {
private final Map<String, Renderable> contextMap = new HashMap<>();
private final ScopedContext context;
private final Runnable op;

public ScopedContextRunner(ScopedContext context, Runnable op) {
this.context = context;
this.op = op;
}

@Override
public void run() {
ScopedContext scopedContext = context;
// If the current context has a Map then we can just use it.
if (context.contextMap == null) {
do {
if (scopedContext.contextMap != null) {
// Once we hit a scope with an already populated Map we won't need to go any further.
contextMap.putAll(scopedContext.contextMap);
break;
} else if (scopedContext.key != null) {
contextMap.putIfAbsent(scopedContext.key, scopedContext.value);
}
scopedContext = scopedContext.parent;
} while (scopedContext != null);
scopedContext = new ScopedContext(contextMap);
}
ScopedContextAnchor.addScopedContext(scopedContext);
try {
op.run();
} finally {
ScopedContextAnchor.removeScopedContext();
}
}
}

private static class ScopedContextCaller<R> implements Callable<R> {
private final Map<String, Renderable> contextMap = new HashMap<>();
private final ScopedContext context;
private final Callable<R> op;

public ScopedContextCaller(ScopedContext context, Callable<R> op) {
this.context = context;
this.op = op;
}

@Override
public R call() throws Exception {
ScopedContext scopedContext = context;
// If the current context has a Map then we can just use it.
if (context.contextMap == null) {
do {
if (scopedContext.contextMap != null) {
// Once we hit a scope with an already populated Map we won't need to go any further.
contextMap.putAll(scopedContext.contextMap);
break;
} else if (scopedContext.key != null) {
contextMap.putIfAbsent(scopedContext.key, scopedContext.value);
}
scopedContext = scopedContext.parent;
} while (scopedContext != null);
scopedContext = new ScopedContext(contextMap);
}
ScopedContextAnchor.addScopedContext(scopedContext);
try {
return op.call();
} finally {
ScopedContextAnchor.removeScopedContext();
}
}
}

/**
* Interface for converting Objects stored in the ContextScope to Strings for logging.
*/
public static interface Renderable {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please let's not introduce a yet another Object-to-String helper interface ecosystem. I think StringBuilderFormattable fits the bill here.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

With regard to the get() method. This API supports Objects - something users have been requesting for a long time. I added them here because they can be safely used the way this is implemented. There is no point in accepting an object if user's cannot query them since logging will NEVER log an object, only its string representation.

How? There are no StringBuilders at all in ScopedContext. It is used to convert an object into its String representation so it can be included in the LogEvent's ContextMap as a single String item. While the Object's render method certainly might use a StringBuilder internally the code storing the data into the Map certainly doesn't want one. Furthermore, if you look at the default implementation the render method simply calls toString() on the object. For the 90+% of use cases where the object is already a String this is effectively a no-op as it just returns "this". Using a StringBuilder would require much more overhead.

/**
* Render the object as a String.
* @return the String representation of the Object.
*/
default String render() {
return this.toString();
}

default Object getObject() {
return this;
}
}

private static class ObjectRenderable implements Renderable {
private final Object object;

public ObjectRenderable(Object object) {
this.object = object;
}

@Override
public String render() {
return object.toString();
}

@Override
public Object getObject() {
return object;
}
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,69 @@
/*
* Licensed to the Apache Software Foundation (ASF) under one or more
* contributor license agreements. See the NOTICE file distributed with
* this work for additional information regarding copyright ownership.
* The ASF licenses this file to you 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.apache.logging.log4j.internal;

import java.util.ArrayDeque;
import java.util.Deque;
import java.util.Optional;
import org.apache.logging.log4j.ScopedContext;

/**
* Anchor for the ScopedContext. This class is private and not for public consumption.
*/
public class ScopedContextAnchor {
private static final ThreadLocal<Deque<ScopedContext>> scopedContext = new ThreadLocal<>();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Umm... I am strongly against this. ScopedValues have landed to JVM – we should use them instead. Opting for ThreadLocals is a very risky liability and recipe for failure. I will detail this out in my review.

Copy link
Member Author

@rgoers rgoers Mar 21, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

  1. This is NOT meant for only Java 21 and above. It is targeted at Log4j API which still supports Java 8. Note that it could be possible to provide a different implementation for Java 21 if it makes sense to do so.
  2. ThreadLocals are NOT risky even with Virtual Threads when they are used in this way. I specifically looked for a mention of being able to disable ThreadLocals and could not find anything as I recall you previously mentioning that. However, they should NOT be used to cache objects as we have done in the past. Instead, "normal" object pooling should be used. I will also say that in my first incarnation I used a Map where the key was the threadId. But I changed that since it is nothing more than a slower version of a ThreadLocal.

As an aside, I looked at the ScopedValue javadoc and some examples of how to use it. I am not overly impressed. To be honest I would prefer ScopedContext since it is quite a bit simpler and shouldl be more powerful once I have finished.


/**
* Returns an immutable Map containing all the key/value pairs as Renderable objects.
* @return An immutable copy of the Map at the current scope.
*/
public static Optional<ScopedContext> getContext() {
Deque<ScopedContext> stack = scopedContext.get();
if (stack != null) {
return Optional.of(stack.getFirst());
}
return Optional.empty();
}

/**
* Add the ScopeContext.
* @param context The ScopeContext.
*/
public static void addScopedContext(ScopedContext context) {
Deque<ScopedContext> stack = scopedContext.get();
if (stack == null) {
stack = new ArrayDeque<>();
scopedContext.set(stack);
}
stack.addFirst(context);
}

/**
* Remove the top ScopeContext.
*/
public static void removeScopedContext() {
Deque<ScopedContext> stack = scopedContext.get();
if (stack != null) {
if (!stack.isEmpty()) {
stack.removeFirst();
}
if (stack.isEmpty()) {
scopedContext.remove();
}
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -32,7 +32,7 @@
* @see <a href="http://logging.apache.org/log4j/2.x/manual/api.html">Log4j 2 API manual</a>
*/
@Export
@Version("2.20.2")
@Version("2.24.0")
package org.apache.logging.log4j;

import org.osgi.annotation.bundle.Export;
Expand Down
Loading
Loading