MB-55150 Revise request logging

Change-Id: I7c940e974962755e0a3711417f8e1bec675ef438
Reviewed-on: https://review.couchbase.org/c/query/+/185617
Reviewed-by: Sitaram Vemulapalli <sitaram.vemulapalli@couchbase.com>
Tested-by: Donald Haggart <donald.haggart@couchbase.com>

logging/file_logger.go

@@ -24,7 +24,7 @@ type FileLogger struct {
 }
 
 func (this *FileLogger) SetRequestId(id string) {
-	this.requestId = id + " "
+	this.requestId = " " + id
 }
 
 func (this *FileLogger) Level() Level {
@@ -40,10 +40,13 @@ func (this *FileLogger) Stringf(l Level, format string, args ...interface{}) str
 	if l == DEBUG || l == TRACE {
 		fl = getFileLine(1)
 	}
-	return time.Now().Format(_TIMESTAMP_FORMAT) + string(l.Byte()) + fmtpkg.Sprintf(format, args...) + fl
+	return time.Now().Format(SHORT_TIMESTAMP_FORMAT) + string(l.Abbreviation()) + fmtpkg.Sprintf(format, args...) + fl
 }
 
 func (this *FileLogger) log(l Level, fn func() string) {
+	if l < this.logLevel {
+		return
+	}
 	now := time.Now()
 	var fl string
 	if l == DEBUG || l == TRACE {
@@ -83,10 +86,14 @@ func (this *FileLogger) log(l Level, fn func() string) {
 		this.file.Seek(0, os.SEEK_END)
 		this.file.WriteString("... truncated ...\n")
 	}
-	this.file.WriteString(now.Format(_TIMESTAMP_FORMAT))
+	this.file.WriteString(now.Format(SHORT_TIMESTAMP_FORMAT))
 	this.file.WriteString(this.requestId)
-	this.file.Write(l.Byte())
-	this.file.WriteString(fn() + fl + "\n")
+	this.file.WriteString(l.Abbreviation())
+	this.file.WriteString(fn())
+	if len(fl) > 0 {
+		this.file.WriteString(fl)
+	}
+	this.file.WriteString("\n")
 	this.Unlock()
 }
 

logging/logger.go

@@ -36,8 +36,8 @@ func (level Level) String() string {
 	return _LEVEL_NAMES[level]
 }
 
-func (level Level) Byte() []byte {
-	return []byte{_LEVEL_NAMES[level][0], ' '}
+func (level Level) Abbreviation() string {
+	return _ABBREVIATED_LEVEL_NAMES[level]
 }
 
 func (level Level) FunctionName() string {
@@ -57,6 +57,17 @@ var _LEVEL_NAMES = []string{
 	NONE:   "NONE",
 }
 
+var _ABBREVIATED_LEVEL_NAMES = []string{
+	DEBUG:  " D ",
+	TRACE:  " T ",
+	INFO:   " I ",
+	WARN:   " W ",
+	ERROR:  " E ",
+	SEVERE: " S ",
+	FATAL:  " F ",
+	NONE:   " N ",
+}
+
 var _LEVEL_MAP = map[string]Level{
 	"debug":  DEBUG,
 	"trace":  TRACE,
@@ -68,6 +79,9 @@ var _LEVEL_MAP = map[string]Level{
 	"none":   NONE,
 }
 
+const FULL_TIMESTAMP_FORMAT = "2006-01-02T15:04:05.000-07:00" // time.RFC3339 with milliseconds
+const SHORT_TIMESTAMP_FORMAT = "2006-01-02T15:04:05.000 "
+
 // cache logging enablement to improve runtime performance (reduces from multiple tests to a single test on each call)
 var (
 	cachedDebug   bool

logging/logger_golog/logger_golog.go

@@ -130,7 +130,7 @@ func (gl *goLogger) log(level logging.Level, rlevel logging.Level, msg string) {
 }
 
 func (gl *goLogger) str(level logging.Level, rlevel logging.Level, msg string) string {
-	tm := time.Now().Format("2006-01-02T15:04:05.000-07:00") // time.RFC3339 with milliseconds
+	tm := time.Now().Format(logging.FULL_TIMESTAMP_FORMAT)
 	return gl.entryFormatter.format(tm, level, rlevel, msg)
 }
 

logging/temp_file_logger.go

@@ -18,7 +18,6 @@ import (
 )
 
 const _MAX_TRACE_SIZE = 64 * 1024 * 1024
-const _TIMESTAMP_FORMAT = "2006-01-02T15:04:05.000 "
 
 func splitOnNUL(data []byte, atEOF bool) (advance int, token []byte, err error) {
 	if atEOF && len(data) == 0 {
@@ -58,10 +57,13 @@ func (this *TempFileLogger) Stringf(l Level, format string, args ...interface{})
 	if l == DEBUG || l == TRACE {
 		fl = getFileLine(1)
 	}
-	return time.Now().Format(_TIMESTAMP_FORMAT) + string(l.Byte()) + fmtpkg.Sprintf(format, args...) + fl
+	return time.Now().Format(SHORT_TIMESTAMP_FORMAT) + string(l.Abbreviation()) + fmtpkg.Sprintf(format, args...) + fl
 }
 
 func (this *TempFileLogger) log(l Level, fn func() string) {
+	if l < this.logLevel {
+		return
+	}
 	now := time.Now()
 	var fl string
 	if l == DEBUG || l == TRACE {
@@ -102,9 +104,12 @@ func (this *TempFileLogger) log(l Level, fn func() string) {
 		this.file.WriteString("... truncated ...")
 		this.file.Write([]byte{0})
 	}
-	this.file.WriteString(now.Format(_TIMESTAMP_FORMAT))
-	this.file.Write(l.Byte())
-	this.file.WriteString(fn() + fl)
+	this.file.WriteString(now.Format(SHORT_TIMESTAMP_FORMAT))
+	this.file.WriteString(l.Abbreviation())
+	this.file.WriteString(fn())
+	if len(fl) > 0 {
+		this.file.WriteString(fl)
+	}
 	this.file.Write([]byte{0})
 	this.Unlock()
 }

server/http/service_request.go

@@ -79,7 +79,6 @@ func newHttpRequest(rv *httpRequest, resp http.ResponseWriter, req *http.Request
 
 	// handles request level logging
 	rv.logger, _ = resolver.NewLogger("builtin")
-	rv.logger.Infof("Request received")
 
 	// Limit body size in case of denial-of-service attack
 	req.Body = http.MaxBytesReader(resp, req.Body, int64(size))
@@ -137,6 +136,8 @@ func newHttpRequest(rv *httpRequest, resp http.ResponseWriter, req *http.Request
 	if err == nil {
 		err = httpArgs.processParameters(rv)
 	}
+	// logger may have been changed by parameters so log first message only after processing
+	rv.logger.Infof("Request received at %v", reqTime.Format(logging.SHORT_TIMESTAMP_FORMAT))
 
 	if err == nil {
 		if rv.stmtCnt == 0 {
@@ -203,7 +204,7 @@ func newHttpRequest(rv *httpRequest, resp http.ResponseWriter, req *http.Request
 		rv.Fail(err)
 	}
 	// start - temporary logging of requests
-	logging.Debuga(func() string {
+	dfn := func() string {
 		u, _, _ := cbauth.ExtractCreds(req)
 		data := make(map[string]interface{}, 7)
 		data["user"] = u
@@ -230,7 +231,9 @@ func newHttpRequest(rv *httpRequest, resp http.ResponseWriter, req *http.Request
 		data["args"] = a
 		b, _ := json.Marshal(data)
 		return string(b)
-	}, rv.logger)
+	}
+	logging.Debuga(dfn)
+	rv.logger.Infoa(dfn)
 	// end - temporary logging of requests
 	rv.jsonArgs = jsonArgs{}
 	rv.urlArgs = urlArgs{}