httpbp: Set http.Server.ErrorLog

It's used by upstream server to log some of the kinda-breaking issues,
for example [1]. Since the majority of the http servers at Reddit are
public facing, when those happens it's usually just user messing with
us, not really that the http client we control doing things wrong. This
gives us a way to suppress those logs, and also emit counters to better
track how many times those happened.

This also makes the upstream http server to use the same json logger by
zap as the rest of our code, at warning level.

[1]: golang/go#25192 (comment)

Author: fishy

httpbp/error_logger.go

@@ -0,0 +1,56 @@
+package httpbp
+
+import (
+	"log"
+	"strings"
+
+	"github.com/prometheus/client_golang/prometheus"
+	"github.com/prometheus/client_golang/prometheus/promauto"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+
+	"github.com/reddit/baseplate.go/internal/prometheusbpint"
+)
+
+var httpServerLoggingCounter = promauto.With(prometheusbpint.GlobalRegistry).NewCounterVec(prometheus.CounterOpts{
+	Name: "httpbp_server_upstream_issue_logs_total",
+	Help: "Number of logs emitted by stdlib http server regarding an upstream issue",
+}, []string{"upstream_issue"})
+
+// This is a special zapcore used by stdlib http server to handle error logging.
+type wrappedCore struct {
+	zapcore.Core
+
+	counter25192  prometheus.Counter
+	suppress25192 bool
+}
+
+func (w wrappedCore) Check(entry zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry {
+	// Example message:
+	//     URL query contains semicolon, which is no longer a supported separator; parts of the query may be stripped when parsed; see golang.org/issue/25192
+	if strings.Contains(entry.Message, "golang.org/issue/25192") {
+		w.counter25192.Inc()
+		if w.suppress25192 {
+			// drop the log
+			return ce
+		}
+	}
+
+	return w.Core.Check(entry, ce)
+}
+
+func httpServerLogger(base *zap.Logger, suppress25192 bool) (*log.Logger, error) {
+	return zap.NewStdLogAt(base.WithOptions(
+		zap.Fields(zap.String("from", "http-server")),
+		zap.WrapCore(func(c zapcore.Core) zapcore.Core {
+			return wrappedCore{
+				Core: c,
+
+				suppress25192: suppress25192,
+				counter25192: httpServerLoggingCounter.With(prometheus.Labels{
+					"upstream_issue": "25192",
+				}),
+			}
+		}),
+	), zapcore.WarnLevel)
+}

httpbp/error_logger_test.go

@@ -0,0 +1,75 @@
+package httpbp
+
+import (
+	"io"
+	"strings"
+	"testing"
+
+	"github.com/prometheus/client_golang/prometheus"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+
+	"github.com/reddit/baseplate.go/prometheusbp/promtest"
+)
+
+func initBaseLogger(w io.Writer) *zap.Logger {
+	// Mostly copied from zap.NewExample, to make the log deterministic.
+	encoderCfg := zapcore.EncoderConfig{
+		MessageKey:     "msg",
+		LevelKey:       "level",
+		NameKey:        "logger",
+		EncodeLevel:    zapcore.LowercaseLevelEncoder,
+		EncodeTime:     zapcore.ISO8601TimeEncoder,
+		EncodeDuration: zapcore.StringDurationEncoder,
+	}
+	core := zapcore.NewCore(zapcore.NewJSONEncoder(encoderCfg), zapcore.AddSync(w), zap.DebugLevel)
+	return zap.New(core)
+}
+
+func TestHTTPServerLogger(t *testing.T) {
+	t.Run("suppressed", func(t *testing.T) {
+		defer promtest.NewPrometheusMetricTest(t, "25192", httpServerLoggingCounter, prometheus.Labels{
+			"upstream_issue": "25192",
+		}).CheckDelta(2)
+
+		var sb strings.Builder
+		logger, err := httpServerLogger(initBaseLogger(&sb), true)
+		if err != nil {
+			t.Fatalf("httpServerLogger failed: %v", err)
+		}
+		logger.Printf("Hello, golang.org/issue/25192!")
+		logger.Printf("Hello, golang.org/issue/25192!")
+		if str := sb.String(); strings.TrimSpace(str) != "" {
+			t.Errorf("Expected logs being suppressed, got %q", str)
+		}
+
+		sb.Reset()
+		logger.Printf("Hello, world!")
+		const want = `{"level":"warn","msg":"Hello, world!","from":"http-server"}`
+		if got := sb.String(); strings.TrimSpace(got) != want {
+			t.Errorf("Got %q, want %q", got, want)
+		}
+	})
+
+	t.Run("not-suppressed", func(t *testing.T) {
+		defer promtest.NewPrometheusMetricTest(t, "25192", httpServerLoggingCounter, prometheus.Labels{
+			"upstream_issue": "25192",
+		}).CheckDelta(1)
+
+		var sb strings.Builder
+		logger, err := httpServerLogger(initBaseLogger(&sb), false)
+		if err != nil {
+			t.Fatalf("httpServerLogger failed: %v", err)
+		}
+		logger.Printf("Hello, golang.org/issue/25192!")
+		if got, want := sb.String(), `{"level":"warn","msg":"Hello, golang.org/issue/25192!","from":"http-server"}`; strings.TrimSpace(got) != want {
+			t.Errorf("Got %q, want %q", got, want)
+		}
+
+		sb.Reset()
+		logger.Printf("Hello, world!")
+		if got, want := sb.String(), `{"level":"warn","msg":"Hello, world!","from":"http-server"}`; strings.TrimSpace(got) != want {
+			t.Errorf("Got %q, want %q", got, want)
+		}
+	})
+}

httpbp/server.go

@@ -157,6 +157,17 @@ type ServerArgs struct {
 	// Logger is an optional arg to be called when the InjectEdgeRequestContext
 	// middleware failed to parse the edge request header for any reason.
 	Logger log.Wrapper
+
+	// The http.Server from stdlib would emit a log regarding [1] whenever it
+	// happens. Set SuppressIssue25192 to true to suppress that log.
+	//
+	// Regardless of the value of SuppressIssue25192,
+	// we always emit a prometheus counter of:
+	//
+	//     httpbp_server_upstream_issue_logs_total{upstream_issue="25192"}
+	//
+	// [1]: https://github.com/golang/go/issues/25192#issuecomment-992276264
+	SuppressIssue25192 bool
 }
 
 // ValidateAndSetDefaults checks the ServerArgs for any errors and sets any
@@ -221,9 +232,21 @@ func NewBaseplateServer(args ServerArgs) (baseplate.Server, error) {
 		return nil, err
 	}
 
+	logger, err := httpServerLogger(log.C(context.Background()).Desugar(), args.SuppressIssue25192)
+	if err != nil {
+		// Should not happen, but if it really happens, we just fallback to stdlib
+		// logger, which is not that big a deal either.
+		log.Errorw(
+			"Failed to create error logger for stdlib http server",
+			"err", err,
+		)
+	}
+
 	srv := &http.Server{
 		Addr:    args.Baseplate.GetConfig().Addr,
 		Handler: args.EndpointRegistry,
+
+		ErrorLog: logger,
 	}
 	for _, f := range args.OnShutdown {
 		srv.RegisterOnShutdown(f)