JsonTemplateLayout: Cannot replace recycler factory, template always uses standard factory

[rschuetz]

Description

I'm trying to plug in a new RecyclerFactoryConverter following https://logging.apache.org/log4j/2.x/manual/json-template-layout.html#extending-recycler. The factory is using a pool to cache the objects, hence it is using a new spec string like pool or pool:capacity=123, which is unknown to the default RecyclerFactories class called by RecyclerFactoryConverter.

The class gets loaded properly, the log contains:

WARN Ignoring TypeConverter [org.apache.logging.log4j.layout.template.json.util.RecyclerFactoryConverter@21ca139c] for type [interface org.apache.logging.log4j.layout.template.json.util.RecyclerFactory] that conflicts with [com.XXX.messaging.log4j.ExtRecycleFactoryConverter@226f885f], since they are not comparable.

To configure the converter I use

-Dlog4j.layout.jsonTemplate.recyclerFactory=pool

However, when initializing log4j2, it fails with

2025-01-14T14:47:01.370078759Z main ERROR Could not create plugin of type class org.apache.logging.log4j.layout.template.json.JsonTemplateLayout for element JsonTemplateLayout: java.lang.IllegalArgumentException: invalid recycler factory: pool java.lang.reflect.InvocationTargetException
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.createBuilder(PluginBuilder.java:167)
	at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:121)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:1164)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:1085)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:1077)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:1077)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:681)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:264)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:313)
	at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:631)
	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:713)
	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:735)
	at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:260)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:154)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:46)
	at org.apache.logging.log4j.LogManager.getContext(LogManager.java:197)
	at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:136)
	at org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:58)
	at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:46)
	at org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:32)
	at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:432)
	at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:457)
	at com.XXX.messaging.startup.Messaging$Starter.<clinit>(Messaging.java:111)
	at com.XXX.messaging.startup.Messaging.main(Messaging.java:56)
Caused by: java.lang.IllegalArgumentException: invalid recycler factory: pool
	at org.apache.logging.log4j.layout.template.json.util.RecyclerFactories.ofSpec(RecyclerFactories.java:84)
	at org.apache.logging.log4j.layout.template.json.JsonTemplateLayoutDefaults.getRecyclerFactory(JsonTemplateLayoutDefaults.java:118)
	at org.apache.logging.log4j.layout.template.json.JsonTemplateLayout$Builder.<init>(JsonTemplateLayout.java:361)
	at org.apache.logging.log4j.layout.template.json.JsonTemplateLayout$Builder.<init>(JsonTemplateLayout.java:316)
	at org.apache.logging.log4j.layout.template.json.JsonTemplateLayout.newBuilder(JsonTemplateLayout.java:312)
	... 28 more

i.e. it's not using the replacement at all, potentially due to the hardcoded reference in

logging-log4j2/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/JsonTemplateLayoutDefaults.java

Line 118 in 4d0f818

