jdk/test/java/util/logging/HigherResolutionTimeStamps/LogRecordWithNanosAPI.java
author dfuchs
Wed, 25 Feb 2015 18:41:07 +0100
changeset 29117 7956b5dc0eac
child 34439 fbb6e8d9611c
permissions -rw-r--r--
8072645: java.util.logging should use java.time to get more precise time stamps Summary: j.u.logging uses j.t.Instant to store LogRecord time stamps. XMLFormatter format is updated to allow for a new optional <nanos> element containing a nano second adjustment. SimpleFormatter passes a ZonedDateTime object to String.format. LogRecord getMillis/setMillis are deprecated, replaced by getInstant/setInstant. Reviewed-by: scolebourne, plevart, rriggs Contributed-by: daniel.fuchs@oracle.com, peter.levart@gmail.com

/*
 * Copyright (c) 2015, Oracle and/or its affiliates. All rights reserved.
 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
 *
 * This code is free software; you can redistribute it and/or modify it
 * under the terms of the GNU General Public License version 2 only, as
 * published by the Free Software Foundation.
 *
 * This code is distributed in the hope that it will be useful, but WITHOUT
 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
 * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
 * version 2 for more details (a copy is included in the LICENSE file that
 * accompanied this code).
 *
 * You should have received a copy of the GNU General Public License version
 * 2 along with this work; if not, write to the Free Software Foundation,
 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
 *
 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
 * or visit www.oracle.com if you need additional information or have any
 * questions.
 */
import java.io.ByteArrayInputStream;
import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.io.ObjectInputStream;
import java.io.ObjectOutputStream;
import java.time.Instant;
import java.util.Objects;
import java.util.logging.Level;
import java.util.logging.LogRecord;
import java.util.logging.SimpleFormatter;

/**
 * @test
 * @bug 8072645
 * @summary tests the new methods added to LogRecord.
 * @run main LogRecordWithNanosAPI
 * @author danielfuchs
 */
public class LogRecordWithNanosAPI {

    static final int MILLIS_IN_SECOND = 1000;
    static final int NANOS_IN_MILLI = 1000_000;
    static final int NANOS_IN_SECOND = 1000_000_000;

    static final boolean verbose = true;

    static final class TestAssertException extends RuntimeException {
        TestAssertException(String msg) { super(msg); }
    }

    private static void assertEquals(long expected, long received, String msg) {
        if (expected != received) {
            throw new TestAssertException("Unexpected result for " + msg
                    + ".\n\texpected: " + expected
                    +  "\n\tactual:   " + received);
        } else if (verbose) {
            System.out.println("Got expected " + msg + ": " + received);
        }
    }

    private static void assertEquals(Object expected, Object received, String msg) {
        if (!Objects.equals(expected, received)) {
            throw new TestAssertException("Unexpected result for " + msg
                    + ".\n\texpected: " + expected
                    +  "\n\tactual:   " + received);
        } else if (verbose) {
            System.out.println("Got expected " + msg + ": " + received);
        }
    }

    // The nano second fractional part of a second, contained in a time expressed
    // as a number of millisecond from the epoch.
    private static long nanoInSecondFromEpochMilli(long millis) {
        return (((millis%MILLIS_IN_SECOND) + MILLIS_IN_SECOND)%MILLIS_IN_SECOND)*NANOS_IN_MILLI;
    }

