Send every log line to a syslog server as well (closes #28)

With SWWAF_LOG_REMOTE_URL set (syslog+udp, syslog+tcp or syslog+tls),
every line on stdout is also sent as the message of an RFC 5424 record,
octet-counted over TCP and TLS, from a bounded buffer that drops its
oldest line when full, so a slow or unreachable server holds up nothing.
Failed connections are retried with backoff; lines sent, dropped and
waiting are metrics. At a stop the lines still waiting get at most two
seconds. Standard library only: log/syslog writes only the older format.

Deviation: SWWAF_LOG_REMOTE_APP_NAME defaults to the host's name until
SWWAF_INSTANCE_NAME exists.

Model: opus-5-5

internal/remotelog/remotelog_test.go

@@ -0,0 +1,458 @@
+package remotelog_test
+
+import (
+	"bufio"
+	"bytes"
+	"context"
+	"crypto/ecdsa"
+	"crypto/elliptic"
+	"crypto/rand"
+	"crypto/tls"
+	"crypto/x509"
+	"crypto/x509/pkix"
+	"encoding/json"
+	"fmt"
+	"io"
+	"log/slog"
+	"math/big"
+	"net"
+	"net/url"
+	"os"
+	"slices"
+	"strconv"
+	"strings"
+	"sync"
+	"testing"
+	"testing/synctest"
+	"time"
+
+	"sneak.berlin/go/smallwebwaf/internal/remotelog"
+)
+
+// The tests run in a synctest bubble, where the time package runs on a
+// clock of the test's own, which starts at 2000-01-01T00:00:00Z: a wait
+// lasts exactly as long as it should, however slowly the test process
+// runs, and synctest.Wait returns once the sender has done all it can
+// before time passes. The endpoint is a listener on the loopback address.
+// A test reads from it only once the records are on their way, and checks
+// the sender's counts first, since a goroutine of the bubble that waits on
+// the network keeps that clock from moving on.
+
+const (
+	// started is the time a record made as a test starts gives.
+	started = "2000-01-01T00:00:00.000Z"
+	appName = "fsn1app1/gitea"
+	// local0 is the number of the default facility, and local0Info the
+	// priority of its records.
+	local0     = 16
+	local0Info = "<134>"
+	// loopback is where the endpoints listen.
+	loopback = "127.0.0.1:0"
+)
+
+func TestRecordsOverUDPGoOnePerDatagram(t *testing.T) {
+	t.Parallel()
+
+	synctest.Test(t, func(t *testing.T) {
+		endpoint, err := (&net.ListenConfig{}).ListenPacket(t.Context(), "udp", loopback)
+		if err != nil {
+			t.Fatalf("listen: %v", err)
+		}
+
+		t.Cleanup(func() { _ = endpoint.Close() })
+
+		sender, _, _ := run(t, params(remotelog.SchemeUDP, endpoint.LocalAddr()))
+
+		_, _ = sender.Write([]byte(`{"type":"request"}` + "\n" + `{"type":"process"}` + "\n"))
+
+		synctest.Wait()
+		wantCounts(t, sender, 2, 0, 0)
+
+		for _, line := range []string{`{"type":"request"}`, `{"type":"process"}`} {
+			datagram := make([]byte, 1024)
+
+			n, _, err := endpoint.ReadFrom(datagram)
+			if err != nil {
+				t.Fatalf("read: %v", err)
+			}
+
+			want := record(t, local0Info, appName, line)
+			if string(datagram[:n]) != want {
+				t.Errorf("datagram %q, want %q", datagram[:n], want)
+			}
+		}
+	})
+}
+
+func TestRecordsOverTCPAreOctetCountedWithTheirFacility(t *testing.T) {
+	t.Parallel()
+
+	synctest.Test(t, func(t *testing.T) {
+		endpoint := listen(t, loopback)
+		endpointParams := params(remotelog.SchemeTCP, endpoint.Addr())
+		endpointParams.Facility = 19 // local3
+		endpointParams.AppName = "gitea"
+		sender, _, _ := run(t, endpointParams)
+
+		_, _ = sender.Write([]byte("first\nsecond\n"))
+
+		synctest.Wait()
+		wantCounts(t, sender, 2, 0, 0)
+
+		frames := bufio.NewReader(accept(t, endpoint))
+		wantFrame(t, frames, record(t, "<158>", "gitea", "first"))
+		wantFrame(t, frames, record(t, "<158>", "gitea", "second"))
+	})
+}
+
+func TestStalledEndpointHoldsUpNoWriteAndOldestRecordsAreDropped(t *testing.T) {
+	t.Parallel()
+
+	synctest.Test(t, func(t *testing.T) {
+		certificate, roots := testCertificate(t)
+		endpoint := listen(t, loopback)
+		endpointParams := params(remotelog.SchemeTLS, endpoint.Addr())
+		endpointParams.RootCAs = roots
+		endpointParams.Buffer = 3
+		sender, _, _ := run(t, endpointParams)
+
+		// The sender connects, and its TLS handshake waits for an answer
+		// the endpoint does not give yet.
+		conn := accept(t, endpoint)
+
+		var stdout bytes.Buffer
+
+		out := io.MultiWriter(&stdout, sender)
+		for i := range 5 {
+			_, _ = fmt.Fprintf(out, "line %d\n", i+1)
+		}
+
+		if stdout.String() != "line 1\nline 2\nline 3\nline 4\nline 5\n" {
+			t.Errorf("stdout has %q", stdout.String())
+		}
+
+		wantCounts(t, sender, 0, 2, 3)
+
+		// Once the endpoint answers, the three newest records are sent.
+		server := tls.Server(conn, &tls.Config{
+			Certificates: []tls.Certificate{certificate},
+			MinVersion:   tls.VersionTLS12,
+		})
+
+		err := server.HandshakeContext(t.Context())
+		if err != nil {
+			t.Fatalf("handshake: %v", err)
+		}
+
+		synctest.Wait()
+		wantCounts(t, sender, 3, 2, 0)
+
+		frames := bufio.NewReader(server)
+		for _, line := range []string{"line 3", "line 4", "line 5"} {
+			wantFrame(t, frames, record(t, local0Info, appName, line))
+		}
+	})
+}
+
+func TestReconnectsWithBackoffAfterTheEndpointGoesAway(t *testing.T) {
+	t.Parallel()
+
+	synctest.Test(t, func(t *testing.T) {
+		endpoint := listen(t, loopback)
+		addr := endpoint.Addr()
+		sender, logged, _ := run(t, params(remotelog.SchemeTCP, addr))
+
+		_, _ = sender.Write([]byte("one\n"))
+
+		synctest.Wait()
+		wantCounts(t, sender, 1, 0, 0)
+
+		conn := accept(t, endpoint)
+		wantFrame(t, bufio.NewReader(conn), record(t, local0Info, appName, "one"))
+
+		// The endpoint goes away. The sender notices when a record fails,
+		// and tries to connect again at once, then a second later, then two
+		// seconds after that.
+		_ = conn.Close()
+		_ = endpoint.Close()
+
+		writeUntilDropped(t, sender, 1)
+		sent := sender.Sent()
+
+		_, _ = sender.Write([]byte("two\n"))
+
+		time.Sleep(time.Second)
+		synctest.Wait()
+
+		endpoint = listen(t, addr.String())
+
+		time.Sleep(2*time.Second - time.Nanosecond)
+		synctest.Wait()
+		wantCounts(t, sender, sent, 1, 1)
+
+		// The endpoint is back, and the record waiting is sent.
+		time.Sleep(time.Nanosecond)
+		synctest.Wait()
+		wantCounts(t, sender, sent+1, 1, 0)
+
+		conn = accept(t, endpoint)
+		wantFrame(t, bufio.NewReader(conn), record(t, local0Info, appName, "two"))
+		wantRetries(t, logged, "1s", "2s")
+
+		// Having connected, the sender waits a second again after the
+		// next failure.
+		_ = conn.Close()
+		_ = endpoint.Close()
+
+		writeUntilDropped(t, sender, 2)
+		wantRetries(t, logged, "1s", "2s", "1s")
+	})
+}
+
+func TestRecordsWaitingAtTheStopAreSent(t *testing.T) {
+	t.Parallel()
+
+	synctest.Test(t, func(t *testing.T) {
+		// Nothing listens at addr when the sender starts: it fails to
+		// connect, and waits a second to try again.
+		endpoint := listen(t, loopback)
+		addr := endpoint.Addr()
+		_ = endpoint.Close()
+
+		sender, logged, stop := run(t, params(remotelog.SchemeTCP, addr))
+
+		synctest.Wait()
+		wantRetries(t, logged, "1s")
+
+		_, _ = sender.Write([]byte("one\ntwo\n"))
+		endpoint = listen(t, addr.String())
+
+		// Stopped before that second is over, it connects to send them.
+		stop()
+		wantCounts(t, sender, 2, 0, 0)
+
+		frames := bufio.NewReader(accept(t, endpoint))
+		wantFrame(t, frames, record(t, local0Info, appName, "one"))
+		wantFrame(t, frames, record(t, local0Info, appName, "two"))
+	})
+}
+
+// output collects what the sender logs.
+type output struct {
+	mu  sync.Mutex
+	buf bytes.Buffer
+}
+
+// Write adds lines the sender logs.
+func (o *output) Write(p []byte) (int, error) {
+	o.mu.Lock()
+	defer o.mu.Unlock()
+
+	return o.buf.Write(p)
+}
+
+// text returns everything logged so far.
+func (o *output) text() string {
+	o.mu.Lock()
+	defer o.mu.Unlock()
+
+	return o.buf.String()
+}
+
+// params returns the settings of a Sender for the endpoint at addr, in
+// the form scheme names: room for ten lines, the default facility, and
+// appName.
+func params(scheme string, addr net.Addr) remotelog.Params {
+	return remotelog.Params{
+		URL:      &url.URL{Scheme: scheme, Host: addr.String()},
+		Buffer:   10,
+		Facility: local0,
+		AppName:  appName,
+	}
+}
+
+// run runs a Sender with settings until the test ends or the function
+// it returns is called, which waits for Run to return. It returns the
+// Sender, and what it logs.
+func run(t *testing.T, settings remotelog.Params) (*remotelog.Sender, *output, func()) {
+	t.Helper()
+
+	sender := remotelog.New(settings)
+	logged := &output{}
+	ctx, cancel := context.WithCancel(t.Context())
+	ran := make(chan struct{})
+
+	go func() {
+		sender.Run(ctx, slog.New(slog.NewJSONHandler(logged, nil)))
+		close(ran)
+	}()
+
+	stop := func() {
+		cancel()
+		<-ran
+	}
+	t.Cleanup(stop)
+
+	return sender, logged, stop
+}
+
+// listen returns a TCP listener at addr, closed when the test ends.
+func listen(t *testing.T, addr string) net.Listener {
+	t.Helper()
+
+	listener, err := (&net.ListenConfig{}).Listen(t.Context(), "tcp", addr)
+	if err != nil {
+		t.Fatalf("listen: %v", err)
+	}
+
+	t.Cleanup(func() { _ = listener.Close() })
+
+	return listener
+}
+
+// accept returns the next connection to listener, closed when the test
+// ends.
+func accept(t *testing.T, listener net.Listener) net.Conn {
+	t.Helper()
+
+	conn, err := listener.Accept()
+	if err != nil {
+		t.Fatalf("accept: %v", err)
+	}
+
+	t.Cleanup(func() { _ = conn.Close() })
+
+	return conn
+}
+
+// record returns the record of line made as the test started, with the
+// priority and the app name given.
+func record(t *testing.T, priority, app, line string) string {
+	t.Helper()
+
+	hostname, err := os.Hostname()
+	if err != nil || hostname == "" {
+		hostname = "-"
+	}
+
+	return priority + "1 " + started + " " + hostname + " " + app + " - - - " + line
+}
+
+// wantFrame reads the next octet-counted frame from frames, and checks
+// that it holds want.
+func wantFrame(t *testing.T, frames *bufio.Reader, want string) {
+	t.Helper()
+
+	count, err := frames.ReadString(' ')
+	if err != nil {
+		t.Fatalf("read a frame's length: %v", err)
+	}
+
+	length, err := strconv.Atoi(strings.TrimSuffix(count, " "))
+	if err != nil {
+		t.Fatalf("frame starts %q, not with its length", count)
+	}
+
+	got := make([]byte, length)
+
+	_, err = io.ReadFull(frames, got)
+	if err != nil {
+		t.Fatalf("read a frame: %v", err)
+	}
+
+	if string(got) != want {
+		t.Errorf("frame %q, want %q", got, want)
+	}
+}
+
+// wantCounts checks the records sender has sent, dropped and holds in
+// its buffer.
+func wantCounts(
+	t *testing.T, sender *remotelog.Sender, sent, dropped int64, depth int,
+) {
+	t.Helper()
+
+	if sender.Sent() != sent || sender.Dropped() != dropped || sender.Depth() != depth {
+		t.Fatalf("sent %d, dropped %d, %d in the buffer; want %d, %d and %d",
+			sender.Sent(), sender.Dropped(), sender.Depth(), sent, dropped, depth)
+	}
+}
+
+// writeUntilDropped writes a line at a time until the count of records
+// sender has dropped reaches dropped. The records it sends on a
+// connection the endpoint has closed are lost before one fails; how many
+// depends on when the endpoint's host answers that the connection is
+// gone.
+func writeUntilDropped(t *testing.T, sender *remotelog.Sender, dropped int64) {
+	t.Helper()
+
+	for sender.Dropped() < dropped {
+		_, _ = sender.Write([]byte("lost\n"))
+
+		synctest.Wait()
+	}
+}
+
+// wantRetries checks that the sender logged a failed attempt to connect
+// for each of delays, the time until the next attempt, in order, and
+// logged nothing else.
+func wantRetries(t *testing.T, logged *output, delays ...string) {
+	t.Helper()
+
+	var got []string
+
+	for line := range strings.Lines(logged.text()) {
+		var fields map[string]any
+
+		err := json.Unmarshal([]byte(line), &fields)
+		if err != nil || fields["msg"] != "connecting to SWWAF_LOG_REMOTE_URL failed" {
+			t.Fatalf("logged %q", line)
+		}
+
+		delay, _ := fields["connecting_again_in"].(string)
+		got = append(got, delay)
+	}
+
+	if !slices.Equal(got, delays) {
+		t.Errorf("logged failures to connect again in %v, want %v", got, delays)
+	}
+}
+
+// testCertificate returns a certificate for 127.0.0.1 that is its own
+// CA, and a pool that holds it.
+func testCertificate(t *testing.T) (tls.Certificate, *x509.CertPool) {
+	t.Helper()
+
+	key, err := ecdsa.GenerateKey(elliptic.P256(), rand.Reader)
+	if err != nil {
+		t.Fatalf("generate a key: %v", err)
+	}
+
+	template := &x509.Certificate{
+		SerialNumber:          big.NewInt(1),
+		Subject:               pkix.Name{CommonName: "smallwebwaf test CA"},
+		NotBefore:             time.Now().Add(-time.Hour),
+		NotAfter:              time.Now().Add(time.Hour),
+		IsCA:                  true,
+		BasicConstraintsValid: true,
+		KeyUsage:              x509.KeyUsageCertSign | x509.KeyUsageDigitalSignature,
+		ExtKeyUsage:           []x509.ExtKeyUsage{x509.ExtKeyUsageServerAuth},
+		IPAddresses:           []net.IP{net.IPv4(127, 0, 0, 1)},
+	}
+
+	der, err := x509.CreateCertificate(rand.Reader, template, template,
+		&key.PublicKey, key)
+	if err != nil {
+		t.Fatalf("create a certificate: %v", err)
+	}
+
+	certificate, err := x509.ParseCertificate(der)
+	if err != nil {
+		t.Fatalf("parse the certificate: %v", err)
+	}
+
+	roots := x509.NewCertPool()
+	roots.AddCert(certificate)
+
+	return tls.Certificate{Certificate: [][]byte{der}, PrivateKey: key}, roots
+}