[
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)