    /**
     * Serializes a log record, then deserializes it and check that both
     * records match.
     * @param record the log record to serialize & deserialize.
     * @param hasExceedingNanos whether the record has a nano adjustment whose
     *            value exceeds 1ms.
     * @throws IOException Unexpected.
     * @throws ClassNotFoundException  Unexpected.
     */
    public static void test(LogRecord record, boolean hasExceedingNanos)
            throws IOException, ClassNotFoundException {

        // Format the given logRecord using the SimpleFormatter
        SimpleFormatter formatter = new SimpleFormatter();
        String str = formatter.format(record);

        // Serialize the given LogRecord
        final ByteArrayOutputStream baos = new ByteArrayOutputStream();
        final ObjectOutputStream oos = new ObjectOutputStream(baos);
        oos.writeObject(record);
        oos.flush();
        oos.close();

        // First checks that the log record can be deserialized
        final ByteArrayInputStream bais =
                new ByteArrayInputStream(baos.toByteArray());
        final ObjectInputStream ois = new ObjectInputStream(bais);
        final LogRecord record2 = (LogRecord)ois.readObject();

        assertEquals(record.getMillis(), record2.getMillis(), "getMillis()");
        assertEquals(record.getInstant().getEpochSecond(),
                record2.getInstant().getEpochSecond(),
                "getInstant().getEpochSecond()");
        assertEquals(record.getInstant().getNano(),
                record2.getInstant().getNano(),
                "getInstant().getNano()");
        assertEquals(record.getInstant().toEpochMilli(),
                record2.getInstant().toEpochMilli(),
                "getInstant().toEpochMilli()");
        long millis = record.getMillis();
        millis = hasExceedingNanos
                ? Instant.ofEpochSecond(millis/MILLIS_IN_SECOND,
                        (millis%MILLIS_IN_SECOND)*NANOS_IN_MILLI
                        + record.getInstant().getNano() % NANOS_IN_MILLI).toEpochMilli()
                : millis;
        assertEquals(millis, record.getInstant().toEpochMilli(),
                "getMillis()/getInstant().toEpochMilli()");
        millis = record2.getMillis();
        millis = hasExceedingNanos
                ? Instant.ofEpochSecond(millis/MILLIS_IN_SECOND,
                        (millis%MILLIS_IN_SECOND)*NANOS_IN_MILLI
                        + record2.getInstant().getNano() % NANOS_IN_MILLI).toEpochMilli()
                : millis;
        assertEquals(millis, record2.getInstant().toEpochMilli(),
                "getMillis()/getInstant().toEpochMilli()");
        long nanos = nanoInSecondFromEpochMilli(record.getMillis())
                + record.getInstant().getNano() % NANOS_IN_MILLI;
        assertEquals(nanos, record.getInstant().getNano(),
                "nanoInSecondFromEpochMilli(record.getMillis())"
                + " + record.getInstant().getNano() % NANOS_IN_MILLI /getInstant().getNano()");
        nanos = nanoInSecondFromEpochMilli(record2.getMillis())
                + record2.getInstant().getNano() % NANOS_IN_MILLI;
        assertEquals(nanos, record2.getInstant().getNano(),
                "nanoInSecondFromEpochMilli(record2.getMillis())"
                + " + record2.getInstant().getNano() % NANOS_IN_MILLI /getInstant().getNano()");

        // Format the deserialized LogRecord using the SimpleFormatter, and
        // check that the string representation obtained matches the string
        // representation of the original LogRecord
        String str2 = formatter.format(record2);
        if (!str.equals(str2))
            throw new RuntimeException("Unexpected values in deserialized object:"
                + "\n\tExpected:  " + str
                + "\n\tRetrieved: "+str);

    }


