From 360e0a1669d2e4ed1f5518214d3d96b28ba991a2 Mon Sep 17 00:00:00 2001 From: Mahmood Ali Date: Sun, 19 Apr 2020 11:02:35 -0400 Subject: [PATCH 1/2] 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") + +} From 5a5354a86fc0b8661a9a2a0b305d4aeb720fe080 Mon Sep 17 00:00:00 2001 From: Mahmood Ali Date: Mon, 20 Apr 2020 10:36:39 -0400 Subject: [PATCH 2/2] update changelog [ci skip] --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 52677ffed7f..2d4c7938001 100644 --- a/CHANGELOG.md +++ b/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)]