From fc5a108d53c4bf0b7fc901b2bbd5a040b6e41632 Mon Sep 17 00:00:00 2001
From: Anton Kaliaev <anton.kalyaev@gmail.com>
Date: Thu, 25 Feb 2021 11:06:24 +0400
Subject: [PATCH] libs/log: [JSON format] include timestamp (#6174)

Closes #6146
---
 CHANGELOG_PENDING.md             |  1 +
 libs/cli/flags/log_level_test.go |  2 +-
 libs/log/filter_test.go          |  6 +++---
 libs/log/tm_json_logger.go       | 11 ++++++++++-
 libs/log/tracing_logger_test.go  |  2 +-
 5 files changed, 16 insertions(+), 6 deletions(-)

diff --git a/CHANGELOG_PENDING.md b/CHANGELOG_PENDING.md
index 016ab7e2f..2fd0360e3 100644
--- a/CHANGELOG_PENDING.md
+++ b/CHANGELOG_PENDING.md
@@ -71,6 +71,7 @@ Friendly reminder, we have a [bug bounty program](https://hackerone.com/tendermi
 - [rpc/client/http] \#6163 Do not drop events even if the `out` channel is full (@melekes)
 - [node] \#6059 Validate and complete genesis doc before saving to state store (@silasdavis)
 - [state] \#6067 Batch save state data (@githubsands & @cmwaters)
+- [libs/log] \#6174 Include timestamp (`ts` field; `time.RFC3339Nano` format) in JSON logger output (@melekes)
 
 ### BUG FIXES
 
diff --git a/libs/cli/flags/log_level_test.go b/libs/cli/flags/log_level_test.go
index c4c1707b5..9d1b24009 100644
--- a/libs/cli/flags/log_level_test.go
+++ b/libs/cli/flags/log_level_test.go
@@ -15,7 +15,7 @@ const (
 
 func TestParseLogLevel(t *testing.T) {
 	var buf bytes.Buffer
-	jsonLogger := log.NewTMJSONLogger(&buf)
+	jsonLogger := log.NewTMJSONLoggerNoTS(&buf)
 
 	correctLogLevels := []struct {
 		lvl              string
diff --git a/libs/log/filter_test.go b/libs/log/filter_test.go
index 06cba762b..b2ba18394 100644
--- a/libs/log/filter_test.go
+++ b/libs/log/filter_test.go
@@ -58,7 +58,7 @@ func TestVariousLevels(t *testing.T) {
 		tc := tc
 		t.Run(tc.name, func(t *testing.T) {
 			var buf bytes.Buffer
-			logger := log.NewFilter(log.NewTMJSONLogger(&buf), tc.allowed)
+			logger := log.NewFilter(log.NewTMJSONLoggerNoTS(&buf), tc.allowed)
 
 			logger.Debug("here", "this is", "debug log")
 			logger.Info("here", "this is", "info log")
@@ -74,7 +74,7 @@ func TestVariousLevels(t *testing.T) {
 func TestLevelContext(t *testing.T) {
 	var buf bytes.Buffer
 
-	logger := log.NewTMJSONLogger(&buf)
+	logger := log.NewTMJSONLoggerNoTS(&buf)
 	logger = log.NewFilter(logger, log.AllowError())
 	logger = logger.With("context", "value")
 
@@ -96,7 +96,7 @@ func TestLevelContext(t *testing.T) {
 func TestVariousAllowWith(t *testing.T) {
 	var buf bytes.Buffer
 
-	logger := log.NewTMJSONLogger(&buf)
+	logger := log.NewTMJSONLoggerNoTS(&buf)
 
 	logger1 := log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("context", "value"))
 	logger1.With("context", "value").Info("foo", "bar", "baz")
diff --git a/libs/log/tm_json_logger.go b/libs/log/tm_json_logger.go
index a71ac1034..3ebeddaa3 100644
--- a/libs/log/tm_json_logger.go
+++ b/libs/log/tm_json_logger.go
@@ -11,5 +11,14 @@ import (
 // w.Write. The passed Writer must be safe for concurrent use by multiple
 // goroutines if the returned Logger will be used concurrently.
 func NewTMJSONLogger(w io.Writer) Logger {
-	return &tmLogger{kitlog.NewJSONLogger(w)}
+	logger := kitlog.NewJSONLogger(w)
+	logger = kitlog.With(logger, "ts", kitlog.DefaultTimestampUTC)
+	return &tmLogger{logger}
+}
+
+// NewTMJSONLoggerNoTS is the same as NewTMJSONLogger, but without the
+// timestamp.
+func NewTMJSONLoggerNoTS(w io.Writer) Logger {
+	logger := kitlog.NewJSONLogger(w)
+	return &tmLogger{logger}
 }
diff --git a/libs/log/tracing_logger_test.go b/libs/log/tracing_logger_test.go
index 6d6edc5ca..f32ac9c57 100644
--- a/libs/log/tracing_logger_test.go
+++ b/libs/log/tracing_logger_test.go
@@ -15,7 +15,7 @@ import (
 func TestTracingLogger(t *testing.T) {
 	var buf bytes.Buffer
 
-	logger := log.NewTMJSONLogger(&buf)
+	logger := log.NewTMJSONLoggerNoTS(&buf)
 
 	logger1 := log.NewTracingLogger(logger)
 	err1 := errors.New("courage is grace under pressure")