    public static void main(String[] args) throws Exception {
        int count=0;
        LogRecord record = new LogRecord(Level.INFO, "Java Version: {0}");
        record.setLoggerName("test");
        record.setParameters(new Object[] {System.getProperty("java.version")});
        final int nanos = record.getInstant().getNano() % NANOS_IN_MILLI;
        final long millis = record.getMillis();
        final Instant instant = record.getInstant();
        if (millis != instant.toEpochMilli()) {
            throw new RuntimeException("Unexpected millis: "
                    + record.getMillis());
        }
        test(record, false);

        // nano adjustment < 1ms (canonical case)
        int newNanos = (nanos + 111111) % NANOS_IN_MILLI;
        record.setInstant(Instant.ofEpochSecond(millis/MILLIS_IN_SECOND,
                (millis % MILLIS_IN_SECOND) * NANOS_IN_MILLI + newNanos));
        assertEquals(newNanos, record.getInstant().getNano() % NANOS_IN_MILLI,
                "record.getInstant().getNano() % NANOS_IN_MILLI");
        assertEquals(millis, record.getMillis(), "record.getMillis()");
        assertEquals(Instant.ofEpochSecond(millis/MILLIS_IN_SECOND,
                (millis%MILLIS_IN_SECOND)*NANOS_IN_MILLI + newNanos),
                record.getInstant(), "record.getInstant()");
        test(record, false);
        assertEquals(newNanos, record.getInstant().getNano() % NANOS_IN_MILLI,
                "record.getInstant().getNano() % NANOS_IN_MILLI");
        assertEquals(millis, record.getMillis(), "record.getMillis()");
        assertEquals(Instant.ofEpochSecond(millis/MILLIS_IN_SECOND,
                (millis%MILLIS_IN_SECOND)*NANOS_IN_MILLI + newNanos),
                record.getInstant(), "record.getInstant()");

        // nano adjustment > 1ms - non canonical - should still work
        int newExceedingNanos = 2111_111;
        record.setInstant(Instant.ofEpochSecond(millis/MILLIS_IN_SECOND,
                (millis % MILLIS_IN_SECOND) * NANOS_IN_MILLI + newExceedingNanos));
        assertEquals(newExceedingNanos % NANOS_IN_MILLI,
                record.getInstant().getNano() % NANOS_IN_MILLI,
                "record.getInstant().getNano() % NANOS_IN_MILLI");
        assertEquals(millis + newExceedingNanos / NANOS_IN_MILLI,
                record.getMillis(), "record.getMillis()");
        assertEquals(Instant.ofEpochSecond(millis/MILLIS_IN_SECOND,
                (millis%MILLIS_IN_SECOND)*NANOS_IN_MILLI + newExceedingNanos),
                record.getInstant(), "record.getInstant()");
        test(record, true);
        assertEquals(newExceedingNanos % NANOS_IN_MILLI,
                record.getInstant().getNano() % NANOS_IN_MILLI,
                "record.getInstant().getNano() % NANOS_IN_MILLI");
        assertEquals(millis  + newExceedingNanos / NANOS_IN_MILLI,
                record.getMillis(), "record.getMillis()");
        assertEquals(Instant.ofEpochSecond(millis/MILLIS_IN_SECOND,
                (millis%MILLIS_IN_SECOND)*NANOS_IN_MILLI + newExceedingNanos),
                record.getInstant(), "record.getInstant()");

        // nano adjustement > 1s - non canonical - should still work
        newExceedingNanos = 1111_111_111;
        record.setInstant(Instant.ofEpochSecond(millis/MILLIS_IN_SECOND,
                (millis % MILLIS_IN_SECOND) * NANOS_IN_MILLI + newExceedingNanos));
        assertEquals(newExceedingNanos % NANOS_IN_MILLI,
                record.getInstant().getNano() % NANOS_IN_MILLI,
                "record.getInstant().getNano() % NANOS_IN_MILLI");
        assertEquals(millis  + newExceedingNanos / NANOS_IN_MILLI,
                record.getMillis(), "record.getMillis()");
        assertEquals(Instant.ofEpochSecond(millis/MILLIS_IN_SECOND,
                (millis%MILLIS_IN_SECOND)*NANOS_IN_MILLI + newExceedingNanos),
                record.getInstant(), "record.getInstant()");
        test(record, true);
        assertEquals(newExceedingNanos % NANOS_IN_MILLI,
                record.getInstant().getNano() % NANOS_IN_MILLI,
                "record.getInstant().getNano() % NANOS_IN_MILLI");
        assertEquals(millis  + newExceedingNanos / NANOS_IN_MILLI,
                record.getMillis(), "record.getMillis()");
        assertEquals(Instant.ofEpochSecond(millis/MILLIS_IN_SECOND,
                (millis%MILLIS_IN_SECOND)*NANOS_IN_MILLI + newExceedingNanos),
                record.getInstant(), "record.getInstant()");

        // nano adjustement < 0 - non canonical - should still work
        newExceedingNanos = -1;
        record.setInstant(Instant.ofEpochSecond(millis/MILLIS_IN_SECOND,
                (millis % MILLIS_IN_SECOND) * NANOS_IN_MILLI + newExceedingNanos));
        assertEquals(newExceedingNanos + NANOS_IN_MILLI,
                record.getInstant().getNano() % NANOS_IN_MILLI,
                "record.getInstant().getNano() % NANOS_IN_MILLI");
        assertEquals(millis -1, record.getMillis(), "record.getMillis()");
        assertEquals(Instant.ofEpochSecond(millis/MILLIS_IN_SECOND,
                (millis%MILLIS_IN_SECOND)*NANOS_IN_MILLI + newExceedingNanos),
                record.getInstant(), "record.getInstant()");
        test(record, true);
        record.setInstant(Instant.ofEpochSecond(millis/MILLIS_IN_SECOND,
                (millis % MILLIS_IN_SECOND) * NANOS_IN_MILLI + newExceedingNanos));
        assertEquals(millis -1, record.getMillis(), "record.getMillis()");
        assertEquals(Instant.ofEpochSecond(millis/MILLIS_IN_SECOND,
                (millis%MILLIS_IN_SECOND)*NANOS_IN_MILLI + newExceedingNanos),
                record.getInstant(), "record.getInstant()");

        // setMillis
        record.setMillis(millis-1);
        assertEquals(millis-1, record.getInstant().toEpochMilli(),
                "record.getInstant().toEpochMilli()");
        assertEquals(millis-1, record.getMillis(),
                "record.getMillis()");
        assertEquals(0, record.getInstant().getNano() % NANOS_IN_MILLI,
                "record.getInstant().getNano() % NANOS_IN_MILLI");
        test(record, false);
        assertEquals(millis-1, record.getInstant().toEpochMilli(),
                "record.getInstant().toEpochMilli()");
        assertEquals(millis-1, record.getMillis(),
                "record.getMillis()");
        assertEquals(0, record.getInstant().getNano() % NANOS_IN_MILLI,
                "record.getInstant().getNano() % NANOS_IN_MILLI");

        // setMillis to 0
        record.setMillis(0);
        assertEquals(0, record.getInstant().toEpochMilli(),
                "record.getInstant().toEpochMilli()");
        assertEquals(0, record.getMillis(),
                "record.getMillis()");
        assertEquals(0, record.getInstant().getNano() % NANOS_IN_MILLI,
                "record.getInstant().getNano() % NANOS_IN_MILLI");
        test(record, false);
        assertEquals(0, record.getInstant().toEpochMilli(),
                "record.getInstant().toEpochMilli()");
        assertEquals(0, record.getMillis(),
                "record.getMillis()");
        assertEquals(0, record.getInstant().getNano() % NANOS_IN_MILLI,
                "record.getInstant().getNano() % NANOS_IN_MILLI");

        // setMillis to -1
        record.setMillis(-1);
        assertEquals(-1, record.getInstant().toEpochMilli(),
                "record.getInstant().toEpochMilli()");
        assertEquals(-1, record.getMillis(),
                "record.getMillis()");
        assertEquals(0, record.getInstant().getNano() % NANOS_IN_MILLI,
                "record.getInstant().getNano() % NANOS_IN_MILLI");
        test(record, false);
        assertEquals(-1, record.getInstant().toEpochMilli(),
                "record.getInstant().toEpochMilli()");
        assertEquals(-1, record.getMillis(),
                "record.getMillis()");
        assertEquals(0, record.getInstant().getNano() % NANOS_IN_MILLI,
                "record.getInstant().getNano() % NANOS_IN_MILLI");

        try {
            record.setInstant(null);
        } catch (NullPointerException x) {
            System.out.println("Got expected NPE when trying to call record.setInstant(null): " + x);
        }

    }

}