From 36d14dbf6665119337650b37629beced691661c4 Mon Sep 17 00:00:00 2001 From: Zach Reyes <39203661+zasweq@users.noreply.github.com> Date: Wed, 2 Nov 2022 19:46:50 -0400 Subject: [PATCH] Fix binary logging bug which logs a server header on a trailers only response (#5763) --- gcp/observability/logging_test.go | 17 +++-------------- internal/transport/transport.go | 10 ++++++++++ stream.go | 12 ++++++++++-- test/end2end_test.go | 4 ++-- 4 files changed, 25 insertions(+), 18 deletions(-) diff --git a/gcp/observability/logging_test.go b/gcp/observability/logging_test.go index d91af4afc67f..03638a9b49d7 100644 --- a/gcp/observability/logging_test.go +++ b/gcp/observability/logging_test.go @@ -608,9 +608,9 @@ func (s) TestBothClientAndServerRPCEvents(t *testing.T) { t.Fatalf("unexpected error: %v, expected an EOF error", err) } fle.mu.Lock() - if len(fle.entries) != 17 { + if len(fle.entries) != 16 { fle.mu.Unlock() - t.Fatalf("Unexpected length of entries %v, want 17 (collective of client and server)", len(fle.entries)) + t.Fatalf("Unexpected length of entries %v, want 16 (collective of client and server)", len(fle.entries)) } fle.mu.Unlock() } @@ -936,24 +936,13 @@ func (s) TestPrecedenceOrderingInConfiguration(t *testing.T) { SequenceID: 2, Authority: ss.Address, }, - { - Type: eventTypeServerHeader, - Logger: loggerClient, - ServiceName: "grpc.testing.TestService", - MethodName: "FullDuplexCall", - SequenceID: 3, - Authority: ss.Address, - Payload: payload{ - Metadata: map[string]string{}, - }, - }, { Type: eventTypeServerTrailer, Logger: loggerClient, ServiceName: "grpc.testing.TestService", MethodName: "FullDuplexCall", Authority: ss.Address, - SequenceID: 4, + SequenceID: 3, Payload: payload{ Metadata: map[string]string{}, }, diff --git a/internal/transport/transport.go b/internal/transport/transport.go index e21587b5321c..2e615ee20cc5 100644 --- a/internal/transport/transport.go +++ b/internal/transport/transport.go @@ -43,6 +43,10 @@ import ( "google.golang.org/grpc/tap" ) +// ErrNoHeaders is used as a signal that a trailers only response was received, +// and is not a real error. +var ErrNoHeaders = errors.New("stream has no headers") + const logLevel = 2 type bufferPool struct { @@ -366,9 +370,15 @@ func (s *Stream) Header() (metadata.MD, error) { return s.header.Copy(), nil } s.waitOnHeader() + if !s.headerValid { return nil, s.status.Err() } + + if s.noHeaders { + return nil, ErrNoHeaders + } + return s.header.Copy(), nil } diff --git a/stream.go b/stream.go index b10ab1ab6324..960c3e33dfd3 100644 --- a/stream.go +++ b/stream.go @@ -752,17 +752,25 @@ func (cs *clientStream) withRetry(op func(a *csAttempt) error, onSuccess func()) func (cs *clientStream) Header() (metadata.MD, error) { var m metadata.MD + noHeader := false err := cs.withRetry(func(a *csAttempt) error { var err error m, err = a.s.Header() + if err == transport.ErrNoHeaders { + noHeader = true + return nil + } return toRPCErr(err) }, cs.commitAttemptLocked) + if err != nil { cs.finish(err) return nil, err } - if len(cs.binlogs) != 0 && !cs.serverHeaderBinlogged { - // Only log if binary log is on and header has not been logged. + + if len(cs.binlogs) != 0 && !cs.serverHeaderBinlogged && !noHeader { + // Only log if binary log is on and header has not been logged, and + // there is actually headers to log. logEntry := &binarylog.ServerHeader{ OnClientSide: true, Header: m, diff --git a/test/end2end_test.go b/test/end2end_test.go index 438b43ca82f4..8e50ca70e569 100644 --- a/test/end2end_test.go +++ b/test/end2end_test.go @@ -8259,8 +8259,8 @@ func (s) TestGlobalBinaryLoggingOptions(t *testing.T) { t.Fatalf("unexpected error: %v, expected an EOF error", err) } - if csbl.mml.events != 9 { - t.Fatalf("want 9 client side binary logging events, got %v", csbl.mml.events) + if csbl.mml.events != 8 { + t.Fatalf("want 8 client side binary logging events, got %v", csbl.mml.events) } if ssbl.mml.events != 8 { t.Fatalf("want 8 server side binary logging events, got %v", ssbl.mml.events)