feat!: add WithLogHandler option for more logging control

cmd/frisbii/flags.go

@@ -44,7 +44,8 @@ var Flags = []cli.Flag{
 	},
 	&cli.StringFlag{
 		Name:  "log-file",
-		Usage: "path to file to append HTTP request and error logs to, defaults to stdout",
+		Usage: "path to file to append HTTP request and error logs to, defaults to stdout (-)",
+		Value: "-",
 	},
 	&cli.DurationFlag{
 		Name:  "max-response-duration",

cmd/frisbii/main.go

@@ -3,6 +3,7 @@ package main
 import (
 	"context"
 	"fmt"
+	"io"
 	"net/url"
 	"os"
 	"os/signal"
@@ -124,8 +125,12 @@ func action(c *cli.Context) error {
 	}
 
 	loader.SetStatus("Loaded CARs, starting server ...")
-	logWriter := c.App.Writer
-	if config.LogFile != "" {
+	var logWriter io.Writer
+	switch config.LogFile {
+	case "":
+	case "-":
+		logWriter = c.App.Writer
+	default:
 		logWriter, err = os.OpenFile(config.LogFile, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
 		if err != nil {
 			return err
@@ -139,9 +144,9 @@ func action(c *cli.Context) error {
 
 	server, err := frisbii.NewFrisbiiServer(
 		ctx,
-		logWriter,
 		lsys,
 		config.Listen,
+		frisbii.WithLogWriter(logWriter),
 		frisbii.WithMaxResponseDuration(config.MaxResponseDuration),
 		frisbii.WithMaxResponseBytes(config.MaxResponseBytes),
 		frisbii.WithCompressionLevel(config.CompressionLevel),

frisbii.go

@@ -3,7 +3,6 @@ package frisbii
 import (
 	"context"
 	"errors"
-	"io"
 	"net"
 	"net/http"
 
@@ -26,7 +25,6 @@ var advMetadata = metadata.Default.New(metadata.IpfsGatewayHttp{})
 type FrisbiiServer struct {
 	ctx         context.Context
 	lsys        linking.LinkSystem
-	logWriter   io.Writer
 	httpOptions []HttpOption
 
 	listener        net.Listener
@@ -41,7 +39,6 @@ type IndexerProvider interface {
 
 func NewFrisbiiServer(
 	ctx context.Context,
-	logWriter io.Writer,
 	lsys linking.LinkSystem,
 	address string,
 	httpOptions ...HttpOption,
@@ -50,12 +47,8 @@ func NewFrisbiiServer(
 	if err != nil {
 		return nil, err
 	}
-	if logWriter == nil {
-		logWriter = io.Discard
-	}
 	return &FrisbiiServer{
 		ctx:         ctx,
-		logWriter:   logWriter,
 		lsys:        lsys,
 		httpOptions: httpOptions,
 		listener:    listener,
@@ -73,7 +66,7 @@ func (fs *FrisbiiServer) Serve() error {
 	server := &http.Server{
 		Addr:        fs.Addr().String(),
 		BaseContext: func(listener net.Listener) context.Context { return fs.ctx },
-		Handler:     NewLogMiddleware(fs.mux, fs.logWriter),
+		Handler:     NewLogMiddleware(fs.mux, fs.httpOptions...),
 	}
 	logger.Debugf("Serve() server on %s", fs.Addr().String())
 	return server.Serve(fs.listener)

frisbii_test.go

@@ -6,6 +6,8 @@ import (
 	"io"
 	"math/rand"
 	"net/http"
+	"net/url"
+	"strconv"
 	"testing"
 	"time"
 
@@ -83,7 +85,7 @@ func TestFrisbiiServer(t *testing.T) {
 	lsys.SetWriteStorage(store)
 	lsys.TrustedStorage = true
 
-	entity, err := unixfsgen.Parse("file:1MiB")
+	entity, err := unixfsgen.Parse("file:1MiB{zero}")
 	require.NoError(t, err)
 	t.Logf("Generating: %s", entity.Describe(""))
 	rootEnt, err := entity.Generate(lsys, rndReader)
@@ -95,11 +97,25 @@ func TestFrisbiiServer(t *testing.T) {
 			ctx, cancel := context.WithTimeout(context.Background(), 3*time.Second)
 			defer cancel()
 
-			opts := []frisbii.HttpOption{}
+			opts := []frisbii.HttpOption{
+				frisbii.WithLogHandler(func(time time.Time, remoteAddr, method string, url url.URL, status int, duration time.Duration, bytes int, compressionRatio, userAgent, msg string) {
+					t.Logf("%s %s %s %d %s %d %s %s %s", remoteAddr, method, url.String(), status, duration, bytes, compressionRatio, userAgent, msg)
+					req.Equal("GET", method)
+					req.Equal("/ipfs/"+rootEnt.Root.String(), url.Path)
+					req.Equal(http.StatusOK, status)
+					if tc.expectGzip {
+						req.NotEqual("-", compressionRatio)
+						// convert compressionRatio string to a float64
+						compressionRatio, err := strconv.ParseFloat(compressionRatio, 64)
+						req.NoError(err)
+						req.True(compressionRatio > 10, "compression ratio (%s) should be > 10", compressionRatio) // it's all zeros
+					}
+				}),
+			}
 			if tc.serverCompressionLevel != gzip.NoCompression {
 				opts = append(opts, frisbii.WithCompressionLevel(tc.serverCompressionLevel))
 			}
-			server, err := frisbii.NewFrisbiiServer(ctx, nil, lsys, "localhost:0", opts...)
+			server, err := frisbii.NewFrisbiiServer(ctx, lsys, "localhost:0", opts...)
 			req.NoError(err)
 			go func() {
 				req.NoError(server.Serve())

httpipfs.go

@@ -36,6 +36,8 @@ type httpOptions struct {
 	MaxResponseDuration time.Duration
 	MaxResponseBytes    int64
 	CompressionLevel    int
+	LogWriter           io.Writer
+	LogHandler          LogHandler
 }
 
 type HttpOption func(*httpOptions)
@@ -77,6 +79,43 @@ func WithCompressionLevel(l int) HttpOption {
 	}
 }
 
+// WithLogWriter sets the writer that will be used to log requests. By default,
+// requests are not logged.
+//
+// The log format for requests (including errors) is roughly equivalent to a
+// standard nginx or Apache log format; that is, a space-separated list of
+// elements, where the elements that may contain spaces are quoted. The format
+// of each line can be specified as:
+//
+//	%s %s %s "%s" %d %d %d %s "%s" "%s"
+//
+// Where the elements are:
+//
+// 1. RFC 3339 timestamp
+// 2. Remote address
+// 3. Method
+// 4. Path
+// 5. Response status code
+// 6. Response duration (in milliseconds)
+// 7. Response size
+// 8. Compression ratio (or `-` if no compression)
+// 9. User agent
+// 10. Error (or `""` if no error)
+func WithLogWriter(w io.Writer) HttpOption {
+	return func(o *httpOptions) {
+		o.LogWriter = w
+	}
+}
+
+// WithLogHandler sets a handler function that will be used to log requests. By
+// default, requests are not logged. This is an alternative to WithLogWriter
+// that allows for more control over the logging.
+func WithLogHandler(h LogHandler) HttpOption {
+	return func(o *httpOptions) {
+		o.LogHandler = h
+	}
+}
+
 // NewHttpIpfs returns an http.Handler that serves IPLD data via HTTP according
 // to the Trustless Gateway specification.
 func NewHttpIpfs(
@@ -87,10 +126,10 @@ func NewHttpIpfs(
 	cfg := toConfig(opts)
 	handlerFunc := NewHttpIpfsHandlerFunc(ctx, lsys, opts...)
 	if cfg.CompressionLevel != gzip.NoCompression {
-		gzipHandler := gziphandler.MustNewGzipLevelHandler(cfg.CompressionLevel)
+		gzipWrapper := gziphandler.MustNewGzipLevelHandler(cfg.CompressionLevel)
 		// mildly awkward level of wrapping going on here but HttpIpfs is really
 		// just a HandlerFunc->Handler converter
-		handlerFunc = gzipHandler(&HttpIpfs{handlerFunc: handlerFunc}).ServeHTTP
+		handlerFunc = gzipWrapper(&HttpIpfs{handlerFunc: handlerFunc}).ServeHTTP
 		logger.Debugf("enabling compression with a level of %d", cfg.CompressionLevel)
 	}
 	return &HttpIpfs{handlerFunc: handlerFunc}
@@ -243,11 +282,15 @@ func NewHttpIpfsHandlerFunc(
 
 		var writer io.Writer = newIpfsResponseWriter(res, cfg.MaxResponseBytes, func() {
 			// called once we start writing blocks into the CAR (on the first Put())
+
+			close(bytesWrittenCh) // signal that we've started writing, so we can't log errors to the response now
+
 			res.Header().Set("Content-Disposition", fmt.Sprintf("attachment; filename=%q", fileName))
 			res.Header().Set("Cache-Control", trustlesshttp.ResponseCacheControlHeader)
 			res.Header().Set("Content-Type", accept.WithQuality(1).String())
 			etag := request.Etag()
-			if _, ok := res.(*gziphandler.GzipResponseWriter); ok {
+			switch res.(type) {
+			case *gziphandler.GzipResponseWriter, gziphandler.GzipResponseWriterWithCloseNotify:
 				// there are conditions where we may have a GzipResponseWriter but the
 				// response will not be compressed, but they are related to very small
 				// response sizes so this shouldn't matter (much)
@@ -257,8 +300,6 @@ func NewHttpIpfsHandlerFunc(
 			res.Header().Set("X-Content-Type-Options", "nosniff")
 			res.Header().Set("X-Ipfs-Path", "/"+datamodel.ParsePath(req.URL.Path).String())
 			res.Header().Set("Vary", "Accept, Accept-Encoding")
-
-			close(bytesWrittenCh)
 		})
 
 		if lrw, ok := res.(*LoggingResponseWriter); ok {
@@ -295,7 +336,7 @@ type countingWriter struct {
 
 func (cw *countingWriter) Write(p []byte) (int, error) {
 	n, err := cw.Writer.Write(p)
-	cw.lrw.wroteBytes += n
+	cw.lrw.WroteBytes(n)
 	return n, err
 }