public static RecyclerFactory getRecyclerFactory() {

Replacing it with

    public static RecyclerFactory getRecyclerFactory()
    {
        final String recyclerFactorySpec = PROPERTIES.getStringProperty("log4j.layout.jsonTemplate.recyclerFactory");
        return TypeConverters.convert(recyclerFactorySpec, RecyclerFactory.class, null);
    }

helps, but I'm not sure if this is correct.

Configuration

Version: 2.23.1

Operating system: Ubuntu 24.04

JDK: OpenJDK Runtime Environment Temurin-17.0.10+7 (build 17.0.10+7)

Logs

See above.

Reproduction

Due to customized build systems here a bit complicated. In general it should be sufficient to

1. create something like ExampleRecyclerFactory (from https://logging.apache.org/log4j/2.x/manual/json-template-layout.html#extending-recycler) and return ThreadLocalRecyclerFactory.INSTANCE just to return something working
2. make sure the plugin can be found (annotationProcessor("org.apache.logging.log4j", "log4j-core") in gradle)
3. configure log4j to use JsonTemplateLayout
4. set -Dlog4j.layout.jsonTemplate.recyclerFactory=pool system property to let the default RecyclerFactories class fail if it gets called despite of the configuration

[vy]

@rschuetz, this is indeed a bug (thanks for the report! 🙇) and your suggested fix makes sense. I will submit a PR containing the fix along with some tests.

In the meantime, as a workaround, you can try extending your custom RecyclerFactory from java.util.Queue and activate it by setting the recyclerFactory plugin attribute to queue:supplier=path.to.your.RecyclerFactory.new,capacity=123. Does this work for you?

[vy]

@rschuetz, curious: would you mind briefly explaining your custom recycler factory? How does it work? Do you use an external library for the pool? If so, which one? Where did the recyclers bundled with JTL fall short in your use case?

[rschuetz]

@rschuetz, this is indeed a bug (thanks for the report! 🙇) and your suggested fix makes sense. I will submit a PR containing the fix along with some tests.

@vy, excellent, thanks a lot!

@rschuetz, curious: would you mind briefly explaining your custom recycler factory? How does it work? Do you use an external library for the pool? If so, which one? Where did the recyclers bundled with JTL fall short in your use case?

The issue I face is that I need a very large maxStringLength - 10.000.000 characters (yes, I know ... I saw your comment on #2516 before ... but there is no other option for now), as one of the background services in the application generates threaddumps (for debugging/support reasons) in a standard format in the logged message in case some threads got stuck, and truncating these dumps would make them useless. Unfortunately this also means all other threads gets buffers of the same size.

So if we run with this buffer size there is a risk for OOMs / wasting a lot of memory if many buffers get allocated. threadLocal won't work due to the number of active threads, queue has no upper limit (threads would still get their buffer if there is no buffer in the queue) and dummy will increase GC pressure a lot.

Therefore I added a pooling recycler that simply just uses Apache Commons Pool with a maximum size and blocks if all buffers are in use. Not more, hope it works for now, as log frequency is not high.

Actually IMHO it would be better if maxStringLength wouldn't be needed or would at least not require pre-allocated buffers to the string again i.e. if the JSON document could be streamed out using smaller buffers instead.

@vy: Would it make sense if I'd open a ticket for something like that, or is it not possible at all?

In the meantime, as a workaround, you can try extending your custom RecyclerFactory from java.util.Queue and activate it by setting the recyclerFactory plugin attribute to queue:supplier=path.to.your.RecyclerFactory.new,capacity=123. Does this work for you?

Thanks a lot, but as there is no upper limit here, it wouldn't be safe. For now I put a patched copy of JsonTemplateLayoutDefaults at the beginning of the classpath.

[vy]

queue has no upper limit

@rschuetz, I think you have a misunderstanding on the way queueing recycler works. It uses Queue#poll(), which can be a blocking operation. If JCTools is not in the classpath, or, if you explicitly specify the queue to be j.u.c.ArrayBlockingQueue, poll() requests exceeding the capacity¹ will block – precisely what you wanted, right? In conclusion, you can either use the default queueing recycler by explicitly opting for j.u.c.ArrayBlockingQueue:

queue:supplier=java.util.concurrent.ArrayBlockingQueue.new

or you can provide your own queue supplier where you block on poll() if the queue is empty.

¹ Unless provided, the queue capacity defaults to max(2 * Runtime.getRuntime().availableProcessors() + 1, 8).

[rschuetz]

@vy: The "there is no upper limit" does not relate to the queue but the total number of simultaneously active buffers. By default, j.u.c.ArrayBlockingQueue#poll does not block, i.e. as long as the queue is empty (initially or if all cached elements are in use) #poll returns null and QueueingRecyclerFactory creates a new buffer. I.e. the total number of simultaneously active buffers is not limited. The number will only go down to the configured capacity again when all buffers have been released and pushed back to / dropped by after calling Queue#offer.

Yes, I could introduce a custom queue instead, that blocks on #poll to simulate a pool - but how should it know how to create a new buffer then? It has no reference to the supplier and I cannot influence the code that instantiates the queue.

Closed ticked by accident ... Sorry.

[vy]

j.u.c.ArrayBlockingQueue#poll does not block, i.e. as long as the queue is empty (initially or if all cached elements are in use) #poll returns null

@rschuetz, you're right, my oversight.

Yes, I could introduce a custom queue instead, that blocks on #poll to simulate a pool - but how should it know how to create a new buffer then?

Initially your buffer will be empty, you'll return null. QueueingRecycler will invoke supplier to create a new instance. Once the new instance is used by the caller, it will be passed to your queue via Recycler::release, right?

@rschuetz, could you confirm that #3398 fixes the issue, please?

[rschuetz]

@vy: Fix works for me locally. Thanks a lot!