[
https://issues.apache.org/jira/browse/LOG4J2-2118?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16251820#comment-16251820
]
Remko Popma commented on LOG4J2-2118:
-------------------------------------
{quote}
Is there a way to avoid paying the cost of message formatting since my layout
will never use it?
{quote}
Yes, you can set your own MessageFactory and custom Message implementation(s)
that don't do this formatting.
{quote}
If I understand correctly, lazy formatting logic has been ruled out due to
concurrency issues. Is that accurate? If not, I'd be happy to try to write the
code for that with some guidance.
{quote}
If you do any form of asynchronous logging, either with the AsyncAppender or
with Async Loggers, there is a moment when information is passed from the
application thread to the background thread. The application thread then
returns and the background thread will complete the text formatting, converting
text to bytes and writing these bytes to the destination device in parallel
with the application doing other work.
Log4j takes a "snapshot" of all objects that were logged at the time of the
hand-off, before the application thread returns. This is the "eager" formatting
you mention.
It is a good question to ask why Log4j does this eager formatting. Wouldn't it
be more efficient to do this in the background thread?
The reason we do this is as follows: If Log4j did not take this snapshot but
instead did the formatting in the background thread, the application might
mutates one of the parameters that were passed in the log message _before_ the
background thread gets a chance to format the text. If that happened, the value
that appears in the log no longer reflects the object at the time of the
logging call, but at some other later time. This would make the log unusable
for troubleshooting purposes.
Log4j cannot guarantee that the application won't modify log message parameters
after the logging call so it does the safe thing and takes a snapshot by
eagerly formatting the message.
There is a system property to switch off eager formatting, see
{{o.a.l.l.core.util.Constants#FORMAT_MESSAGES_IN_BACKGROUND}} and its usages.
> MutableLogEvent does not retain the Message format string
> ---------------------------------------------------------
>
> Key: LOG4J2-2118
> URL: https://issues.apache.org/jira/browse/LOG4J2-2118
> Project: Log4j 2
> Issue Type: Bug
> Components: Layouts
> Affects Versions: 2.8
> Environment: Mac OS X 10.11.6
> Java 1.8.0_141
> Reporter: Zack Slayton
> Labels: layout
>
> I'm attempting to create a custom binary Layout that stores the provided
> format string separate from the parameters rather than eagerly formatting
> them all into a single piece of text. However, when I went to implement
> `Layout::toByteArray`, I discovered that the `Message::getFormat` method
> always returns null.
> {code:java}
> import org.apache.logging.log4j.LogManager;
> import org.apache.logging.log4j.Logger;
> import org.apache.logging.log4j.core.LogEvent;
> import org.apache.logging.log4j.core.config.plugins.Plugin;
> import org.apache.logging.log4j.core.config.plugins.PluginFactory;
> import org.apache.logging.log4j.core.layout.AbstractLayout;
> import java.io.Serializable;
> import java.util.Arrays;
> @Plugin(name = "MyLayout", category = "Core", elementType = "layout",
> printObject = true)
> public class MyLayout extends AbstractLayout {
> public MyLayout() {
> super(null, null, null);
> }
> @PluginFactory
> public static MyLayout createLayout(){
> return new MyLayout();
> }
> public static void main(String[] args) {
> Logger log = LogManager.getLogger(MyLayout.class);
> log.info("Here's a thing: {}. And another: {}", 75, "walrus");
> }
> @Override
> public byte[] toByteArray(LogEvent event) {
> System.out.println("Format: " + event.getMessage().getFormat());
> System.out.println("Parameters: " +
> Arrays.toString(event.getMessage().getParameters()));
> return new byte[0];
> }
> @Override
> public Serializable toSerializable(LogEvent event) {
> return null;
> }
> @Override
> public String getContentType() {
> return null;
> }
> @Override
> public byte[] getFooter() {
> return new byte[0];
> }
> @Override
> public byte[] getHeader() {
> return new byte[0];
> }
> }
> {code}
> If I run `main` (with an extra `PatternLayout`+`Console` appender in my
> config), I see the following output:
> {code}
> 17:55:28.524 [main] INFO com.example.logging.plugins.MyLayout - Here's a
> thing: 75. And another: walrus
> Format: null
> Parameters: [75, walrus]
> {code}
> I had expected to be able to see the format string and the array of
> parameters, but instead I can only see the parameters. The format string is
> always null.
> This appears to be due to the implementation of `MutableLogEvent::setMessage`
> highlighted [in
> LOG4J2-1510|https://issues.apache.org/jira/browse/LOG4J2-1510]. Because the
> messages are reusable, they appear to be eagerly formatted and the format
> string itself is discarded. The `getFormat` method is hardcoded to return
> `null`.
> Is this by design? If so, what is the prescribed approach to getting the
> format string in my layout? (Preferably one that does not disable the
> performance optimizations offered by enabling threadlocals.)
> Thanks!
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
