Merge pull request #7748 from hashicorp/b-noisy-http-logs

agent: route http logs through hclog

CHANGELOG.md

@@ -3,6 +3,7 @@
 BUG FIXES:
 
  * core: Fixed a bug that only ran a task `shutdown_delay` if the task had a registered service [[GH-7663](https://github.com/hashicorp/nomad/issues/7663)]
+ * agent: Fixed a bug where http server logs did not honor json log formatting, and reduced http server logging level to Trace [[GH-7748](https://github.com/hashicorp/nomad/issues/7748)]
  * driver/docker: Fixed a bug where retrying failed docker creation may in rare cases trigger a panic [[GH-7749](https://github.com/hashicorp/nomad/issues/7749)]
  * vault: Upgrade http2 library to fix Vault API calls that fail with `http2: no cached connection was available` [[GH-7673](https://github.com/hashicorp/nomad/issues/7673)]
 

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() {

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
+}

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")
+
+}