Log4j2 JSONLayout timestamp pattern

Question

Apparently, JSONLayout in log4j2 doesn't have timestamp pattern support. Normally it only has JSON formatting options, but nothing as such pattern option.

{
  "configuration": {
    "name": "logggg",
    "packages" : "logger.savemyjob",
    "appenders": {
      "RollingFile": {
        "name": "rollingStone",
        "fileName": "async_rolled.log",
        "filePattern": "async_rolled-%d{MM-dd-yy-HH-mm-ss}-%i.log.gz",
        "immediateFlush" : false,
         "JSONLayout": {
            "complete": true,
            "compact": false,
            "eventEol": true
         },
        "SizeBasedTriggeringPolicy": {
          "size": "10 MB"
        },
        "DefaultRolloverStrategy": {
          "max": "10"
        }
      }
    },
    "loggers": {
      "root": {
        "level": "debug",
        "appender-ref": {
          "ref": "rollingStone"
        }
      }
    }
  }
}

Log Example,

{
  "timeMillis" : 1482231551081,
  "thread" : "main",
  "level" : "debug",
  "endOfBatch" : false,
  "threadId" : 1,
  "threadPriority" : 5, 
  "message" : "log4j might suck"
}

And when I looked at their API, looks too verbose and don't see quite an easier way adding a timestamp field.

JsonLayout plugin seems to be the one I need to override, since its final can't even extend but otherwise I have to copy the whole dependent classes.

@Plugin(name = "JsonLayout", category = Node.CATEGORY, elementType = Layout.ELEMENT_TYPE, printObject = true)
public final class JsonLayout extends AbstractJacksonLayout {

protected JsonLayout(final Configuration config, final boolean locationInfo, final boolean properties,
            final boolean encodeThreadContextAsList,
            final boolean complete, final boolean compact, final boolean eventEol, final String headerPattern,
            final String footerPattern, final Charset charset) {
        super(config, new JacksonFactory.JSON(encodeThreadContextAsList).newWriter(locationInfo, properties, compact),
                charset, compact, complete, eventEol,
                PatternLayout.createSerializer(config, null, headerPattern, DEFAULT_HEADER, null, false, false),
                PatternLayout.createSerializer(config, null, footerPattern, DEFAULT_FOOTER, null, false, false));
    }

}

