[jira] [Commented] (LOG4J2-1883) Timestamp does not seem to support microseconds level

["Anthony Maire (JIRA)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/LOG4J2-1883?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16055753#comment-16055753 ] 

Anthony Maire commented on LOG4J2-1883:
---------------------------------------

I made a first draft here : https://github.com/m-anthony/logging-log4j2/commit/61c3486aecded6931fe84f19b3cac9daa3d5d0e5
It allows to capture a precise timestamp in LogEvent instance, but displaying it is not handled yet

However I am not satisfied at all with this draft for several reasons :
- Using the new Clock API is pretty hard, since getting a timestamp needs several method calls. Moreover converting the "nanoseconds from a given reference" to seconds + nano since epoch is tricky since we need to handle negative value and we don't have access to Math.floorDiv / Math.floorMod methods. This leads to a copy/pasting of that query + conversion code for each LogEvent implementation, and some ugly hacks for initializing the final fields of Log4jLogEvent using the default constructor. The initial motivation was to avoid object allocation, but having such a painful API only for performance reason is not a good idea at all.
- getTimeMillis() is no longer backed by a field, and it causes some problems for serialization. To keep  the tests valid, I had to change the output of the serialized events in XML/JSON/JDBC. So there will be some backward compatibility issues for users
- Most date formatter are handled through FastDateFormat from Apache Commons Lang that does not know how to format timestamp with sub-millisecond resolution. We have the same issue with JDK classes : you need JDK8 to have sub-millisecond parsing/formatting. So even if we had the precise timestamp, we won't be able to integrate it in the standard "\%d" pattern

Basically, to have a clean handling of this feature, Java8 will help a lot, but unfortunately we are not using it yet.
Meanwhile, I think we should do only minimal code changes and the best idea could be to reuse the nanoTime field that was added for LOG4J2-1076, and use a specific pattern converter to format it as the sub-millisecond part of the timestamp.
This will limit the impacting change to that niche feature instead of causing lots of backward compatibility issues, and wait until log4J migrating to Java 8 to have a implement a clean integration with the \%d pattern converter

We can create a new pattern converter (or maybe change the meaning of the current \%N pattern ?), let's call it \%sm or \%subMillis (Sorry, I cannot find a good name ...), it will extract logEvent.nanoTime modulo 1 million (i.e the subMilli part of the timestamp) and format it
This pattern can have a parameter which will be the number of digits to display. For instance you can use \%d\{ISO8601\}\%sm\{3\} to have a ISO8601 timestamp with micro-second resolution
The only thing that is missing is a way to inject a precise time source, and call it only when needed (since a custom JNR call can be 5 times more costly than System.nanoTime if running on Java 9 is not an option).
I think that the simplest thing is :
- Having Clock extends the NanoClock interface, most implementations will return 0 here, and SystemClock() will return System.nanoTime() (for now, in Java 9 it should be based on java.time.Clock$SystemClock.instant())
- replace in PatternParser.parse() config.setNanoClock(new SystemNanoClock()) by config.setNanoClock(ClockFactory.getClock()) when such a patternCOnverter is detected

Any further input on this ? 


> Timestamp does not seem to support microseconds level
> -----------------------------------------------------
>
>                 Key: LOG4J2-1883
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-1883
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Configurators
>         Environment: Linux with any JDK including JDK1.8
>            Reporter: Madhava Dass
>            Priority: Critical
>
> Used log4j and 'log4j2.xml' to configure timestamp format as:
> {code}
> <?xml version="1.0" encoding="UTF-8"?>
> <Configuration status="WARN">
>     <Appenders>
>         <Console name="Console" target="SYSTEM_OUT">
>             <PatternLayout pattern="[%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX}{UTC}][%level][%logger{36}]:%msg%n"/>
>         </Console>
>     </Appenders>
>     <Loggers>
>         <Root level="DEBUG">
>             <AppenderRef ref="Console"/>
>         </Root>
>     </Loggers>
> </Configuration>
> {code}
> This pattern produces the time stamp as:
> {code}
> [2017-03-29T13:55:28.363000][null]:[Thread-1]: - <message>
> {code}
> The desired output is:
> {code}
> [2017-03-29T13:55:28.363701-07:00][null]:[Thread-1]: - <message>
> {code}
> Different versions of JDKs were tried including JDK 1.8. It does not seem to make any difference in the outcome.
> Is there a way to get the desired time stamp through pattern matching configuration in the '*.xml' file?



--
This message was sent by Atlassian JIRA
(v6.4.14#64029)