Merge pull request #8957 from vespa-engine/bjorncs/vespalog-timestamp-format

Increase number of decimals in log timestamp from 3 to 6

8 files changed, 60 insertions, 56 deletions

diff --git a/logserver/src/test/java/com/yahoo/logserver/handlers/archive/ArchiverHandlerTestCase.java b/logserver/src/test/java/com/yahoo/logserver/handlers/archive/ArchiverHandlerTestCase.java
index 525d02c4298..578caab366c 100644
--- a/logserver/src/test/java/com/yahoo/logserver/handlers/archive/ArchiverHandlerTestCase.java
+++ b/logserver/src/test/java/com/yahoo/logserver/handlers/archive/ArchiverHandlerTestCase.java
@@ -28,10 +28,10 @@ import static org.junit.Assert.fail;
 public class ArchiverHandlerTestCase {
 
     private static final String[] mStrings = {
-            "1095159244.095\thost\t1/2\tservice\tcomponent\tinfo\tpayload1",
-            "1095206399.000\thost\t1/2\tservice\tcomponent\tinfo\tpayload2",
-            "1095206400.000\thost\t1/2\tservice\tcomponent\tinfo\tpayload3",
-            "1095206401.000\thost\t1/2\tservice\tcomponent\tinfo\tpayload4",
+            "1095159244.095000\thost\t1/2\tservice\tcomponent\tinfo\tpayload1",
+            "1095206399.000000\thost\t1/2\tservice\tcomponent\tinfo\tpayload2",
+            "1095206400.000000\thost\t1/2\tservice\tcomponent\tinfo\tpayload3",
+            "1095206401.000000\thost\t1/2\tservice\tcomponent\tinfo\tpayload4",
     };
 
     private static final LogMessage[] msg = new LogMessage[mStrings.length];
diff --git a/vespalog/abi-spec.json b/vespalog/abi-spec.json
index 6f9f631c6a5..10a7a83c835 100644
--- a/vespalog/abi-spec.json
+++ b/vespalog/abi-spec.json
@@ -264,6 +264,7 @@
       "public void <init>()",
       "public static java.lang.String escape(java.lang.String)",
       "public static void formatTime(long, java.lang.StringBuilder)",
+      "public static java.lang.String formatTime(java.time.Instant)",
       "public static java.lang.String format(java.lang.String, java.lang.String, java.lang.String, long, java.lang.String, java.lang.String, java.lang.String, java.lang.Throwable)",
       "public static void formatException(java.lang.Throwable, java.lang.StringBuilder)"
     ],
diff --git a/vespalog/src/main/java/com/yahoo/log/VespaFormat.java b/vespalog/src/main/java/com/yahoo/log/VespaFormat.java
index 3d1a2ae0dc8..d0dc5607af5 100644
--- a/vespalog/src/main/java/com/yahoo/log/VespaFormat.java
+++ b/vespalog/src/main/java/com/yahoo/log/VespaFormat.java
@@ -11,6 +11,7 @@ import java.util.regex.Pattern;
  * written by Bjørn Borud, licensed under the Apache 2.0 license.
  * 
  * @author arnej27959
