improve logging of http/grpc servers

- remove warning in favour of key-value
- add missing message when serving http plain-text
- align message wording
- change "prefix" with "service" in log messages
- log error stopping HTTP server as error, not warn
- incorrect error message "failed while serving http",
  it was unclear if it was http or https

go.mod

@@ -42,7 +42,7 @@ require (
 	github.com/jackc/pgx/v4 v4.17.2
 	github.com/johannesboyne/gofakes3 v0.0.0-20220314170512-33c13122505e
 	github.com/jwangsadinata/go-multimap v0.0.0-20190620162914-c29f3d7f33b6
-	github.com/jzelinskie/cobrautil/v2 v2.0.0-00010101000000-000000000000
+	github.com/jzelinskie/cobrautil/v2 v2.0.0-20221003230316-3022721fa8f0
 	github.com/jzelinskie/stringz v0.0.1
 	github.com/lib/pq v1.10.7
 	github.com/mostynb/go-grpc-compression v1.1.17

go.sum

@@ -242,6 +242,8 @@ github.com/go-logr/logr v1.2.3/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbV
 github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag=
 github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE=
 github.com/go-logr/zapr v1.2.0 h1:n4JnPI1T3Qq1SFEi/F8rwLrZERp2bso19PJZDB9dayk=
+github.com/go-logr/zerologr v1.2.2 h1:nKJ1glUZQPURRpe20GaqCBgNyGYg9cylaerwrwKoogE=
+github.com/go-logr/zerologr v1.2.2/go.mod h1:eIsB+dwGuN3lAGytcpbXyBeiY8GKInIxy+Qwe+gI5lI=
 github.com/go-openapi/jsonpointer v0.19.3/go.mod h1:Pl9vOtqEWErmShwVjC8pYs9cog34VGT37dQOVbmoatg=
 github.com/go-openapi/jsonpointer v0.19.5 h1:gZr+CIYByUqjcgeLXnQu2gHYQC9o73G2XUeOFYEICuY=
 github.com/go-openapi/jsonpointer v0.19.5/go.mod h1:Pl9vOtqEWErmShwVjC8pYs9cog34VGT37dQOVbmoatg=
@@ -482,8 +484,8 @@ github.com/julienschmidt/httprouter v1.2.0/go.mod h1:SYymIcj16QtmaHHD7aYtjjsJG7V
 github.com/julienschmidt/httprouter v1.3.0/go.mod h1:JR6WtHb+2LUe8TCKY3cZOxFyyO8IZAc4RVcycCCAKdM=
 github.com/jwangsadinata/go-multimap v0.0.0-20190620162914-c29f3d7f33b6 h1:OzCtZaD1uI5Fc1C+4oNAp7kZ4ibh5OIgxI29moH/IbE=
 github.com/jwangsadinata/go-multimap v0.0.0-20190620162914-c29f3d7f33b6/go.mod h1:CEusGbCRDFcHX9EgEhPsgJX33kpp9CfSFRBAoSGOems=
-github.com/jzelinskie/cobrautil v0.0.13-0.20220923164429-6dcc9495477a h1:kDNYsFya9fU9op5VhQbFvyS9niVz4oXf6rp5msKYoZo=
-github.com/jzelinskie/cobrautil v0.0.13-0.20220923164429-6dcc9495477a/go.mod h1:6ZtWJBr5t74cu9ysAyXs9j2Wkxc++ZR/09St+9CG68M=
+github.com/jzelinskie/cobrautil/v2 v2.0.0-20221003230316-3022721fa8f0 h1:PQtSXhXhIND0B9Qea303xJ/TsHFFlr+HVsU/kB8rKQo=
+github.com/jzelinskie/cobrautil/v2 v2.0.0-20221003230316-3022721fa8f0/go.mod h1:iqQf0oijpU31L1tuvD9+dKxkhdAv9IaKlnzVattaDwo=
 github.com/jzelinskie/stringz v0.0.1 h1:IahR+y8ct2nyj7B6i8UtFsGFj4ex1SX27iKFYsAheLk=
 github.com/jzelinskie/stringz v0.0.1/go.mod h1:hHYbgxJuNLRw91CmpuFsYEOyQqpDVFg8pvEh23vy4P0=
 github.com/kisielk/errcheck v1.1.0/go.mod h1:EZBBE59ingxPouuu3KfxchcWSUPOHkagtvWXihfKN4Q=

internal/datastore/proxy/caching.go

@@ -11,7 +11,6 @@ import (
 	"github.com/stretchr/testify/require"
 	"golang.org/x/sync/singleflight"
 
-	log "github.com/authzed/spicedb/internal/logging"
 	"github.com/authzed/spicedb/pkg/cache"
 	"github.com/authzed/spicedb/pkg/datastore"
 	core "github.com/authzed/spicedb/pkg/proto/core/v1"

internal/dispatch/caching/caching.go

@@ -10,6 +10,7 @@ import (
 
 	"github.com/dustin/go-humanize"
 	"github.com/prometheus/client_golang/prometheus"
+	"github.com/stretchr/testify/require"
 
 	"github.com/authzed/spicedb/internal/dispatch"
 	"github.com/authzed/spicedb/internal/dispatch/keys"

internal/dispatch/graph/check_test.go

@@ -5,7 +5,7 @@ import (
 	"fmt"
 	"testing"
 
-	"github.com/authzed/spicedb/internal/logging"
+	log "github.com/authzed/spicedb/internal/logging"
 
 	"github.com/shopspring/decimal"
 	"github.com/stretchr/testify/require"
@@ -150,7 +150,7 @@ func TestMaxDepth(t *testing.T) {
 
 	mutation := tuple.Create(tuple.Parse("folder:oops#owner@folder:oops#owner"))
 
-	ctx := logging.Logger.WithContext(datastoremw.ContextWithHandle(context.Background()))
+	ctx := log.Logger.WithContext(datastoremw.ContextWithHandle(context.Background()))
 	require.NoError(datastoremw.SetInContext(ctx, ds))
 
 	revision, err := common.UpdateTuplesInDatastore(ctx, ds, mutation)
@@ -287,7 +287,7 @@ func newLocalDispatcher(t testing.TB) (context.Context, dispatch.Dispatcher, dec
 	cachingDispatcher.SetDelegate(dispatch)
 	require.NoError(t, err)
 
-	ctx := logging.Logger.WithContext(datastoremw.ContextWithHandle(context.Background()))
+	ctx := log.Logger.WithContext(datastoremw.ContextWithHandle(context.Background()))
 	require.NoError(t, datastoremw.SetInContext(ctx, ds))
 
 	return ctx, cachingDispatcher, revision

internal/dispatch/graph/lookupsubjects_test.go

@@ -6,7 +6,7 @@ import (
 	"sort"
 	"testing"
 
-	"github.com/authzed/spicedb/internal/logging"
+	log "github.com/authzed/spicedb/internal/logging"
 
 	"github.com/shopspring/decimal"
 	"github.com/stretchr/testify/require"
@@ -182,7 +182,7 @@ func TestLookupSubjectsMaxDepth(t *testing.T) {
 
 	ds, _ := testfixtures.StandardDatastoreWithSchema(rawDS, require)
 
-	ctx := logging.Logger.WithContext(datastoremw.ContextWithHandle(context.Background()))
+	ctx := log.Logger.WithContext(datastoremw.ContextWithHandle(context.Background()))
 	require.NoError(datastoremw.SetInContext(ctx, ds))
 
 	tpl := tuple.Parse("folder:oops#owner@folder:oops#owner")

internal/logging/logger.go

@@ -10,53 +10,35 @@ import (
 var Logger zerolog.Logger
 
 func init() {
-	nop := zerolog.Nop()
-	SetGlobalLogger(nop)
+	SetGlobalLogger(zerolog.Nop())
 }
 
 func SetGlobalLogger(logger zerolog.Logger) {
 	Logger = logger
+	zerolog.DefaultContextLogger = &Logger
 }
 
-func With() zerolog.Context {
-	return Logger.With()
-}
+func With() zerolog.Context { return Logger.With() }
 
-func Err(err error) *zerolog.Event {
-	return Logger.Err(err)
-}
+func Err(err error) *zerolog.Event { return Logger.Err(err) }
 
-func Trace() *zerolog.Event {
-	return Logger.Trace()
-}
+func Trace() *zerolog.Event { return Logger.Trace() }
 
-func Debug() *zerolog.Event {
-	return Logger.Debug()
-}
+func Debug() *zerolog.Event { return Logger.Debug() }
 
-func Info() *zerolog.Event {
-	return Logger.Info()
-}
+func Info() *zerolog.Event { return Logger.Info() }
 
-func Warn() *zerolog.Event {
-	return Logger.Warn()
-}
+func Warn() *zerolog.Event { return Logger.Warn() }
 
-func Error() *zerolog.Event {
-	return Logger.Error()
-}
+func Error() *zerolog.Event { return Logger.Error() }
 
-func Fatal() *zerolog.Event {
-	return Logger.Fatal()
-}
+func Fatal() *zerolog.Event { return Logger.Fatal() }
 
-func WithLevel(level zerolog.Level) *zerolog.Event {
-	return Logger.WithLevel(level)
-}
+func WithLevel(level zerolog.Level) *zerolog.Event { return Logger.WithLevel(level) }
 
-func Log() *zerolog.Event {
-	return Logger.Log()
-}
+func Log() *zerolog.Event { return Logger.Log() }
+
+func Ctx(ctx context.Context) *zerolog.Logger { return zerolog.Ctx(ctx) }
 
 func Print(v ...interface{}) {
 	Logger.Debug().CallerSkipFrame(1).Msg(fmt.Sprint(v...))
@@ -65,7 +47,3 @@ func Print(v ...interface{}) {
 func Printf(format string, v ...interface{}) {
 	Logger.Debug().CallerSkipFrame(1).Msgf(format, v...)
 }
-
-func Ctx(ctx context.Context) *zerolog.Logger {
-	return zerolog.Ctx(ctx)
-}

internal/services/cert_test.go

@@ -110,7 +110,6 @@ func TestCertRotation(t *testing.T) {
 	emptyDS, err := memdb.NewMemdbDatastore(0, 10, time.Duration(90_000_000_000_000))
 	require.NoError(t, err)
 	ds, revision := tf.StandardDatastoreWithData(emptyDS, require.New(t))
-
 	srv, err := server.NewConfigWithOptions(
 		server.WithDatastore(ds),
 		server.WithDispatcher(graph.NewLocalOnlyDispatcher(1)),

pkg/cmd/devtools.go

@@ -8,18 +8,17 @@ import (
 	"os/signal"
 	"time"
 
-	"github.com/go-logr/zerologr"
-
 	v0 "github.com/authzed/authzed-go/proto/authzed/api/v0"
 	"github.com/authzed/grpcutil"
 	"github.com/aws/aws-sdk-go/aws"
 	"github.com/aws/aws-sdk-go/aws/credentials"
+	"github.com/go-logr/zerologr"
 	grpczerolog "github.com/grpc-ecosystem/go-grpc-middleware/providers/zerolog/v2"
 	grpclog "github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging"
 	grpcprom "github.com/grpc-ecosystem/go-grpc-prometheus"
 	"github.com/jzelinskie/cobrautil/v2"
-	cobragrpc "github.com/jzelinskie/cobrautil/v2/grpc"
-	cobrahttp "github.com/jzelinskie/cobrautil/v2/http"
+	"github.com/jzelinskie/cobrautil/v2/cobragrpc"
+	"github.com/jzelinskie/cobrautil/v2/cobrahttp"
 	"github.com/jzelinskie/stringz"
 	"github.com/spf13/cobra"
 	"go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc"
@@ -33,9 +32,9 @@ import (
 )
 
 func RegisterDevtoolsFlags(cmd *cobra.Command) {
-	cobragrpc.RegisterGrpcServerFlags(cmd.Flags(), "grpc", "gRPC", ":50051", true)
-	cobrahttp.RegisterHTTPServerFlags(cmd.Flags(), "metrics", "metrics", ":9090", true)
-	cobrahttp.RegisterHTTPServerFlags(cmd.Flags(), "http", "download", ":8443", false)
+	grpcServiceBuilder().RegisterFlags(cmd.Flags())
+	httpMetricsServiceBuilder().RegisterFlags(cmd.Flags())
+	httpDownloadServiceBuilder().RegisterFlags(cmd.Flags())
 
 	cmd.Flags().String("share-store", "inmemory", "kind of share store to use")
 	cmd.Flags().String("share-store-salt", "", "salt for share store hashing")
@@ -57,12 +56,9 @@ func NewDevtoolsCommand(programName string) *cobra.Command {
 	}
 }
 
-func runfunc(cmd *cobra.Command, args []string) error {
-	grpcUtil := cobragrpc.New("grpc",
-		cobragrpc.WithLogger(zerologr.New(&log.Logger)),
-		cobragrpc.WithFlagPrefix("grpc"),
-	)
-	grpcServer, err := grpcUtil.ServerFromFlags(cmd,
+func runfunc(cmd *cobra.Command, _ []string) error {
+	grpcBuilder := grpcServiceBuilder()
+	grpcServer, err := grpcBuilder.ServerFromFlags(cmd,
 		grpc.ChainUnaryInterceptor(
 			grpclog.UnaryServerInterceptor(grpczerolog.InterceptorLogger(log.Logger)),
 			otelgrpc.UnaryServerInterceptor(),
@@ -80,34 +76,26 @@ func runfunc(cmd *cobra.Command, args []string) error {
 	registerDeveloperGrpcServices(grpcServer, shareStore)
 
 	go func() {
-		if err := grpcUtil.ListenFromFlags(cmd, grpcServer); err != nil {
+		if err := grpcBuilder.ListenFromFlags(cmd, grpcServer); err != nil {
 			log.Warn().Err(err).Msg("gRPC service did not shutdown cleanly")
 		}
 	}()
 
 	// Start the metrics endpoint.
-	metricsHTTP := cobrahttp.New("metrics",
-		cobrahttp.WithLogger(zerologr.New(&log.Logger)),
-		cobrahttp.WithFlagPrefix("metrics"),
-		cobrahttp.WithHandler(server.MetricsHandler(server.DisableTelemetryHandler)),
-	)
+	metricsHTTP := httpMetricsServiceBuilder()
 	metricsSrv := metricsHTTP.ServerFromFlags(cmd)
 	go func() {
-		if err := metricsHTTP.ListenWithServerFromFlags(cmd, metricsSrv); err != nil {
+		if err := metricsHTTP.ListenFromFlags(cmd, metricsSrv); err != nil {
 			log.Fatal().Err(err).Msg("failed while serving metrics")
 		}
 	}()
 
 	// start the http download api
-	downloadHTTP := cobrahttp.New("download",
-		cobrahttp.WithLogger(zerologr.New(&log.Logger)),
-		cobrahttp.WithFlagPrefix("http"),
-		cobrahttp.WithHandler(v0svc.DownloadHandler(shareStore)),
-	)
+	downloadHTTP := httpDownloadServiceBuilder(cobrahttp.WithHandler(v0svc.DownloadHandler(shareStore)))
 	downloadSrv := downloadHTTP.ServerFromFlags(cmd)
 	downloadSrv.ReadHeaderTimeout = 5 * time.Second
 	go func() {
-		if err := downloadHTTP.ListenWithServerFromFlags(cmd, downloadSrv); err != nil {
+		if err := downloadHTTP.ListenFromFlags(cmd, downloadSrv); err != nil {
 			log.Fatal().Err(err).Msg("failed while serving download http api")
 		}
 	}()
@@ -127,6 +115,28 @@ func runfunc(cmd *cobra.Command, args []string) error {
 	return nil
 }
 
+func httpDownloadServiceBuilder(option ...cobrahttp.Option) *cobrahttp.Builder {
+	option = append(option,
+		cobrahttp.WithLogger(zerologr.New(&log.Logger)),
+		cobrahttp.WithFlagPrefix("http"))
+	return cobrahttp.New("download", option...)
+}
+
+func httpMetricsServiceBuilder() *cobrahttp.Builder {
+	return cobrahttp.New("metrics",
+		cobrahttp.WithLogger(zerologr.New(&log.Logger)),
+		cobrahttp.WithFlagPrefix("metrics"),
+		cobrahttp.WithHandler(server.MetricsHandler(server.DisableTelemetryHandler)),
+	)
+}
+
+func grpcServiceBuilder() *cobragrpc.Builder {
+	return cobragrpc.New("grpc",
+		cobragrpc.WithLogger(zerologr.New(&log.Logger)),
+		cobragrpc.WithFlagPrefix("grpc"),
+	)
+}
+
 func shareStoreFromCmd(cmd *cobra.Command) (v0svc.ShareStore, error) {
 	shareStoreSalt := cobrautil.MustGetStringExpanded(cmd, "share-store-salt")
 	shareStoreKind := cobrautil.MustGetStringExpanded(cmd, "share-store")

pkg/cmd/root.go

@@ -1,17 +1,17 @@
 package cmd
 
 import (
-	cobraotel "github.com/jzelinskie/cobrautil/v2/otel"
-	cobralog "github.com/jzelinskie/cobrautil/v2/zerolog"
+	"github.com/jzelinskie/cobrautil/v2/cobraotel"
+	"github.com/jzelinskie/cobrautil/v2/cobrazerolog"
 	"github.com/spf13/cobra"
 
 	"github.com/authzed/spicedb/pkg/cmd/server"
 	"github.com/authzed/spicedb/pkg/releases"
 )
 
 func RegisterRootFlags(cmd *cobra.Command) {
-	cobralog.RegisterZeroLogFlags(cmd.PersistentFlags(), "log")
-	cobraotel.RegisterOpenTelemetryFlags(cmd.PersistentFlags(), "otel", cmd.Use)
+	cobrazerolog.New().RegisterFlags(cmd.PersistentFlags())
+	cobraotel.New(cmd.Use).RegisterFlags(cmd.PersistentFlags())
 	releases.RegisterFlags(cmd.PersistentFlags())
 }
 

pkg/cmd/server/defaults.go

@@ -12,8 +12,8 @@ import (
 	grpclog "github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging"
 	grpcprom "github.com/grpc-ecosystem/go-grpc-prometheus"
 	"github.com/jzelinskie/cobrautil/v2"
-	cobraotel "github.com/jzelinskie/cobrautil/v2/otel"
-	cobralog "github.com/jzelinskie/cobrautil/v2/zerolog"
+	"github.com/jzelinskie/cobrautil/v2/cobraotel"
+	"github.com/jzelinskie/cobrautil/v2/cobrazerolog"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
 	"github.com/rs/zerolog"
@@ -56,9 +56,9 @@ func ServeExample(programName string) string {
 func DefaultPreRunE(programName string) cobrautil.CobraRunFunc {
 	return cobrautil.CommandStack(
 		cobrautil.SyncViperPreRunE(programName),
-		cobralog.New(
-			cobralog.WithAsync(1000, 10*time.Millisecond),
-			cobralog.WithTarget(func(logger zerolog.Logger) {
+		cobrazerolog.New(
+			cobrazerolog.WithAsync(1000, 10*time.Millisecond),
+			cobrazerolog.WithTarget(func(logger zerolog.Logger) {
 				logging.SetGlobalLogger(logger)
 			}),
 		).RunE(),