simplelog/handler_errors_internal_test.go

package simplelog

import (
	"bytes"
	"context"
	"errors"
	"log/slog"
	"net"
	"net/http"
	"net/http/httptest"
	"strings"
	"testing"
	"time"
)

// These tests sit inside the package so they can point a handler at a sink
// that fails, which callers outside the package cannot do.

// errSinkFailed is what failingWriter returns from every write.
var errSinkFailed = errors.New("sink failed")

// failingWriter is a sink whose every write fails.
type failingWriter struct{}

func (failingWriter) Write(_ []byte) (int, error) {
	return 0, errSinkFailed
}

func errorTestRecord() slog.Record {
	return slog.NewRecord(time.Now(), slog.LevelInfo, "casting", 0)
}

// The handler is derived with WithAttrs and WithGroup, so the test also
// fails if either of them drops the sink.
func TestJSONHandlerReturnsWriteError(t *testing.T) {
	t.Parallel()

	handler := (&JSONHandler{out: failingWriter{}}).
		WithAttrs([]slog.Attr{slog.String("service", "cattbox")}).
		WithGroup("cast")

	err := handler.Handle(context.Background(), errorTestRecord())
	if !errors.Is(err, errSinkFailed) {
		t.Fatalf("Handle returned %v, want the sink's error", err)
	}
}

func TestConsoleHandlerReturnsWriteError(t *testing.T) {
	t.Parallel()

	handler := (&ConsoleHandler{out: failingWriter{}}).
		WithAttrs([]slog.Attr{slog.String("service", "cattbox")}).
		WithGroup("cast")

	err := handler.Handle(context.Background(), errorTestRecord())
	if !errors.Is(err, errSinkFailed) {
		t.Fatalf("Handle returned %v, want the sink's error", err)
	}
}

// A failing handler must not stop the record reaching the handlers after
// it, and its error must still reach the caller.
func TestMultiplexHandlerDeliversPastFailingHandler(t *testing.T) {
	t.Parallel()

	var delivered bytes.Buffer

	handler := &MultiplexHandler{handlers: []ExtendedHandler{
		&JSONHandler{out: failingWriter{}},
		&JSONHandler{out: &delivered},
	}}

	err := handler.Handle(context.Background(), errorTestRecord())
	if !errors.Is(err, errSinkFailed) {
		t.Fatalf("Handle returned %v, want the failing handler's error", err)
	}

	if !strings.Contains(delivered.String(), `"Message":"casting"`) {
		t.Fatalf(
			"second handler did not receive the record: %q",
			delivered.String(),
		)
	}
}

// When more than one handler fails, the caller gets every failure, not
// only the first.
func TestMultiplexHandlerReturnsEveryFailure(t *testing.T) {
	t.Parallel()

	server := httptest.NewServer(http.HandlerFunc(
		func(w http.ResponseWriter, _ *http.Request) {
			w.WriteHeader(http.StatusInternalServerError)
		},
	))
	defer server.Close()

	webhook, err := NewWebhookHandler(server.URL)
	if err != nil {
		t.Fatalf("NewWebhookHandler: %v", err)
	}

	handler := &MultiplexHandler{handlers: []ExtendedHandler{
		&JSONHandler{out: failingWriter{}},
		webhook,
	}}

	err = handler.Handle(context.Background(), errorTestRecord())
	if !errors.Is(err, errSinkFailed) {
		t.Fatalf("Handle returned %v, want the JSON handler's error", err)
	}

	if !errors.Is(err, errWebhookStatus) {
		t.Fatalf("Handle returned %v, want the webhook's error", err)
	}
}

func TestWebhookHandlerReturnsErrorOnServerError(t *testing.T) {
	t.Parallel()

	server := httptest.NewServer(http.HandlerFunc(
		func(w http.ResponseWriter, _ *http.Request) {
			w.WriteHeader(http.StatusInternalServerError)
		},
	))
	defer server.Close()

	handler, err := NewWebhookHandler(server.URL)
	if err != nil {
		t.Fatalf("NewWebhookHandler: %v", err)
	}

	err = handler.Handle(context.Background(), errorTestRecord())
	if !errors.Is(err, errWebhookStatus) {
		t.Fatalf("Handle returned %v, want an error for the 500 answer", err)
	}
}