+ * @author bjorncs
  */
 public class VespaFormat {
 
@@ -87,31 +88,18 @@ public class VespaFormat {
 
 
     /**
-     * It is easier to slice and dice strings in Java than formatting
-     * numbers...
+     * @deprecated Use {@link #formatTime(Instant)} ()}
      */
+    @Deprecated(since = "7", forRemoval = true)
     public static void formatTime (long time, StringBuilder sbuffer) {
-        String timeString = Long.toString(time);
-        int len = timeString.length();
-
-        // something wrong.  handle it by just returning the input
-        // long as a string.  we prefer this to just crashing in
-        // the substring handling.
-        if (len < 3) {
-            sbuffer.append(timeString);
-            return;
-        }
-        sbuffer.append(timeString.substring(0, len - 3));
-        sbuffer.append('.');
-        sbuffer.append(timeString.substring(len - 3));
+        sbuffer.append(formatTime(Instant.ofEpochMilli(time)));
     }
 
-    static String formatTime(Instant instant) {
-        StringBuilder builder = new StringBuilder();
-        VespaFormat.formatTime(instant.toEpochMilli(), builder);
-        return builder.toString();
+    public static String formatTime(Instant instant) {
+        return String.format("%d.%06d", instant.getEpochSecond(), instant.getNano() / 1000);
     }
 
+    @Deprecated(since = "7", forRemoval = true) // Unused - this is not the format used by the Vespa log handler
     public static String format(String levelName,
                                 String component,
                                 String componentPrefix,
@@ -165,6 +153,7 @@ public class VespaFormat {
      * @param sbuf The stringbuffer into which we wish to
      *             format the Throwable
      */
+    @Deprecated(since = "7", forRemoval = true) // Unused - this is not the format used by the Vespa log handler
     public static void formatException (Throwable t, StringBuilder sbuf) {
         Throwable last = t;
         int depth = 0;
diff --git a/vespalog/src/main/java/com/yahoo/log/VespaFormatter.java b/vespalog/src/main/java/com/yahoo/log/VespaFormatter.java
index 9db9fd09b26..72a80227138 100644
--- a/vespalog/src/main/java/com/yahoo/log/VespaFormatter.java
+++ b/vespalog/src/main/java/com/yahoo/log/VespaFormatter.java
@@ -2,6 +2,8 @@
 // $Id$
 package com.yahoo.log;
 
+import com.yahoo.log.event.Event;
+
 import java.io.PrintWriter;
 import java.io.StringWriter;
 import java.util.logging.LogRecord;
@@ -9,8 +11,6 @@ import java.util.logging.SimpleFormatter;
 import java.util.regex.Matcher;
 import java.util.regex.Pattern;
 
-import com.yahoo.log.event.Event;
-
 /**
  * This class implements a log formatter which takes care of
  * formatting messages according to the VESPA common log format.
@@ -98,7 +98,7 @@ public class VespaFormatter extends SimpleFormatter {
         String component = r.getLoggerName();
 
         // format the time
-        VespaFormat.formatTime(r.getMillis(), sbuf);
+        sbuf.append(VespaFormat.formatTime(r.getInstant()));
         sbuf.append("\t");
 
         sbuf.append(hostname).append("\t")
diff --git a/vespalog/src/test/java/com/yahoo/log/LogSetupTestCase.java b/vespalog/src/test/java/com/yahoo/log/LogSetupTestCase.java
index d0e2baf47c5..2cea88b1c36 100644
--- a/vespalog/src/test/java/com/yahoo/log/LogSetupTestCase.java
+++ b/vespalog/src/test/java/com/yahoo/log/LogSetupTestCase.java
@@ -1,20 +1,24 @@
 // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
 package com.yahoo.log;
 
+import org.junit.Before;
+import org.junit.Rule;
+import org.junit.Test;
+import org.junit.rules.TemporaryFolder;
+
+import java.io.File;
 import java.io.IOException;
 import java.time.Instant;
+import java.util.logging.Level;
 import java.util.logging.LogRecord;
 import java.util.logging.Logger;
-import java.util.logging.Level;
-import java.io.File;
-
-import org.junit.Rule;
-import org.junit.Test;
-import org.junit.Before;
-import org.junit.rules.TemporaryFolder;
 
-import static org.junit.Assert.*;
 import static org.hamcrest.CoreMatchers.is;
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertFalse;
+import static org.junit.Assert.assertNotNull;
+import static org.junit.Assert.assertThat;
+import static org.junit.Assert.assertTrue;
 
 /**
  * Make sure we can install the logging stuff properly.
@@ -52,7 +56,7 @@ public class LogSetupTestCase {
         hostname = Util.getHostName();
         pid = Util.getPID();
 
-        zookeeperLogRecordString = "1107011348.029\t"
+        zookeeperLogRecordString = "1107011348.029000\t"
                 + hostname
                 + "\t"
                 + pid
diff --git a/vespalog/src/test/java/com/yahoo/log/VespaFormatterTestCase.java b/vespalog/src/test/java/com/yahoo/log/VespaFormatterTestCase.java
index cbfbd609f61..d3d1d52c1d5 100644
--- a/vespalog/src/test/java/com/yahoo/log/VespaFormatterTestCase.java
+++ b/vespalog/src/test/java/com/yahoo/log/VespaFormatterTestCase.java
@@ -40,7 +40,7 @@ public class VespaFormatterTestCase {
         testRecord1.setInstant(Instant.ofEpochMilli(1098709021843L));
         testRecord1.setThreadID(123);
 
-        expected1 = "1098709021.843\t"
+        expected1 = "1098709021.843000\t"
             + hostname + "\t"
             + pid
             + "/123" + "\t"
@@ -49,7 +49,7 @@ public class VespaFormatterTestCase {
             + "info\t"
             + "this is a test\n";
 
-        expected2 = "1098709021.843\t"
+        expected2 = "1098709021.843000\t"
             + hostname + "\t"
             + pid
             + "/123" + "\t"
@@ -64,7 +64,7 @@ public class VespaFormatterTestCase {
         testRecord2.setThreadID(123);
         testRecord2.setLoggerName("org.foo");
 
-        expected3 = "1098709021.843\t"
+        expected3 = "1098709021.843000\t"
             + hostname + "\t"
             + pid
             + "/123" + "\t"
@@ -73,7 +73,7 @@ public class VespaFormatterTestCase {
             + "info\t"
             + "this is a test\n";
 
-        expected4 = "1098709021.843\t"
+        expected4 = "1098709021.843000\t"
             + hostname + "\t"
             + pid
             + "/123" + "\t"
@@ -112,7 +112,7 @@ public class VespaFormatterTestCase {
         Object[] params = { "a small", "message" };
         testRecord.setParameters(params);
 
-        String expected = "1098709021.843\t"
+        String expected = "1098709021.843000\t"
                           + hostname + "\t"
                           + pid
                           + "/123" + "\t"
@@ -232,6 +232,7 @@ public class VespaFormatterTestCase {
      * of runtime errors. -bb
      */
     @Test
+    @SuppressWarnings("removal") // for VespaFormat.formatException
     public void testExceptionFormatting () {
         StringBuilder sb = new StringBuilder(128);
         Exception e = new Exception("testing", new Exception("nested"));
@@ -240,9 +241,10 @@ public class VespaFormatterTestCase {
 
 
     @Test
-    public void testGeneralFormat() {
+    @SuppressWarnings("removal")
+    public void testGeneralFormat() { // for VespaFormat.format
         String[] expected = new String[] {
-                "54.321",
+                "54.321000",
                 "hostname",
                 "26019/UnitTest-Thread-37",
                 "UnitTestRunner",
diff --git a/vespalog/src/test/java/com/yahoo/log/VespaLogHandlerTestCase.java b/vespalog/src/test/java/com/yahoo/log/VespaLogHandlerTestCase.java
index d18bce2f4ec..c0dd856b634 100644
--- a/vespalog/src/test/java/com/yahoo/log/VespaLogHandlerTestCase.java
+++ b/vespalog/src/test/java/com/yahoo/log/VespaLogHandlerTestCase.java
@@ -5,19 +5,28 @@ import org.junit.After;
 import org.junit.Before;
 import org.junit.Test;
 
-import java.io.*;
-import java.time.Instant;
+import java.io.BufferedReader;
+import java.io.ByteArrayOutputStream;
+import java.io.File;
+import java.io.FileInputStream;
+import java.io.FileNotFoundException;
+import java.io.IOException;
+import java.io.InputStreamReader;
+import java.io.OutputStream;
 import java.util.LinkedList;
 import java.util.List;
 import java.util.concurrent.BrokenBarrierException;
 import java.util.concurrent.CyclicBarrier;
 import java.util.logging.Level;
 import java.util.logging.LogRecord;
-import java.util.logging.Logger;
 
-import static java.time.Instant.ofEpochMilli;
+import static java.time.Instant.ofEpochSecond;
 import static org.hamcrest.core.Is.is;
-import static org.junit.Assert.*;
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertFalse;
+import static org.junit.Assert.assertThat;
+import static org.junit.Assert.assertTrue;
+import static org.junit.Assert.fail;
 
 /**
  * @author  Bjorn Borud
@@ -43,8 +52,8 @@ public class VespaLogHandlerTestCase {
         pid = Util.getPID();
 
         record1 = new LogRecord(Level.INFO, "This is a test");
-        record1.setInstant(ofEpochMilli(1100011348029L));
-        record1String = "1100011348.029\t"
+        record1.setInstant(ofEpochSecond(1100011348L, 29_123_543));
+        record1String = "1100011348.029123\t"
             + hostname
             + "\t"
 	    + pid
@@ -53,9 +62,9 @@ public class VespaLogHandlerTestCase {
             + "\tmy-test-config-id\tTST\tinfo\tThis is a test";
 
         record2 = new LogRecord(Level.FINE, "This is a test too");
-        record2.setInstant(ofEpochMilli(1100021348029L));
+        record2.setInstant(ofEpochSecond(1100021348L, 29_987_654));
         record2.setLoggerName("com.yahoo.log.test");
-        record2String = "1100021348.029\t"
+        record2String = "1100021348.029987\t"
             + hostname
             + "\t"
 	    + pid
@@ -63,8 +72,8 @@ public class VespaLogHandlerTestCase {
 
         record3 = new LogRecord(Level.WARNING, "another test");
         record3.setLoggerName("com.yahoo.log.test");
-        record3.setInstant(ofEpochMilli(1107011348029L));
-        record3String = "1107011348.029\t"
+        record3.setInstant(ofEpochSecond(1107011348L, 29_000_000L));
+        record3String = "1107011348.029000\t"
             + hostname
             + "\t"
 	    + pid
@@ -73,8 +82,8 @@ public class VespaLogHandlerTestCase {
 
         record4 = new LogRecord(Level.WARNING, "unicode \u00E6\u00F8\u00E5 test \u7881 unicode");
         record4.setLoggerName("com.yahoo.log.test");
-        record4.setInstant(ofEpochMilli(1107011348029L));
-        record4String = "1107011348.029\t"
+        record4.setInstant(ofEpochSecond(1107011348, 29_000_001L));
+        record4String = "1107011348.029000\t"
             + hostname
             + "\t"
 	    + pid
diff --git a/vespalog/src/vespa-logfmt/vespa-logfmt.pl b/vespalog/src/vespa-logfmt/vespa-logfmt.pl
index eed53af8923..f15a44d4419 100755
--- a/vespalog/src/vespa-logfmt/vespa-logfmt.pl
+++ b/vespalog/src/vespa-logfmt/vespa-logfmt.pl
@@ -104,7 +104,6 @@ if ( $opthelp || $bad ) {
 	"  -c REGEX\t--component=REGEX\tselect components matching REGEX\n",
 	"  -m REGEX\t--message=REGEX\t\tselect message text matching REGEX\n",
 	"  -f\t\t--follow\t\tinvoke tail -F to follow input file\n",
-        "  -L\t\t--livestream\t\tfollow log stream from logserver\n",
 	"  -N\t\t--nldequote\t\tdequote newlines in message text field\n",
 	"  -t\t--tc\t--truncatecomponent\tchop component to 15 chars\n",
 	"  --ts\t\t--truncateservice\tchop service to 9 chars\n",