using sec.usec as format instead of usec since epoch (#32)

using sec.usec as format instead of usec since epoch

README.md

@@ -40,7 +40,7 @@ One can also revert server to not be JSON through config.
 
 In JSON mode the output looks like this
 ```json
-{"ts":1683504169239557,"level":"info","file":"logger.go","line":221,"msg":"Log level is now 1 Verbose (was 2 Info"}
+{"ts":1683504169.239557,"level":"info","file":"logger.go","line":221,"msg":"Log level is now 1 Verbose (was 2 Info"}
 ```
 Which can be converted to JSONEntry but is also a fixed, optimized format (ie ts is always first etc)
 

logger.go

@@ -25,6 +25,7 @@ import (
 	"fmt"
 	"io"
 	"log"
+	"math"
 	"os"
 	"runtime"
 	"strings"
@@ -114,7 +115,7 @@ func SetDefaultsForClientTools() {
 // While that serialization of is custom in order to be cheap, it maps to the following
 // structure.
 type JSONEntry struct {
-	TS    int64 // in microseconds since epoch (unix micros)
+	TS    float64 // In seconds since epoch (unix micros resolution), see TimeToTS().
 	Level string
 	File  string
 	Line  int
@@ -124,13 +125,14 @@ type JSONEntry struct {
 	// or https://go.dev/play/p/H0RPmuc3dzv (using github.com/mitchellh/mapstructure)
 }
 
-// LogEntry Ts to time.Time conversion.
+// Time() converts a LogEntry.TS to time.Time.
 // The returned time is set UTC to avoid TZ mismatch.
+// Inverse of TimeToTS().
 func (l *JSONEntry) Time() time.Time {
-	const million = int64(1e6)
+	sec := int64(l.TS)
 	return time.Unix(
-		l.TS/million,        // Microseconds -> Seconds
-		1000*(l.TS%million), // Microseconds -> Nanoseconds
+		sec, // float seconds -> int Seconds
+		int64(math.Round(1e6*(l.TS-float64(sec)))*1000), // reminder -> Nanoseconds
 	)
 }
 
@@ -285,15 +287,29 @@ func jsonWrite(msg string) {
 	jsonWriterMutex.Unlock()
 }
 
-func TimeToTS(t time.Time) int64 {
-	return t.UnixMicro()
+// Converts a time.Time to a float64 timestamp (seconds since epoch at microsecond resolution).
+// This is what is used in JSONEntry.TS.
+func TimeToTS(t time.Time) float64 {
+	// note that nanos like 1688763601.199999400 become 1688763601.1999996 in float64 (!)
+	// so we use UnixMicro to hide this problem which also means we don't give the nearest
+	// microseconds but it gets truncated instead ( https://go.dev/play/p/rzojmE2odlg )
+	usec := t.UnixMicro()
+	tfloat := float64(usec) / 1e6
+	return tfloat
+}
+
+// timeToTStr is copying the string-ification code from jsonTimestamp(),
+// it is used by tests to individually test what jsonTimestamp does.
+func timeToTStr(t time.Time) string {
+	return fmt.Sprintf("%.6f", TimeToTS(t))
 }
 
 func jsonTimestamp() string {
 	if Config.NoTimestamp {
 		return ""
 	}
-	return fmt.Sprintf("\"ts\":%d,", TimeToTS(time.Now()))
+	// Change timeToTStr if changing this.
+	return fmt.Sprintf("\"ts\":%.6f,", TimeToTS(time.Now()))
 }
 
 func logPrintf(lvl Level, format string, rest ...interface{}) {

logger_test.go

@@ -23,6 +23,7 @@ import (
 	"log"
 	"os"
 	"os/exec"
+	"strconv"
 	"strings"
 	"sync"
 	"testing"
@@ -44,17 +45,17 @@ func TestLoggerFilenameLine(t *testing.T) {
 	SetFlags(0)
 	SetLogLevel(Debug)
 	if LogDebug() {
-		Debugf("test") // line 47
+		Debugf("test") // line 48
 	}
-	SetLogLevel(-1)      // line 49
-	SetLogLevel(Warning) // line 50
+	SetLogLevel(-1)      // line 50
+	SetLogLevel(Warning) // line 51
 	Infof("should not show (info level)")
 	Printf("Should show despite being Info - unconditional Printf without line/file")
 	w.Flush()
 	actual := b.String()
-	expected := "D logger_test.go:47-prefix-test\n" +
-		"E logger_test.go:49-prefix-SetLogLevel called with level -1 lower than Debug!\n" +
-		"I logger_test.go:50-prefix-Log level is now 3 Warning (was 0 Debug)\n" +
+	expected := "D logger_test.go:48-prefix-test\n" +
+		"E logger_test.go:50-prefix-SetLogLevel called with level -1 lower than Debug!\n" +
+		"I logger_test.go:51-prefix-Log level is now 3 Warning (was 0 Debug)\n" +
 		"I -prefix-Should show despite being Info - unconditional Printf without line/file\n"
 	if actual != expected {
 		t.Errorf("unexpected:\n%s\nvs:\n%s\n", actual, expected)
@@ -74,11 +75,11 @@ func TestLoggerFilenameLineJSON(t *testing.T) {
 	SetOutput(w)
 	SetLogLevel(Debug)
 	if LogDebug() {
-		Debugf("a test") // line 77
+		Debugf("a test") // line 78
 	}
 	w.Flush()
 	actual := b.String()
-	expected := `{"level":"dbug","file":"` + thisFilename + `","line":77,"msg":"a test"}` + "\n"
+	expected := `{"level":"dbug","file":"` + thisFilename + `","line":78,"msg":"a test"}` + "\n"
 	if actual != expected {
 		t.Errorf("unexpected:\n%s\nvs:\n%s\n", actual, expected)
 	}
@@ -97,11 +98,11 @@ func Test_LogS_JSON_no_json_with_filename(t *testing.T) {
 	SetOutput(w)
 	// Start of the actual test
 	S(Verbose, "This won't show")
-	S(Warning, "This will show", Str("key1", "value 1"), Attr("key2", 42)) // line 100
+	S(Warning, "This will show", Str("key1", "value 1"), Attr("key2", 42)) // line 101
 	Printf("This will show too")                                           // no filename/line and shows despite level
 	_ = w.Flush()
 	actual := b.String()
-	expected := "W logger_test.go:100-bar-This will show, key1=value 1, key2=42\n" +
+	expected := "W logger_test.go:101-bar-This will show, key1=value 1, key2=42\n" +
 		"I -bar-This will show too\n"
 	if actual != expected {
 		t.Errorf("got %q expected %q", actual, expected)
@@ -383,16 +384,23 @@ func TestLoggerJSONNoTimestampNoFilename(t *testing.T) {
 
 // Test that TimeToTs and Time() are inverse of one another.
 func TestTimeToTs(t *testing.T) {
+	var prev float64
 	// tight loop to get different times, at highest resolution
-	for i := 0; i < 1000; i++ {
+	for i := 0; i < 100000; i++ {
 		now := time.Now()
-		int64Ts := TimeToTS(now)
-		e := JSONEntry{TS: int64Ts}
+		// now = now.Add(69 * time.Nanosecond)
+		usecTSstr := timeToTStr(now)
+		usecTS, _ := strconv.ParseFloat(usecTSstr, 64)
+		if i != 0 && usecTS < prev {
+			t.Fatalf("clock went back in time at iter %d %v vs %v", i, usecTS, prev)
+		}
+		prev = usecTS
+		e := JSONEntry{TS: usecTS}
 		inv := e.Time()
 		// Round to microsecond because that's the resolution of the timestamp
 		// (note that on a mac for instance, there is no nanosecond resolution anyway)
 		if !microsecondResolution(now).Equal(inv) {
-			t.Fatalf("unexpected time %v != %v (%d)", now, inv, int64Ts)
+			t.Fatalf("[at %d] unexpected time %v -> %v != %v (%v %v)", i, now, microsecondResolution(now), inv, usecTS, usecTSstr)
 		}
 	}
 }
@@ -550,6 +558,25 @@ func TestStaticFlagDefault(t *testing.T) {
 	}
 }
 
+func TestTimeToTS(t *testing.T) {
+	// test a few times and expected string
+	for _, tst := range []struct {
+		sec    int64
+		nano   int64
+		result string
+	}{
+		{1688763601, 42000, "1688763601.000042"},     // 42 usec after the seconds part, checking for leading zeroes
+		{1688763601, 199999999, "1688763601.199999"}, // nanosec are truncated away not rounded (see note in TimeToTS)
+		{1688763601, 200000999, "1688763601.200000"}, // boundary
+	} {
+		tm := time.Unix(tst.sec, tst.nano)
+		ts := timeToTStr(tm)
+		if ts != tst.result {
+			t.Errorf("unexpected ts for %d, %d -> %q instead of %q (%v)", tst.sec, tst.nano, ts, tst.result, tm)
+		}
+	}
+}
+
 func BenchmarkLogDirect1(b *testing.B) {
 	setLevel(Error)
 	for n := 0; n < b.N; n++ {