Fixing bug of missing access logs

src/code.cloudfoundry.org/gorouter/handlers/access_log.go

@@ -51,7 +51,21 @@ func (a *accessLog) ServeHTTP(rw http.ResponseWriter, r *http.Request, next http
 	requestBodyCounter := &countingReadCloser{delegate: r.Body}
 	r.Body = requestBodyCounter
 
-	next(rw, r)
+	var panicVal any
+	func() {
+		defer func() { panicVal = recover() }()
+		next(rw, r)
+	}()
+
+	if writeErr := proxyWriter.WriteError(); writeErr != nil {
+		a.logger.Error("client-connection-error-during-streaming",
+			log.ErrAttr(writeErr),
+			slog.String("request_path", r.URL.Path),
+			slog.String("request_method", r.Method),
+			slog.Int("status_code", proxyWriter.Status()),
+			slog.Int("bytes_sent", proxyWriter.Size()),
+			slog.String("remote_addr", r.RemoteAddr))
+	}
 
 	reqInfo, err := ContextRequestInfo(r)
 	if err != nil {
@@ -65,6 +79,9 @@ func (a *accessLog) ServeHTTP(rw http.ResponseWriter, r *http.Request, next http
 	alr.BodyBytesSent = proxyWriter.Size()
 	alr.StatusCode = proxyWriter.Status()
 	alr.RouterError = proxyWriter.Header().Get(router_http.CfRouterError)
+	if alr.RouterError == "" && proxyWriter.WriteError() != nil {
+		alr.RouterError = "client_connection_closed_during_streaming"
+	}
 	alr.FailedAttempts = reqInfo.FailedAttempts
 	alr.RoundTripSuccessful = reqInfo.RoundTripSuccessful
 
@@ -84,6 +101,10 @@ func (a *accessLog) ServeHTTP(rw http.ResponseWriter, r *http.Request, next http
 	alr.LocalAddress = reqInfo.LocalAddress
 
 	a.accessLogger.Log(*alr)
+
+	if panicVal != nil {
+		panic(panicVal)
+	}
 }
 
 type countingReadCloser struct {

src/code.cloudfoundry.org/gorouter/handlers/proxywriter.go

@@ -29,7 +29,7 @@ func (p *proxyWriterHandler) ServeHTTP(rw http.ResponseWriter, r *http.Request,
 		log.Panic(p.logger, "request-info-err", log.ErrAttr(err))
 		return
 	}
-	proxyWriter := utils.NewProxyResponseWriter(rw)
+	proxyWriter := utils.NewProxyResponseWriter(rw, p.logger)
 	reqInfo.ProxyResponseWriter = proxyWriter
 	next(proxyWriter, r)
 }

src/code.cloudfoundry.org/gorouter/proxy/utils/responsewriter.go

@@ -3,8 +3,11 @@ package utils
 import (
 	"bufio"
 	"errors"
+	"log/slog"
 	"net"
 	"net/http"
+
+	log "code.cloudfoundry.org/gorouter/logger"
 )
 
 type ProxyResponseWriter interface {
@@ -18,23 +21,28 @@ type ProxyResponseWriter interface {
 	SetStatus(status int)
 	Size() int
 	AddHeaderRewriter(HeaderRewriter)
+	WriteError() error
 }
 
 type proxyResponseWriter struct {
 	w      http.ResponseWriter
 	status int
 	size   int
 
+	logger  *slog.Logger
 	flusher http.Flusher
 	done    bool
 
+	writeErr error
+
 	headerRewriters []HeaderRewriter
 }
 
-func NewProxyResponseWriter(w http.ResponseWriter) *proxyResponseWriter {
+func NewProxyResponseWriter(w http.ResponseWriter, logger *slog.Logger) *proxyResponseWriter {
 	proxyWriter := &proxyResponseWriter{
 		w:       w,
 		flusher: w.(http.Flusher),
+		logger:  logger,
 	}
 
 	return proxyWriter
@@ -61,6 +69,17 @@ func (p *proxyResponseWriter) Write(b []byte) (int, error) {
 		p.WriteHeader(http.StatusOK)
 	}
 	size, err := p.w.Write(b)
+	if err != nil {
+		// Store the first write error for logging
+		if p.writeErr == nil {
+			p.writeErr = err
+		}
+		p.logger.Error("response-writing-err",
+			log.ErrAttr(err),
+			slog.Int("bytes_written", size),
+			slog.Int("total_size", p.size),
+			slog.Int("status", p.status))
+	}
 	p.size += size
 	return size, err
 }
@@ -118,3 +137,7 @@ func (p *proxyResponseWriter) Unwrap() http.ResponseWriter {
 func (p *proxyResponseWriter) AddHeaderRewriter(r HeaderRewriter) {
 	p.headerRewriters = append(p.headerRewriters, r)
 }
+
+func (p *proxyResponseWriter) WriteError() error {
+	return p.writeErr
+}

src/code.cloudfoundry.org/gorouter/proxy/utils/responsewriter_test.go

@@ -3,8 +3,10 @@ package utils
 import (
 	"bufio"
 	"errors"
+	"log/slog"
 	"net"
 	"net/http"
+	"os"
 
 	. "github.com/onsi/ginkgo/v2"
 	. "github.com/onsi/gomega"
@@ -66,13 +68,15 @@ func (f *fakeHeaderRewriter) RewriteHeader(h http.Header) {
 
 var _ = Describe("ProxyWriter", func() {
 	var (
-		fake  *fakeResponseWriter
-		proxy *proxyResponseWriter
+		fake   *fakeResponseWriter
+		proxy  *proxyResponseWriter
+		logger *slog.Logger
 	)
 
 	BeforeEach(func() {
+		logger = slog.New(slog.NewTextHandler(os.Stderr, nil))
 		fake = newFakeResponseWriter()
-		proxy = NewProxyResponseWriter(fake)
+		proxy = NewProxyResponseWriter(fake, logger)
 	})
 
 	It("delegates the call to Header", func() {
@@ -89,7 +93,7 @@ var _ = Describe("ProxyWriter", func() {
 		fake := &fakeHijackerResponseWriter{
 			fakeResponseWriter: *newFakeResponseWriter(),
 		}
-		proxy = NewProxyResponseWriter(fake)
+		proxy = NewProxyResponseWriter(fake, logger)
 		proxy.Hijack()
 		Expect(fake.hijackCalled).To(BeTrue())
 	})
@@ -199,4 +203,40 @@ var _ = Describe("ProxyWriter", func() {
 			Expect(responseWriter).To(Equal(fake))
 		})
 	})
+
+	Describe("WriteError", func() {
+		It("returns nil when no write error has occurred", func() {
+			proxy.Write([]byte("foo"))
+			Expect(proxy.WriteError()).To(BeNil())
+		})
+
+		It("returns the first write error that occurred", func() {
+			fakeWithError := &fakeResponseWriterWithError{
+				fakeResponseWriter: *newFakeResponseWriter(),
+				writeError:         errors.New("connection reset by peer"),
+			}
+			proxyWithError := NewProxyResponseWriter(fakeWithError, logger)
+
+			proxyWithError.Write([]byte("data1"))
+			Expect(proxyWithError.WriteError()).To(MatchError("connection reset by peer"))
+
+			// Subsequent writes should preserve the first error
+			fakeWithError.writeError = errors.New("second error")
+			proxyWithError.Write([]byte("data2"))
+			Expect(proxyWithError.WriteError()).To(MatchError("connection reset by peer"))
+		})
+	})
 })
+
+type fakeResponseWriterWithError struct {
+	fakeResponseWriter
+	writeError error
+}
+
+func (f *fakeResponseWriterWithError) Write(b []byte) (int, error) {
+	f.writeCalled = true
+	if f.writeError != nil {
+		return len(b) / 2, f.writeError
+	}
+	return len(b), nil
+}