From 360e0a1669d2e4ed1f5518214d3d96b28ba991a2 Mon Sep 17 00:00:00 2001
From: Mahmood Ali <mahmood@hashicorp.com>
Date: Sun, 19 Apr 2020 11:02:35 -0400
Subject: [PATCH] agent: route http logs through hclog

Pipe http server log to hclog, so that it uses the same logging format
as rest of nomad logs.  Also, supports emitting them as json logs, when
json formatting is set.

The http server logs are emitted as Trace level, as they are typically
repsent HTTP client errors (e.g. failed tls handshakes, invalid headers,
etc).

Though, Panic logs represent server errors and are relayed as Error
level.
---
 command/agent/http.go             |  1 +
 command/agent/http_stdlog.go      | 33 +++++++++++++++++++++
 command/agent/http_stdlog_test.go | 48 +++++++++++++++++++++++++++++++
 3 files changed, 82 insertions(+)
 create mode 100644 command/agent/http_stdlog.go
 create mode 100644 command/agent/http_stdlog_test.go

diff --git a/command/agent/http.go b/command/agent/http.go
index d2d7f1914d3..0fffaee8bb1 100644
--- a/command/agent/http.go
+++ b/command/agent/http.go
@@ -146,6 +146,7 @@ func NewHTTPServer(agent *Agent, config *Config) (*HTTPServer, error) {
 		Addr:      srv.Addr,
 		Handler:   gzip(mux),
 		ConnState: makeConnState(config.TLSConfig.EnableHTTP, handshakeTimeout, maxConns),
+		ErrorLog:  newHTTPServerLogger(srv.logger),
 	}
 
 	go func() {
diff --git a/command/agent/http_stdlog.go b/command/agent/http_stdlog.go
new file mode 100644
index 00000000000..a960bb655ab
--- /dev/null
+++ b/command/agent/http_stdlog.go
@@ -0,0 +1,33 @@
+package agent
+
+import (
+	"bytes"
+	"log"
+
+	hclog "github.com/hashicorp/go-hclog"
+)
+
+func newHTTPServerLogger(logger hclog.Logger) *log.Logger {
+	return log.New(&httpServerLoggerAdapter{logger}, "", 0)
+}
+
+// a logger adapter that forwards http server logs as a Trace level
+// hclog log entries. Logs related to panics are forwarded with Error level.
+//
+// HTTP server logs are typically spurious as they represent HTTP
+// client errors (e.g. TLS handshake failures).
+type httpServerLoggerAdapter struct {
+	logger hclog.Logger
+}
+
+func (l *httpServerLoggerAdapter) Write(data []byte) (int, error) {
+	if bytes.Contains(data, []byte("panic")) {
+		str := string(bytes.TrimRight(data, " \t\n"))
+		l.logger.Error(str)
+	} else if l.logger.IsTrace() {
+		str := string(bytes.TrimRight(data, " \t\n"))
+		l.logger.Trace(str)
+	}
+
+	return len(data), nil
+}
diff --git a/command/agent/http_stdlog_test.go b/command/agent/http_stdlog_test.go
new file mode 100644
index 00000000000..523086b2218
--- /dev/null
+++ b/command/agent/http_stdlog_test.go
@@ -0,0 +1,48 @@
+package agent
+
+import (
+	"bytes"
+	"testing"
+
+	"github.com/hashicorp/go-hclog"
+	"github.com/stretchr/testify/require"
+)
+
+func TestHttpServerLoggerFilters_Level_Info(t *testing.T) {
+	var buf bytes.Buffer
+	hclogger := hclog.New(&hclog.LoggerOptions{
+		Name:   "testlog",
+		Output: &buf,
+		Level:  hclog.Info,
+	})
+
+	stdlogger := newHTTPServerLogger(hclogger)
+
+	// spurious logging would be filtered out
+	stdlogger.Printf("spurious logging: %v", "arg")
+	require.Empty(t, buf.String())
+
+	// panics are included
+	stdlogger.Printf("panic while processing: %v", "endpoint")
+	require.Contains(t, buf.String(), "[ERROR] testlog: panic while processing: endpoint")
+
+}
+
+func TestHttpServerLoggerFilters_Level_Trace(t *testing.T) {
+	var buf bytes.Buffer
+	hclogger := hclog.New(&hclog.LoggerOptions{
+		Name:   "testlog",
+		Output: &buf,
+		Level:  hclog.Trace,
+	})
+
+	stdlogger := newHTTPServerLogger(hclogger)
+
+	// spurious logging will be included as Trace level
+	stdlogger.Printf("spurious logging: %v", "arg")
+	require.Contains(t, buf.String(), "[TRACE] testlog: spurious logging: arg")
+
+	stdlogger.Printf("panic while processing: %v", "endpoint")
+	require.Contains(t, buf.String(), "[ERROR] testlog: panic while processing: endpoint")
+
+}