From beb7fb699afbbd56efc6736f63e9c372609e3f83 Mon Sep 17 00:00:00 2001 From: Patrick Steinhardt Date: Tue, 5 Sep 2023 14:31:08 +0200 Subject: grpc/backchannel: Simplify logging with yamux We're currently passing in an `io.WriteCloser()` to Yamux that is then being used as logger. This has the consequence that we're quite tied to the actual implementation of the logger because `WriterLevel()` is not something that's typically available in other logging libraries. But more importantly, it means that all log messages are now written at the error level, which isn't quite what we want. The current setup is actually a limitation of the Yamux package itself: we can either pass in a log writer, or a `log.Logger`. We don't really want either though. This limitation has been fixed upstream via 13a7bc0 (Fix hashicorp/yamux#72, abstract logger into interface, 2019-04-15), which converts starts to accept an interface instead of a `log.Logger`. The library didn't release a new version since then though, and given that this is change has been implemented four years ago, it seems quite unlikely that a new release will be created soonish. That being said though, upgrading to that unstable version should be fine as the only change between our current v0.1.1 and that commit is the change to use that logger interface. Let's upgrade Yamux to the version including this change and refactor our code to pass the `logrus.FieldLogger` directly instead of passing an `io.Writer`. --- NOTICE | 12 +++++++++--- go.mod | 2 +- go.sum | 4 ++-- internal/grpc/backchannel/backchannel.go | 7 ++++--- internal/grpc/backchannel/client.go | 6 +----- internal/grpc/backchannel/server.go | 9 ++------- 6 files changed, 19 insertions(+), 21 deletions(-) diff --git a/NOTICE b/NOTICE index 63a420e5d..199fb8f78 100644 --- a/NOTICE +++ b/NOTICE @@ -16028,7 +16028,6 @@ package yamux import ( "fmt" "io" - "log" "os" "time" ) @@ -16076,7 +16075,7 @@ type Config struct { // Logger is used to pass in the logger to be used. Either Logger or // LogOutput can be set, not both. - Logger *log.Logger + Logger Logger } // DefaultConfig is used to return a default configuration @@ -16176,7 +16175,7 @@ type Session struct { config *Config // logger is used for our logs - logger *log.Logger + logger Logger // conn is the underlying connection conn io.ReadWriteCloser @@ -19111,6 +19110,13 @@ import ( "time" ) +// Logger is a abstract of *log.Logger +type Logger interface { + Print(v ...interface{}) + Printf(format string, v ...interface{}) + Println(v ...interface{}) +} + var ( timerPool = &sync.Pool{ New: func() interface{} { diff --git a/go.mod b/go.mod index e0ad087f0..f6c9962c4 100644 --- a/go.mod +++ b/go.mod @@ -21,7 +21,7 @@ require ( github.com/grpc-ecosystem/go-grpc-middleware v1.4.0 github.com/grpc-ecosystem/go-grpc-prometheus v1.2.0 github.com/hashicorp/golang-lru/v2 v2.0.6 - github.com/hashicorp/yamux v0.1.1 + github.com/hashicorp/yamux v0.1.2-0.20220728231024-8f49b6f63f18 github.com/jackc/pgx/v5 v5.4.3 github.com/kelseyhightower/envconfig v1.4.0 github.com/libgit2/git2go/v34 v34.0.0 diff --git a/go.sum b/go.sum index 692d9e607..e2738d7cf 100644 --- a/go.sum +++ b/go.sum @@ -395,8 +395,8 @@ github.com/hashicorp/golang-lru v0.5.0/go.mod h1:/m3WP610KZHVQ1SGc6re/UDhFvYD7pJ github.com/hashicorp/golang-lru v0.5.1/go.mod h1:/m3WP610KZHVQ1SGc6re/UDhFvYD7pJ4Ao+sR/qLZy8= github.com/hashicorp/golang-lru/v2 v2.0.6 h1:3xi/Cafd1NaoEnS/yDssIiuVeDVywU0QdFGl3aQaQHM= github.com/hashicorp/golang-lru/v2 v2.0.6/go.mod h1:QeFd9opnmA6QUJc5vARoKUSoFhyfM2/ZepoAG6RGpeM= -github.com/hashicorp/yamux v0.1.1 h1:yrQxtgseBDrq9Y652vSRDvsKCJKOUD+GzTS4Y0Y8pvE= -github.com/hashicorp/yamux v0.1.1/go.mod h1:CtWFDAQgb7dxtzFs4tWbplKIe2jSi3+5vKbgIO0SLnQ= +github.com/hashicorp/yamux v0.1.2-0.20220728231024-8f49b6f63f18 h1:IVujPV6DRIu1fYF4zUHrfhkngJzmYjelXa+iSUiFZSI= +github.com/hashicorp/yamux v0.1.2-0.20220728231024-8f49b6f63f18/go.mod h1:CtWFDAQgb7dxtzFs4tWbplKIe2jSi3+5vKbgIO0SLnQ= github.com/hhatto/gorst v0.0.0-20181029133204-ca9f730cac5b h1:Jdu2tbAxkRouSILp2EbposIb8h4gO+2QuZEn3d9sKAc= github.com/hhatto/gorst v0.0.0-20181029133204-ca9f730cac5b/go.mod h1:HmaZGXHdSwQh1jnUlBGN2BeEYOHACLVGzYOXCbsLvxY= github.com/hpcloud/tail v1.0.0 h1:nfCOvKYfkgYP8hkirhJocXT2+zOD8yUNjXaWfTlyFKI= diff --git a/internal/grpc/backchannel/backchannel.go b/internal/grpc/backchannel/backchannel.go index 990e3e5fb..627a492d2 100644 --- a/internal/grpc/backchannel/backchannel.go +++ b/internal/grpc/backchannel/backchannel.go @@ -29,20 +29,21 @@ package backchannel import ( - "io" "net" "sync" "github.com/hashicorp/yamux" + "github.com/sirupsen/logrus" ) // magicBytes are sent by the client to server to identify as a multiplexing aware client. var magicBytes = []byte("backchannel") // muxConfig returns a new config to use with the multiplexing session. -func muxConfig(logger io.Writer, cfg Configuration) *yamux.Config { +func muxConfig(logger logrus.FieldLogger, cfg Configuration) *yamux.Config { yamuxCfg := yamux.DefaultConfig() - yamuxCfg.LogOutput = logger + yamuxCfg.Logger = logger + yamuxCfg.LogOutput = nil // gRPC is already configured to send keep alives so we don't need yamux to do this for us. // gRPC is a better choice as it sends the keep alives also to non-multiplexed connections. yamuxCfg.EnableKeepAlive = false diff --git a/internal/grpc/backchannel/client.go b/internal/grpc/backchannel/client.go index fe3ff8a77..f6f3d0663 100644 --- a/internal/grpc/backchannel/client.go +++ b/internal/grpc/backchannel/client.go @@ -115,18 +115,14 @@ func (ch clientHandshake) serve(ctx context.Context, conn net.Conn) (net.Conn, e return nil, fmt.Errorf("write backchannel magic bytes: %w", err) } - logger := ch.logger.WithField("component", "backchannel.YamuxClient").WriterLevel(logrus.ErrorLevel) - // Initiate the multiplexing session. - muxSession, err := yamux.Client(conn, muxConfig(logger, ch.cfg)) + muxSession, err := yamux.Client(conn, muxConfig(ch.logger.WithField("component", "backchannel.YamuxClient"), ch.cfg)) if err != nil { - logger.Close() return nil, fmt.Errorf("open multiplexing session: %w", err) } go func() { <-muxSession.CloseChan() - logger.Close() }() // Initiate the stream to the server. This is used by the client's gRPC session. diff --git a/internal/grpc/backchannel/server.go b/internal/grpc/backchannel/server.go index 44e2e6405..4e815e07f 100644 --- a/internal/grpc/backchannel/server.go +++ b/internal/grpc/backchannel/server.go @@ -99,8 +99,6 @@ func (s *ServerHandshaker) Handshake(conn net.Conn, authInfo credentials.AuthInf // gRPC server closes the conn if there is an error, which closes the multiplexing // session as well. - logger := s.logger.WithField("component", "backchannel.YamuxServer").WriterLevel(logrus.ErrorLevel) - // Open the server side of the multiplexing session. // // Gitaly is using custom settings with a lower accept backlog and higher receive @@ -109,16 +107,14 @@ func (s *ServerHandshaker) Handshake(conn net.Conn, authInfo credentials.AuthInf cfg := DefaultConfiguration() cfg.AcceptBacklog = 1 cfg.MaximumStreamWindowSizeBytes = 16 * 1024 * 1024 - muxSession, err := yamux.Server(conn, muxConfig(logger, cfg)) + muxSession, err := yamux.Server(conn, muxConfig(s.logger.WithField("component", "backchannel.YamuxServer"), cfg)) if err != nil { - logger.Close() return nil, nil, fmt.Errorf("create multiplexing session: %w", err) } // Accept the client's stream. This is the client's gRPC session to the server. clientToServerStream, err := muxSession.Accept() if err != nil { - logger.Close() return nil, nil, fmt.Errorf("accept client's stream: %w", err) } @@ -133,7 +129,6 @@ func (s *ServerHandshaker) Handshake(conn net.Conn, authInfo credentials.AuthInf )..., ) if err != nil { - logger.Close() return nil, nil, fmt.Errorf("dial backchannel: %w", err) } @@ -147,7 +142,7 @@ func (s *ServerHandshaker) Handshake(conn net.Conn, authInfo credentials.AuthInf var firstErr error for _, closer := range []io.Closer{ - backchannelConn, muxSession, logger, + backchannelConn, muxSession, } { if err := closer.Close(); err != nil && firstErr == nil { firstErr = err -- cgit v1.2.3