Skip to content

Commit a9f9ce5

Browse files
fishyfishy
committed
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)
1 parent 155114b commit a9f9ce5

File tree

3 files changed

+197
-0
lines changed

3 files changed

+197
-0
lines changed

‎httpbp/error_logger.go

+78
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,78 @@
1+
package httpbp
2+
3+
import (
4+
"log"
5+
"strconv"
6+
"strings"
7+
8+
"github.com/prometheus/client_golang/prometheus"
9+
"github.com/prometheus/client_golang/prometheus/promauto"
10+
"go.uber.org/zap"
11+
"go.uber.org/zap/zapcore"
12+
13+
"github.com/reddit/baseplate.go/internal/prometheusbpint"
14+
"github.com/reddit/baseplate.go/randbp"
15+
)
16+
17+
var httpServerLoggingCounter = promauto.With(prometheusbpint.GlobalRegistry).NewCounterVec(prometheus.CounterOpts{
18+
Name: "httpbp_server_upstream_issue_logs_total",
19+
Help: "Number of logs emitted by stdlib http server regarding an upstream issue",
20+
}, []string{"upstream_issue"})
21+
22+
type issueConfig struct {
23+
sampleRate float64
24+
counter prometheus.Counter
25+
}
26+
27+
var supportedIDs = []int64{
28+
25192,
29+
}
30+
31+
// This is a special zapcore used by stdlib http server to handle error logging.
32+
type wrappedCore struct {
33+
zapcore.Core
34+
35+
issues map[int64]issueConfig
36+
}
37+
38+
func (w wrappedCore) Check(entry zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry {
39+
// Example message:
40+
// 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
41+
if strings.Contains(entry.Message, "golang.org/issue/25192") {
42+
cfg := w.issues[25192]
43+
cfg.counter.Inc()
44+
if !randbp.ShouldSampleWithRate(cfg.sampleRate) {
45+
// drop the log
46+
return ce
47+
}
48+
}
49+
50+
return w.Core.Check(entry, ce)
51+
}
52+
53+
func httpServerLogger(sampleRates map[int64]float64, base *zap.Logger) (*log.Logger, error) {
54+
issues := make(map[int64]issueConfig, len(supportedIDs))
55+
for _, id := range supportedIDs {
56+
rate, ok := sampleRates[id]
57+
if !ok {
58+
rate = 1
59+
}
60+
issues[id] = issueConfig{
61+
sampleRate: rate,
62+
counter: httpServerLoggingCounter.With(prometheus.Labels{
63+
"upstream_issue": strconv.FormatInt(id, 10),
64+
}),
65+
}
66+
}
67+
68+
return zap.NewStdLogAt(base.WithOptions(
69+
zap.Fields(zap.String("from", "http-server")),
70+
zap.WrapCore(func(c zapcore.Core) zapcore.Core {
71+
return wrappedCore{
72+
Core: c,
73+
74+
issues: issues,
75+
}
76+
}),
77+
), zapcore.WarnLevel)
78+
}

‎httpbp/error_logger_test.go

+92
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,92 @@
1+
package httpbp
2+
3+
import (
4+
"io"
5+
"strings"
6+
"testing"
7+
8+
"github.com/prometheus/client_golang/prometheus"
9+
"go.uber.org/zap"
10+
"go.uber.org/zap/zapcore"
11+
12+
"github.com/reddit/baseplate.go/prometheusbp/promtest"
13+
)
14+
15+
func initBaseLogger(w io.Writer) *zap.Logger {
16+
// Mostly copied from zap.NewExample, to make the log deterministic.
17+
encoderCfg := zapcore.EncoderConfig{
18+
MessageKey: "msg",
19+
LevelKey: "level",
20+
NameKey: "logger",
21+
EncodeLevel: zapcore.LowercaseLevelEncoder,
22+
EncodeTime: zapcore.ISO8601TimeEncoder,
23+
EncodeDuration: zapcore.StringDurationEncoder,
24+
}
25+
core := zapcore.NewCore(zapcore.NewJSONEncoder(encoderCfg), zapcore.AddSync(w), zap.DebugLevel)
26+
return zap.New(core)
27+
}
28+
29+
func TestHTTPServerLogger(t *testing.T) {
30+
t.Run("no-panic", func(t *testing.T) {
31+
defer promtest.NewPrometheusMetricTest(t, "25192", httpServerLoggingCounter, prometheus.Labels{
32+
"upstream_issue": "25192",
33+
}).CheckDelta(1)
34+
35+
logger, err := httpServerLogger(nil, initBaseLogger(io.Discard))
36+
if err != nil {
37+
t.Fatalf("httpServerLogger failed: %v", err)
38+
}
39+
// Make sure that empty map won't cause panics with matching log lines.
40+
logger.Printf("Hello, golang.org/issue/25192!")
41+
})
42+
43+
t.Run("suppressed", func(t *testing.T) {
44+
defer promtest.NewPrometheusMetricTest(t, "25192", httpServerLoggingCounter, prometheus.Labels{
45+
"upstream_issue": "25192",
46+
}).CheckDelta(2)
47+
48+
var sb strings.Builder
49+
logger, err := httpServerLogger(map[int64]float64{
50+
25192: 0,
51+
}, initBaseLogger(&sb))
52+
if err != nil {
53+
t.Fatalf("httpServerLogger failed: %v", err)
54+
}
55+
logger.Printf("Hello, golang.org/issue/25192!")
56+
logger.Printf("Hello, golang.org/issue/25192!")
57+
if str := sb.String(); strings.TrimSpace(str) != "" {
58+
t.Errorf("Expected logs being suppressed, got %q", str)
59+
}
60+
61+
sb.Reset()
62+
logger.Printf("Hello, world!")
63+
const want = `{"level":"warn","msg":"Hello, world!","from":"http-server"}`
64+
if got := sb.String(); strings.TrimSpace(got) != want {
65+
t.Errorf("Got %q, want %q", got, want)
66+
}
67+
})
68+
69+
t.Run("not-suppressed", func(t *testing.T) {
70+
defer promtest.NewPrometheusMetricTest(t, "25192", httpServerLoggingCounter, prometheus.Labels{
71+
"upstream_issue": "25192",
72+
}).CheckDelta(1)
73+
74+
var sb strings.Builder
75+
logger, err := httpServerLogger(map[int64]float64{
76+
25192: 1,
77+
}, initBaseLogger(&sb))
78+
if err != nil {
79+
t.Fatalf("httpServerLogger failed: %v", err)
80+
}
81+
logger.Printf("Hello, golang.org/issue/25192!")
82+
if got, want := sb.String(), `{"level":"warn","msg":"Hello, golang.org/issue/25192!","from":"http-server"}`; strings.TrimSpace(got) != want {
83+
t.Errorf("Got %q, want %q", got, want)
84+
}
85+
86+
sb.Reset()
87+
logger.Printf("Hello, world!")
88+
if got, want := sb.String(), `{"level":"warn","msg":"Hello, world!","from":"http-server"}`; strings.TrimSpace(got) != want {
89+
t.Errorf("Got %q, want %q", got, want)
90+
}
91+
})
92+
}

‎httpbp/server.go

+27
Original file line numberDiff line numberDiff line change
@@ -157,6 +157,21 @@ type ServerArgs struct {
157157
// Logger is an optional arg to be called when the InjectEdgeRequestContext
158158
// middleware failed to parse the edge request header for any reason.
159159
Logger log.Wrapper
160+
161+
// UpstreamIssueLoggingSampleRates decides the sample rates to keep the logs
162+
// emitted by stdlib http.Server regarding an upstream issue.
163+
//
164+
// The key is the upstream issue id.
165+
// Currently the only supported one is 25192 [1],
166+
// but the supported issue ids might expand in the future.
167+
//
168+
// When a supported issue id is not in the map,
169+
// currently the default sample rate is 1
170+
// (100% sampled, e.g. not dropping those logs).
171+
// This might be changed to 0 in the future.
172+
//
173+
// [1]: https://github.com/golang/go/issues/25192#issuecomment-992276264
174+
UpstreamIssueLoggingSampleRates map[int64]float64
160175
}
161176

162177
// ValidateAndSetDefaults checks the ServerArgs for any errors and sets any
@@ -221,9 +236,21 @@ func NewBaseplateServer(args ServerArgs) (baseplate.Server, error) {
221236
return nil, err
222237
}
223238

239+
logger, err := httpServerLogger(args.UpstreamIssueLoggingSampleRates, log.C(context.Background()).Desugar())
240+
if err != nil {
241+
// Should not happen, but if it really happens, we just fallback to stdlib
242+
// logger, which is not that big a deal either.
243+
log.Errorw(
244+
"Failed to create error logger for stdlib http server",
245+
"err", err,
246+
)
247+
}
248+
224249
srv := &http.Server{
225250
Addr: args.Baseplate.GetConfig().Addr,
226251
Handler: args.EndpointRegistry,
252+
253+
ErrorLog: logger,
227254
}
228255
for _, f := range args.OnShutdown {
229256
srv.RegisterOnShutdown(f)

0 commit comments

Comments
 (0)