The architecture looks more complicated than I expected :(, I am tracing from the Logger.

I also considered changing the LogEvent itself,

public interface LogEvent extends Serializable {

    @Deprecated
    Map<String, String> getContextMap();

    ReadOnlyStringMap getContextData();

    ThreadContext.ContextStack getContextStack();

    String getLoggerFqcn();

    Level getLevel();

    String getLoggerName();

    Marker getMarker();

    Message getMessage();

    long getTimeMillis();

    StackTraceElement getSource();

    String getThreadName();

    long getThreadId();

    int getThreadPriority();

    Throwable getThrown();

    ThrowableProxy getThrownProxy();

    boolean isEndOfBatch();

    boolean isIncludeLocation();

    void setEndOfBatch(boolean endOfBatch);

    void setIncludeLocation(boolean locationRequired);

    long getNanoTime();

    String getTimestamp();
}

and also MutableLogEvent

public class MutableLogEvent implements LogEvent, ReusableMessage {

    public void initFrom(final LogEvent event) {

        SimpleDateFormat standardDateFormat = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");
        this.timestamp = standardDateFormat.format(new Date(event.getTimeMillis()));
    }
}

I'm guessing it might work, though it broke few core log4j-core tests. I basically want to know the tricks to add extra json field with minimum change.

I see few other impls like JSONEventLayoutV1, which seems to be totally different impl than log4j json api which is pretty good performance wise.

Here's my failed attempt to override, LogEvent, https://github.com/prayagupd/sell-peace/blob/custom_timestamp/supply-peace/src/main/java/org/apache/logging/log4j/core/DnLogEvent.java

The questions is getting longer, I basically want to know the important things not to miss when I override the log4j2 api.

Stanstance

Answer 1

If this is just a matter of adding a new field containing the timestamp, apart from the timeMillis provided by default, why don't You try to use Lookups on the new custom field.

The JsonLayout configuration may then looks like this:

<JsonLayout>
    <KeyValuePair key="timestamp" value="$${date:yyyy-MM-dd'T'HH:mm:ss.SSSZ}" />
</JsonLayout>

The $$ is the Lookup, and the characters behind date: are the format that java SimpleDateFormat can accept.

Guanine

Thank you Peter! This should be marked as the accepted solution, it's the simplest and most elegant one. – Curran

A small note: I apply this setup for producing DataDog-compatible logs. To my surprise, they don't accept 4-digit timezone format (like +0100), it must have : separator inside (like +01:00). For this reason, replace Z pattern letter with XXX. – Primer

Answer 2

So, In short I needed to write 7 objects. The flow is as below

CustomLogEvent 
    -> LogEventToCustomLogEventConverter 
       -> CustomLogEventMixIn 
           -> CustomLog4jJsonModule 
                  -> CustomLog4jJsonObjectMapper 
                      -> CustomJacksonFactory 
                          -> CustomJSONLayout

CustomJSONLayout is the plugin I would use in my log4j2.json that supports params as config.

So, I ended up using a Inheritence and composition at the same time for LogEvent.

public class JsonLogEvent implements LogEvent{

    static final String TIMESTAMP_FORMAT = "yyyy-MM-dd HH:mm:ss";
    static final DateFormat isoDateFormat = new SimpleDateFormat(TIMESTAMP_FORMAT);

    private LogEvent wrappedLogEvent;

    public JsonLogEvent(LogEvent wrappedLogEvent) {
        this.wrappedLogEvent = wrappedLogEvent;
    }

    public String getTimestamp() {
        return isoDateFormat.format(new Date(this.getTimeMillis()));
    }
}

And CustomLogEventMixIn, that has timestamp as key.

@JsonSerialize(converter = JsonLogEvent.LogEventToCustomLogEventConverter.class)
@JsonRootName(XmlConstants.ELT_EVENT)
@JsonFilter("org.apache.logging.log4j.core.impl.Log4jLogEvent")
@JsonPropertyOrder({"timestamp", "threadName", "level", "loggerName", "marker", "message", "thrown",
        XmlConstants.ELT_CONTEXT_MAP, JsonConstants.ELT_CONTEXT_STACK, "loggerFQCN", "Source", "endOfBatch", "timeMillis" })
abstract class CustomLogEventMixIn extends LogEventMixIn {

    @JsonProperty("timestamp")
    public abstract String getTimestamp();

    private static final long serialVersionUID = 1L;

}

public static class LogEventToCustomLogEventConverter extends StdConverter<LogEvent, JsonLogEvent> {

    @Override
    public JsonLogEvent convert(LogEvent value) {
        return new JsonLogEvent(value);
    }
}

LogEventMixIn is used by Log4jJsonModule

public class CustomLog4jJsonModule extends Log4jJsonModule {

    private static final long serialVersionUID = 1L;

    CustomLog4jJsonModule() {
        super();
    }

    @Override
    public void setupModule(final SetupContext context) {
        super.setupModule(context);

        context.setMixInAnnotations(LogEvent.class, CustomLogEventMixIn.class);
    }
}

public class CustomLog4jJsonObjectMapper extends ObjectMapper {

    public CustomLog4jJsonObjectMapper() {
        this.registerModule(new CustomLog4jJsonModule());
        this.setSerializationInclusion(JsonInclude.Include.NON_EMPTY);
    }

}

Tracking down how JsonLayout being used was very helpful.

Stanstance

Answer 3

You can use the line below:

<KeyValuePair key="@timestamp" value="$${date:dd-MM-yyyy HH:mm:ss}"/>

Line in context inside log4j2.xml:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
    <Properties>
        <Property name="activeProfile">${sys:spring.profiles.active}</Property>
    </Properties>
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <JSONLayout eventEol="true"
                        complete="false"
                        locationInfo="true"
                        includeTimeMillis="true">
                <KeyValuePair key="@timestamp" value="$${date:dd-MM-yyyy HH:mm:ss}"/>
                <KeyValuePair key="requestId"  value="$${ctx:X-Request-Id}"/>
            </JSONLayout>
        </Console>
    </Appenders>
    <Loggers>
        <Root level="info">
            <AppenderRef ref="Console" />
        </Root>
    </Loggers>
</Configuration>

Rubella

Answer 4

The first thing to do is to raise a feature request on the Log4j2 JIRA issue tracker. This sounds like something that could benefit many users so it's worth trying to get it fixed in Log4j itself.

Meanwhile, let's look at a custom solution. I wouldn't change LogEvent, this will result in a fragile solution (may not work with Async Loggers and AsyncAppender for example). Also you may run into trouble when you want to upgrade to later versions of Log4j2. The LogEvent already has the data that you need (timeMillis), it just needs to get formatted.

The official way is to create a custom Json layout plugin. You could do a rewrite or you can start with copying code. (Another topic to raise in the JIRA ticket.) The key class to change is probably LogEventJsonMixIn.

Log4j2 uses Jackson to generate the json strings. You probably need to replace LogEventJsonMixIn with a version that gives a formatted date instead of the raw millis. Jackson may have a Deserialiser for this already, otherwise you need to write your own. The Log4j community may also be able to give more ideas.

Vulgar

Thanks Remko. I might create a JIRA issue. I ended up doing like you said, created Wrapper JsonLogEvent around LogEvent which returns the formatted time. And CustomLogEventMixIn extending LogEventMixIn that has timestamp json key. – Stanstance

Probably useful for others too. If left on StackOverflow everyone needs to implement this as a custom solution. May be good to incorporate into Log4j. – Vulgar

@Stanstance would be helpful if can you share the solution – Urinal