// Following the redirect would resend the request as a GET without the
// record, and the GET is answered with 200, so only an error for the
// redirect itself tells the caller the record was lost.
func TestWebhookHandlerReturnsErrorOnRedirect(t *testing.T) {
	t.Parallel()

	server := httptest.NewServer(http.HandlerFunc(
		func(w http.ResponseWriter, r *http.Request) {
			if r.URL.Path != "/moved" {
				http.Redirect(w, r, "/moved", http.StatusFound)
			}
		},
	))
	defer server.Close()

	handler, err := NewWebhookHandler(server.URL)
	if err != nil {
		t.Fatalf("NewWebhookHandler: %v", err)
	}

	err = handler.Handle(context.Background(), errorTestRecord())
	if !errors.Is(err, errWebhookStatus) {
		t.Fatalf("Handle returned %v, want an error for the redirect", err)
	}
}

// A server that accepts the request and never answers must not hold up
// the log call: Handle gives up after webhookTimeout and says why.
func TestWebhookHandlerTimesOutOnServerThatNeverAnswers(t *testing.T) {
	t.Parallel()

	testEnded := make(chan struct{})

	server := httptest.NewServer(http.HandlerFunc(
		func(_ http.ResponseWriter, _ *http.Request) {
			<-testEnded
		},
	))

	// server.Close waits for running requests, so the server's handler
	// is released first.
	defer func() {
		close(testEnded)
		server.Close()
	}()

	handler, err := NewWebhookHandler(server.URL)
	if err != nil {
		t.Fatalf("NewWebhookHandler: %v", err)
	}

	// Handle runs in a goroutine so that a lost timeout fails the test
	// instead of hanging the test run.
	handleErr := make(chan error, 1)

	go func() {
		handleErr <- handler.Handle(context.Background(), errorTestRecord())
	}()

	select {
	case err = <-handleErr:
	case <-time.After(webhookTimeout + time.Second):
		t.Fatal("Handle did not return within webhookTimeout")
	}

	var netErr net.Error
	if !errors.As(err, &netErr) || !netErr.Timeout() {
		t.Fatalf("Handle returned %v, want a timeout error", err)
	}
}

// A server that sends a 2xx status and then never finishes the answer
// must not hold up the log call either: reading the answer counts toward
// webhookTimeout, and Handle returns the read's error.
func TestWebhookHandlerTimesOutOnServerThatStallsTheAnswer(t *testing.T) {
	t.Parallel()

	testEnded := make(chan struct{})

	server := httptest.NewServer(http.HandlerFunc(
		func(w http.ResponseWriter, _ *http.Request) {
			w.WriteHeader(http.StatusOK)

			// Flush sends the status now; the answer stays unfinished
			// until the test ends.
			err := http.NewResponseController(w).Flush()
			if err != nil {
				t.Errorf("flush the status: %v", err)
			}

			<-testEnded
		},
	))

	// server.Close waits for running requests, so the server's handler
	// is released first.
	defer func() {
		close(testEnded)
		server.Close()
	}()

	handler, err := NewWebhookHandler(server.URL)
	if err != nil {
		t.Fatalf("NewWebhookHandler: %v", err)
	}

	// Handle runs in a goroutine so that a lost timeout fails the test
	// instead of hanging the test run.
	handleErr := make(chan error, 1)

	go func() {
		handleErr <- handler.Handle(context.Background(), errorTestRecord())
	}()

	select {
	case err = <-handleErr:
	case <-time.After(webhookTimeout + time.Second):
		t.Fatal("Handle did not return within webhookTimeout")
	}

	var netErr net.Error
	if !errors.As(err, &netErr) || !netErr.Timeout() {
		t.Fatalf("Handle returned %v, want a timeout error", err)
	}
}